Remove double record exception #712
Conversation
Deploying logfire-docs with
|
| Latest commit: |
fe7d66b
|
| Status: | ✅ Deploy successful! |
| Preview URL: | https://e6902e5a.logfire-docs.pages.dev |
| Branch Preview URL: | https://remove-double-record-excepti.logfire-docs.pages.dev |
| @@ -1948,13 +1948,13 @@ def __init__(self, span: trace_api.Span) -> None: | |||
| self._token = context_api.attach(trace_api.set_span_in_context(self._span)) | |||
|
|
|||
| def __enter__(self) -> FastLogfireSpan: | |||
| self._span.__enter__() | |||
There was a problem hiding this comment.
This is maybe unnecessary but seems reasonable to add, and I hope this class will be refactored/simplified soon anyway.
There was a problem hiding this comment.
Given how optimised this class is, I'd rather not add it here, but maybe it can stay in LogfireSpan.
| @@ -1990,6 +1990,7 @@ def __enter__(self) -> LogfireSpan: | |||
| attributes=self._otlp_attributes, | |||
| links=self._links, | |||
| ) | |||
| self._span.__enter__() | |||
There was a problem hiding this comment.
Same note as above, this might not be necessary but seems fine to add and arguably more correct(?)
| if self._span.is_recording(): | ||
| with handle_internal_errors(): | ||
| if self._added_attributes: | ||
| self._span.set_attribute( | ||
| ATTRIBUTES_JSON_SCHEMA_KEY, attributes_json_schema(self._json_schema_properties) | ||
| ) |
There was a problem hiding this comment.
I just moved the logic from end() here, noting we can drop a check since we already know self._span is not None, and we don't currently rely on the LogfireSpan methods being called at the same time that the otel methods would be called.
logfire/_internal/tracer.py
Outdated
| if self.is_recording() and isinstance(exc_value, BaseException): | ||
| self.record_exception(exc_value, escaped=True) |
There was a problem hiding this comment.
This is basically just the logic that used to be in main._exit_span. The parent class's version of this just calls self.end(), and I kept that below.
tests/test_logfire.py
Outdated
| def test_logfire_span_records_exceptions_once(): | ||
| # logfire.configure(send_to_logfire=False, console=False, additional_span_processors=[BatchSpanProcessor(exporter)]) | ||
| n_calls_to_record_exception = 0 | ||
|
|
||
| def patched_record_exception(*args: Any, **kwargs: Any) -> Any: | ||
| nonlocal n_calls_to_record_exception | ||
| n_calls_to_record_exception += 1 | ||
|
|
||
| return record_exception(*args, **kwargs) | ||
|
|
||
| with patch('logfire._internal.tracer.record_exception', patched_record_exception), patch( | ||
| 'logfire._internal.main.record_exception', patched_record_exception | ||
| ): | ||
| with pytest.raises(RuntimeError): | ||
| with logfire.span('foo'): | ||
| raise RuntimeError('error') | ||
|
|
||
| assert n_calls_to_record_exception == 1 |
There was a problem hiding this comment.
I confirmed this test fails on main and makes two calls instead of one.
There was a problem hiding this comment.
It looks like the doubling was introduced by #696
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## main #712 +/- ##
=========================================
Coverage 100.00% 100.00%
=========================================
Files 137 137
Lines 11031 11041 +10
Branches 1539 1539
=========================================
+ Hits 11031 11041 +10 ☔ View full report in Codecov by Sentry. |
| ATTRIBUTES_JSON_SCHEMA_KEY, attributes_json_schema(self._json_schema_properties) | ||
| ) | ||
|
|
||
| self._span.end(end_time) |
There was a problem hiding this comment.
We used to only call self._span.end here if self._span was recording. Is that actually the right behavior though? The changes I made ensure that end() always gets called, even on a non-recording span, and that's why the timestamps changed below (because it generates another timestamp in the unconditional call to end()).
I can go back to only calling span.end() if the span is recording but I'm not sure if that's correct..
There was a problem hiding this comment.
import opentelemetry.trace
import logfire
logfire.configure()
tracer = opentelemetry.trace.get_tracer(__name__)
span = tracer.start_span('foo')
assert span.is_recording()
span.end()
assert not span.is_recording()
span.end() # Logs a warning: Calling end() on an ended span.So keeping the current behaviour seems best.
logfire/_internal/tracer.py
Outdated
| if self.is_recording() and isinstance(exc_value, BaseException): | ||
| self.record_exception(exc_value, escaped=True) | ||
|
|
||
| self.end() |
There was a problem hiding this comment.
| if self.is_recording() and isinstance(exc_value, BaseException): | |
| self.record_exception(exc_value, escaped=True) | |
| self.end() | |
| if self.is_recording(): | |
| if isinstance(exc_value, BaseException): | |
| self.record_exception(exc_value, escaped=True) | |
| self.end() |
I confirmed that this would get us back to the old timestamp behavior, again, not sure if this is better or worse than the version currently in this PR. But I think one of these two options should be okay
There was a problem hiding this comment.
I decided to make this change because, 1, it preserves the old behavior, and 2, I think it marginally reduces overhead. We can always just dedent the call to self.end() if we think the method should be called even if the inner span is not a recording span.
We are currently double-recording exceptions in LogfireSpan's due to some convoluted logic that this PR simplifies