Log traces

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

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"}')
+            '{"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)