Merge pull request #420 from alphagov/ris-log-request-pid

request logging: include pid, "thread ident" and flask "endpoint"

dmutils/__init__.py

@@ -4,4 +4,4 @@
 import flask_featureflags  # noqa
 
 
-__version__ = '40.1.0'
+__version__ = '40.2.0'

dmutils/logging.py

@@ -2,6 +2,8 @@
 import logging
 import sys
 import re
+from os import getpid
+from threading import get_ident as get_thread_ident
 
 from flask import request, current_app
 from flask.ctx import has_request_context
@@ -37,7 +39,16 @@ def after_request(response):
             extra={
                 'method': request.method,
                 'url': request.url,
-                'status': response.status_code
+                'endpoint': request.endpoint,
+                'status': response.status_code,
+                # pid and thread ident are both available on LogRecord by default, as `process` and `thread`
+                # respectively but I don't see a straightforward way of selectively including them only in certain
+                # log messages - they are designed to be included when the formatter is being configured. This is why
+                # I'm manually grabbing them and putting them in as `extra` here, avoiding the existing parameter names
+                # to prevent LogRecord from complaining
+                '_process': getpid(),
+                # stringifying this as it could potentially be a long that json is unable to represent accurately
+                '_thread': str(get_thread_ident()),
             })
         return response
 

tests/test_logging.py

@@ -11,7 +11,7 @@
 
 from flask import request
 
-from dmtestutils.comparisons import AnySupersetOf
+from dmtestutils.comparisons import AnySupersetOf, RestrictedAny
 
 from dmutils.logging import init_app, RequestExtraContextFilter, JSONFormatter, CustomLogFormatter
 from dmutils.logging import LOG_FORMAT, get_json_log_format
@@ -93,7 +93,14 @@ def test_app_after_request_logs_responses_with_info_level(app):
         logger.log.assert_called_once_with(
             logging.INFO,
             '{method} {url} {status}',
-            extra={'url': u'http://localhost/', 'status': 404, 'method': 'GET'}
+            extra={
+                "url": "http://localhost/",
+                "status": 404,
+                "method": "GET",
+                "endpoint": None,
+                "_process": RestrictedAny(lambda value: isinstance(value, int)),
+                "_thread": RestrictedAny(lambda value: isinstance(value, (str, bytes,))),
+            },
         )
 
 
@@ -109,7 +116,14 @@ def error_route():
         logger.log.assert_called_once_with(
             logging.ERROR,
             '{method} {url} {status}',
-            extra={'url': u'http://localhost/', 'status': 500, 'method': 'GET'}
+            extra={
+                "url": "http://localhost/",
+                "status": 500,
+                "method": "GET",
+                "endpoint": "error_route",
+                "_process": RestrictedAny(lambda value: isinstance(value, int)),
+                "_thread": RestrictedAny(lambda value: isinstance(value, (str, bytes,))),
+            },
         )