opentelemetry-instrumentation-tornado: server metrics recorded twice when a handler raises, http.server.active_requests goes negative
Maintainers usually reply within 1 day
Nobody has claimed this yet.
Assessment
- Difficulty
- 2/5
- Estimated time
- 1-3 hours
- Newbie friendliness
- 86/100
- Issue type
- Bug
- Clarity
- Clearly specified
- Activity status
- Active
- Tech stack
- python
- Domain
- backend, observability
Research direction
Start in instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/init.py at _log_exception and _on_finish, then trace their calls to _record_on_finish_metrics. Reproduce the failing-handler case from the issue and add regression coverage alongside the existing metrics tests; done means one duration and response-size sample, the final status code, and active_requests returning to zero.
Written by the indexing model from the issue text.
Description
Describe your environment
- OS: Windows 11
- Python version: 3.12.12
- Package version: opentelemetry-instrumentation-tornado 0.66b0 (latest release). Reproduced on current main (commit 188dcd98), which has the same code.
- Tornado version: 6.5.10
What happened?
When a Tornado handler raises an exception, the server metrics for that single request are recorded twice:
http.server.duration(andhttp.server.request.durationwith new semconv) gets two data points instead of one. For an unhandled exception, one of them has the wrong status code (200).http.server.active_requestsis decremented twice, so it goes to-1for every failed request and keeps drifting negative.- The response size histograms are also recorded twice.
Cause: both the log_exception and on_finish wrappers call _record_on_finish_metrics, and Tornado calls both for a failing request (_handle_request_exception -> log_exception, then send_error -> finish -> on_finish).
_log_exception: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/188dcd98/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py#L621_on_finish: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/188dcd98/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py#L588
The first call runs before the error response is written, so handler.get_status() still returns 200. Spans aren't affected because _finish_span is guarded by the handler context being removed after the first call. The metrics path has no such guard.
Steps to Reproduce
import tornado.web
from tornado.testing import AsyncHTTPTestCase
from opentelemetry.instrumentation.tornado import TornadoInstrumentor
from opentelemetry.sdk.metrics import MeterProvider
from opentelemetry.sdk.metrics.export import InMemoryMetricReader
reader = InMemoryMetricReader()
TornadoInstrumentor().instrument(meter_provider=MeterProvider(metric_readers=[reader]))
class BoomHandler(tornado.web.RequestHandler):
def get(self):
raise ValueError("boom")
class Test(AsyncHTTPTestCase):
def get_app(self):
return tornado.web.Application([("/boom", BoomHandler)])
def test(self):
self.fetch("/boom") # a single request
t = Test("test")
t.setUp(); t.test(); t.tearDown()
for rm in reader.get_metrics_data().resource_metrics:
for sm in rm.scope_metrics:
for m in sm.metrics:
if m.name == "http.server.duration":
for dp in m.data.data_points:
print(m.name, "status", dp.attributes["http.status_code"], "count", dp.count)
if m.name == "http.server.active_requests":
print(m.name, "value", sum(dp.value for dp in m.data.data_points))
Same result with raise tornado.web.HTTPError(403): 2 duration data points with status 403, and active_requests at -1.
Expected Result
http.server.active_requests value 0
http.server.duration status 500 count 1
One request should give one duration sample with the final status code, and active_requests should return to 0.
Actual Result
http.server.active_requests value -1
http.server.duration status 200 count 1
http.server.duration status 500 count 1
Additional context
- Existing metrics tests only cover successful requests, so this path isn't tested.
Would you like to implement a fix?
Yes
Tip
React with 👍 to help prioritize this issue. Please use comments to provide useful context, avoiding +1 or me too, to help us triage it. Learn more here.
- Dominant language
- Python
- Stars
- 1.1k
- Forks
- 1.1k
- Avg merge
- 2d 5h
- Merged PRs (30d)
- 21
Getting set up
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.
More from open-telemetry/opentelemetry-python-contrib
-
Difficulty 2/5 1-3 hours Newbie friendliness 76/100
open-telemetry/opentelemetry-python-contrib#5118 ·
Maintainers usually reply within 1 day
-
bug
Difficulty 1/5 Under an hour Newbie friendliness 86/100
open-telemetry/opentelemetry-python-contrib#5116 ·
Maintainers usually reply within 1 day
-
bug
Difficulty 2/5 1-3 hours Newbie friendliness 86/100
open-telemetry/opentelemetry-python-contrib#5100 ·
Maintainers usually reply within 1 day
-
feature-request
Difficulty 2/5 1-3 hours Newbie friendliness 75/100
open-telemetry/opentelemetry-python-contrib#5071 ·
Maintainers usually reply within 1 day
-
bug
Difficulty 2/5 1-3 hours Newbie friendliness 68/100
open-telemetry/opentelemetry-python-contrib#5069 ·
Maintainers usually reply within 1 day
All issues in open-telemetry/opentelemetry-python-contrib
Similar issues
-
[Bug] @deck.gl/arcgis dist import resolves to unpublished @deck.gl/core source path (9.3.11, 9.4.0)Open
Difficulty 2/5 1-3 hours Newbie friendliness 72/100
Maintainers usually reply within 1 day
-
workflow: a tick's dispatch counts as 'only this step', and no review self-grants a round unattendedOpenworkflow
Difficulty 2/5 1-3 hours Newbie friendliness 85/100
kristofdegrave/homeassistant-smart-charging#1505 ·
Maintainers usually reply within 1 day
-
metadata submission
Difficulty 2/5 1-3 hours Newbie friendliness 82/100
-
bug
Difficulty 2/5 1-3 hours Newbie friendliness 65/100
canonical/content-cache-operator#163 · 1 comment ·
Maintainers usually reply within 1 day
-
[submission]Opensubmission
Difficulty 1/5 Under an hour Newbie friendliness 65/100
leanprover/lean-eval-submissions#1852 ·
Maintainers usually reply within 1 day