feat: Add opt-in root exit spans to logging

Signed-off-by: Ferenc Géczi <ferenc.geczi@ibm.com>

src/instana/instrumentation/logging.py

@@ -8,7 +8,7 @@
 from collections.abc import Mapping
 
 from ..log import logger
-from ..util.traceutils import get_active_tracer
+from ..util.traceutils import get_tracer_tuple, tracing_is_off
 
 
 @wrapt.patch_function_wrapper('logging', 'Logger._log')
@@ -17,33 +17,34 @@ def log_with_instana(wrapped, instance, argv, kwargs):
     # argv[1] = message
     # argv[2] = args for message
     try:
-        active_tracer = get_active_tracer()
+        tracer, parent_span, _ = get_tracer_tuple()
 
         # Only needed if we're tracing and serious log
-        if active_tracer and argv[0] >= logging.WARN:
-
-            msg = str(argv[1])
-            args = argv[2]
-            if args and len(args) == 1 and isinstance(args[0], Mapping) and args[0]:
-                args = args[0]
-
-            # get the formatted log message
-            msg = msg % args
-
-            # 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 active_tracer.start_active_span('log', child_of=active_tracer.active_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.mark_as_errored()
+        if tracing_is_off() or argv[0] < logging.WARN:
+            return wrapped(*argv, **kwargs)
+
+        msg = str(argv[1])
+        args = argv[2]
+        if args and len(args) == 1 and isinstance(args[0], Mapping) and args[0]:
+            args = args[0]
+
+        # get the formatted log message
+        msg = msg % args
+
+        # 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.mark_as_errored()
     except Exception:
         logger.debug('log_with_instana:', exc_info=True)
 

tests/clients/test_logging.py

@@ -3,7 +3,7 @@
 
 import logging
 import unittest
-from instana.singletons import tracer
+from instana.singletons import agent, tracer
 
 
 class TestLogging(unittest.TestCase):
@@ -14,8 +14,8 @@ def setUp(self):
         self.logger = logging.getLogger('unit test')
 
     def tearDown(self):
-        """ Do nothing for now """
-        return None
+        """ Ensure that allow_exit_as_root has the default value """
+        agent.options.allow_exit_as_root = False
 
     def test_no_span(self):
         with tracer.start_active_span('test'):
@@ -58,3 +58,19 @@ def test_parameters(self):
 
         self.assertIsNotNone(spans[0].data["log"].get('parameters'))
 
+    def test_no_root_exit_span(self):
+        agent.options.allow_exit_as_root = True
+        self.logger.info('info message')
+
+        spans = self.recorder.queued_spans()
+        self.assertEqual(0, len(spans))
+
+    def test_root_exit_span(self):
+        agent.options.allow_exit_as_root = True
+        self.logger.warning('foo %s', 'bar')
+
+        spans = self.recorder.queued_spans()
+        self.assertEqual(1, len(spans))
+        self.assertEqual(2, spans[0].k)
+
+        self.assertEqual('foo bar', spans[0].data["log"].get('message'))