From 70097f32e3a35f2fab23d851db8400d963210ae0 Mon Sep 17 00:00:00 2001
From: Simon Davy <simon.davy@canonical.com>
Date: Tue, 10 Dec 2019 18:36:56 +0000
Subject: [PATCH] Sentry logging breadcrumb fixes

Ensure that there is an active sentry context by activating it before
each request. Previously, there was no active context for the very first
request a worker served.

Also improves logging breadcrumbs:
 - remove duplicated information
 - condense file/lineno/funcName into one item
 - stringify keys so breadcrumb displays properly

Cleans up the depreacted use of LogRecord._structured
---
 talisker/context.py   |  2 +-
 talisker/logs.py      |  3 +--
 talisker/sentry.py    | 31 ++++++++++++++++++++++++-------
 talisker/wsgi.py      |  1 +
 tests/test_logging.py | 20 +++++++++++++-------
 5 files changed, 40 insertions(+), 17 deletions(-)

diff --git a/talisker/context.py b/talisker/context.py
index 4fffebf4..b8918c72 100644
--- a/talisker/context.py
+++ b/talisker/context.py
@@ -65,7 +65,7 @@
         else:
             early_log(
                 __name__,
-                'error',
+                'warning',
                 'aiocontextvars is installed, but it does not function with '
                 'python {}. Please use python >= 3.5.3 if you wish to use '
                 'talisker with asyncio.'.format(
diff --git a/talisker/logs.py b/talisker/logs.py
index 3dc7fd32..8996e8ce 100644
--- a/talisker/logs.py
+++ b/talisker/logs.py
@@ -342,7 +342,6 @@ def format(self, record):
             # we never want sentry to capture DEBUG logs in its breadcrumbs, as
             # they may be sensitive
             if record.levelno > logging.DEBUG:
-
                 talisker.sentry.record_log_breadcrumb(record)
 
             if len(record.message) > self.MAX_MSG_SIZE:
@@ -356,7 +355,7 @@ def format(self, record):
             s = self._fmt % record.__dict__
 
             # add our structured tags *before* exception info is added
-            structured = getattr(record, '_structured', {})
+            structured = getattr(record, 'extra', {})
             if record.exc_info and 'errno' not in structured:
                 structured.update(get_errno_fields(record.exc_info[1]))
             if structured:
diff --git a/talisker/sentry.py b/talisker/sentry.py
index 0110b058..b50013fa 100644
--- a/talisker/sentry.py
+++ b/talisker/sentry.py
@@ -54,6 +54,7 @@
     'get_client',
     'record_breadcrumb',
     'report_wsgi',
+    'new_context',
     'set_client',
 ]
 
@@ -75,6 +76,9 @@
     import raven.handlers.logging
 except ImportError:
     # dummy APIs that do nothing
+    def new_context():
+        pass
+
     def record_breadcrumb(*args, **kwargs):
         pass
 
@@ -112,6 +116,14 @@ def __exit__(self, exc_type, exc, traceback):
     raven.breadcrumbs.ignore_logger('talisker.slowqueries')
     raven.breadcrumbs.ignore_logger('talisker.requests')
 
+    FILTERED_EXTRAS = {
+        'request_id',  # do not need request_id for each log breadcrumb
+        'exc_type',    # exc info already displayed
+    }
+
+    def new_context():
+        get_client().context.activate()
+
     def record_breadcrumb(*args, **kwargs):
         raven.breadcrumbs.record(*args, **kwargs)
 
@@ -124,7 +136,7 @@ def record_log_breadcrumb(record):
             record.message,
             record.args,
             {
-                'extra': getattr(record, '_structured', {}),
+                'extra': getattr(record, 'extra', {}),
                 'exc_info': record.exc_info,
                 'stack_info': getattr(record, 'stack_info', None)
             },
@@ -141,14 +153,19 @@ def record_log_breadcrumb(record):
 
         def processor(data):
             metadata = {
-                'path': record.pathname,
-                'lineno': record.lineno,
+                'location': '{}:{}:{}'.format(
+                    record.pathname,
+                    record.lineno,
+                    getattr(record, 'funcName', ''),
+                ),
             }
-            if hasattr(record, 'func'):
-                metadata['func'] = record.func
-            metadata.update(getattr(record, '_structured', {}))
+            extra = getattr(record, 'extra', {})
+            metadata.update(
+                (k, str(v)) for k, v in extra.items()
+                if k not in FILTERED_EXTRAS
+            )
             data.update({
-                'message': record.message,
+                'message': record.getMessage(),
                 'category': record.name,
                 'level': record.levelname.lower(),
                 'data': metadata,
diff --git a/talisker/wsgi.py b/talisker/wsgi.py
index 263b685f..706f0ba2 100644
--- a/talisker/wsgi.py
+++ b/talisker/wsgi.py
@@ -512,6 +512,7 @@ def __init__(self, app, environ=None, headers=None):
 
     def __call__(self, environ, start_response):
         Context.new()
+        talisker.sentry.new_context()
         config = talisker.get_config()
         # populate default values
         Context.current.soft_timeout = config.soft_request_timeout
diff --git a/tests/test_logging.py b/tests/test_logging.py
index 4b25bb56..3919b8d5 100644
--- a/tests/test_logging.py
+++ b/tests/test_logging.py
@@ -187,21 +187,27 @@ def test_logger_collects_raven_breadcrumbs():
 
     fmt = logs.StructuredFormatter()
     with raven.context.Context() as ctx:
-        fmt.format(make_record({'foo': 'bar'}, 'info'))
-        record = make_record({'foo': 'bar'}, 'info')
-        record.levelno = logging.DEBUG
-        record.levelname = 'debug'
+        record = make_record(
+            {
+                'foo': 'bar',
+                'number': 1,
+            },
+            'msg',
+        )
+        record.levelno = logging.INFO
+        record.levelname = 'info'
+        record.funcName = 'func'
         fmt.format(record)
         breadcrumbs = ctx.breadcrumbs.get_buffer()
 
     assert len(breadcrumbs) == 1
-    assert breadcrumbs[0]['message'] == 'info'
+    assert breadcrumbs[0]['message'] == 'msg'
     assert breadcrumbs[0]['level'] == 'info'
     assert breadcrumbs[0]['category'] == 'name'
     assert breadcrumbs[0]['data'] == {
         'foo': 'bar',
-        'lineno': 'lno',
-        'path': 'fn',
+        'location': 'fn:lno:func',
+        'number': '1',
     }