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..245236a3 --- /dev/null +++ b/instana/instrumentation/logging.py @@ -0,0 +1,45 @@ +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 + 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') + diff --git a/instana/json_span.py b/instana/json_span.py index 83c57d46..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 @@ -36,6 +37,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..5e302480 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"] @@ -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), @@ -152,10 +161,21 @@ 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": + 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} json_span = JsonSpan(n=span.operation_name, + k=kind, t=span.context.trace_id, p=span.parent_id, s=span.context.span_id, @@ -234,7 +254,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): 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)