PYTHON-5947 Add OpenTelemetry operation spans - #2991
Conversation
4a8db0c to
ba21bb8
Compare
Codecov Report❌ Patch coverage is 📢 Thoughts on this report? Let us know! |
4e0c468 to
6638ae1
Compare
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
|
Semgrep found 2 GitHub Actions step uses a mutable tag or branch reference. Tags and branch names can be silently repointed by the action owner, enabling supply-chain attacks — as seen in the trivy-action and kics-github-action compromises. Pin the reference to a full 40-character commit SHA instead, e.g. 🛟 Help? Slack #semgrep-help or go/semgrep-help. Resolution Options:
|
NoahStapp
left a comment
NoahStapp
left a comment
There was a problem hiding this comment.
Can you run a micro benchmark measuring performance impact both when OTel is enabled as well as disabled?
| :param is_run_command: If this is a runCommand operation, defaults to False. | ||
| :param is_aggregate_write: If this is a aggregate operation with a write, defaults to False. | ||
| :param operation_id: Stable operation id shared across retries, defaults to None | ||
| :param operation_telemetry: A caller-owned operation span outliving this call, |
There was a problem hiding this comment.
How can the operation span outlive this call and this method own a fresh span? Not clear what that means.
There was a problem hiding this comment.
I clarified that AsyncCursor._refresh is the intended user.
| dbname: str, | ||
| collection: Optional[str] = None, | ||
| ) -> _CommandCursor: | ||
| """Run a command-cursor read within its own operation span. |
There was a problem hiding this comment.
| """Run a command-cursor read within its own operation span. | |
| """Run a command cursor read within its own operation span. |
No hyphen between command and cursor.
| # One span covering every attempt. A caller needing it to outlive this | ||
| # object (a cursor) passes its own and keeps ownership. |
There was a problem hiding this comment.
self._owns_telemetry = True means that we create the span here, otherwise it's passed in because a cursor owns it? Comment doesn't make that clear.
| ``query_text_max_length`` is None as validated from user input; the options | ||
| a client holds have been through :func:`_resolve_tracing_options`, so both | ||
| fields are resolved. |
There was a problem hiding this comment.
Does this mean that query_text_max_length is always None? Not sure what this comment means.
There was a problem hiding this comment.
None is to allow the env var to override when resolved. I created _UnresolvedTracingOptions to distinguish between the two states.
| return f"{command_name} {dbname}" | ||
|
|
||
|
|
||
| # Some `_Op` values are the wire command name ("drop"/"create") rather than the |
There was a problem hiding this comment.
Why not rename _Op for consistency if it's entirely internal?
There was a problem hiding this comment.
Logging wants the wire name, OTel wants the logical name (good times).
There was a problem hiding this comment.
Do you know the motivation behind that choice in the spec? Having two of our telemetry APIs record different names for the same operation seems very confusing for both us and users.
There was a problem hiding this comment.
Turns out I was confused as well, there are two different fields, db.operation.name and db.command.name. I made the comment more explicit.
| # spec's db.operation.name ("dropCollection"/"createCollection"). Translate here | ||
| # instead of renaming `_Op`: `_WRITES_WITH_CLUSTER_TIME` in operations.py matches | ||
| # these exact strings to pick which writes get afterClusterTime. | ||
| _OPERATION_NAME_OVERRIDES = { |
There was a problem hiding this comment.
I think we need "rename -> renameCollection" here too.
There was a problem hiding this comment.
Rename is not one of the supported operations.
There was a problem hiding this comment.
Why is that list prefaced with "including but not limited to the following operations"? Does that imply we should support rename if it's easy to do so?
There was a problem hiding this comment.
Forgot to reply, updated to point to DRIVERS-3625 for the follow up work.
| # built inside it. Before the sensitive-command return below, since the | ||
| # operation span needs those attributes even when the command gets no span. | ||
| current_operation = _CURRENT_OPERATION_NAME.get() | ||
| if current_operation is not None: |
There was a problem hiding this comment.
Does this backfill run on each retry attempt too? If so, does it need to?
There was a problem hiding this comment.
Clarified the comment. Yes, repeating is necessary in case an attempt dies before the command is built, and it is idempotent.
| except BaseException as exc: | ||
| if operation_telemetry is not None: | ||
| operation_telemetry.failed(exc) | ||
| raise | ||
| else: | ||
| if operation_telemetry is not None: | ||
| operation_telemetry.succeeded() |
There was a problem hiding this comment.
Can this not use the with telemetry or contextlib.nullcontext() pattern used elsewhere instead? Same question twice in mongo_client.py too.
I ran a test with |
Give every public API call an operation span containing one command span per command sent to the server, per the OpenTelemetry driver specification. The span covers all retry attempts of one _retry_internal call, so retries appear as sibling command spans rather than being collapsed into one. killCursors and endSessions bypass the retry layer and start their spans at the call site instead, as does an unacknowledged client bulk write, which never reaches the command-span code that would fill in its namespace. Cursor-creating operations (find, aggregate, listCollections, listIndexes) are covered here, but only for the command that creates the cursor. Spans for caller-driven getMores come in a later change, as do transaction spans. _otel.py also takes over the specification's naming and attribute rules, so _telemetry.py deals only with span lifecycles and a specification change need not touch it. Namespace parsing moves to helpers_shared._split_namespace.
Lead with the condition rather than the bare adjective.
The vendored unified spec fixtures it pointed at arrive in a later change, so the note described tests absent from this one.
…d test Evergreen only runs on PRs whose base is a configured branch, so the upper PRs in this stack get no Evergreen coverage, and the otel tests only run in Evergreen's otel variant. Add a temporary GitHub Actions job that runs them on every branch in the stack, against a replica set so the transaction span tests are included. Remove the job before merging. Also drop test_operation_name_normalizes_enum_operation. All 22 vendored fixtures assert db.operation.name with literal values, so the _Op formatting regression it guards fails them loudly, and adding a test here only to delete it once the fixtures land is churn.
…the end The mutable-action-tag scanners reported two findings in test_minimum, which this branch does not touch: inserting the otel job mid-file shifted those lines by 31 and the diff-based scan attributed them to this change. Appending the job instead leaves every pre-existing line where it was. Pin the job's own actions to commit hashes so the newly added lines do not trip the same rule. drivers-evergreen-tools has no pinned use elsewhere in this file, so v1.0.1 is spelled out; its commit is the same one master points at, so the topology input this job relies on is unchanged.
The parameter's description packed two mutually exclusive branches into one clause, so it read as though the span both outlived the call and was freshly owned by it. Split the two cases apart and name AsyncCursor as the one caller that passes a span, along with why it keeps ownership. Also drops the claim that a cursor's span is shared by its getMores, which is not true yet: the cursor clears its span once the creating command completes.
The unacknowledged path skips _retryable_write, which is what opens the operation span on the acknowledged path, so open one at the call site. Matches what the client-level bulk write already did, and both now use the telemetry object as a context manager instead of hand-written try/except/else, as does _retryable_read_cursor. Split the tracing option TypedDict in two. As validated from user input, query_text_max_length is None when unset, which is distinct from an explicit 0; once _resolve_tracing_options has folded in the environment variables it is always an int. Giving the two states separate types lets the resolved reader stop re-checking for None. Also record why the operation-name overrides exist: "dropCollection" and "createCollection" are deviations the spec is expected to correct, and "dropSearchIndexes" is only our `_Op` member being plural.
Several of these grew while answering review questions and ended up explaining spec history or restating the code. Cut each to the invariant a reader needs.
e73f9f0 to
a698db5
Compare
Trimming took out four things that carry information: the AsyncCursor._refresh pointer, the distinction between db.operation.name and db.command.name, that start_command_span is a no-op with tracing off, and that the backfill has to precede the sensitive-command return.
"Ambient" is not OpenTelemetry's term; the spec and the API both say current.
| [ | ||
| # All three topologies, subset to keep the task count at 22. | ||
| # | ||
| # Replica set in full: the only topology where transaction spans |
There was a problem hiding this comment.
What does "in full" mean here?
There was a problem hiding this comment.
It meant the replica set variant isn't subsetted the way the other two are. Reworded to "Replica set keeps every task".
| error on every failure path, and an exhausted cursor's close() ends it | ||
| on the way out; both are idempotent, so this only has to cover the | ||
| remaining case of a successful send that leaves the cursor open. | ||
| """ |
There was a problem hiding this comment.
Excessively long docstring here for an internal helper method. This also appears to be the only use of this method, can we just inline it instead?
There was a problem hiding this comment.
Trimmed the docstring. I kept the method rather than inlining it, because PR 4 gives it a second call site and an own_span parameter when getMores get their own spans, so inlining here would be reverted there.
|
|
||
|
|
||
| T = TypeVar("T") | ||
| _CommandCursor = TypeVar("_CommandCursor", bound=AsyncCommandCursor[Any]) |
There was a problem hiding this comment.
What's the typevar for? Can we just use AsyncCommandCursor[Any] in place of it?
| @@ -633,7 +640,10 @@ def __init__( | |||
| .. seealso:: The MongoDB documentation on `connections <https://dochub.mongodb.org/core/connections>`_. | |||
|
|
|||
| .. versionchanged:: 4.18 | |||
There was a problem hiding this comment.
Should all of these versionchanged notes for OTel be 4.XX to avoid missing them later?
| :param is_run_command: If this is a runCommand operation, defaults to False. | ||
| :param is_aggregate_write: If this is a aggregate operation with a write, defaults to False. | ||
| :param operation_id: Stable operation id shared across retries, defaults to None | ||
| :param operation_telemetry: As for ``_retry_internal``, defaults to None. |
There was a problem hiding this comment.
What does "as for" mean here?
There was a problem hiding this comment.
Reworded to "Same as _retry_internal's". Do you think we should repeat the reasoning here?
|
|
||
| The span ends with the command that created the cursor. | ||
| """ | ||
| operation_telemetry = _operation_telemetry_or_none( |
There was a problem hiding this comment.
We need to pass is_run_command here too.
| operation_telemetry=self._operation_telemetry, | ||
| ) | ||
| except OperationFailure as exc: | ||
| self._end_operation_telemetry(exc) |
There was a problem hiding this comment.
We need to wait to call this until the tailable error check below that returns normally. Otherwise we'll emit an error span even if we don't raise an error.
There was a problem hiding this comment.
Good call, I added test_tailable_rollover_is_not_an_error_span as a regression test
| handle.span.end() | ||
| return | ||
| _CURRENT_OPERATION_NAME.reset(handle._name_token) | ||
| handle._cm.__exit__(None, None, None) |
There was a problem hiding this comment.
Can any of these calls raise an error and interrupt this cleanup process?
There was a problem hiding this comment.
I wrapped the recording calls in try/finally.
| if span is None: | ||
| return | ||
| span.record_exception(exc) | ||
| _set_exception_attributes(span, exc) | ||
| code = failure.get("code") | ||
| if code is not None: | ||
| span.set_attribute("db.response.status_code", str(code)) | ||
| span.set_status(Status(StatusCode.ERROR, description=failure.get("errmsg"))) | ||
| span.end() |
There was a problem hiding this comment.
Can any of these calls raise an error and interrupt this cleanup process?
There was a problem hiding this comment.
I wrapped this one in try/finally as well.
| summary = _build_query_summary(current_operation, dbname, collection) | ||
| current_span.update_name(summary) | ||
| current_span.set_attribute("db.namespace", dbname) | ||
| current_span.set_attribute("db.operation.summary", summary) | ||
| if collection: | ||
| current_span.set_attribute("db.collection.name", collection) |
There was a problem hiding this comment.
Can we detect if these are already set correctly and skip this if so to save the cost of these calls?
There was a problem hiding this comment.
The OTel API has no getter for a span's attributes, so detecting "already set" means tracking it ourselves in another contextvar. I don't think it is worth it.
Ends a tailable cursor's operation span successfully when a rollover returns instead of raising, threads is_run_command into the command cursor span, and ends every span in a finally so a failed attribute write cannot strand it. Drops a typevar that carried no type information and renames _retryable_read_cursor after what it adds.
3 participants
PYTHON-5947
First of five PRs splitting #2964. Base is
otel; review in order.PYTHON-5947-otel-1-operationsPYTHON-5947-otel-2-transactionsPYTHON-5947-otel-3-unifiedPYTHON-5947-otel-4-getmorePYTHON-5947-otel-5-error-typeerror.typecommand span attributeChanges in this PR
Adds one span per public API call, containing one command span per command sent to the server, per the OpenTelemetry driver specification. Without it a retried operation's command spans share no parent, so a reader cannot tell which attempts belong to the same call.
killCursors,endSessions, and unacknowledged client bulk writes get operation spans too.find,aggregate,listCollections,listIndexes) are covered, but only for the command that creates the cursor. ThegetMorespec has pending changes, so getMore spans are deferred to PR 4.0,False,""). This affected structured command logging as well as spans.Opt-in: no behavior change unless the
tracingclient option orOTEL_PYTHON_INSTRUMENTATION_MONGODB_ENABLEDis set. With tracing off there is no added allocation per command.Around 1,000 of the added lines are
just synchrooutput and another ~745 are tests.Test Plan
just lintclean.Checklist
Checklist for Author
Checklist for Reviewer