From 0d051e2ff59a9bbfd759aa77f4b3bfde8c952d5f Mon Sep 17 00:00:00 2001 From: "John.Lockwood" Date: Mon, 17 Jul 2017 12:27:39 -0700 Subject: [PATCH 1/4] Log traces --- furious/handlers/__init__.py | 3 +++ furious/tests/handlers/test__init__.py | 5 +++-- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/furious/handlers/__init__.py b/furious/handlers/__init__.py index b153283..c4ba795 100644 --- a/furious/handlers/__init__.py +++ b/furious/handlers/__init__.py @@ -43,6 +43,7 @@ def process_async_task(headers, request_body): def _log_task_info(headers, extra_task_info=None): """Processes the header from task requests to log analytical data.""" ran_at = time.time() + trace = headers.get("X-Cloud-Trace-Context") task_eta = float(headers.get('X-Appengine-Tasketa', 0.0)) task_info = { 'retry_count': headers.get('X-Appengine-Taskretrycount', ''), @@ -51,6 +52,8 @@ def _log_task_info(headers, extra_task_info=None): 'ran': ran_at, 'gae_latency_seconds': ran_at - task_eta } + if trace: + task_info['trace'] = trace if extra_task_info: task_info['extra'] = extra_task_info diff --git a/furious/tests/handlers/test__init__.py b/furious/tests/handlers/test__init__.py index b2735f3..584b039 100644 --- a/furious/tests/handlers/test__init__.py +++ b/furious/tests/handlers/test__init__.py @@ -32,14 +32,15 @@ def test_all_headers(self, debug_mock, time_mock): headers = { 'X-Appengine-Taskretrycount': 'blue', 'X-Appengine-Taskexecutioncount': 'yellow', - 'X-Appengine-Tasketa': '0.50' + 'X-Appengine-Tasketa': '0.50', + 'X-Cloud-Trace-Context': "atrace" } handlers._log_task_info(headers) expected_logs = ( '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, ' - '"task_eta": 0.5, "execution_count": "yellow"}') + '"task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') debug_mock.assert_called_with('TASK-INFO: %s', expected_logs) From 75eab4fc9c8142b8b547526323ac30828f8b17ef Mon Sep 17 00:00:00 2001 From: "John.Lockwood" Date: Fri, 21 Jul 2017 08:20:51 -0700 Subject: [PATCH 2/4] Reorder serialized expected test dict --- furious/tests/handlers/test__init__.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/furious/tests/handlers/test__init__.py b/furious/tests/handlers/test__init__.py index 584b039..cc76735 100644 --- a/furious/tests/handlers/test__init__.py +++ b/furious/tests/handlers/test__init__.py @@ -72,7 +72,7 @@ def test_ignore_extra_headers(self, debug_mock, time_mock): handlers._log_task_info(headers) expected_logs = ( - '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, ' - '"task_eta": 0.5, "execution_count": "yellow"}') + '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, + "task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') debug_mock.assert_called_with('TASK-INFO: %s', expected_logs) From 20d7da76176f1e8c8b6b192b13c4becd6de397dc Mon Sep 17 00:00:00 2001 From: "John.Lockwood" Date: Fri, 21 Jul 2017 08:49:17 -0700 Subject: [PATCH 3/4] Fix multiline string --- furious/tests/handlers/test__init__.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/furious/tests/handlers/test__init__.py b/furious/tests/handlers/test__init__.py index cc76735..17785cc 100644 --- a/furious/tests/handlers/test__init__.py +++ b/furious/tests/handlers/test__init__.py @@ -72,7 +72,7 @@ def test_ignore_extra_headers(self, debug_mock, time_mock): handlers._log_task_info(headers) expected_logs = ( - '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, - "task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') + '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, ' + '"task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') debug_mock.assert_called_with('TASK-INFO: %s', expected_logs) From ee9bf68b180f658ebd19e9f45a2cb80945a2091e Mon Sep 17 00:00:00 2001 From: "John.Lockwood" Date: Fri, 21 Jul 2017 08:53:00 -0700 Subject: [PATCH 4/4] Unfix wrong expectation. fix right one --- furious/tests/handlers/test__init__.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/furious/tests/handlers/test__init__.py b/furious/tests/handlers/test__init__.py index 17785cc..af3ccbe 100644 --- a/furious/tests/handlers/test__init__.py +++ b/furious/tests/handlers/test__init__.py @@ -39,8 +39,8 @@ def test_all_headers(self, debug_mock, time_mock): handlers._log_task_info(headers) expected_logs = ( - '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, ' - '"task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') + '{"gae_latency_seconds": 1.0, "task_eta": 0.5, "trace": "atrace", ' + '"execution_count": "yellow", "ran": 1.5, "retry_count": "blue"}') debug_mock.assert_called_with('TASK-INFO: %s', expected_logs) @@ -73,6 +73,6 @@ def test_ignore_extra_headers(self, debug_mock, time_mock): expected_logs = ( '{"ran": 1.5, "retry_count": "blue", "gae_latency_seconds": 1.0, ' - '"task_eta": 0.5, "execution_count": "yellow", "trace": "atrace"}') + '"task_eta": 0.5, "execution_count": "yellow"}') debug_mock.assert_called_with('TASK-INFO: %s', expected_logs)