open-telemetry / open-telemetry/opentelemetry-python-contrib
Django with sql commentor functionality duplicates SQL queries in debug mode and CaptureQueriesContext
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 1.1k
- Forks
- 1.1k
- Avg merge
- 4d 15h
- Merged PRs (30d)
- 16
Description
Describe your environment
Django 3.2, Python 3.10
Steps to reproduce
When instrumentation is active with either DEBUG = True turned on in settings.py or the CaptureQueriesContext context manager, it appears that multiple queries are executed. Here's a trimmed down test that shows what I mean:
def test_has_otel_comment(client: django.test.Client, span_capture: InMemorySpanExporter) -> None:
with CaptureQueriesContext(connection) as ctx:
response = client.get(
"/data",
)
(django_span,) = span_capture.get_finished_spans() # type: ignore[no-untyped-call]
traceparent = otel_traceparent(django_span)
query, _debug_query = ctx.captured_queries
assert (
'SELECT COUNT(*) AS "__count" FROM "auth_user"'
f" /*controller='tests.tracing.contrib.swdjango.test_sqlcomments.data',db_driver='django.db.backends.sqlite3',framework='django%%3A{djangoversion}',route='data',traceparent='{traceparent}'*/"
in query
)
assert response.json() == {"numusers": 0}
Note that the ctx.captured_queries has 2 queries - the first one is a string and is manually added by the sql_commentor middleware:
This is a really strange choice to me as it makes it look like 2x the number of queries are executed. Plus, the list ends up with different shapes - Django's CursorDebugWrapper uses a dict shape for the queries log but the sqlcommentor middleware adds a separate query as a plain string.
What is the expected behavior?
A single query from CaptureQueriesContext
In my case I use the CaptureQueriesContext to count the number of queries executed to ensure that data is appropriately prefetched/select_related.
What is the actual behavior?
Multiple queries are added to the queries_log for the connection
Additional context
Researching this a bit, it looks like this was present in the original SQLCommentor implementation. I can't find information as to why though. Based on what I can see from Django, the CursorDebugWrapper reaches out through the cursor to get the raw database query that was executed against the db. This usually includes the comment with the traceparent.
Current status of the raw query in the sql key of the queries_log from the CursorDebugWrapper
- Postgres ✅ - Includes the comment
- sqlite ❌ - Only includes the original query does not "see" the query modified by the middleware
- MySQL ❓ - not tested but probably
- Oracle ❓ - not tested probably not since this does the same sort of param replacement that SQLIte has
EDIT - it looks like the above raw sql queries is only relevant with execute(), not executemany(). In the case of executemany(), Django intentionally disables using the cursor to retrieve the last executed query.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with sqlcommenter_middleware.py around lines 115-117 and reproduce the provided CaptureQueriesContext case, then compare its entries with Django's CursorDebugWrapper behavior for execute() across SQLite and PostgreSQL. Done means the context contains one query per execution with a consistent query-log shape, while the SQL comment remains available where supported.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- django, python
- Domain
- backend, databases, observability
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 45/100