From b2f78baf684cbc85abcd5258c9be608f67827b60 Mon Sep 17 00:00:00 2001 From: steveww Date: Thu, 7 Feb 2019 10:43:27 +0000 Subject: [PATCH 1/5] logging instrumentation --- instana/__init__.py | 1 + instana/instrumentation/logging.py | 43 ++++++++++++++++++++++++++++++ instana/json_span.py | 1 + instana/recorder.py | 15 +++++++++-- 4 files changed, 58 insertions(+), 2 deletions(-) create mode 100644 instana/instrumentation/logging.py diff --git a/instana/__init__.py b/instana/__init__.py index 2dd0411d..cb575967 100644 --- a/instana/__init__.py +++ b/instana/__init__.py @@ -62,6 +62,7 @@ def boot_agent(): # Import & initialize instrumentation if (sys.version_info >= (3, 4)) and (sys.version_info < (3, 7)): from .instrumentation import asynqp # noqa + from .instrumentation import logging # noqa from .instrumentation import mysqlpython # noqa from .instrumentation import redis # noqa from .instrumentation import sqlalchemy # noqa diff --git a/instana/instrumentation/logging.py b/instana/instrumentation/logging.py new file mode 100644 index 00000000..b3790b3b --- /dev/null +++ b/instana/instrumentation/logging.py @@ -0,0 +1,43 @@ +from __future__ import absolute_import + +import wrapt +import logging +import sys + +from ..log import logger +from ..singletons import tracer + +@wrapt.patch_function_wrapper('logging', 'Logger._log') +def log_with_instana(wrapped, instance, argv, kwargs): + # argv[0] = level + # argv[1] = message + # argv[2] = args for message + parent_span = tracer.active_span + + # Only needed if we're tracing and serious log + if parent_span and argv[0] >= logging.WARN: + # get the formatted log message + msg = argv[1] % argv[2] + + # get additional information if an exception is being handled + parameters = None + (t, v, tb) = sys.exc_info() + if t is not None and v is not None: + parameters = '{} {}'.format(t , v) + + # create logging span + with tracer.start_active_span('log', child_of=parent_span) as scope: + scope.span.log_kv({ 'message': msg }) + if parameters is not None: + scope.span.log_kv({ 'parameters': parameters }) + # extra tags for an error + if argv[0] >= logging.ERROR: + scope.span.set_tag('error', True) + ec = scope.span.tags.get('ec', 0) + scope.span.set_tag('ec', ec + 1) + + + return wrapped(*argv, **kwargs) + +logger.debug('Instrumenting logging') + diff --git a/instana/json_span.py b/instana/json_span.py index 83c57d46..6d3538de 100644 --- a/instana/json_span.py +++ b/instana/json_span.py @@ -36,6 +36,7 @@ class Data(object): service = None sqlalchemy = None soap = None + log = None def __init__(self, **kwds): self.__dict__.update(kwds) diff --git a/instana/recorder.py b/instana/recorder.py index 246fbf07..8f9df768 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -24,11 +24,11 @@ class InstanaRecorder(SpanRecorder): registered_spans = ("django", "memcache", "mysql", "rabbitmq", "redis", - "rpc-client", "rpc-server", "sqlalchemy", "soap", "urllib3", "wsgi") + "rpc-client", "rpc-server", "sqlalchemy", "soap", "urllib3", "wsgi", "log") http_spans = ("django", "wsgi", "urllib3", "soap") exit_spans = ("memcache", "mysql", "rabbitmq", "redis", "rpc-client", - "sqlalchemy", "soap", "urllib3") + "sqlalchemy", "soap", "urllib3", "log") entry_spans = ("django", "wsgi", "rabbitmq", "rpc-server") entry_kind = ["entry", "server", "consumer"] @@ -152,6 +152,17 @@ def build_registered_span(self, span): tskey = list(data.custom.logs.keys())[0] data.mysql.error = data.custom.logs[tskey]['message'] + if span.operation_name == "log": + logger.debug('found a log') + data.log = {} + # use last special key values + # TODO - logic might need a tweak here + for l in span.logs: + if "message" in l.key_values: + data.log["message"] = l.key_values.pop("message", None) + if "parameters" in l.key_values: + data.log["parameters"] = l.key_values.pop("parameters", None) + entity_from = {'e': instana.singletons.agent.from_.pid, 'h': instana.singletons.agent.from_.agentUuid} From 9fba5d07e695d66b13202ad1c5f1b48aa1f2d227 Mon Sep 17 00:00:00 2001 From: steveww Date: Thu, 7 Feb 2019 13:40:50 +0000 Subject: [PATCH 2/5] fix k --- instana/json_span.py | 1 + instana/recorder.py | 7 ++++++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/instana/json_span.py b/instana/json_span.py index 6d3538de..edb12545 100644 --- a/instana/json_span.py +++ b/instana/json_span.py @@ -1,4 +1,5 @@ class JsonSpan(object): + k = None t = 0 p = None s = 0 diff --git a/instana/recorder.py b/instana/recorder.py index 8f9df768..d59238b2 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -175,6 +175,10 @@ def build_registered_span(self, span): f=entity_from, data=data) + # log is a special case as it is not entry nor exit + if span.operation_name == "log": + json_span.k = 3 # intermediate span + if span.stack: json_span.stack = span.stack @@ -245,7 +249,8 @@ def get_span_kind(self, span): elif span.tags["span.kind"] in self.exit_kind: kind = "exit" else: - kind = "local" + kind = "intermediate" + return kind def collect_logs(self, span): From 8dff0bada6c046fd8a39934c8f3203c3abb2832d Mon Sep 17 00:00:00 2001 From: steveww Date: Thu, 7 Feb 2019 16:02:48 +0000 Subject: [PATCH 3/5] error handling --- instana/instrumentation/logging.py | 54 ++++++++++++++++-------------- 1 file changed, 28 insertions(+), 26 deletions(-) diff --git a/instana/instrumentation/logging.py b/instana/instrumentation/logging.py index b3790b3b..245236a3 100644 --- a/instana/instrumentation/logging.py +++ b/instana/instrumentation/logging.py @@ -12,32 +12,34 @@ def log_with_instana(wrapped, instance, argv, kwargs): # argv[0] = level # argv[1] = message # argv[2] = args for message - parent_span = tracer.active_span - - # Only needed if we're tracing and serious log - if parent_span and argv[0] >= logging.WARN: - # get the formatted log message - msg = argv[1] % argv[2] - - # get additional information if an exception is being handled - parameters = None - (t, v, tb) = sys.exc_info() - if t is not None and v is not None: - parameters = '{} {}'.format(t , v) - - # create logging span - with tracer.start_active_span('log', child_of=parent_span) as scope: - scope.span.log_kv({ 'message': msg }) - if parameters is not None: - scope.span.log_kv({ 'parameters': parameters }) - # extra tags for an error - if argv[0] >= logging.ERROR: - scope.span.set_tag('error', True) - ec = scope.span.tags.get('ec', 0) - scope.span.set_tag('ec', ec + 1) - - - return wrapped(*argv, **kwargs) + try: + parent_span = tracer.active_span + + # Only needed if we're tracing and serious log + if parent_span and argv[0] >= logging.WARN: + # get the formatted log message + msg = argv[1] % argv[2] + + # get additional information if an exception is being handled + parameters = None + (t, v, tb) = sys.exc_info() + if t is not None and v is not None: + parameters = '{} {}'.format(t , v) + + # create logging span + with tracer.start_active_span('log', child_of=parent_span) as scope: + scope.span.log_kv({ 'message': msg }) + if parameters is not None: + scope.span.log_kv({ 'parameters': parameters }) + # extra tags for an error + if argv[0] >= logging.ERROR: + scope.span.set_tag('error', True) + ec = scope.span.tags.get('ec', 0) + scope.span.set_tag('ec', ec + 1) + except Exception as e: + logger.debug('Exception: %s', e, exc_info=True) + finally: + return wrapped(*argv, **kwargs) logger.debug('Instrumenting logging') From 986f3a791770fe95f6b517233c4f1699eb57a2ab Mon Sep 17 00:00:00 2001 From: steveww Date: Thu, 7 Feb 2019 16:03:17 +0000 Subject: [PATCH 4/5] fix up registered kind --- instana/recorder.py | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/instana/recorder.py b/instana/recorder.py index d59238b2..5e302480 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -95,6 +95,13 @@ def build_registered_span(self, span): """ Takes a BasicSpan and converts it into a registered JsonSpan """ data = Data(baggage=span.context.baggage) + kind = 1 # entry + if span.operation_name in self.exit_spans: + kind = 2 # exit + # log is a special case as it is not entry nor exit + if span.operation_name == "log": + kind = 3 # intermediate span + logs = self.collect_logs(span) if len(logs) > 0: if data.custom is None: @@ -116,6 +123,8 @@ def build_registered_span(self, span): sort=span.tags.pop('sort', None), address=span.tags.pop('address', None), key=span.tags.pop('key', None)) + if data.rabbitmq.sort == 'consume': + kind = 1 # entry if span.operation_name == "redis": data.redis = RedisData(connection=span.tags.pop('connection', None), @@ -153,7 +162,6 @@ def build_registered_span(self, span): data.mysql.error = data.custom.logs[tskey]['message'] if span.operation_name == "log": - logger.debug('found a log') data.log = {} # use last special key values # TODO - logic might need a tweak here @@ -167,6 +175,7 @@ def build_registered_span(self, span): 'h': instana.singletons.agent.from_.agentUuid} json_span = JsonSpan(n=span.operation_name, + k=kind, t=span.context.trace_id, p=span.parent_id, s=span.context.span_id, @@ -175,10 +184,6 @@ def build_registered_span(self, span): f=entity_from, data=data) - # log is a special case as it is not entry nor exit - if span.operation_name == "log": - json_span.k = 3 # intermediate span - if span.stack: json_span.stack = span.stack From 07db9819c9784d9817747bc206c843ab0c243e0c Mon Sep 17 00:00:00 2001 From: steveww Date: Thu, 7 Feb 2019 17:06:19 +0000 Subject: [PATCH 5/5] logging tests --- tests/test_logging.py | 50 +++++++++++++++++++++++++++++++++++++++++++ tests/test_ot_span.py | 2 +- 2 files changed, 51 insertions(+), 1 deletion(-) create mode 100644 tests/test_logging.py diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 00000000..8ae4aced --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,50 @@ +from __future__ import absolute_import + +import logging +import unittest +from instana.singletons import tracer + + +class TestLogging(unittest.TestCase): + def setUp(self): + """ Clear all spans before a test run """ + self.recorder = tracer.recorder + self.recorder.clear_spans() + self.logger = logging.getLogger('unit test') + + def tearDown(self): + """ Do nothing for now """ + return None + + def test_no_span(self): + with tracer.start_active_span('test'): + self.logger.info('info message') + + + spans = self.recorder.queued_spans() + self.assertEqual(1, len(spans)) + + def test_extra_span(self): + with tracer.start_active_span('test'): + self.logger.warn('foo %s', 'bar') + + spans = self.recorder.queued_spans() + self.assertEqual(2, len(spans)) + self.assertEqual(3, spans[0].k) # intermediate kind + + self.assertEqual('foo bar', spans[0].data.log.get('message')) + + def test_parameters(self): + with tracer.start_active_span('test'): + try: + a = 42 + b = 0 + c = a / b + except Exception as e: + self.logger.exception('Exception: %s', str(e)) + + spans = self.recorder.queued_spans() + self.assertEqual(2, len(spans)) + + self.assertIsNotNone(spans[0].data.log.get('parameters')) + diff --git a/tests/test_ot_span.py b/tests/test_ot_span.py index 4e1391fe..20996e06 100644 --- a/tests/test_ot_span.py +++ b/tests/test_ot_span.py @@ -127,4 +127,4 @@ def test_span_kind(self): assert_equals('exit', span.data.sdk.Type) span = spans[4] - assert_equals('local', span.data.sdk.Type) + assert_equals('intermediate', span.data.sdk.Type)