diff --git a/notifications_utils/logging.py b/notifications_utils/logging.py index 5ceadaa9..f188e7b7 100644 --- a/notifications_utils/logging.py +++ b/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()) diff --git a/notifications_utils/version.py b/notifications_utils/version.py index 3db1b9fe..5d724e8d 100644 --- a/notifications_utils/version.py +++ b/notifications_utils/version.py @@ -1 +1 @@ -__version__ = '2.2.5' +__version__ = '2.2.6' diff --git a/tests/test_logging.py b/tests/test_logging.py index 51f1dabe..798b51ef 100644 --- a/tests/test_logging.py +++ b/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."