From ccd2e7b46468c0a9ed287fb87ae29a25d565b5d7 Mon Sep 17 00:00:00 2001 From: Ondrej Kohout Date: Mon, 4 Sep 2017 11:11:14 +0100 Subject: [PATCH] Add call ID to log message --- README.rst | 4 ++-- nameko_tracer/dependency.py | 15 ++++++++++++--- tests/test_dependency.py | 16 ++++++++++++---- 3 files changed, 26 insertions(+), 9 deletions(-) diff --git a/README.rst b/README.rst index 54a324f..d47e202 100644 --- a/README.rst +++ b/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 diff --git a/nameko_tracer/dependency.py b/nameko_tracer/dependency.py index 7d3d149..36cc217 100644 --- a/nameko_tracer/dependency.py +++ b/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) diff --git a/tests/test_dependency.py b/tests/test_dependency.py index e7c5a16..3f57381 100644 --- a/tests/test_dependency.py +++ b/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,13 +133,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.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] == @@ -143,6 +149,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 (