From 90d23d7e135b4a4a623b6efb072dcbbba9ea5ccb Mon Sep 17 00:00:00 2001 From: sroda Date: Tue, 30 Aug 2022 13:33:20 +0300 Subject: [PATCH 01/11] Add metrics instrumentation --- .../instrumentation/tornado/__init__.py | 97 ++++++++++--- .../instrumentation/tornado/client.py | 32 ++++- .../instrumentation/tornado/package.py | 2 + .../tests/test_instrumentation.py | 2 +- .../tests/test_metrics_instrumentation.py | 127 ++++++++++++++++++ 5 files changed, 238 insertions(+), 22 deletions(-) create mode 100644 instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py 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 20ad51cd9c..93e3dc8191 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -157,6 +157,8 @@ def client_resposne_hook(span, future): from functools import partial from logging import getLogger from typing import Collection +from timeit import default_timer + import tornado.web import wrapt @@ -177,6 +179,7 @@ def client_resposne_hook(span, future): unwrap, ) from opentelemetry.propagators import textmap +from opentelemetry.metrics import Histogram, get_meter from opentelemetry.semconv.trace import SpanAttributes from opentelemetry.trace.status import Status, StatusCode from opentelemetry.util._time import _time_ns @@ -189,6 +192,7 @@ def client_resposne_hook(span, future): normalise_request_header_name, normalise_response_header_name, ) +from opentelemetry.util.http import get_excluded_urls, get_traced_request_attrs from .client import fetch_async # pylint: disable=E0401 @@ -231,7 +235,31 @@ def _instrument(self, **kwargs): process lifetime. """ tracer_provider = kwargs.get("tracer_provider") - tracer = trace.get_tracer(__name__, __version__, tracer_provider) + self.tracer = trace.get_tracer(__name__, __version__, tracer_provider) + + meter_provider = kwargs.get("meter_provider") + self.meter = get_meter(__name__, __version__, meter_provider) + + self.duration_histogram = self.meter.create_histogram( + name="http.server.duration", + unit="ms", + description="measures the duration outbound HTTP requests", + ) + self.request_size_histogram = self.meter.create_histogram( + name="http.server.request.size", + unit="By", + description="measures the size of HTTP request messages (compressed)", + ) + self.response_size_histogram = self.meter.create_histogram( + name="http.server.response.size", + unit="By", + description="measures the size of HTTP response messages (compressed)", + ) + self.active_requests_histogram = self.meter.create_up_down_counter( + name="http.server.active_requests", + unit="requests", + description="measures the number of concurrent HTTP requests that are currently in-flight", + ) client_request_hook = kwargs.get("client_request_hook", None) client_response_hook = kwargs.get("client_response_hook", None) @@ -239,7 +267,7 @@ def _instrument(self, **kwargs): def handler_init(init, handler, args, kwargs): cls = handler.__class__ - if patch_handler_class(tracer, cls, server_request_hook): + if patch_handler_class(self, cls, server_request_hook): self.patched_handlers.append(cls) return init(*args, **kwargs) @@ -250,7 +278,11 @@ def handler_init(init, handler, args, kwargs): "tornado.httpclient", "AsyncHTTPClient.fetch", partial( - fetch_async, tracer, client_request_hook, client_response_hook + fetch_async, + self.tracer, + client_request_hook, + client_response_hook, + self.response_size_histogram, ), ) @@ -262,14 +294,14 @@ def _uninstrument(self, **kwargs): self.patched_handlers = [] -def patch_handler_class(tracer, cls, request_hook=None): +def patch_handler_class(self, cls, request_hook=None): if getattr(cls, _OTEL_PATCHED_KEY, False): return False setattr(cls, _OTEL_PATCHED_KEY, True) - _wrap(cls, "prepare", partial(_prepare, tracer, request_hook)) - _wrap(cls, "on_finish", partial(_on_finish, tracer)) - _wrap(cls, "log_exception", partial(_log_exception, tracer)) + _wrap(cls, "prepare", partial(_prepare, self, request_hook)) + _wrap(cls, "on_finish", partial(_on_finish, self)) + _wrap(cls, "log_exception", partial(_log_exception, self)) return True @@ -289,29 +321,28 @@ def _wrap(cls, method_name, wrapper): wrapt.apply_patch(cls, method_name, wrapper) -def _prepare(tracer, request_hook, func, handler, args, kwargs): - start_time = _time_ns() +def _prepare(self, request_hook, func, handler, args, kwargs): request = handler.request if _excluded_urls.url_disabled(request.uri): return func(*args, **kwargs) - ctx = _start_span(tracer, handler, start_time) + ctx = _start_span(self, handler) if request_hook: request_hook(ctx.span, handler) return func(*args, **kwargs) -def _on_finish(tracer, func, handler, args, kwargs): +def _on_finish(self, func, handler, args, kwargs): response = func(*args, **kwargs) - _finish_span(tracer, handler) + _finish_span(self, handler) return response -def _log_exception(tracer, func, handler, args, kwargs): +def _log_exception(self, func, handler, args, kwargs): error = None if len(args) == 3: error = args[1] - _finish_span(tracer, handler, error) + _finish_span(self, handler, error) return func(*args, **kwargs) @@ -377,11 +408,14 @@ def _get_full_handler_name(handler): return f"{klass.__module__}.{klass.__qualname__}" -def _start_span(tracer, handler, start_time) -> _TraceContext: +def _start_span(self, handler) -> _TraceContext: + start_time_ns = _time_ns() + start_time = default_timer() + span, token = _start_internal_or_server_span( - tracer=tracer, + tracer=self.tracer, span_name=_get_operation_name(handler, handler.request), - start_time=start_time, + start_time=start_time_ns, context_carrier=handler.request.headers, context_getter=textmap.default_getter, ) @@ -398,6 +432,14 @@ def _start_span(tracer, handler, start_time) -> _TraceContext: if len(custom_attributes) > 0: span.set_attributes(custom_attributes) + metric_attributes = _create_metric_attributes(handler) + request_size = len(handler.request.body) + + self.request_size_histogram.record( + request_size, attributes=metric_attributes + ) + self.active_requests_histogram.add(1, attributes=metric_attributes) + activation = trace.use_span(span, end_on_exit=True) activation.__enter__() # pylint: disable=E1101 ctx = _TraceContext(activation, span, token) @@ -410,10 +452,15 @@ def _start_span(tracer, handler, start_time) -> _TraceContext: if propagator: propagator.inject(handler, setter=response_propagation_setter) + elapsed_time = round((default_timer() - start_time) * 1000) + + self.duration_histogram.record(elapsed_time, attributes=metric_attributes) + self.active_requests_histogram.add(-1, attributes=metric_attributes) + return ctx -def _finish_span(tracer, handler, error=None): +def _finish_span(self, handler, error=None): status_code = handler.get_status() reason = getattr(handler, "_reason") finish_args = (None, None, None) @@ -423,7 +470,7 @@ def _finish_span(tracer, handler, error=None): if isinstance(error, tornado.web.HTTPError): status_code = error.status_code if not ctx and status_code == 404: - ctx = _start_span(tracer, handler, _time_ns()) + ctx = _start_span(self, handler, _time_ns()) else: status_code = 500 reason = None @@ -462,3 +509,15 @@ def _finish_span(tracer, handler, error=None): if ctx.token: context.detach(ctx.token) delattr(handler, _HANDLER_CONTEXT_KEY) + + +def _create_metric_attributes(handler): + metric_attributes = { + SpanAttributes.HTTP_METHOD: handler.request.method, + SpanAttributes.HTTP_SCHEME: handler.request.protocol, + SpanAttributes.HTTP_STATUS_CODE: handler.get_status(), + SpanAttributes.HTTP_FLAVOR: handler.request.version, + SpanAttributes.HTTP_HOST: handler.request.host, + } + + return metric_attributes diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py index 03497ec5ca..79cf63cd0f 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py @@ -41,7 +41,16 @@ def _normalize_request(args, kwargs): return (new_args, new_kwargs) -def fetch_async(tracer, request_hook, response_hook, func, _, args, kwargs): +def fetch_async( + tracer, + request_hook, + response_hook, + response_size_histogram, + func, + _, + args, + kwargs, +): start_time = _time_ns() # Return immediately if no args were provided (error) @@ -78,12 +87,15 @@ def fetch_async(tracer, request_hook, response_hook, func, _, args, kwargs): _finish_tracing_callback, span=span, response_hook=response_hook, + response_size_histogram=response_size_histogram, ) ) return future -def _finish_tracing_callback(future, span, response_hook): +def _finish_tracing_callback( + future, span, response_hook, response_size_histogram +): status_code = None description = None exc = future.exception() @@ -102,6 +114,22 @@ def _finish_tracing_callback(future, span, response_hook): description=description, ) ) + response = future.result() + metric_attributes = _create_metric_attributes(response) + response_size = int(response.headers["Content-Length"]) + + response_size_histogram.record(response_size, attributes=metric_attributes) + if response_hook: response_hook(span, future) span.end() + + +def _create_metric_attributes(response): + metric_attributes = { + SpanAttributes.HTTP_STATUS_CODE: response.code, + SpanAttributes.HTTP_URL: remove_url_credentials(response.request.url), + SpanAttributes.HTTP_METHOD: response.request.method, + } + + return metric_attributes diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/package.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/package.py index 195980dd07..734587b752 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/package.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/package.py @@ -14,3 +14,5 @@ _instruments = ("tornado >= 5.1.1",) + +_supports_metrics = True diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py index 8dcc94b683..94051b0c5d 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py @@ -55,12 +55,12 @@ def get_app(self): return app def setUp(self): + super().setUp() TornadoInstrumentor().instrument( server_request_hook=getattr(self, "server_request_hook", None), client_request_hook=getattr(self, "client_request_hook", None), client_response_hook=getattr(self, "client_response_hook", None), ) - super().setUp() # pylint: disable=protected-access self.env_patch = patch.dict( "os.environ", diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py new file mode 100644 index 0000000000..5181887093 --- /dev/null +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -0,0 +1,127 @@ +# Copyright The OpenTelemetry Authors +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + + +from timeit import default_timer +from tornado.testing import AsyncHTTPTestCase + +from opentelemetry import trace +from opentelemetry.instrumentation.tornado import ( + TornadoInstrumentor, +) +from opentelemetry.test.test_base import TestBase + +from .tornado_test_app import ( + make_app, +) + + +class TornadoTest(AsyncHTTPTestCase, TestBase): + # pylint:disable=no-self-use + def get_app(self): + tracer = trace.get_tracer(__name__) + app = make_app(tracer) + return app + + def setUp(self): + super().setUp() + TornadoInstrumentor().instrument( + server_request_hook=getattr(self, "server_request_hook", None), + client_request_hook=getattr(self, "client_request_hook", None), + client_response_hook=getattr(self, "client_response_hook", None), + meter_provider=self.meter_provider, + ) + + def tearDown(self): + TornadoInstrumentor().uninstrument() + super().tearDown() + + +class TestTornadoInstrumentor(TornadoTest): + def test_basic_metrics(self): + start_time = default_timer() + response = self.fetch("/") + client_duration_estimated = (default_timer() - start_time) * 1000 + + expected_attributes = { + "http.status_code": 200, + "http.method": "GET", + "http.flavor": "HTTP/1.1", + "http.scheme": "http", + "http.host": response.request.headers["host"], + } + expected_response_attributes = { + "http.status_code": response.code, + "http.method": "GET", + "http.url": self.get_url("/"), + } + expected_data = { + "http.server.request.size": 0, + "http.server.response.size": int( + response.headers["Content-Length"] + ), + } + expected_metrics = [ + "http.server.duration", + "http.server.request.size", + "http.server.response.size", + "http.server.active_requests", + ] + + resource_metrics = ( + self.memory_metrics_reader.get_metrics_data().resource_metrics + ) + for metrics in resource_metrics: + for scope_metrics in metrics.scope_metrics: + self.assertEqual( + len(scope_metrics.metrics), len(expected_metrics) + ) + for metric in scope_metrics.metrics: + for data_point in metric.data.data_points: + if metric.name in expected_data: + self.assertEqual( + data_point.sum, expected_data[metric.name] + ) + + self.assertIn(metric.name, expected_metrics) + if metric.name == "http.server.duration": + self.assertAlmostEqual( + data_point.sum, + client_duration_estimated, + delta=1000, + ) + + if metric.name == "http.server.response.size": + self.assertDictEqual( + expected_response_attributes, + dict(data_point.attributes), + ) + else: + self.assertDictEqual( + expected_attributes, + dict(data_point.attributes), + ) + + def test_metric_uninstrument(self): + self.fetch("/") + TornadoInstrumentor().uninstrument() + self.fetch("/") + + metrics_list = self.memory_metrics_reader.get_metrics_data() + for resource_metric in metrics_list.resource_metrics: + for scope_metric in resource_metric.scope_metrics: + for metric in scope_metric.metrics: + if metric.name != "http.server.active_requests": + for point in list(metric.data.data_points): + self.assertEqual(point.count, 1) From 4d52bbb6648e87d337244f8adeb24c368b33a275 Mon Sep 17 00:00:00 2001 From: sroda Date: Tue, 30 Aug 2022 14:53:17 +0300 Subject: [PATCH 02/11] Add entry to CHANGELOG.md --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 20cdb6cb5f..f1366aa535 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `opentelemetry-instrumentation-redis` add support to instrument RedisCluster clients ([#1177](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1177)) - `opentelemetry-instrumentation-sqlalchemy` Added span for the connection phase ([#1133](https://github.com/open-telemetry/opentelemetry-python-contrib/issues/1133)) +- `opentelemetry-instrumentation-tornado` Add metric instrumentation + ([#1252](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1252)) ## [1.12.0rc2-0.32b0](https://github.com/open-telemetry/opentelemetry-python/releases/tag/v1.12.0rc2-0.32b0) - 2022-07-01 From f5369ed3bb322b4ca48ccea5db04c75293486586 Mon Sep 17 00:00:00 2001 From: sroda Date: Tue, 30 Aug 2022 15:08:27 +0300 Subject: [PATCH 03/11] Run tox generate --- instrumentation/README.md | 2 +- .../opentelemetry/instrumentation/tornado/__init__.py | 6 ++---- .../tests/test_metrics_instrumentation.py | 9 +++------ 3 files changed, 6 insertions(+), 11 deletions(-) diff --git a/instrumentation/README.md b/instrumentation/README.md index deeb3693f0..845cd0845e 100644 --- a/instrumentation/README.md +++ b/instrumentation/README.md @@ -38,7 +38,7 @@ | [opentelemetry-instrumentation-sqlite3](./opentelemetry-instrumentation-sqlite3) | sqlite3 | No | [opentelemetry-instrumentation-starlette](./opentelemetry-instrumentation-starlette) | starlette ~= 0.13.0 | No | [opentelemetry-instrumentation-system-metrics](./opentelemetry-instrumentation-system-metrics) | psutil >= 5 | No -| [opentelemetry-instrumentation-tornado](./opentelemetry-instrumentation-tornado) | tornado >= 5.1.1 | No +| [opentelemetry-instrumentation-tornado](./opentelemetry-instrumentation-tornado) | tornado >= 5.1.1 | Yes | [opentelemetry-instrumentation-urllib](./opentelemetry-instrumentation-urllib) | urllib | No | [opentelemetry-instrumentation-urllib3](./opentelemetry-instrumentation-urllib3) | urllib3 >= 1.0.0, < 2.0.0 | Yes | [opentelemetry-instrumentation-wsgi](./opentelemetry-instrumentation-wsgi) | wsgi | Yes \ No newline at end of file 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 63e41a4574..0939b388ef 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -157,9 +157,8 @@ def client_resposne_hook(span, future): from functools import partial from logging import getLogger from time import time_ns -from typing import Collection from timeit import default_timer - +from typing import Collection import tornado.web import wrapt @@ -179,8 +178,8 @@ def client_resposne_hook(span, future): http_status_to_status_code, unwrap, ) -from opentelemetry.propagators import textmap from opentelemetry.metrics import Histogram, get_meter +from opentelemetry.propagators import textmap from opentelemetry.semconv.trace import SpanAttributes from opentelemetry.trace.status import Status, StatusCode from opentelemetry.util.http import ( @@ -192,7 +191,6 @@ def client_resposne_hook(span, future): normalise_request_header_name, normalise_response_header_name, ) -from opentelemetry.util.http import get_excluded_urls, get_traced_request_attrs from .client import fetch_async # pylint: disable=E0401 diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index 5181887093..806222b99a 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -14,17 +14,14 @@ from timeit import default_timer + from tornado.testing import AsyncHTTPTestCase from opentelemetry import trace -from opentelemetry.instrumentation.tornado import ( - TornadoInstrumentor, -) +from opentelemetry.instrumentation.tornado import TornadoInstrumentor from opentelemetry.test.test_base import TestBase -from .tornado_test_app import ( - make_app, -) +from .tornado_test_app import make_app class TornadoTest(AsyncHTTPTestCase, TestBase): From df4dcf88b22579e8328cb64b898d88430da0d8d6 Mon Sep 17 00:00:00 2001 From: sroda Date: Tue, 30 Aug 2022 15:33:39 +0300 Subject: [PATCH 04/11] Fix conflict issues --- .../src/opentelemetry/instrumentation/tornado/__init__.py | 7 +++---- .../src/opentelemetry/instrumentation/tornado/client.py | 2 +- 2 files changed, 4 insertions(+), 5 deletions(-) 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 0939b388ef..7fcbe20fe5 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -178,7 +178,7 @@ def client_resposne_hook(span, future): http_status_to_status_code, unwrap, ) -from opentelemetry.metrics import Histogram, get_meter +from opentelemetry.metrics import get_meter from opentelemetry.propagators import textmap from opentelemetry.semconv.trace import SpanAttributes from opentelemetry.trace.status import Status, StatusCode @@ -407,13 +407,12 @@ def _get_full_handler_name(handler): def _start_span(self, handler) -> _TraceContext: - start_time_ns = _time_ns() start_time = default_timer() span, token = _start_internal_or_server_span( tracer=self.tracer, span_name=_get_operation_name(handler, handler.request), - start_time=start_time_ns, + start_time=time_ns(), context_carrier=handler.request.headers, context_getter=textmap.default_getter, ) @@ -468,7 +467,7 @@ def _finish_span(self, handler, error=None): if isinstance(error, tornado.web.HTTPError): status_code = error.status_code if not ctx and status_code == 404: - ctx = _start_span(self, handler, _time_ns()) + ctx = _start_span(self, handler) else: status_code = 500 reason = None diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py index bd8b066fe5..1513f34f3a 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py @@ -51,7 +51,7 @@ def fetch_async( args, kwargs, ): - start_time = _time_ns() + start_time = time_ns() # Return immediately if no args were provided (error) # or original_request is set (meaning we are in a redirect step). From 033c62c42cb879f6c5f683499025b937a2b6b367 Mon Sep 17 00:00:00 2001 From: sroda Date: Thu, 22 Sep 2022 11:47:43 +0300 Subject: [PATCH 05/11] Fix after CR and change the test format --- .../instrumentation/tornado/__init__.py | 101 ++++++++----- .../instrumentation/tornado/client.py | 4 +- .../tests/test_metrics_instrumentation.py | 139 ++++++++++-------- 3 files changed, 149 insertions(+), 95 deletions(-) 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 7fcbe20fe5..95768365ac 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -292,14 +292,14 @@ def _uninstrument(self, **kwargs): self.patched_handlers = [] -def patch_handler_class(self, cls, request_hook=None): +def patch_handler_class(instrumentation, cls, request_hook=None): if getattr(cls, _OTEL_PATCHED_KEY, False): return False setattr(cls, _OTEL_PATCHED_KEY, True) - _wrap(cls, "prepare", partial(_prepare, self, request_hook)) - _wrap(cls, "on_finish", partial(_on_finish, self)) - _wrap(cls, "log_exception", partial(_log_exception, self)) + _wrap(cls, "prepare", partial(_prepare, instrumentation, request_hook)) + _wrap(cls, "on_finish", partial(_on_finish, instrumentation)) + _wrap(cls, "log_exception", partial(_log_exception, instrumentation)) return True @@ -319,28 +319,36 @@ def _wrap(cls, method_name, wrapper): wrapt.apply_patch(cls, method_name, wrapper) -def _prepare(self, request_hook, func, handler, args, kwargs): +def _prepare(instrumentation, request_hook, func, handler, args, kwargs): + instrumentation.start_time = default_timer() request = handler.request if _excluded_urls.url_disabled(request.uri): return func(*args, **kwargs) - ctx = _start_span(self, handler) + + _record_prepare_metrics(instrumentation, handler) + + ctx = _start_span(instrumentation.tracer, handler) if request_hook: request_hook(ctx.span, handler) return func(*args, **kwargs) -def _on_finish(self, func, handler, args, kwargs): +def _on_finish(instrumentation, func, handler, args, kwargs): response = func(*args, **kwargs) - _finish_span(self, handler) + + _record_on_finish_metrics(instrumentation, handler) + + _finish_span(instrumentation.tracer, handler) + return response -def _log_exception(self, func, handler, args, kwargs): +def _log_exception(instrumentation, func, handler, args, kwargs): error = None if len(args) == 3: error = args[1] - _finish_span(self, handler, error) + _finish_span(instrumentation, handler, error) return func(*args, **kwargs) @@ -406,11 +414,9 @@ def _get_full_handler_name(handler): return f"{klass.__module__}.{klass.__qualname__}" -def _start_span(self, handler) -> _TraceContext: - start_time = default_timer() - +def _start_span(tracer, handler) -> _TraceContext: span, token = _start_internal_or_server_span( - tracer=self.tracer, + tracer=tracer, span_name=_get_operation_name(handler, handler.request), start_time=time_ns(), context_carrier=handler.request.headers, @@ -429,14 +435,6 @@ def _start_span(self, handler) -> _TraceContext: if len(custom_attributes) > 0: span.set_attributes(custom_attributes) - metric_attributes = _create_metric_attributes(handler) - request_size = len(handler.request.body) - - self.request_size_histogram.record( - request_size, attributes=metric_attributes - ) - self.active_requests_histogram.add(1, attributes=metric_attributes) - activation = trace.use_span(span, end_on_exit=True) activation.__enter__() # pylint: disable=E1101 ctx = _TraceContext(activation, span, token) @@ -449,15 +447,10 @@ def _start_span(self, handler) -> _TraceContext: if propagator: propagator.inject(handler, setter=response_propagation_setter) - elapsed_time = round((default_timer() - start_time) * 1000) - - self.duration_histogram.record(elapsed_time, attributes=metric_attributes) - self.active_requests_histogram.add(-1, attributes=metric_attributes) - return ctx -def _finish_span(self, handler, error=None): +def _finish_span(tracer, handler, error=None): status_code = handler.get_status() reason = getattr(handler, "_reason") finish_args = (None, None, None) @@ -467,7 +460,7 @@ def _finish_span(self, handler, error=None): if isinstance(error, tornado.web.HTTPError): status_code = error.status_code if not ctx and status_code == 404: - ctx = _start_span(self, handler) + ctx = _start_span(tracer, handler) else: status_code = 500 reason = None @@ -508,13 +501,51 @@ def _finish_span(self, handler, error=None): delattr(handler, _HANDLER_CONTEXT_KEY) -def _create_metric_attributes(handler): +def _record_prepare_metrics(instrumentation, handler): + request_size = len(handler.request.body) + metric_attributes = _create_metric_attributes(handler) + + instrumentation.request_size_histogram.record( + request_size, attributes=metric_attributes + ) + + active_requests_attributes = _create_active_requests_attributes( + handler.request + ) + instrumentation.active_requests_histogram.add( + 1, attributes=active_requests_attributes + ) + + +def _record_on_finish_metrics(instrumentation, handler): + elapsed_time = round((default_timer() - instrumentation.start_time) * 1000) + + metric_attributes = _create_metric_attributes(handler) + instrumentation.duration_histogram.record( + elapsed_time, attributes=metric_attributes + ) + + active_requests_attributes = _create_active_requests_attributes( + handler.request + ) + instrumentation.active_requests_histogram.add( + -1, attributes=active_requests_attributes + ) + + +def _create_active_requests_attributes(request): metric_attributes = { - SpanAttributes.HTTP_METHOD: handler.request.method, - SpanAttributes.HTTP_SCHEME: handler.request.protocol, - SpanAttributes.HTTP_STATUS_CODE: handler.get_status(), - SpanAttributes.HTTP_FLAVOR: handler.request.version, - SpanAttributes.HTTP_HOST: handler.request.host, + SpanAttributes.HTTP_METHOD: request.method, + SpanAttributes.HTTP_SCHEME: request.protocol, + SpanAttributes.HTTP_FLAVOR: request.version, + SpanAttributes.HTTP_HOST: request.host, } return metric_attributes + + +def _create_metric_attributes(handler): + metric_attributes = _create_active_requests_attributes(handler.request) + metric_attributes[SpanAttributes.HTTP_STATUS_CODE] = handler.get_status() + + return metric_attributes diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py index 1513f34f3a..af7a5882db 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py @@ -99,12 +99,13 @@ def _finish_tracing_callback( status_code = None description = None exc = future.exception() + response = future.result() if span.is_recording() and exc: if isinstance(exc, HTTPError): status_code = exc.code description = f"{type(exc).__name__}: {exc}" else: - status_code = future.result().code + status_code = response.code if status_code is not None: span.set_attribute(SpanAttributes.HTTP_STATUS_CODE, status_code) @@ -114,7 +115,6 @@ def _finish_tracing_callback( description=description, ) ) - response = future.result() metric_attributes = _create_metric_attributes(response) response_size = int(response.headers["Content-Length"]) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index 806222b99a..ade88c3a81 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -19,6 +19,7 @@ from opentelemetry import trace from opentelemetry.instrumentation.tornado import TornadoInstrumentor +from opentelemetry.sdk.metrics.export import HistogramDataPoint from opentelemetry.test.test_base import TestBase from .tornado_test_app import make_app @@ -31,6 +32,32 @@ def get_app(self): app = make_app(tracer) return app + def get_sorted_metrics(self): + resource_metrics = ( + self.memory_metrics_reader.get_metrics_data().resource_metrics + ) + for metrics in resource_metrics: + for scope_metrics in metrics.scope_metrics: + all_metrics = [metric for metric in scope_metrics.metrics] + return self.sorted_metrics(all_metrics) + + @staticmethod + def sorted_metrics(metrics): + """ + Sorts metrics by metric name. + """ + return sorted( + metrics, + key=lambda m: m.name, + ) + + def assertMetricHasAttributes(self, metric, expected_attributes): + for data_point in metric.data.data_points: + self.assertDictEqual( + expected_attributes, + dict(data_point.attributes), + ) + def setUp(self): super().setUp() TornadoInstrumentor().instrument( @@ -51,64 +78,60 @@ def test_basic_metrics(self): response = self.fetch("/") client_duration_estimated = (default_timer() - start_time) * 1000 - expected_attributes = { - "http.status_code": 200, - "http.method": "GET", - "http.flavor": "HTTP/1.1", - "http.scheme": "http", - "http.host": response.request.headers["host"], - } - expected_response_attributes = { - "http.status_code": response.code, - "http.method": "GET", - "http.url": self.get_url("/"), - } - expected_data = { - "http.server.request.size": 0, - "http.server.response.size": int( - response.headers["Content-Length"] - ), - } - expected_metrics = [ - "http.server.duration", - "http.server.request.size", - "http.server.response.size", - "http.server.active_requests", - ] + metrics = self.get_sorted_metrics() + self.assertEqual(len(metrics), 4) + active_request, duration, request_size, response_size = metrics + + self.assertEqual(active_request.name, "http.server.active_requests") + self.assertMetricHasAttributes( + active_request, + { + "http.method": "GET", + "http.flavor": "HTTP/1.1", + "http.scheme": "http", + "http.host": response.request.headers["host"], + }, + ) - resource_metrics = ( - self.memory_metrics_reader.get_metrics_data().resource_metrics + self.assertEqual(duration.name, "http.server.duration") + for data_point in duration.data.data_points: + self.assertAlmostEqual( + data_point.sum, + client_duration_estimated, + delta=200, + ) + self.assertMetricHasAttributes( + duration, + { + "http.status_code": 201, + "http.method": "GET", + "http.flavor": "HTTP/1.1", + "http.scheme": "http", + "http.host": response.request.headers["host"], + }, + ) + + self.assertEqual(request_size.name, "http.server.request.size") + self.assertMetricHasAttributes( + request_size, + { + "http.status_code": 200, + "http.method": "GET", + "http.flavor": "HTTP/1.1", + "http.scheme": "http", + "http.host": response.request.headers["host"], + }, + ) + + self.assertEqual(response_size.name, "http.server.response.size") + self.assertMetricHasAttributes( + response_size, + { + "http.status_code": response.code, + "http.method": "GET", + "http.url": self.get_url("/"), + }, ) - for metrics in resource_metrics: - for scope_metrics in metrics.scope_metrics: - self.assertEqual( - len(scope_metrics.metrics), len(expected_metrics) - ) - for metric in scope_metrics.metrics: - for data_point in metric.data.data_points: - if metric.name in expected_data: - self.assertEqual( - data_point.sum, expected_data[metric.name] - ) - - self.assertIn(metric.name, expected_metrics) - if metric.name == "http.server.duration": - self.assertAlmostEqual( - data_point.sum, - client_duration_estimated, - delta=1000, - ) - - if metric.name == "http.server.response.size": - self.assertDictEqual( - expected_response_attributes, - dict(data_point.attributes), - ) - else: - self.assertDictEqual( - expected_attributes, - dict(data_point.attributes), - ) def test_metric_uninstrument(self): self.fetch("/") @@ -119,6 +142,6 @@ def test_metric_uninstrument(self): for resource_metric in metrics_list.resource_metrics: for scope_metric in resource_metric.scope_metrics: for metric in scope_metric.metrics: - if metric.name != "http.server.active_requests": - for point in list(metric.data.data_points): + for point in list(metric.data.data_points): + if isinstance(point, HistogramDataPoint): self.assertEqual(point.count, 1) From 340b2966cdbbca68bb1b781c7f3659dc12a74354 Mon Sep 17 00:00:00 2001 From: sroda Date: Thu, 22 Sep 2022 13:53:27 +0300 Subject: [PATCH 06/11] Fix duration metric test --- .../tests/test_metrics_instrumentation.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index ade88c3a81..c105ae3336 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -94,12 +94,12 @@ def test_basic_metrics(self): ) self.assertEqual(duration.name, "http.server.duration") - for data_point in duration.data.data_points: - self.assertAlmostEqual( - data_point.sum, - client_duration_estimated, - delta=200, - ) + data_point = list(duration.data.data_points)[0] + self.assertAlmostEqual( + data_point.sum, + client_duration_estimated, + delta=200, + ) self.assertMetricHasAttributes( duration, { From 3ab38f07212d51a5d64576213a19b6640a2c20d4 Mon Sep 17 00:00:00 2001 From: sroda Date: Sun, 2 Oct 2022 14:31:41 +0300 Subject: [PATCH 07/11] Add client instrumentation --- .../instrumentation/tornado/__init__.py | 36 ++++- .../instrumentation/tornado/client.py | 21 ++- .../tests/test_metrics_instrumentation.py | 144 ++++++++++++++---- 3 files changed, 165 insertions(+), 36 deletions(-) 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 95768365ac..d73e9cd206 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -236,29 +236,45 @@ def _instrument(self, **kwargs): self.tracer = trace.get_tracer(__name__, __version__, tracer_provider) meter_provider = kwargs.get("meter_provider") - self.meter = get_meter(__name__, __version__, meter_provider) + meter = get_meter(__name__, __version__, meter_provider) - self.duration_histogram = self.meter.create_histogram( + self.duration_histogram = meter.create_histogram( name="http.server.duration", unit="ms", description="measures the duration outbound HTTP requests", ) - self.request_size_histogram = self.meter.create_histogram( + self.request_size_histogram = meter.create_histogram( name="http.server.request.size", unit="By", description="measures the size of HTTP request messages (compressed)", ) - self.response_size_histogram = self.meter.create_histogram( + self.response_size_histogram = meter.create_histogram( name="http.server.response.size", unit="By", description="measures the size of HTTP response messages (compressed)", ) - self.active_requests_histogram = self.meter.create_up_down_counter( + self.active_requests_histogram = meter.create_up_down_counter( name="http.server.active_requests", unit="requests", description="measures the number of concurrent HTTP requests that are currently in-flight", ) + client_duration_histogram = meter.create_histogram( + name="http.client.duration", + unit="ms", + description="measures the duration outbound HTTP requests", + ) + client_request_size_histogram = meter.create_histogram( + name="http.client.request.size", + unit="By", + description="measures the size of HTTP request messages (compressed)", + ) + client_response_size_histogram = meter.create_histogram( + name="http.client.response.size", + unit="By", + description="measures the size of HTTP response messages (compressed)", + ) + client_request_hook = kwargs.get("client_request_hook", None) client_response_hook = kwargs.get("client_response_hook", None) server_request_hook = kwargs.get("server_request_hook", None) @@ -280,7 +296,9 @@ def handler_init(init, handler, args, kwargs): self.tracer, client_request_hook, client_response_hook, - self.response_size_histogram, + client_duration_histogram, + client_request_size_histogram, + client_response_size_histogram, ), ) @@ -520,7 +538,12 @@ def _record_prepare_metrics(instrumentation, handler): def _record_on_finish_metrics(instrumentation, handler): elapsed_time = round((default_timer() - instrumentation.start_time) * 1000) + response_size = int(handler._headers.get("Content-Length", 0)) metric_attributes = _create_metric_attributes(handler) + instrumentation.response_size_histogram.record( + response_size, attributes=metric_attributes + ) + instrumentation.duration_histogram.record( elapsed_time, attributes=metric_attributes ) @@ -539,6 +562,7 @@ def _create_active_requests_attributes(request): SpanAttributes.HTTP_SCHEME: request.protocol, SpanAttributes.HTTP_FLAVOR: request.version, SpanAttributes.HTTP_HOST: request.host, + SpanAttributes.HTTP_TARGET: request.path, } return metric_attributes diff --git a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py index af7a5882db..090f87a88b 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/client.py @@ -45,6 +45,8 @@ def fetch_async( tracer, request_hook, response_hook, + duration_histogram, + request_size_histogram, response_size_histogram, func, _, @@ -87,6 +89,8 @@ def fetch_async( _finish_tracing_callback, span=span, response_hook=response_hook, + duration_histogram=duration_histogram, + request_size_histogram=request_size_histogram, response_size_histogram=response_size_histogram, ) ) @@ -94,12 +98,19 @@ def fetch_async( def _finish_tracing_callback( - future, span, response_hook, response_size_histogram + future, + span, + response_hook, + duration_histogram, + request_size_histogram, + response_size_histogram, ): status_code = None description = None exc = future.exception() + response = future.result() + if span.is_recording() and exc: if isinstance(exc, HTTPError): status_code = exc.code @@ -115,9 +126,15 @@ def _finish_tracing_callback( description=description, ) ) + metric_attributes = _create_metric_attributes(response) - response_size = int(response.headers["Content-Length"]) + request_size = int(response.request.headers.get("Content-Length", 0)) + response_size = int(response.headers.get("Content-Length", 0)) + duration_histogram.record( + response.request_time, attributes=metric_attributes + ) + request_size_histogram.record(request_size, attributes=metric_attributes) response_size_histogram.record(response_size, attributes=metric_attributes) if response_hook: diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index c105ae3336..34b9b28a3f 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -19,7 +19,10 @@ from opentelemetry import trace from opentelemetry.instrumentation.tornado import TornadoInstrumentor -from opentelemetry.sdk.metrics.export import HistogramDataPoint +from opentelemetry.sdk.metrics.export import ( + HistogramDataPoint, + NumberDataPoint, +) from opentelemetry.test.test_base import TestBase from .tornado_test_app import make_app @@ -51,13 +54,43 @@ def sorted_metrics(metrics): key=lambda m: m.name, ) - def assertMetricHasAttributes(self, metric, expected_attributes): - for data_point in metric.data.data_points: - self.assertDictEqual( - expected_attributes, - dict(data_point.attributes), + def assertMetricExpected( + self, metric, expected_value, expected_attributes + ): + data_point = next(metric.data.data_points) + + if isinstance(data_point, HistogramDataPoint): + self.assertEqual( + data_point.sum, + expected_value, + ) + elif isinstance(data_point, NumberDataPoint): + self.assertEqual( + data_point.value, + expected_value, ) + self.assertDictEqual( + expected_attributes, + dict(data_point.attributes), + ) + + def assertDurationMetricExpected( + self, metric, duration_estimated, expected_attributes + ): + data_point = next(metric.data.data_points) + + self.assertAlmostEqual( + data_point.sum, + duration_estimated, + delta=200, + ) + + self.assertDictEqual( + expected_attributes, + dict(data_point.attributes), + ) + def setUp(self): super().setUp() TornadoInstrumentor().instrument( @@ -79,57 +112,112 @@ def test_basic_metrics(self): client_duration_estimated = (default_timer() - start_time) * 1000 metrics = self.get_sorted_metrics() - self.assertEqual(len(metrics), 4) - active_request, duration, request_size, response_size = metrics - - self.assertEqual(active_request.name, "http.server.active_requests") - self.assertMetricHasAttributes( - active_request, + self.assertEqual(len(metrics), 7) + + ( + client_duration, + client_request_size, + client_response_size, + ) = metrics[:3] + + ( + server_active_request, + server_duration, + server_request_size, + server_response_size, + ) = metrics[3:] + + self.assertEqual( + server_active_request.name, "http.server.active_requests" + ) + self.assertMetricExpected( + server_active_request, + 0, { "http.method": "GET", "http.flavor": "HTTP/1.1", "http.scheme": "http", + "http.target": "/", "http.host": response.request.headers["host"], }, ) - self.assertEqual(duration.name, "http.server.duration") - data_point = list(duration.data.data_points)[0] - self.assertAlmostEqual( - data_point.sum, + self.assertEqual(server_duration.name, "http.server.duration") + self.assertDurationMetricExpected( + server_duration, client_duration_estimated, - delta=200, - ) - self.assertMetricHasAttributes( - duration, { - "http.status_code": 201, + "http.status_code": response.code, "http.method": "GET", "http.flavor": "HTTP/1.1", "http.scheme": "http", + "http.target": "/", "http.host": response.request.headers["host"], }, ) - self.assertEqual(request_size.name, "http.server.request.size") - self.assertMetricHasAttributes( - request_size, + self.assertEqual(server_request_size.name, "http.server.request.size") + self.assertMetricExpected( + server_request_size, + 0, { "http.status_code": 200, "http.method": "GET", "http.flavor": "HTTP/1.1", "http.scheme": "http", + "http.target": "/", "http.host": response.request.headers["host"], }, ) - self.assertEqual(response_size.name, "http.server.response.size") - self.assertMetricHasAttributes( - response_size, + self.assertEqual( + server_response_size.name, "http.server.response.size" + ) + self.assertMetricExpected( + server_response_size, + len(response.body), + { + "http.status_code": response.code, + "http.method": "GET", + "http.flavor": "HTTP/1.1", + "http.scheme": "http", + "http.target": "/", + "http.host": response.request.headers["host"], + }, + ) + + self.assertEqual(client_duration.name, "http.client.duration") + self.assertDurationMetricExpected( + client_duration, + client_duration_estimated, + { + "http.status_code": response.code, + "http.method": "GET", + "http.url": response.effective_url, + }, + ) + + self.assertEqual(client_request_size.name, "http.client.request.size") + self.assertMetricExpected( + client_request_size, + 0, + { + "http.status_code": response.code, + "http.method": "GET", + "http.url": response.effective_url, + }, + ) + + self.assertEqual( + client_response_size.name, "http.client.response.size" + ) + self.assertMetricExpected( + client_response_size, + len(response.body), { "http.status_code": response.code, "http.method": "GET", - "http.url": self.get_url("/"), + "http.url": response.effective_url, }, ) From d1f5f43d4cac54b9aaf36c4aeaf888d5207ab761 Mon Sep 17 00:00:00 2001 From: sroda Date: Sun, 2 Oct 2022 14:45:22 +0300 Subject: [PATCH 08/11] Fix lint --- .../instrumentation/tornado/__init__.py | 8 +++++++- .../tests/test_metrics_instrumentation.py | 20 +++++++++---------- 2 files changed, 17 insertions(+), 11 deletions(-) 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 d73e9cd206..df6de3c3ac 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -366,6 +366,8 @@ def _log_exception(instrumentation, func, handler, args, kwargs): if len(args) == 3: error = args[1] + _record_on_finish_metrics(instrumentation, handler, error) + _finish_span(instrumentation, handler, error) return func(*args, **kwargs) @@ -535,11 +537,15 @@ def _record_prepare_metrics(instrumentation, handler): ) -def _record_on_finish_metrics(instrumentation, handler): +def _record_on_finish_metrics(instrumentation, handler, error=None): elapsed_time = round((default_timer() - instrumentation.start_time) * 1000) response_size = int(handler._headers.get("Content-Length", 0)) metric_attributes = _create_metric_attributes(handler) + + if isinstance(error, tornado.web.HTTPError): + metric_attributes[SpanAttributes.HTTP_STATUS_CODE] = error.status_code + instrumentation.response_size_histogram.record( response_size, attributes=metric_attributes ) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py index 34b9b28a3f..14ef4b842a 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_metrics_instrumentation.py @@ -41,7 +41,7 @@ def get_sorted_metrics(self): ) for metrics in resource_metrics: for scope_metrics in metrics.scope_metrics: - all_metrics = [metric for metric in scope_metrics.metrics] + all_metrics = list(scope_metrics.metrics) return self.sorted_metrics(all_metrics) @staticmethod @@ -54,7 +54,7 @@ def sorted_metrics(metrics): key=lambda m: m.name, ) - def assertMetricExpected( + def assert_metric_expected( self, metric, expected_value, expected_attributes ): data_point = next(metric.data.data_points) @@ -75,7 +75,7 @@ def assertMetricExpected( dict(data_point.attributes), ) - def assertDurationMetricExpected( + def assert_duration_metric_expected( self, metric, duration_estimated, expected_attributes ): data_point = next(metric.data.data_points) @@ -130,7 +130,7 @@ def test_basic_metrics(self): self.assertEqual( server_active_request.name, "http.server.active_requests" ) - self.assertMetricExpected( + self.assert_metric_expected( server_active_request, 0, { @@ -143,7 +143,7 @@ def test_basic_metrics(self): ) self.assertEqual(server_duration.name, "http.server.duration") - self.assertDurationMetricExpected( + self.assert_duration_metric_expected( server_duration, client_duration_estimated, { @@ -157,7 +157,7 @@ def test_basic_metrics(self): ) self.assertEqual(server_request_size.name, "http.server.request.size") - self.assertMetricExpected( + self.assert_metric_expected( server_request_size, 0, { @@ -173,7 +173,7 @@ def test_basic_metrics(self): self.assertEqual( server_response_size.name, "http.server.response.size" ) - self.assertMetricExpected( + self.assert_metric_expected( server_response_size, len(response.body), { @@ -187,7 +187,7 @@ def test_basic_metrics(self): ) self.assertEqual(client_duration.name, "http.client.duration") - self.assertDurationMetricExpected( + self.assert_duration_metric_expected( client_duration, client_duration_estimated, { @@ -198,7 +198,7 @@ def test_basic_metrics(self): ) self.assertEqual(client_request_size.name, "http.client.request.size") - self.assertMetricExpected( + self.assert_metric_expected( client_request_size, 0, { @@ -211,7 +211,7 @@ def test_basic_metrics(self): self.assertEqual( client_response_size.name, "http.client.response.size" ) - self.assertMetricExpected( + self.assert_metric_expected( client_response_size, len(response.body), { From 9f24abf65860ead8836f1ba39412d4ac842a0ae7 Mon Sep 17 00:00:00 2001 From: sroda Date: Mon, 3 Oct 2022 17:39:05 +0300 Subject: [PATCH 09/11] Use metrics dict instead of instrumentation class --- .../instrumentation/tornado/__init__.py | 122 +++++++++++------- .../tests/test_instrumentation.py | 6 +- 2 files changed, 79 insertions(+), 49 deletions(-) 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 df6de3c3ac..3d8fc6d979 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -158,7 +158,7 @@ def client_resposne_hook(span, future): from logging import getLogger from time import time_ns from timeit import default_timer -from typing import Collection +from typing import Collection, Dict import tornado.web import wrapt @@ -179,6 +179,7 @@ def client_resposne_hook(span, future): unwrap, ) from opentelemetry.metrics import get_meter +from opentelemetry.metrics._internal.instrument import Histogram from opentelemetry.propagators import textmap from opentelemetry.semconv.trace import SpanAttributes from opentelemetry.trace.status import Status, StatusCode @@ -200,6 +201,12 @@ def client_resposne_hook(span, future): _OTEL_PATCHED_KEY = "_otel_patched_key" +_START_TIME = "start_time" +_SERVER_DURATION_HISTOGRAM = "http.server.duration" +_SERVER_REQUEST_SIZE_HISTOGRAM = "http.server.request.size" +_SERVER_RESPONSE_SIZE_HISTOGRAM = "http.server.response.size" +_SERVER_ACTIVE_REQUESTS_HISTOGRAM = "http.server.active_requests" + _excluded_urls = get_excluded_urls("TORNADO") _traced_request_attrs = get_traced_request_attrs("TORNADO") response_propagation_setter = FuncSetter(tornado.web.RequestHandler.add_header) @@ -233,31 +240,12 @@ def _instrument(self, **kwargs): process lifetime. """ tracer_provider = kwargs.get("tracer_provider") - self.tracer = trace.get_tracer(__name__, __version__, tracer_provider) + tracer = trace.get_tracer(__name__, __version__, tracer_provider) meter_provider = kwargs.get("meter_provider") meter = get_meter(__name__, __version__, meter_provider) - self.duration_histogram = meter.create_histogram( - name="http.server.duration", - unit="ms", - description="measures the duration outbound HTTP requests", - ) - self.request_size_histogram = meter.create_histogram( - name="http.server.request.size", - unit="By", - description="measures the size of HTTP request messages (compressed)", - ) - self.response_size_histogram = meter.create_histogram( - name="http.server.response.size", - unit="By", - description="measures the size of HTTP response messages (compressed)", - ) - self.active_requests_histogram = meter.create_up_down_counter( - name="http.server.active_requests", - unit="requests", - description="measures the number of concurrent HTTP requests that are currently in-flight", - ) + server_histograms = _create_server_histograms(meter) client_duration_histogram = meter.create_histogram( name="http.client.duration", @@ -281,7 +269,9 @@ def _instrument(self, **kwargs): def handler_init(init, handler, args, kwargs): cls = handler.__class__ - if patch_handler_class(self, cls, server_request_hook): + if patch_handler_class( + tracer, server_histograms, cls, server_request_hook + ): self.patched_handlers.append(cls) return init(*args, **kwargs) @@ -293,7 +283,7 @@ def handler_init(init, handler, args, kwargs): "AsyncHTTPClient.fetch", partial( fetch_async, - self.tracer, + tracer, client_request_hook, client_response_hook, client_duration_histogram, @@ -310,14 +300,49 @@ def _uninstrument(self, **kwargs): self.patched_handlers = [] -def patch_handler_class(instrumentation, cls, request_hook=None): +def _create_server_histograms(meter) -> Dict[str, Histogram]: + histograms = { + _SERVER_DURATION_HISTOGRAM: meter.create_histogram( + name="http.server.duration", + unit="ms", + description="measures the duration outbound HTTP requests", + ), + _SERVER_REQUEST_SIZE_HISTOGRAM: meter.create_histogram( + name="http.server.request.size", + unit="By", + description="measures the size of HTTP request messages (compressed)", + ), + _SERVER_RESPONSE_SIZE_HISTOGRAM: meter.create_histogram( + name="http.server.response.size", + unit="By", + description="measures the size of HTTP response messages (compressed)", + ), + _SERVER_ACTIVE_REQUESTS_HISTOGRAM: meter.create_up_down_counter( + name="http.server.active_requests", + unit="requests", + description="measures the number of concurrent HTTP requests that are currently in-flight", + ), + } + + return histograms + + +def patch_handler_class(tracer, server_histograms, cls, request_hook=None): if getattr(cls, _OTEL_PATCHED_KEY, False): return False setattr(cls, _OTEL_PATCHED_KEY, True) - _wrap(cls, "prepare", partial(_prepare, instrumentation, request_hook)) - _wrap(cls, "on_finish", partial(_on_finish, instrumentation)) - _wrap(cls, "log_exception", partial(_log_exception, instrumentation)) + _wrap( + cls, + "prepare", + partial(_prepare, tracer, server_histograms, request_hook), + ) + _wrap(cls, "on_finish", partial(_on_finish, tracer, server_histograms)) + _wrap( + cls, + "log_exception", + partial(_log_exception, tracer, server_histograms), + ) return True @@ -337,38 +362,41 @@ def _wrap(cls, method_name, wrapper): wrapt.apply_patch(cls, method_name, wrapper) -def _prepare(instrumentation, request_hook, func, handler, args, kwargs): - instrumentation.start_time = default_timer() +def _prepare( + tracer, server_histograms, request_hook, func, handler, args, kwargs +): + server_histograms[_START_TIME] = default_timer() + request = handler.request if _excluded_urls.url_disabled(request.uri): return func(*args, **kwargs) - _record_prepare_metrics(instrumentation, handler) + _record_prepare_metrics(server_histograms, handler) - ctx = _start_span(instrumentation.tracer, handler) + ctx = _start_span(tracer, handler) if request_hook: request_hook(ctx.span, handler) return func(*args, **kwargs) -def _on_finish(instrumentation, func, handler, args, kwargs): +def _on_finish(tracer, server_histograms, func, handler, args, kwargs): response = func(*args, **kwargs) - _record_on_finish_metrics(instrumentation, handler) + _record_on_finish_metrics(server_histograms, handler) - _finish_span(instrumentation.tracer, handler) + _finish_span(tracer, handler) return response -def _log_exception(instrumentation, func, handler, args, kwargs): +def _log_exception(tracer, server_histograms, func, handler, args, kwargs): error = None if len(args) == 3: error = args[1] - _record_on_finish_metrics(instrumentation, handler, error) + _record_on_finish_metrics(server_histograms, handler, error) - _finish_span(instrumentation, handler, error) + _finish_span(tracer, handler, error) return func(*args, **kwargs) @@ -521,24 +549,26 @@ def _finish_span(tracer, handler, error=None): delattr(handler, _HANDLER_CONTEXT_KEY) -def _record_prepare_metrics(instrumentation, handler): +def _record_prepare_metrics(server_histograms, handler): request_size = len(handler.request.body) metric_attributes = _create_metric_attributes(handler) - instrumentation.request_size_histogram.record( + server_histograms[_SERVER_REQUEST_SIZE_HISTOGRAM].record( request_size, attributes=metric_attributes ) active_requests_attributes = _create_active_requests_attributes( handler.request ) - instrumentation.active_requests_histogram.add( + server_histograms[_SERVER_ACTIVE_REQUESTS_HISTOGRAM].add( 1, attributes=active_requests_attributes ) -def _record_on_finish_metrics(instrumentation, handler, error=None): - elapsed_time = round((default_timer() - instrumentation.start_time) * 1000) +def _record_on_finish_metrics(server_histograms, handler, error=None): + elapsed_time = round( + (default_timer() - server_histograms[_START_TIME]) * 1000 + ) response_size = int(handler._headers.get("Content-Length", 0)) metric_attributes = _create_metric_attributes(handler) @@ -546,18 +576,18 @@ def _record_on_finish_metrics(instrumentation, handler, error=None): if isinstance(error, tornado.web.HTTPError): metric_attributes[SpanAttributes.HTTP_STATUS_CODE] = error.status_code - instrumentation.response_size_histogram.record( + server_histograms[_SERVER_RESPONSE_SIZE_HISTOGRAM].record( response_size, attributes=metric_attributes ) - instrumentation.duration_histogram.record( + server_histograms[_SERVER_DURATION_HISTOGRAM].record( elapsed_time, attributes=metric_attributes ) active_requests_attributes = _create_active_requests_attributes( handler.request ) - instrumentation.active_requests_histogram.add( + server_histograms[_SERVER_ACTIVE_REQUESTS_HISTOGRAM].add( -1, attributes=active_requests_attributes ) diff --git a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py index 94051b0c5d..2b47ddc822 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/tests/test_instrumentation.py @@ -110,9 +110,9 @@ def test_patch_references(self): def test_patch_applied_only_once(self): tracer = trace.get_tracer(__name__) - self.assertTrue(patch_handler_class(tracer, AsyncHandler)) - self.assertFalse(patch_handler_class(tracer, AsyncHandler)) - self.assertFalse(patch_handler_class(tracer, AsyncHandler)) + self.assertTrue(patch_handler_class(tracer, {}, AsyncHandler)) + self.assertFalse(patch_handler_class(tracer, {}, AsyncHandler)) + self.assertFalse(patch_handler_class(tracer, {}, AsyncHandler)) unpatch_handler_class(AsyncHandler) From 5c0e8bd6d7d38198c1570f233ab9ee58a800731b Mon Sep 17 00:00:00 2001 From: sroda Date: Wed, 12 Oct 2022 12:59:15 +0300 Subject: [PATCH 10/11] Fix after cr --- .../instrumentation/tornado/__init__.py | 51 +++++++++++-------- 1 file changed, 30 insertions(+), 21 deletions(-) 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 3d8fc6d979..c316c8075f 100644 --- a/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py @@ -200,8 +200,10 @@ def client_resposne_hook(span, future): _HANDLER_CONTEXT_KEY = "_otel_trace_context_key" _OTEL_PATCHED_KEY = "_otel_patched_key" - _START_TIME = "start_time" +_CLIENT_DURATION_HISTOGRAM = "http.client.duration" +_CLIENT_REQUEST_SIZE_HISTOGRAM = "http.client.request.size" +_CLIENT_RESPONSE_SIZE_HISTOGRAM = "http.client.response.size" _SERVER_DURATION_HISTOGRAM = "http.server.duration" _SERVER_REQUEST_SIZE_HISTOGRAM = "http.server.request.size" _SERVER_RESPONSE_SIZE_HISTOGRAM = "http.server.response.size" @@ -245,24 +247,9 @@ def _instrument(self, **kwargs): meter_provider = kwargs.get("meter_provider") meter = get_meter(__name__, __version__, meter_provider) + client_histograms = _create_client_histograms(meter) server_histograms = _create_server_histograms(meter) - client_duration_histogram = meter.create_histogram( - name="http.client.duration", - unit="ms", - description="measures the duration outbound HTTP requests", - ) - client_request_size_histogram = meter.create_histogram( - name="http.client.request.size", - unit="By", - description="measures the size of HTTP request messages (compressed)", - ) - client_response_size_histogram = meter.create_histogram( - name="http.client.response.size", - unit="By", - description="measures the size of HTTP response messages (compressed)", - ) - client_request_hook = kwargs.get("client_request_hook", None) client_response_hook = kwargs.get("client_response_hook", None) server_request_hook = kwargs.get("server_request_hook", None) @@ -286,9 +273,9 @@ def handler_init(init, handler, args, kwargs): tracer, client_request_hook, client_response_hook, - client_duration_histogram, - client_request_size_histogram, - client_response_size_histogram, + client_histograms[_CLIENT_DURATION_HISTOGRAM], + client_histograms[_CLIENT_REQUEST_SIZE_HISTOGRAM], + client_histograms[_CLIENT_RESPONSE_SIZE_HISTOGRAM], ), ) @@ -327,6 +314,28 @@ def _create_server_histograms(meter) -> Dict[str, Histogram]: return histograms +def _create_client_histograms(meter) -> Dict[str, Histogram]: + histograms = { + _CLIENT_DURATION_HISTOGRAM: meter.create_histogram( + name="http.client.duration", + unit="ms", + description="measures the duration outbound HTTP requests", + ), + _CLIENT_REQUEST_SIZE_HISTOGRAM: meter.create_histogram( + name="http.client.request.size", + unit="By", + description="measures the size of HTTP request messages (compressed)", + ), + _CLIENT_RESPONSE_SIZE_HISTOGRAM: meter.create_histogram( + name="http.client.response.size", + unit="By", + description="measures the size of HTTP response messages (compressed)", + ), + } + + return histograms + + def patch_handler_class(tracer, server_histograms, cls, request_hook=None): if getattr(cls, _OTEL_PATCHED_KEY, False): return False @@ -550,7 +559,7 @@ def _finish_span(tracer, handler, error=None): def _record_prepare_metrics(server_histograms, handler): - request_size = len(handler.request.body) + request_size = int(handler.request.headers.get("Content-Length", 0)) metric_attributes = _create_metric_attributes(handler) server_histograms[_SERVER_REQUEST_SIZE_HISTOGRAM].record( From 6044ab225c5f42e7677a5c722ba655de63ec89b7 Mon Sep 17 00:00:00 2001 From: sroda Date: Wed, 12 Oct 2022 15:52:02 +0300 Subject: [PATCH 11/11] Move the entry in CHANGELOG to Unreleased section --- CHANGELOG.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c4864ef35d..6e26036875 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,9 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased](https://github.com/open-telemetry/opentelemetry-python/compare/v1.13.0-0.34b0...HEAD) +- Add metric instrumentation for tornado + ([#1252](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1252)) + ### Added @@ -74,8 +77,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#1197](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1197)) - Add metric instumentation for flask ([#1186](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1186)) -- Add metric instrumentation for tornado - ([#1252](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1252)) - Add a test for asgi using NoOpTracerProvider ([#1367](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1367))