Reorder on_finish call order to correctly instrument all tornado work done during a request (#499)

Co-authored-by: alrex <[email protected]>

Author: pitabwire

CHANGELOG.md

@@ -6,6 +6,8 @@ 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)
 
+- `opentelemetry-instrumentation-tornado` properly instrument work done in tornado on_finish method.
+  ([#499](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/499))
 - `opentelemetry-instrumentation` Fixed cases where trying to use an instrumentation package without the
   target library was crashing auto instrumentation agent.
   ([#530](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/530))

instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py

@@ -213,8 +213,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):

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)

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,16 @@ 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 +102,7 @@ def make_app(tracer):
             (r"/error", BadHandler),
             (r"/cor", CoroutineHandler),
             (r"/async", AsyncHandler),
+            (r"/on_finish", FinishedHandler),
             (r"/healthz", HealthCheckHandler),
             (r"/ping", HealthCheckHandler),
         ]