New logging instrumentation (#128)

* logging instrumentation

* fix k

* error handling

* fix up registered kind

* logging tests

Author: steveww

instana/__init__.py

@@ -63,6 +63,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

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')
+

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)

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):

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'))
+

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)