Add ability to log request ID to all output messages (#3510)

* Add request ID to all log messages

* Drive-by: add JSON formatter in config example

* Document how to log requests IDs

* make format

* Add unit test that covers StreamHandler

Author: leplatrem

docs/configuration/settings.rst

@@ -456,6 +456,19 @@ Example output:
     {"Pid": 19240, "Type": "root", "Timestamp": 1489067817834153984, "Severity": 4, "Hostname": "pluo", "Logger": "%", "EnvVersion": "2.0", "Fields": {"perm": "read", "userid": "ldap:[email protected]", "message": "Permission not granted.", "uri": "/buckets/123"}}
 
 
+Request IDs
+:::::::::::
+
+In order to add requests IDs to log messages, set the provided handler:
+
+.. code-block:: ini
+
+    [handler_console]
+    class = kinto.core.StreamHandlerWithRequestID
+
+It will read the value from the ``X-Request-Id`` request header if present, or generate a random string when the request is received otherwise.
+
+
 .. _handling-exceptions-with-sentry:
 
 Handling exceptions with Sentry

kinto/config/kinto.tpl

@@ -245,7 +245,7 @@ keys = root, kinto
 keys = console
 
 [formatters]
-keys = color
+keys = color, json
 
 [logger_root]
 level = INFO
@@ -258,10 +258,13 @@ qualname = kinto
 propagate = 0
 
 [handler_console]
-class = StreamHandler
+class = kinto.core.StreamHandlerWithRequestID
 args = (sys.stderr,)
 level = NOTSET
 formatter = color
 
 [formatter_color]
 class = logging_color_formatter.ColorFormatter
+
+[formatter_json]
+class = kinto.core.JsonLogFormatter

kinto/core/__init__.py

@@ -151,6 +151,20 @@ def __init__(self, fmt=None, datefmt=None, style="%"):
         self.logger_name = logger_name
 
 
+class StreamHandlerWithRequestID(logging.StreamHandler):
+    """
+    A custom StreamHandler that adds the Dockerflow's `RequestIdLogFilter`.
+
+    Defining a custom handler seems to be the only way to bypass the fact that
+    ``logging.config.fileConfig()`` does not load filters from ``.ini`` files.
+    """
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        filter_ = dockerflow_logging.RequestIdLogFilter()
+        self.addFilter(filter_)
+
+
 def get_user_info(request):
     # Default user info (shown in hello view for example).
     user_info = {"id": request.prefixed_userid, "principals": request.prefixed_principals}

kinto/core/initialization.py

@@ -4,9 +4,9 @@
 import urllib.parse
 import warnings
 from datetime import datetime
-from secrets import token_hex
 
 from dateutil import parser as dateparser
+from dockerflow.logging import get_or_generate_request_id, request_id_context
 from pyramid.events import ApplicationCreated, NewRequest, NewResponse
 from pyramid.exceptions import ConfigurationError
 from pyramid.httpexceptions import (
@@ -374,12 +374,15 @@ def on_new_request(event):
                 message="Invalid URL path.",
             )
 
+        rid = get_or_generate_request_id(headers=request.headers)
+        request_id_context.set(rid)
+
         request.log_context(
             agent=request.headers.get("User-Agent"),
             path=request_path,
             method=request.method,
             lang=request.headers.get("Accept-Language"),
-            rid=request.headers.get("X-Request-Id", token_hex(16)),
+            rid=rid,
             errno=0,
         )
         qs = dict(errors.request_GET(request))

tests/core/test_logging.py

@@ -1,11 +1,18 @@
+import io
 import json
 import logging
 import unittest
 from unittest import mock
 
+from dockerflow.logging import request_id_context
 from pyramid import testing
 
-from kinto.core import DEFAULT_SETTINGS, JsonLogFormatter, initialization
+from kinto.core import (
+    DEFAULT_SETTINGS,
+    JsonLogFormatter,
+    StreamHandlerWithRequestID,
+    initialization,
+)
 
 from .support import BaseWebTest
 
@@ -162,3 +169,20 @@ def test_logger_name(self):
         self.assertEqual(logged["Type"], "app.log")
         # See https://github.com/mozilla/mozilla-cloud-services-logger/issues/2
         self.assertEqual(logged["Fields"]["msg"], "coucou")
+
+
+class RequestIdFilter(BaseWebTest, unittest.TestCase):
+    def test_stream_logs_rid_field(self):
+        log_buffer = io.StringIO()  # In-memory log capture
+        stream_handler = StreamHandlerWithRequestID(log_buffer)
+        stream_handler.setFormatter(JsonLogFormatter())
+        logger = logging.getLogger(__name__)
+        logger.addHandler(stream_handler)
+
+        request_id_context.set("abc")  # As done in `kinto.core.initalization`.
+        logger.error("Some message")
+
+        captured = log_buffer.getvalue()
+
+        logged = json.loads(captured)
+        self.assertEqual(logged["Fields"]["rid"], "abc")

tests/test_configuration/test.ini

@@ -245,7 +245,7 @@ keys = root, kinto
 keys = console
 
 [formatters]
-keys = color
+keys = color, json
 
 [logger_root]
 level = INFO
@@ -258,10 +258,13 @@ qualname = kinto
 propagate = 0
 
 [handler_console]
-class = StreamHandler
+class = kinto.core.StreamHandlerWithRequestID
 args = (sys.stderr,)
 level = NOTSET
 formatter = color
 
 [formatter_color]
 class = logging_color_formatter.ColorFormatter
+
+[formatter_json]
+class = kinto.core.JsonLogFormatter