From 513a7c88a76f5b805de60a0a1b25b9b41e10a6d4 Mon Sep 17 00:00:00 2001 From: Tovin Seven Date: Tue, 4 Jul 2017 11:09:06 +0700 Subject: [PATCH] OSprofiler with Jaeger Tracing as backend In this patch, I use Uber Jaeger as a tracer. Trace/span from OSprofiler will be sent to Jaeger. We can use Jaeger UI to view trace. A sample image of trace in Jaeger: https://tovin07.github.io/opentracing/jaeger-openstack-image-list.png Reference: - OpenTracing: http://opentracing.io/ - Uber Jager: https://www.jaegertracing.io/docs/ Depends-On: Iaac3ac3853867a67f7e386e762e0522076235daf Change-Id: I8f75af487f50d5e67a1321a4c951d2a0d85733a1 Implements: blueprint opentracing-compatible --- lower-constraints.txt | 2 + osprofiler/_utils.py | 12 ++ osprofiler/drivers/__init__.py | 1 + osprofiler/drivers/jaeger.py | 147 +++++++++++++++++++ osprofiler/opts.py | 9 +- osprofiler/profiler.py | 14 +- osprofiler/tests/unit/drivers/test_jaeger.py | 78 ++++++++++ osprofiler/tests/unit/test_profiler.py | 12 +- osprofiler/tests/unit/test_utils.py | 24 +++ test-requirements.txt | 4 + 10 files changed, 297 insertions(+), 6 deletions(-) create mode 100644 osprofiler/drivers/jaeger.py create mode 100644 osprofiler/tests/unit/drivers/test_jaeger.py diff --git a/lower-constraints.txt b/lower-constraints.txt index a226beb..4ac38ad 100644 --- a/lower-constraints.txt +++ b/lower-constraints.txt @@ -1,6 +1,8 @@ coverage===4.0 ddt===1.0.1 elasticsearch===2.0.0 +futures===3.0.0 +jaeger-client==3.8.0 mock===2.0.0 netaddr===0.7.18 openstackdocstheme===1.18.1 diff --git a/osprofiler/_utils.py b/osprofiler/_utils.py index 3d5c1cc..b60a33d 100644 --- a/osprofiler/_utils.py +++ b/osprofiler/_utils.py @@ -18,8 +18,10 @@ import hashlib import hmac import json import os +import uuid from oslo_utils import secretutils +from oslo_utils import uuidutils import six @@ -147,3 +149,13 @@ def import_modules_from_package(package): new_package = ".".join(root.split(os.sep)).split("....")[1] module_name = "%s.%s" % (new_package, filename[:-3]) __import__(module_name) + + +def shorten_id(span_id): + """Convert from uuid4 to 64 bit id for OpenTracing""" + try: + short_id = uuid.UUID(span_id).int & (1 << 64) - 1 + except ValueError: + # Return a new short id for this + short_id = shorten_id(uuidutils.generate_uuid()) + return short_id diff --git a/osprofiler/drivers/__init__.py b/osprofiler/drivers/__init__.py index c59f25e..37fdb69 100644 --- a/osprofiler/drivers/__init__.py +++ b/osprofiler/drivers/__init__.py @@ -1,5 +1,6 @@ from osprofiler.drivers import base # noqa from osprofiler.drivers import elasticsearch_driver # noqa +from osprofiler.drivers import jaeger # noqa from osprofiler.drivers import loginsight # noqa from osprofiler.drivers import messaging # noqa from osprofiler.drivers import mongodb # noqa diff --git a/osprofiler/drivers/jaeger.py b/osprofiler/drivers/jaeger.py new file mode 100644 index 0000000..669aa13 --- /dev/null +++ b/osprofiler/drivers/jaeger.py @@ -0,0 +1,147 @@ +# Copyright 2018 Fujitsu Ltd. +# All Rights Reserved. +# +# 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. + +import collections +import datetime +import time + +from oslo_config import cfg +from oslo_serialization import jsonutils +import six.moves.urllib.parse as parser + +from osprofiler import _utils as utils +from osprofiler.drivers import base +from osprofiler import exc + + +class Jaeger(base.Driver): + def __init__(self, connection_str, project=None, service=None, host=None, + conf=cfg.CONF, **kwargs): + """Jaeger driver for OSProfiler.""" + + super(Jaeger, self).__init__(connection_str, project=project, + service=service, host=host, + conf=conf, **kwargs) + try: + import jaeger_client + self.jaeger_client = jaeger_client + except ImportError: + raise exc.CommandError( + "To use OSProfiler with Uber Jaeger tracer, " + "you have to install `jaeger-client` manually. " + "Install with pip:\n `pip install jaeger-client`." + ) + + parsed_url = parser.urlparse(connection_str) + cfg = { + "local_agent": { + "reporting_host": parsed_url.hostname, + "reporting_port": parsed_url.port, + } + } + + # Initialize tracer for each profiler + service_name = "{}-{}".format(project, service) + config = jaeger_client.Config(cfg, service_name=service_name) + self.tracer = config.initialize_tracer() + + self.spans = collections.deque() + + @classmethod + def get_name(cls): + return "jaeger" + + def notify(self, payload): + if payload["name"].endswith("start"): + timestamp = datetime.datetime.strptime(payload["timestamp"], + "%Y-%m-%dT%H:%M:%S.%f") + epoch = datetime.datetime.utcfromtimestamp(0) + start_time = (timestamp - epoch).total_seconds() + + # Create parent span + child_of = self.jaeger_client.SpanContext( + trace_id=utils.shorten_id(payload["base_id"]), + span_id=utils.shorten_id(payload["parent_id"]), + parent_id=None, + flags=self.jaeger_client.span.SAMPLED_FLAG + ) + + # Create Jaeger Tracing span + span = self.tracer.start_span( + operation_name=payload["name"].rstrip("-start"), + child_of=child_of, + tags=self.create_span_tags(payload), + start_time=start_time + ) + + # Replace Jaeger Tracing span_id (random id) to OSProfiler span_id + span.context.span_id = utils.shorten_id(payload["trace_id"]) + self.spans.append(span) + else: + span = self.spans.pop() + + # Store result of db call and function call + for call in ("db", "function"): + if payload.get("info", {}).get(call) is not None: + span.set_tag("result", payload["info"][call]["result"]) + + # Span error tag and log + if payload["info"].get("etype") is not None: + span.set_tag("error", True) + span.log_kv({"error.kind": payload["info"]["etype"]}) + span.log_kv({"message": payload["info"]["message"]}) + + span.finish(finish_time=time.time()) + + def get_report(self, base_id): + """Please use Jaeger Tracing UI for this task.""" + return self._parse_results() + + def list_traces(self, fields=None): + """Please use Jaeger Tracing UI for this task.""" + return [] + + def list_error_traces(self): + """Please use Jaeger Tracing UI for this task.""" + return [] + + def create_span_tags(self, payload): + """Create tags for OpenTracing span. + + :param info: Information from OSProfiler trace. + :returns tags: A dictionary contains standard tags + from OpenTracing sematic conventions, + and some other custom tags related to http, db calls. + """ + tags = {} + info = payload["info"] + + if info.get("db"): + # DB calls + tags["db.statement"] = info["db"]["statement"] + tags["db.params"] = jsonutils.dumps(info["db"]["params"]) + elif info.get("request"): + # WSGI call + tags["http.path"] = info["request"]["path"] + tags["http.query"] = info["request"]["query"] + tags["http.method"] = info["request"]["method"] + tags["http.scheme"] = info["request"]["scheme"] + elif info.get("function"): + # RPC, function calls + tags["args"] = info["function"]["args"] + tags["kwargs"] = info["function"]["kwargs"] + tags["name"] = info["function"]["name"] + + return tags diff --git a/osprofiler/opts.py b/osprofiler/opts.py index 7d633f9..61ffd05 100644 --- a/osprofiler/opts.py +++ b/osprofiler/opts.py @@ -87,10 +87,11 @@ sets the notifier to oslo_messaging. Examples of possible values: -* messaging://: use oslo_messaging driver for sending notifications. -* mongodb://127.0.0.1:27017 : use mongodb driver for sending notifications. -* elasticsearch://127.0.0.1:9200 : use elasticsearch driver for sending -notifications. +* messaging:// - use oslo_messaging driver for sending spans. +* redis://127.0.0.1:6379 - use redis driver for sending spans. +* mongodb://127.0.0.1:27017 - use mongodb driver for sending spans. +* elasticsearch://127.0.0.1:9200 - use elasticsearch driver for sending spans. +* jaeger://127.0.0.1:6831 - use jaeger tracing as driver for sending spans. """) _es_doc_type_opt = cfg.StrOpt( diff --git a/osprofiler/profiler.py b/osprofiler/profiler.py index 29a7a2a..fcbbc38 100644 --- a/osprofiler/profiler.py +++ b/osprofiler/profiler.py @@ -23,6 +23,7 @@ import threading from oslo_utils import reflection from oslo_utils import uuidutils +from osprofiler import _utils as utils from osprofiler import notifier @@ -343,7 +344,10 @@ class Trace(object): def __exit__(self, etype, value, traceback): if etype: - info = {"etype": reflection.get_class_name(etype)} + info = { + "etype": reflection.get_class_name(etype), + "message": value.args[0] if value.args else None + } stop(info=info) else: stop() @@ -359,6 +363,14 @@ class _Profiler(object): self._name = collections.deque() self._host = socket.gethostname() + def get_shorten_id(self, uuid_id): + """Return shorten id of a uuid that will be used in OpenTracing drivers + + :param uuid_id: A string of uuid that was generated by uuidutils + :returns: A shorter 64-bit long id + """ + return format(utils.shorten_id(uuid_id), "x") + def get_base_id(self): """Return base id of a trace. diff --git a/osprofiler/tests/unit/drivers/test_jaeger.py b/osprofiler/tests/unit/drivers/test_jaeger.py new file mode 100644 index 0000000..661d75b --- /dev/null +++ b/osprofiler/tests/unit/drivers/test_jaeger.py @@ -0,0 +1,78 @@ +# Copyright 2018 Fujitsu Ltd. +# All Rights Reserved. +# +# 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. + +import mock + +from osprofiler.drivers import jaeger +from osprofiler.tests import test + + +class JaegerTestCase(test.TestCase): + + def setUp(self): + super(JaegerTestCase, self).setUp() + self.payload_start = { + "name": "api-start", + "base_id": "4e3e0ec6-2938-40b1-8504-09eb1d4b0dee", + "trace_id": "1c089ea8-28fe-4f3d-8c00-f6daa2bc32f1", + "parent_id": "e2715537-3d1c-4f0c-b3af-87355dc5fc5b", + "timestamp": "2018-05-03T04:31:51.781381", + "info": { + "host": "test" + } + } + + self.payload_stop = { + "name": "api-stop", + "base_id": "4e3e0ec6-2938-40b1-8504-09eb1d4b0dee", + "trace_id": "1c089ea8-28fe-4f3d-8c00-f6daa2bc32f1", + "parent_id": "e2715537-3d1c-4f0c-b3af-87355dc5fc5b", + "timestamp": "2018-05-03T04:31:51.781381", + "info": { + "host": "test", + "function": { + "result": 1 + } + } + } + + self.driver = jaeger.Jaeger("jaeger://127.0.0.1:6831", + project="nova", service="api") + + @mock.patch("osprofiler._utils.shorten_id") + def test_notify_start(self, mock_shorten_id): + self.driver.notify(self.payload_start) + calls = [ + mock.call(self.payload_start["base_id"]), + mock.call(self.payload_start["parent_id"]), + mock.call(self.payload_start["trace_id"]) + ] + mock_shorten_id.assert_has_calls(calls, any_order=True) + + @mock.patch("jaeger_client.span.Span") + @mock.patch("time.time") + def test_notify_stop(self, mock_time, mock_span): + fake_time = 1525416065.5958152 + mock_time.return_value = fake_time + + span = mock_span() + self.driver.spans.append(mock_span()) + + self.driver.notify(self.payload_stop) + + mock_time.assert_called_once() + mock_time.reset_mock() + + span.finish.assert_called_once_with(finish_time=fake_time) diff --git a/osprofiler/tests/unit/test_profiler.py b/osprofiler/tests/unit/test_profiler.py index 943760a..96f0654 100644 --- a/osprofiler/tests/unit/test_profiler.py +++ b/osprofiler/tests/unit/test_profiler.py @@ -62,6 +62,13 @@ class ProfilerGlobMethodsTestCase(test.TestCase): class ProfilerTestCase(test.TestCase): + def test_profiler_get_shorten_id(self): + uuid_id = "4e3e0ec6-2938-40b1-8504-09eb1d4b0dee" + prof = profiler._Profiler("secret", base_id="1", parent_id="2") + result = prof.get_shorten_id(uuid_id) + expected = "850409eb1d4b0dee" + self.assertEqual(expected, result) + def test_profiler_get_base_id(self): prof = profiler._Profiler("secret", base_id="1", parent_id="2") self.assertEqual(prof.get_base_id(), "1") @@ -167,7 +174,10 @@ class WithTraceTestCase(test.TestCase): self.assertRaises(ValueError, foo) mock_start.assert_called_once_with("foo", info=None) - mock_stop.assert_called_once_with(info={"etype": "ValueError"}) + mock_stop.assert_called_once_with(info={ + "etype": "ValueError", + "message": "bar" + }) @profiler.trace("function", info={"info": "some_info"}) diff --git a/osprofiler/tests/unit/test_utils.py b/osprofiler/tests/unit/test_utils.py index 19aff30..ffb7b09 100644 --- a/osprofiler/tests/unit/test_utils.py +++ b/osprofiler/tests/unit/test_utils.py @@ -16,6 +16,7 @@ import base64 import hashlib import hmac +import uuid import mock @@ -111,6 +112,29 @@ class UtilsTestCase(test.TestCase): self.assertIsNone(utils.signed_unpack(data, hmac_data, hmac)) + def test_shorten_id_with_valid_uuid(self): + valid_id = "4e3e0ec6-2938-40b1-8504-09eb1d4b0dee" + + uuid_obj = uuid.UUID(valid_id) + + with mock.patch("uuid.UUID") as mock_uuid: + mock_uuid.return_value = uuid_obj + + result = utils.shorten_id(valid_id) + expected = 9584796812364680686 + + self.assertEqual(expected, result) + + @mock.patch("oslo_utils.uuidutils.generate_uuid") + def test_shorten_id_with_invalid_uuid(self, mock_gen_uuid): + invalid_id = "invalid" + mock_gen_uuid.return_value = "1c089ea8-28fe-4f3d-8c00-f6daa2bc32f1" + + result = utils.shorten_id(invalid_id) + expected = 10088334584203457265 + + self.assertEqual(expected, result) + def test_itersubclasses(self): class A(object): diff --git a/test-requirements.txt b/test-requirements.txt index 0ce9cdd..4235472 100644 --- a/test-requirements.txt +++ b/test-requirements.txt @@ -22,3 +22,7 @@ redis # MIT # Build release notes reno # Apache-2.0 + +# For Jaeger Tracing +jaeger-client # Apache-2.0 +futures;python_version=='2.7' or python_version=='2.6' # PSF