Merge pull request #23 from Overseas-Student-Living/more-detailed-log…

…-message

Add call ID to log message

README.rst

@@ -58,8 +58,8 @@ You should see two log records printed out in the first shell:
     $ nameko run traced
     starting services: traced
     Connected to amqp://guest:***@127.0.0.1:5672//
-    entrypoint call trace
-    entrypoint result trace
+    [traced.hello.8eb11de2-0b28-495d-af91-98bd6a051bca] entrypoint call trace
+    [traced.hello.8eb11de2-0b28-495d-af91-98bd6a051bca] entrypoint result trace
 
 The output does not tell much, given the default logging formatter prints
 just the message. But there's much more on the log records, to get it out

nameko_tracer/dependency.py

@@ -58,7 +58,10 @@ def worker_setup(self, worker_ctx):
                 'timestamp': timestamp,
             }
             adapter = self.adapter_factory(worker_ctx)
-            adapter.info('entrypoint call trace', extra=extra)
+            adapter.info(
+                '[%s] entrypoint call trace',
+                worker_ctx.call_id,
+                extra=extra)
         except Exception:
             logger.warning('Failed to log entrypoint trace', exc_info=True)
 
@@ -81,8 +84,14 @@ def worker_result(self, worker_ctx, result=None, exc_info=None):
             }
             adapter = self.adapter_factory(worker_ctx)
             if exc_info:
-                adapter.warning('entrypoint result trace', extra=extra)
+                adapter.warning(
+                    '[%s] entrypoint result trace',
+                    worker_ctx.call_id,
+                    extra=extra)
             else:
-                adapter.info('entrypoint result trace', extra=extra)
+                adapter.info(
+                    '[%s] entrypoint result trace',
+                    worker_ctx.call_id,
+                    extra=extra)
         except Exception:
             logger.warning('Failed to log entrypoint trace', exc_info=True)

tests/test_dependency.py

@@ -72,13 +72,15 @@ def some_method(self, spam):
 
     setup_record, result_record = tracker.log_records
 
-    assert setup_record.msg == 'entrypoint call trace'
+    assert setup_record.msg == '[%s] entrypoint call trace'
     assert setup_record.levelno == logging.INFO
-    assert result_record.msg == 'entrypoint result trace'
+    assert result_record.msg == '[%s] entrypoint result trace'
     assert result_record.levelno == logging.INFO
 
     setup_details = getattr(setup_record, constants.TRACE_KEY)
 
+    assert setup_record.args == (setup_details['call_id'],)
+
     assert setup_details[constants.TIMESTAMP_KEY] == request_timestamp
     assert (
         setup_details[constants.STAGE_KEY] ==
@@ -87,6 +89,8 @@ def some_method(self, spam):
 
     result_details = getattr(result_record, constants.TRACE_KEY)
 
+    assert result_record.args == (result_details['call_id'],)
+
     assert result_details[constants.TIMESTAMP_KEY] == response_timestamp
     assert result_details[constants.RESPONSE_TIME_KEY] == 60.0
     assert (
@@ -129,20 +133,24 @@ def some_method(self, spam):
 
     setup_record, result_record = tracker.log_records
 
-    assert setup_record.msg == 'entrypoint call trace'
+    assert setup_record.msg == '[%s] entrypoint call trace'
     assert setup_record.levelno == logging.INFO
-    assert result_record.msg == 'entrypoint result trace'
+    assert result_record.msg == '[%s] entrypoint result trace'
     assert result_record.levelno == logging.WARNING
 
     setup_details = getattr(setup_record, constants.TRACE_KEY)
 
+    assert setup_record.args == (setup_details['call_id'],)
+
     assert setup_details[constants.TIMESTAMP_KEY] == request_timestamp
     assert (
         setup_details[constants.STAGE_KEY] ==
         constants.Stage.request.value)
 
     result_details = getattr(result_record, constants.TRACE_KEY)
 
+    assert result_record.args == (result_details['call_id'],)
+
     assert result_details[constants.TIMESTAMP_KEY] == response_timestamp
     assert result_details[constants.RESPONSE_TIME_KEY] == 60.0
     assert (