Logging instrumentation safeties; Update tests. (#130)

* Assure string in format

* Update tests to include/test new log spans.

Author: pglombardo

instana/instrumentation/logging.py

@@ -7,6 +7,7 @@
 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
@@ -18,7 +19,9 @@ def log_with_instana(wrapped, instance, argv, kwargs):
         # 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]
+            # clients such as suds-jurko log things such as: Fault(Server: 'Server side fault example.')
+            # So make sure we're working with a string
+            msg = str(argv[1]) % argv[2]
 
             # get additional information if an exception is being handled
             parameters = None
@@ -41,5 +44,6 @@ def log_with_instana(wrapped, instance, argv, kwargs):
     finally:
         return wrapped(*argv, **kwargs)
 
+
 logger.debug('Instrumenting logging')
 

tests/test_django.py

@@ -79,11 +79,12 @@ def test_request_with_error(self):
         assert_equals(500, response.status)
 
         spans = self.recorder.queued_spans()
-        assert_equals(3, len(spans))
+        assert_equals(4, len(spans))
 
-        test_span = spans[2]
-        urllib3_span = spans[1]
-        django_span = spans[0]
+        test_span = spans[3]
+        urllib3_span = spans[2]
+        django_span = spans[1]
+        log_span = spans[0]
 
         assert ('X-Instana-T' in response.headers)
         assert (int(response.headers['X-Instana-T'], 16))
@@ -103,12 +104,15 @@ def test_request_with_error(self):
         assert_equals("test", test_span.data.sdk.name)
         assert_equals("urllib3", urllib3_span.n)
         assert_equals("django", django_span.n)
+        assert_equals("log", log_span.n)
 
         assert_equals(test_span.t, urllib3_span.t)
         assert_equals(urllib3_span.t, django_span.t)
+        assert_equals(django_span.t, log_span.t)
 
         assert_equals(urllib3_span.p, test_span.s)
         assert_equals(django_span.p, urllib3_span.s)
+        assert_equals(log_span.p, django_span.s)
 
         assert_equals(True, django_span.error)
         assert_equals(1, django_span.ec)

tests/test_logging.py

@@ -26,14 +26,24 @@ def test_no_span(self):
 
     def test_extra_span(self):
         with tracer.start_active_span('test'):
-            self.logger.warn('foo %s', 'bar')
+            self.logger.warning('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_log_with_tuple(self):
+        with tracer.start_active_span('test'):
+            self.logger.warning('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:

tests/test_sudsjurko.py

@@ -64,10 +64,13 @@ def test_server_exception(self):
                 pass
 
         spans = self.recorder.queued_spans()
-        assert_equals(3, len(spans))
-        wsgi_span = spans[0]
-        soap_span = spans[1]
-        test_span = spans[2]
+        assert_equals(5, len(spans))
+
+        log_span1 = spans[0]
+        wsgi_span = spans[1]
+        log_span2 = spans[2]
+        soap_span = spans[3]
+        test_span = spans[4]
 
         assert_equals(None, response)
         assert_equals("test", test_span.data.sdk.name)
@@ -98,10 +101,12 @@ def test_server_fault(self):
                 pass
 
         spans = self.recorder.queued_spans()
-        assert_equals(3, len(spans))
-        wsgi_span = spans[0]
-        soap_span = spans[1]
-        test_span = spans[2]
+        assert_equals(5, len(spans))
+        log_span1 = spans[0]
+        wsgi_span = spans[1]
+        log_span2 = spans[2]
+        soap_span = spans[3]
+        test_span = spans[4]
 
         assert_equals(None, response)
         assert_equals("test", test_span.data.sdk.name)
@@ -132,10 +137,13 @@ def test_client_fault(self):
                 pass
 
         spans = self.recorder.queued_spans()
-        assert_equals(3, len(spans))
-        wsgi_span = spans[0]
-        soap_span = spans[1]
-        test_span = spans[2]
+        assert_equals(5, len(spans))
+
+        log_span1 = spans[0]
+        wsgi_span = spans[1]
+        log_span2 = spans[2]
+        soap_span = spans[3]
+        test_span = spans[4]
 
         assert_equals(None, response)
         assert_equals("test", test_span.data.sdk.name)

tests/test_urllib3.py

@@ -450,11 +450,12 @@ def test_exception_logging(self):
                 pass
 
         spans = self.recorder.queued_spans()
-        self.assertEqual(3, len(spans))
+        self.assertEqual(4, len(spans))
 
-        wsgi_span = spans[0]
-        urllib3_span = spans[1]
-        test_span = spans[2]
+        log_span = spans[0]
+        wsgi_span = spans[1]
+        urllib3_span = spans[2]
+        test_span = spans[3]
 
         assert(r)
         self.assertEqual(500, r.status)
@@ -464,10 +465,12 @@ def test_exception_logging(self):
         traceId = test_span.t
         self.assertEqual(traceId, urllib3_span.t)
         self.assertEqual(traceId, wsgi_span.t)
+        self.assertEqual(traceId, log_span.t)
 
         # Parent relationships
         self.assertEqual(urllib3_span.p, test_span.s)
         self.assertEqual(wsgi_span.p, urllib3_span.s)
+        self.assertEqual(log_span.p, wsgi_span.s)
 
         # Error logging
         self.assertFalse(test_span.error)
@@ -477,6 +480,13 @@ def test_exception_logging(self):
         self.assertTrue(wsgi_span.error)
         self.assertEqual(1, wsgi_span.ec)
 
+        # log span
+        self.assertEqual('log', log_span.n)
+        self.assertEqual(3, log_span.k)
+        self.assertTrue(type(log_span.stack) is list)
+        self.assertTrue('log' in log_span.data.__dict__)
+        self.assertTrue('message' in log_span.data.log)
+
         # wsgi
         self.assertEqual("wsgi", wsgi_span.n)
         self.assertEqual('127.0.0.1:5000', wsgi_span.data.http.host)