#API-1123 - Update logger (#186)

notifications_utils/logging.py

@@ -4,6 +4,7 @@
 from itertools import product
 from pathlib import Path
 from time import monotonic
+from uuid import uuid4
 
 from flask import request, g
 from flask.ctx import has_request_context
@@ -13,10 +14,17 @@
 # The "application" and "requestId" fields are non-standard LogRecord attributes added below in the
 # "get_handler" function via filters.  If this causes errors, logging is misconfigured.
 #     https://docs.python.org/3.8/library/logging.html#logrecord-attributes
-LOG_FORMAT = '%(asctime)s %(application)s %(name)s %(levelname)s ' \
-             '%(requestId)s "%(message)s" [in %(pathname)s:%(lineno)d]'
+API_LOG_FORMAT = '%(asctime)s %(application)s %(levelname)s ' \
+                 '%(requestId)s "%(message)s" [in %(pathname)s:%(lineno)d]'
+CELERY_LOG_FORMAT = '%(asctime)s %(application)s %(processName)s %(levelname)s ' \
+                    '%(requestId)s "%(message)s" [in %(pathname)s:%(lineno)d]'
 TIME_FORMAT = '%Y-%m-%dT%H:%M:%S'
 
+_service_map = {
+    'app': 'notification-api',
+    'delivery': 'celery',
+}
+
 logger = logging.getLogger(__name__)
 
 
@@ -134,31 +142,37 @@ def get_handler(app):
     if app.debug:
         # Human readable stdout logs that omit static route 200 responses
         logging.getLogger('werkzeug').addFilter(is_200_static_log)
-        stream_handler.setFormatter(logging.Formatter(LOG_FORMAT, TIME_FORMAT))
-    else:
-        # Machine readable json to stdout
-        stream_handler.setFormatter(JsonFormatter(LOG_FORMAT, TIME_FORMAT))
+
+    stream_handler.setFormatter(
+        JsonFormatter(
+            CELERY_LOG_FORMAT if _service_map.get(app.name, API_LOG_FORMAT) == 'celery' else API_LOG_FORMAT,
+            TIME_FORMAT,
+        )
+    )
 
     return stream_handler
 
 
 class AppNameFilter(logging.Filter):
     def __init__(self, app_name):
-        self.app_name = app_name
+        self.service = _service_map.get(app_name, 'test')
 
     def filter(self, record):
-        record.application = self.app_name
+        record.application = self.service
         return record
 
 
 class RequestIdFilter(logging.Filter):
-    @property
-    def request_id(self):
-        if has_request_context() and hasattr(request, 'request_id'):
-            return request.request_id
-
-        return 'no-request-id'
-
     def filter(self, record):
-        record.requestId = self.request_id
+        # The else is for celery
+        if not getattr(record, 'requestId', ''):
+            record.requestId = RequestIdFilter._get_api_id() if has_request_context() else 'no-request-id'
         return record
+
+    @staticmethod
+    def _get_api_id() -> str:
+        """Generate a request_id.
+
+        g is a Flask global for this request. It's attached to the Flask instance and is only persisted for that request
+        """
+        return g.request_id if getattr(g, 'request_id', '') else str(uuid4())

notifications_utils/version.py

@@ -1 +1 @@
-__version__ = '2.2.5'
+__version__ = '2.2.6'

tests/test_logging.py

@@ -4,9 +4,10 @@
 import uuid
 
 import pytest
-from notifications_utils import logging
 from pythonjsonlogger.jsonlogger import JsonFormatter
 
+from notifications_utils import logging
+
 
 class App:
     def __init__(self, config=None, debug=False):
@@ -119,53 +120,56 @@ def test_should_build_statsd_line_without_service_id_or_time_taken():
     assert logging.build_statsd_line(extra_fields) == "method.endpoint.200"
 
 
-def test_get_handler_sets_up_logging_appropriately_with_debug(tmpdir, app):
+@pytest.mark.parametrize('app_name', ('notification-api', 'celery', None))
+def test_get_handler_sets_up_logging_appropriately_with_debug(tmpdir, app, app_name):
     del app.config['NOTIFY_LOG_PATH']
-
+    app.name = app_name
     app.debug = True
     handler = logging.get_handler(app)
 
-    assert type(handler) == builtin_logging.StreamHandler
-    assert type(handler.formatter) == builtin_logging.Formatter
+    assert type(handler) is builtin_logging.StreamHandler
+    assert type(handler.formatter) is JsonFormatter
     assert not (tmpdir / 'foo').exists()
 
-    application = app.config["NOTIFY_APP_NAME"]
     record = builtin_logging.makeLogRecord({
-        "application": application,
+        "application": app.name,
         "args": ("Cornelius", 42),
         "levelname": "debug",
         "lineno": 1999,
         "msg": "Hello, %s.  Line %d.",
-        "name": "the_name",
         "pathname": "the_path",
         "requestId": "id",
     })
-    message = handler.formatter.format(record)
-    assert message.endswith(f' {application} the_name debug id "Hello, Cornelius.  Line 42." [in the_path:1999]')
-
-
-def test_get_handler_sets_up_logging_appropriately_without_debug(app):
+    message = json.loads(handler.formatter.format(record))
+    assert message['application'] == app_name
+    assert message['levelname'] == 'debug'
+    assert message['requestId'] == 'id'
+    assert message['message'] == 'Hello, Cornelius.  Line 42.'
+    assert message['pathname'] == 'the_path'
+    assert message['lineno'] == 1999
+
+
+@pytest.mark.parametrize('app_name', ('notification-api', 'celery', None))
+def test_get_handler_sets_up_logging_appropriately_without_debug(app, app_name):
+    app.name = app_name
     app.debug = False
     handler = logging.get_handler(app)
-    assert type(handler) == builtin_logging.StreamHandler
-    assert type(handler.formatter) == JsonFormatter
+    assert type(handler) is builtin_logging.StreamHandler
+    assert type(handler.formatter) is JsonFormatter
 
-    application = app.config["NOTIFY_APP_NAME"]
     record = builtin_logging.makeLogRecord({
-        "application": application,
+        "application": app.name,
         "args": ("Cornelius", 42),
         "levelname": "debug",
         "lineno": 1999,
         "msg": "Hello, %s.  Line %d.",
-        "name": "the_name",
         "pathname": "the_path",
         "requestId": "id",
     })
     message = handler.formatter.format(record)
     message_dict = json.loads(message)
     assert "asctime" in message_dict
-    assert message_dict["application"] == application
-    assert message_dict["name"] == "the_name"
+    assert message_dict["application"] == app_name or 'test'
     assert message_dict["levelname"] == "debug"
     assert message_dict["requestId"] == "id"
     assert message_dict["message"] == "Hello, Cornelius.  Line 42."