From 36f1b258af7afebc4839541d95b08a92e9327b93 Mon Sep 17 00:00:00 2001 From: Peter Bwire Date: Sun, 16 May 2021 11:28:35 +0300 Subject: [PATCH 1/4] Reorder on finish call order to correctly close traces --- .../src/opentelemetry/instrumentation/tornado/__init__.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py index e13d24c971..507008babb 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -208,8 +208,9 @@ def _prepare(tracer, request_hook, func, handler, args, kwargs): def _on_finish(tracer, func, handler, args, kwargs): + response = func(*args, **kwargs) _finish_span(tracer, handler) - return func(*args, **kwargs) + return response def _log_exception(tracer, func, handler, args, kwargs): From 6036108c7a12e8067571e06287e257a37b7d0051 Mon Sep 17 00:00:00 2001 From: Peter Bwire Date: Wed, 2 Jun 2021 16:55:49 +0300 Subject: [PATCH 2/4] Test spans created in on_finish have correct parent span --- .../tests/test_instrumentation.py | 48 +++++++++++++++++++ .../tests/tornado_test_app.py | 13 +++++ 2 files changed, 61 insertions(+) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py index 605dde2abc..58c0127647 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py @@ -347,6 +347,54 @@ def test_dynamic_handler(self): }, ) + def test_handler_on_finish(self): + + response = self.fetch("/on_finish") + self.assertEqual(response.code, 200) + + spans = self.sorted_spans(self.memory_exporter.get_finished_spans()) + self.assertEqual(len(spans), 3) + auditor, server, client = spans + + self.assertEqual(server.name, "FinishedHandler.get") + self.assertTrue(server.parent.is_remote) + self.assertNotEqual(server.parent, client.context) + self.assertEqual(server.parent.span_id, client.context.span_id) + self.assertEqual(server.context.trace_id, client.context.trace_id) + self.assertEqual(server.kind, SpanKind.SERVER) + self.assert_span_has_attributes( + server, + { + SpanAttributes.HTTP_METHOD: "GET", + SpanAttributes.HTTP_SCHEME: "http", + SpanAttributes.HTTP_HOST: "127.0.0.1:" + + str(self.get_http_port()), + SpanAttributes.HTTP_TARGET: "/on_finish", + SpanAttributes.NET_PEER_IP: "127.0.0.1", + SpanAttributes.HTTP_STATUS_CODE: 200, + }, + ) + + self.assertEqual(client.name, "GET") + self.assertFalse(client.context.is_remote) + self.assertIsNone(client.parent) + self.assertEqual(client.kind, SpanKind.CLIENT) + self.assert_span_has_attributes( + client, + { + SpanAttributes.HTTP_URL: self.get_url("/on_finish"), + SpanAttributes.HTTP_METHOD: "GET", + SpanAttributes.HTTP_STATUS_CODE: 200, + }, + ) + + self.assertEqual(auditor.name, "audit_task") + self.assertFalse(auditor.context.is_remote) + self.assertEqual(auditor.parent.span_id, server.context.span_id) + self.assertEqual(auditor.context.trace_id, client.context.trace_id) + + self.assertEqual(auditor.kind, SpanKind.INTERNAL) + def test_exclude_lists(self): def test_excluded(path): self.fetch(path) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py index 307dc60b76..5ad31560be 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py @@ -1,4 +1,5 @@ # pylint: disable=W0223,R0201 +import time import tornado.web from tornado import gen @@ -79,6 +80,17 @@ def get(self): self.set_status(202) +class FinishedHandler(tornado.web.RequestHandler): + + def on_finish(self): + with self.application.tracer.start_as_current_span("audit_task"): + time.sleep(0.05) + + def get(self): + self.write("Test can finish") + self.set_status(200) + + class HealthCheckHandler(tornado.web.RequestHandler): def get(self): self.set_status(200) @@ -91,6 +103,7 @@ def make_app(tracer): (r"/error", BadHandler), (r"/cor", CoroutineHandler), (r"/async", AsyncHandler), + (r"/on_finish", FinishedHandler), (r"/healthz", HealthCheckHandler), (r"/ping", HealthCheckHandler), ] From d7b609f91810af0e06c0b046d44afd5117aed266 Mon Sep 17 00:00:00 2001 From: Peter Bwire Date: Wed, 2 Jun 2021 17:04:55 +0300 Subject: [PATCH 3/4] Show changes in changelog.md --- CHANGELOG.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 272482b72c..8074079aa9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased](https://github.com/open-telemetry/opentelemetry-python/compare/v1.3.0-0.22b0...HEAD) +### Changed +- Bugfix to properly instrument work done in tornado on_finish method. + ([#499](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/499)) + ## [0.22b0](https://github.com/open-telemetry/opentelemetry-python/releases/tag/v1.3.0-0.22b0) - 2021-06-01 ### Changed From 7ca068d7ce565339f00a207852fa32792fe03e2b Mon Sep 17 00:00:00 2001 From: alrex Date: Mon, 7 Jun 2021 08:26:50 -0700 Subject: [PATCH 4/4] fix lint --- .../tests/tornado_test_app.py | 1 - 1 file changed, 1 deletion(-) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py index 5ad31560be..c92acc8275 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/tornado_test_app.py @@ -81,7 +81,6 @@ def get(self): class FinishedHandler(tornado.web.RequestHandler): - def on_finish(self): with self.application.tracer.start_as_current_span("audit_task"): time.sleep(0.05)