From c56c7d61e36eebd20a74ddc8686a755d9faa90d3 Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Tue, 23 Apr 2024 12:07:46 -0400 Subject: [PATCH 1/8] Add MozlogHandler that integrates renamed formatter --- docs/django.rst | 18 +++++-------- docs/fastapi.rst | 15 +++-------- docs/flask.rst | 15 +++-------- docs/logging.rst | 15 +++-------- docs/sanic.rst | 17 ++++-------- src/dockerflow/fastapi/middleware.py | 6 ++--- src/dockerflow/logging.py | 39 +++++++++++++++++++--------- tests/core/test_logging.py | 28 +++++++++++--------- tests/django/settings.py | 7 ++--- tests/fastapi/test_fastapi.py | 4 +-- 10 files changed, 72 insertions(+), 92 deletions(-) diff --git a/docs/django.rst b/docs/django.rst index 3a52a82..1bc1245 100644 --- a/docs/django.rst +++ b/docs/django.rst @@ -61,8 +61,8 @@ To install ``python-dockerflow``'s Django support please follow these steps: ] #. :ref:`Configure logging ` to use the - :class:`~dockerflow.logging.JsonLogFormatter` - logging formatter for the ``request.summary`` logger (you may have to + :class:`~dockerflow.logging.MozlogHandler` + logging handler for the ``request.summary`` logger (you may have to extend your existing logging configuration!). .. _`Kubernetes liveness checks`: https://kubernetes.io/docs/tasks/configure-pod-container/configure-liveness-readiness-startup-probes/ @@ -405,20 +405,15 @@ spec: Logging ------- -Dockerflow provides a :class:`~dockerflow.logging.JsonLogFormatter` Python -logging formatter class. +Dockerflow provides a :class:`~dockerflow.logging.MozlogHandler` Python +logging handler class. This handler formats logs according to the Mozlog schema +and emits them to stdout. To use it, put something like this in your Django ``settings`` file and configure **at least** the ``request.summary`` logger that way:: LOGGING = { 'version': 1, - 'formatters': { - 'json': { - '()': 'dockerflow.logging.JsonLogFormatter', - 'logger_name': 'myproject' - } - }, 'filters': { 'request_id': { '()': 'dockerflow.logging.RequestIdLogFilter', @@ -427,8 +422,7 @@ configure **at least** the ``request.summary`` logger that way:: 'handlers': { 'console': { 'level': 'DEBUG', - 'class': 'logging.StreamHandler', - 'formatter': 'json', + 'class': 'dockerflow.logging.MozlogHandler', 'filters': ['request_id'] }, }, diff --git a/docs/fastapi.rst b/docs/fastapi.rst index fe2e734..fc010a4 100644 --- a/docs/fastapi.rst +++ b/docs/fastapi.rst @@ -54,7 +54,7 @@ To install ``python-dockerflow``'s FastAPI support please follow these steps: .. seealso:: :ref:`fastapi-versions` for more information -#. Configure logging to use the ``JsonLogFormatter`` logging formatter for the +#. Configure logging to use the ``MozlogHandler`` logging handler for the ``request.summary`` logger (you may have to extend your existing logging configuration), see :ref:`fastapi-logging` for more information. @@ -280,8 +280,8 @@ spec: Logging ------- -Dockerflow provides a :class:`~dockerflow.logging.JsonLogFormatter` Python -logging formatter class. +Dockerflow provides a :class:`~dockerflow.logging.Mozlog` Python +logging handler class. To use it, put something like this **BEFORE** your FastAPI app is initialized for at least the ``request.summary`` logger: @@ -292,12 +292,6 @@ for at least the ``request.summary`` logger: dictConfig({ 'version': 1, - 'formatters': { - 'json': { - '()': 'dockerflow.logging.JsonLogFormatter', - 'logger_name': 'myproject' - } - }, 'filters': { 'request_id': { '()': 'dockerflow.logging.RequestIdLogFilter', @@ -306,9 +300,8 @@ for at least the ``request.summary`` logger: 'handlers': { 'console': { 'level': 'DEBUG', - 'class': 'logging.StreamHandler', + 'class': 'dockerflow.logging.MozlogHandler', 'filters': ['request_id'], - 'formatter': 'json' }, }, 'loggers': { diff --git a/docs/flask.rst b/docs/flask.rst index c36d2c4..6670cd7 100644 --- a/docs/flask.rst +++ b/docs/flask.rst @@ -56,7 +56,7 @@ To install ``python-dockerflow``'s Flask support please follow these steps: .. seealso:: :ref:`flask-versions` for more information -#. Configure logging to use the ``JsonLogFormatter`` logging formatter for the +#. Configure logging to use the ``MozlogHandler`` logging handler for the ``request.summary`` logger (you may have to extend your existing logging configuration), see :ref:`flask-logging` for more information. @@ -425,8 +425,8 @@ spec: Logging ------- -Dockerflow provides a :class:`~dockerflow.logging.JsonLogFormatter` Python -logging formatter class. +Dockerflow provides a :class:`~dockerflow.logging.MozlogHandler` Python +logging handler class. To use it, put something like this **BEFORE** your Flask app is initialized for at least the ``request.summary`` logger:: @@ -435,12 +435,6 @@ for at least the ``request.summary`` logger:: dictConfig({ 'version': 1, - 'formatters': { - 'json': { - '()': 'dockerflow.logging.JsonLogFormatter', - 'logger_name': 'myproject' - } - }, 'filters': { 'request_id': { '()': 'dockerflow.logging.RequestIdLogFilter', @@ -449,8 +443,7 @@ for at least the ``request.summary`` logger:: 'handlers': { 'console': { 'level': 'DEBUG', - 'class': 'logging.StreamHandler', - 'formatter': 'json', + 'class': 'dockerflow.logging.MozlogHandler', 'filters': ['request_id'] }, }, diff --git a/docs/logging.rst b/docs/logging.rst index d1a8dea..cd5f41d 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -3,8 +3,8 @@ Logging ======= -python-dockerflow provides a :class:`~dockerflow.logging.JsonLogFormatter` -Python logging formatter that produces messages following the JSON schema +python-dockerflow provides a :class:`~dockerflow.logging.MozlogHandler` +Python logging handler that produces messages following the JSON schema for a common application logging format defined by the illustrious Mozilla Cloud Services group. @@ -33,12 +33,6 @@ this:: cfg = { 'version': 1, - 'formatters': { - 'json': { - '()': 'dockerflow.logging.JsonLogFormatter', - 'logger_name': 'myproject' - } - }, 'filters': { 'request_id': { '()': 'dockerflow.logging.RequestIdLogFilter', @@ -47,8 +41,7 @@ this:: 'handlers': { 'console': { 'level': 'DEBUG', - 'class': 'logging.StreamHandler', - 'formatter': 'json', + 'class': 'dockerflow.logging.MozlogHandler', 'filters': ['request_id'] }, }, @@ -109,7 +102,7 @@ thing as the dictionary based configuratio above: filters = request_id [formatter_json] - class = dockerflow.logging.JsonLogFormatter + class = dockerflow.logging.MozlogFormatter Then load the ini file using the :mod:`logging` module function :func:`logging.config.fileConfig`: diff --git a/docs/sanic.rst b/docs/sanic.rst index 08a97b5..a36667b 100644 --- a/docs/sanic.rst +++ b/docs/sanic.rst @@ -53,7 +53,7 @@ To install ``python-dockerflow``'s Sanic support please follow these steps: .. seealso:: :ref:`sanic-versions` for more information -#. Configure logging to use the ``JsonLogFormatter`` logging formatter for the +#. Configure logging to use the ``MozlogHandler`` logging handler for the ``request.summary`` logger (you may have to extend your existing logging configuration), see :ref:`sanic-logging` for more information. @@ -405,8 +405,8 @@ spec: Logging ------- -Dockerflow provides a :class:`~dockerflow.logging.JsonLogFormatter` Python -logging formatter class. +Dockerflow provides a :class:`~dockerflow.logging.MozlogFormatter` Python +logging handler class. To use it, pass something like this to your Sanic app when it is initialized for at least the ``request.summary`` logger:: @@ -415,12 +415,6 @@ for at least the ``request.summary`` logger:: log_config = { 'version': 1, - 'formatters': { - 'json': { - '()': 'dockerflow.logging.JsonLogFormatter', - 'logger_name': 'myproject' - } - }, 'filters': { 'request_id': { '()': 'dockerflow.logging.RequestIdLogFilter', @@ -429,8 +423,7 @@ for at least the ``request.summary`` logger:: 'handlers': { 'console': { 'level': 'DEBUG', - 'class': 'logging.StreamHandler', - 'formatter': 'json', + 'class': 'dockerflow.logging.MozlogHandler', 'filters': ['request_id'] }, }, @@ -440,7 +433,7 @@ for at least the ``request.summary`` logger:: 'level': 'DEBUG', }, } - }) + } sanic = Sanic(__name__, log_config=log) diff --git a/src/dockerflow/fastapi/middleware.py b/src/dockerflow/fastapi/middleware.py index 02a844e..e16c07a 100644 --- a/src/dockerflow/fastapi/middleware.py +++ b/src/dockerflow/fastapi/middleware.py @@ -1,7 +1,6 @@ from __future__ import annotations import logging -import sys import time import urllib from typing import Any, Dict @@ -14,7 +13,7 @@ HTTPScope, ) -from ..logging import JsonLogFormatter, get_or_generate_request_id, request_id_context +from ..logging import MozlogHandler, get_or_generate_request_id, request_id_context class RequestIdMiddleware: @@ -57,9 +56,8 @@ def __init__( if logger is None: logger = logging.getLogger("request.summary") logger.setLevel(logging.INFO) - handler = logging.StreamHandler(sys.stdout) + handler = MozlogHandler() handler.setLevel(logging.INFO) - handler.setFormatter(JsonLogFormatter()) logger.addHandler(handler) self.logger = logger diff --git a/src/dockerflow/logging.py b/src/dockerflow/logging.py index 74e7f5b..d81c0c1 100644 --- a/src/dockerflow/logging.py +++ b/src/dockerflow/logging.py @@ -9,17 +9,31 @@ import sys import traceback import uuid +import warnings from contextvars import ContextVar from typing import ClassVar, Optional +class MozlogHandler(logging.StreamHandler): + def __init__(self, stream=None, name="Dockerflow"): + if stream is None: + stream = sys.stdout + super().__init__(stream=stream) + self.logger_name = name + self.setFormatter(MozlogFormatter()) + + def emit(self, record): + record.logger_name = self.logger_name + super().emit(record) + + class SafeJSONEncoder(json.JSONEncoder): def default(self, o): return repr(o) -class JsonLogFormatter(logging.Formatter): - """Log formatter that outputs machine-readable json. +class MozlogFormatter(logging.Formatter): + """Log formatter that outputs json structured according to the Mozlog schema. This log formatter outputs JSON format messages that are compatible with Mozilla's standard heka-based log aggregation infrastructure. @@ -75,15 +89,7 @@ class JsonLogFormatter(logging.Formatter): ) def __init__(self, fmt=None, datefmt=None, style="%", logger_name="Dockerflow"): - parent_init = logging.Formatter.__init__ - # The style argument was added in Python 3.1 and since - # the logging configuration via config (ini) files uses - # positional arguments we have to do a version check here - # to decide whether to pass the style argument or not. - if sys.version_info[:2] < (3, 1): - parent_init(self, fmt, datefmt) - else: - parent_init(self, fmt=fmt, datefmt=datefmt, style=style) + super().__init__(fmt=fmt, datefmt=datefmt, style=style) self.logger_name = logger_name self.hostname = socket.gethostname() @@ -104,7 +110,7 @@ def convert_record(self, record): out = { "Timestamp": int(record.created * 1e9), "Type": record.name, - "Logger": self.logger_name, + "Logger": getattr(record, "logger_name", self.logger_name), "Hostname": self.hostname, "EnvVersion": self.LOGGING_FORMAT_VERSION, "Severity": self.SYSLOG_LEVEL_MAP.get( @@ -143,6 +149,15 @@ def format(self, record): return json.dumps(out, cls=SafeJSONEncoder) +class JsonLogFormatter(MozlogFormatter): + def __init__(self, *args, **kwargs): + warnings.warn( + "JsonLogFormatter has been deprecated. Use MozlogFormatter instead", + DeprecationWarning, + ) + super().__init__(*args, **kwargs) + + def safer_format_traceback(exc_typ, exc_val, exc_tb): """Format an exception traceback into safer string. We don't want to let users write arbitrary data into our logfiles, diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index 54d2b71..30a43e2 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -11,7 +11,7 @@ import jsonschema import pytest -from dockerflow.logging import JsonLogFormatter +from dockerflow.logging import JsonLogFormatter, MozlogFormatter, MozlogHandler @pytest.fixture() @@ -21,12 +21,13 @@ def _reset_logging(): logger_name = "tests" -formatter = JsonLogFormatter(logger_name=logger_name) +handler = MozlogHandler(name=logger_name) +formatter = MozlogFormatter(logger_name=logger_name) def assert_records(records): assert len(records) == 1 - details = json.loads(formatter.format(records[0])) + details = json.loads(handler.format(records[0])) jsonschema.validate(details, JSON_LOGGING_SCHEMA) return details @@ -42,29 +43,25 @@ def test_initialization_from_ini(caplog, tmpdir): keys = console [formatters] - keys = json + keys = [logger_root] level = INFO handlers = console [handler_console] - class = StreamHandler level = DEBUG - args = (sys.stderr,) - formatter = json - - [formatter_json] - class = dockerflow.logging.JsonLogFormatter + class = dockerflow.logging.MozlogHandler + args = (sys.stdout, 'tests') """ ) ini_file = tmpdir.join("logging.ini") ini_file.write(ini_content) logging.config.fileConfig(str(ini_file)) - logging.info("I am logging in mozlog format now! woo hoo!") logger = logging.getLogger() assert len(logger.handlers) > 0 - assert logger.handlers[0].formatter.logger_name == "Dockerflow" + assert logger.handlers[0].logger_name == "tests" + assert isinstance(logger.handlers[0].formatter, MozlogFormatter) def test_basic_operation(caplog): @@ -156,6 +153,13 @@ def test_ignore_json_message(caplog): assert not formatter.is_value_jsonlike('"spam": "eggs"}') +def test_JsonLogFormatter_emits_warning(caplog): + """Initializing a JsonLogFormatter should emit a deprecation warning""" + + with pytest.deprecated_call(): + JsonLogFormatter(logger_name="deprecated") + + # https://mana.mozilla.org/wiki/pages/viewpage.action?pageId=42895640 JSON_LOGGING_SCHEMA = json.loads( """ diff --git a/tests/django/settings.py b/tests/django/settings.py index 55e80c7..34c8a8f 100644 --- a/tests/django/settings.py +++ b/tests/django/settings.py @@ -54,14 +54,11 @@ LOGGING = { "version": 1, - "formatters": { - "json": {"()": "dockerflow.logging.JsonLogFormatter", "logger_name": "tests"} - }, "handlers": { "console": { "level": "DEBUG", - "class": "logging.StreamHandler", - "formatter": "json", + "class": "dockerflow.logging.MozlogHandler", + "name": "tests", } }, "loggers": {"request.summary": {"handlers": ["console"], "level": "DEBUG"}}, diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 4ec97de..971d1e4 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -14,7 +14,7 @@ MozlogRequestSummaryLogger, RequestIdMiddleware, ) -from dockerflow.logging import JsonLogFormatter, RequestIdLogFilter +from dockerflow.logging import MozlogFormatter, RequestIdLogFilter def create_app(): @@ -109,7 +109,7 @@ def test_mozlog_without_correlation_id_middleware(client, caplog): def test_request_id_passed_to_all_log_messages(caplog): caplog.handler.addFilter(RequestIdLogFilter()) - caplog.handler.setFormatter(JsonLogFormatter()) + caplog.handler.setFormatter(MozlogFormatter()) app = create_app() From d7ca314b09fb83c03b6594c32a89e10af7d6d078 Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 09:46:30 -0400 Subject: [PATCH 2/8] Remove unused fixture from test --- tests/core/test_logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index 30a43e2..fbe5db3 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -33,7 +33,7 @@ def assert_records(records): @pytest.mark.usefixtures("_reset_logging") -def test_initialization_from_ini(caplog, tmpdir): +def test_initialization_from_ini(tmpdir): ini_content = textwrap.dedent( """ [loggers] From 4fbb011cbd1f115be9b1e395a6fb9ef139d8529e Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 11:01:06 -0400 Subject: [PATCH 3/8] Slightly refactor logging test setup - Pass handler and formatter as fixtures to tests - Reset logging after each test --- tests/core/test_logging.py | 39 +++++++++++++++++++++----------------- 1 file changed, 22 insertions(+), 17 deletions(-) diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index fbe5db3..c1178ff 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -19,20 +19,26 @@ def _reset_logging(): logging.shutdown() reload(logging) +pytest.mark.usefixtures = _reset_logging logger_name = "tests" -handler = MozlogHandler(name=logger_name) -formatter = MozlogFormatter(logger_name=logger_name) +@pytest.fixture() +def handler(): + return MozlogHandler(name=logger_name) + +@pytest.fixture() +def formatter(): + return MozlogFormatter(logger_name=logger_name) -def assert_records(records): + +def assert_records(handler, records): assert len(records) == 1 details = json.loads(handler.format(records[0])) jsonschema.validate(details, JSON_LOGGING_SCHEMA) return details -@pytest.mark.usefixtures("_reset_logging") def test_initialization_from_ini(tmpdir): ini_content = textwrap.dedent( """ @@ -64,12 +70,12 @@ class = dockerflow.logging.MozlogHandler assert isinstance(logger.handlers[0].formatter, MozlogFormatter) -def test_basic_operation(caplog): +def test_basic_operation(caplog, handler, formatter): """Ensure log formatter contains all the expected fields and values""" message_text = "simple test" caplog.set_level(logging.DEBUG) logging.debug(message_text) - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert details == formatter.convert_record(caplog.records[0]) assert "Timestamp" in details @@ -81,12 +87,11 @@ def test_basic_operation(caplog): assert details["EnvVersion"] == formatter.LOGGING_FORMAT_VERSION assert details["Fields"]["msg"] == message_text - -def test_custom_paramters(caplog): +def test_custom_paramters(caplog, handler, formatter): """Ensure log formatter can handle custom parameters""" logger = logging.getLogger("tests.test_logging") logger.warning("custom test %s", "one", extra={"more": "stuff"}) - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert details == formatter.convert_record(caplog.records[0]) assert details["Type"] == "tests.test_logging" @@ -95,13 +100,13 @@ def test_custom_paramters(caplog): assert details["Fields"]["more"] == "stuff" -def test_non_json_serializable_parameters_are_converted(caplog): +def test_non_json_serializable_parameters_are_converted(caplog, handler): """Ensure log formatter doesn't fail with non json-serializable params.""" foo = object() foo_repr = repr(foo) logger = logging.getLogger("tests.test_logging") logger.warning("custom test %s", "hello", extra={"foo": foo}) - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert details["Type"] == "tests.test_logging" assert details["Severity"] == 4 @@ -109,13 +114,13 @@ def test_non_json_serializable_parameters_are_converted(caplog): assert details["Fields"]["foo"] == foo_repr -def test_logging_error_tracebacks(caplog): +def test_logging_error_tracebacks(caplog, handler): """Ensure log formatter includes exception traceback information""" try: raise ValueError("\n") except Exception: logging.exception("there was an error") - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -124,14 +129,14 @@ def test_logging_error_tracebacks(caplog): assert "ValueError" in details["Fields"]["traceback"] -def test_logging_exc_info_false(caplog): +def test_logging_exc_info_false(caplog, handler): """Ensure log formatter does not fail and does not include exception traceback information when exc_info is False""" try: raise ValueError("\n") except Exception: logging.exception("there was an error", exc_info=False) - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -139,13 +144,13 @@ def test_logging_exc_info_false(caplog): assert "traceback" not in details["Fields"] -def test_ignore_json_message(caplog): +def test_ignore_json_message(caplog, handler, formatter): """Ensure log formatter ignores messages that are JSON already""" try: raise ValueError("\n") except Exception: logging.exception(json.dumps({"spam": "eggs"})) - details = assert_records(caplog.records) + details = assert_records(handler, caplog.records) assert "msg" not in details["Fields"] assert formatter.is_value_jsonlike('{"spam": "eggs"}') From 47c008a782b95f40f89febc9a7ca526b4abc40d8 Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 11:02:04 -0400 Subject: [PATCH 4/8] Add tests to assert how `logger_name` is attached to records --- tests/core/test_logging.py | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+) diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index c1178ff..bef33b7 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -69,6 +69,37 @@ class = dockerflow.logging.MozlogHandler assert logger.handlers[0].logger_name == "tests" assert isinstance(logger.handlers[0].formatter, MozlogFormatter) +def test_set_logger_name_through_handler(caplog): + handler = MozlogHandler(name="logger_name_handler") + logger = logging.getLogger("test") + logger.addHandler(handler) + logger.warning("hey") + [record] = caplog.records + record.logger_name = "logger_name_handler" + +def test_set_logger_name_through_formatter(caplog): + handler = logging.StreamHandler() + formatter = MozlogFormatter(logger_name="logger_name_formatter") + handler.setFormatter(formatter) + + logger = logging.getLogger("test") + logger.addHandler(handler) + + logger.warning("hey") + [record] = caplog.records + record.logger_name = "logger_name_formatter" + +def test_handler_precedence_logger_name(caplog): + handler = MozlogHandler(name="logger_name_handler") + formatter = MozlogFormatter(logger_name="logger_name_formatter") + handler.setFormatter(formatter) + + logger = logging.getLogger("test") + logger.addHandler(handler) + + logger.warning("hey") + [record] = caplog.records + record.logger_name = "logger_name_handler" def test_basic_operation(caplog, handler, formatter): """Ensure log formatter contains all the expected fields and values""" From 237fb0212dbd751fe89097e4a004fd3f1c09b42e Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 11:03:21 -0400 Subject: [PATCH 5/8] Ruff fixes --- tests/core/test_logging.py | 8 ++++++++ tests/fastapi/test_fastapi.py | 2 ++ 2 files changed, 10 insertions(+) diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index bef33b7..d5540df 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -19,14 +19,17 @@ def _reset_logging(): logging.shutdown() reload(logging) + pytest.mark.usefixtures = _reset_logging logger_name = "tests" + @pytest.fixture() def handler(): return MozlogHandler(name=logger_name) + @pytest.fixture() def formatter(): return MozlogFormatter(logger_name=logger_name) @@ -69,6 +72,7 @@ class = dockerflow.logging.MozlogHandler assert logger.handlers[0].logger_name == "tests" assert isinstance(logger.handlers[0].formatter, MozlogFormatter) + def test_set_logger_name_through_handler(caplog): handler = MozlogHandler(name="logger_name_handler") logger = logging.getLogger("test") @@ -77,6 +81,7 @@ def test_set_logger_name_through_handler(caplog): [record] = caplog.records record.logger_name = "logger_name_handler" + def test_set_logger_name_through_formatter(caplog): handler = logging.StreamHandler() formatter = MozlogFormatter(logger_name="logger_name_formatter") @@ -89,6 +94,7 @@ def test_set_logger_name_through_formatter(caplog): [record] = caplog.records record.logger_name = "logger_name_formatter" + def test_handler_precedence_logger_name(caplog): handler = MozlogHandler(name="logger_name_handler") formatter = MozlogFormatter(logger_name="logger_name_formatter") @@ -101,6 +107,7 @@ def test_handler_precedence_logger_name(caplog): [record] = caplog.records record.logger_name = "logger_name_handler" + def test_basic_operation(caplog, handler, formatter): """Ensure log formatter contains all the expected fields and values""" message_text = "simple test" @@ -118,6 +125,7 @@ def test_basic_operation(caplog, handler, formatter): assert details["EnvVersion"] == formatter.LOGGING_FORMAT_VERSION assert details["Fields"]["msg"] == message_text + def test_custom_paramters(caplog, handler, formatter): """Ensure log formatter can handle custom parameters""" logger = logging.getLogger("tests.test_logging") diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 8453c20..9a5b98a 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -194,6 +194,7 @@ def return_error(): }, } + def test_heartbeat_sync(client): @checks.register def sync_ok(): @@ -226,6 +227,7 @@ def test_heartbeat_mixed_sync(client): @checks.register def sync_ok(): return [] + @checks.register async def async_ok(): return [] From 09757e3b88fb9a9f84b95e02a4830228d290afa7 Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 11:46:04 -0400 Subject: [PATCH 6/8] Use formatter in `assert_records` assertions --- tests/core/test_logging.py | 40 ++++++++++++++++---------------------- 1 file changed, 17 insertions(+), 23 deletions(-) diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index d5540df..f927ca3 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -20,24 +20,18 @@ def _reset_logging(): reload(logging) -pytest.mark.usefixtures = _reset_logging +pytestmark = pytest.mark.usefixtures("_reset_logging") logger_name = "tests" - -@pytest.fixture() -def handler(): - return MozlogHandler(name=logger_name) - - @pytest.fixture() def formatter(): return MozlogFormatter(logger_name=logger_name) -def assert_records(handler, records): +def assert_records(formatter, records): assert len(records) == 1 - details = json.loads(handler.format(records[0])) + details = json.loads(formatter.format(records[0])) jsonschema.validate(details, JSON_LOGGING_SCHEMA) return details @@ -69,10 +63,9 @@ class = dockerflow.logging.MozlogHandler logging.config.fileConfig(str(ini_file)) logger = logging.getLogger() assert len(logger.handlers) > 0 - assert logger.handlers[0].logger_name == "tests" + assert logger.handlers[0].logger_name == logger_name assert isinstance(logger.handlers[0].formatter, MozlogFormatter) - def test_set_logger_name_through_handler(caplog): handler = MozlogHandler(name="logger_name_handler") logger = logging.getLogger("test") @@ -108,12 +101,13 @@ def test_handler_precedence_logger_name(caplog): record.logger_name = "logger_name_handler" -def test_basic_operation(caplog, handler, formatter): +def test_basic_operation(caplog, formatter): """Ensure log formatter contains all the expected fields and values""" message_text = "simple test" caplog.set_level(logging.DEBUG) logging.debug(message_text) - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) + assert details == formatter.convert_record(caplog.records[0]) assert "Timestamp" in details @@ -126,11 +120,11 @@ def test_basic_operation(caplog, handler, formatter): assert details["Fields"]["msg"] == message_text -def test_custom_paramters(caplog, handler, formatter): +def test_custom_paramters(caplog, formatter): """Ensure log formatter can handle custom parameters""" logger = logging.getLogger("tests.test_logging") logger.warning("custom test %s", "one", extra={"more": "stuff"}) - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) assert details == formatter.convert_record(caplog.records[0]) assert details["Type"] == "tests.test_logging" @@ -139,13 +133,13 @@ def test_custom_paramters(caplog, handler, formatter): assert details["Fields"]["more"] == "stuff" -def test_non_json_serializable_parameters_are_converted(caplog, handler): +def test_non_json_serializable_parameters_are_converted(caplog, formatter): """Ensure log formatter doesn't fail with non json-serializable params.""" foo = object() foo_repr = repr(foo) logger = logging.getLogger("tests.test_logging") logger.warning("custom test %s", "hello", extra={"foo": foo}) - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) assert details["Type"] == "tests.test_logging" assert details["Severity"] == 4 @@ -153,13 +147,13 @@ def test_non_json_serializable_parameters_are_converted(caplog, handler): assert details["Fields"]["foo"] == foo_repr -def test_logging_error_tracebacks(caplog, handler): +def test_logging_error_tracebacks(caplog, formatter): """Ensure log formatter includes exception traceback information""" try: raise ValueError("\n") except Exception: logging.exception("there was an error") - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -168,14 +162,14 @@ def test_logging_error_tracebacks(caplog, handler): assert "ValueError" in details["Fields"]["traceback"] -def test_logging_exc_info_false(caplog, handler): +def test_logging_exc_info_false(caplog, formatter): """Ensure log formatter does not fail and does not include exception traceback information when exc_info is False""" try: raise ValueError("\n") except Exception: logging.exception("there was an error", exc_info=False) - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -183,13 +177,13 @@ def test_logging_exc_info_false(caplog, handler): assert "traceback" not in details["Fields"] -def test_ignore_json_message(caplog, handler, formatter): +def test_ignore_json_message(caplog, formatter): """Ensure log formatter ignores messages that are JSON already""" try: raise ValueError("\n") except Exception: logging.exception(json.dumps({"spam": "eggs"})) - details = assert_records(handler, caplog.records) + details = assert_records(formatter, caplog.records) assert "msg" not in details["Fields"] assert formatter.is_value_jsonlike('{"spam": "eggs"}') From 96eab99042b46ef7acfe15ae894ea8db418dac68 Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 12:33:39 -0400 Subject: [PATCH 7/8] Set caplog to INFO in fastapi rid test --- tests/fastapi/test_fastapi.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 9a5b98a..53709a8 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -108,6 +108,7 @@ def test_mozlog_without_correlation_id_middleware(client, caplog): def test_request_id_passed_to_all_log_messages(caplog): + caplog.set_level(logging.INFO) caplog.handler.addFilter(RequestIdLogFilter()) caplog.handler.setFormatter(MozlogFormatter()) From 2b6907032b475166cc164db5e0fb3cb1f54180ec Mon Sep 17 00:00:00 2001 From: Graham Beckley Date: Thu, 25 Apr 2024 13:38:05 -0400 Subject: [PATCH 8/8] Make assertions about LogRecord and formatted output --- src/dockerflow/logging.py | 3 ++- tests/core/test_logging.py | 33 ++++++++++++++++++++++++--------- 2 files changed, 26 insertions(+), 10 deletions(-) diff --git a/src/dockerflow/logging.py b/src/dockerflow/logging.py index d81c0c1..337a194 100644 --- a/src/dockerflow/logging.py +++ b/src/dockerflow/logging.py @@ -72,9 +72,10 @@ class MozlogFormatter(logging.Formatter): "levelname", "levelno", "lineno", + "logger_name", + "message", "module", "msecs", - "message", "msg", "name", "pathname", diff --git a/tests/core/test_logging.py b/tests/core/test_logging.py index f927ca3..6e39ff6 100644 --- a/tests/core/test_logging.py +++ b/tests/core/test_logging.py @@ -22,11 +22,12 @@ def _reset_logging(): pytestmark = pytest.mark.usefixtures("_reset_logging") -logger_name = "tests" +LOGGER_NAME = "tests" + @pytest.fixture() def formatter(): - return MozlogFormatter(logger_name=logger_name) + return MozlogFormatter(logger_name=LOGGER_NAME) def assert_records(formatter, records): @@ -63,21 +64,28 @@ class = dockerflow.logging.MozlogHandler logging.config.fileConfig(str(ini_file)) logger = logging.getLogger() assert len(logger.handlers) > 0 - assert logger.handlers[0].logger_name == logger_name + assert logger.handlers[0].logger_name == LOGGER_NAME assert isinstance(logger.handlers[0].formatter, MozlogFormatter) + def test_set_logger_name_through_handler(caplog): + logger_name = "logger_name_handler" handler = MozlogHandler(name="logger_name_handler") logger = logging.getLogger("test") logger.addHandler(handler) + logger.warning("hey") [record] = caplog.records - record.logger_name = "logger_name_handler" + + assert record.logger_name == logger_name + formatted_record = json.loads(handler.format(record)) + assert formatted_record["Logger"] == logger_name def test_set_logger_name_through_formatter(caplog): + logger_name = "logger_name_formatter" handler = logging.StreamHandler() - formatter = MozlogFormatter(logger_name="logger_name_formatter") + formatter = MozlogFormatter(logger_name=logger_name) handler.setFormatter(formatter) logger = logging.getLogger("test") @@ -85,11 +93,15 @@ def test_set_logger_name_through_formatter(caplog): logger.warning("hey") [record] = caplog.records - record.logger_name = "logger_name_formatter" + + assert not hasattr(record, "logger_name") + formatted_record = json.loads(handler.format(record)) + assert formatted_record["Logger"] == logger_name def test_handler_precedence_logger_name(caplog): - handler = MozlogHandler(name="logger_name_handler") + logger_name = "logger_name_handler" + handler = MozlogHandler(name=logger_name) formatter = MozlogFormatter(logger_name="logger_name_formatter") handler.setFormatter(formatter) @@ -98,7 +110,10 @@ def test_handler_precedence_logger_name(caplog): logger.warning("hey") [record] = caplog.records - record.logger_name = "logger_name_handler" + + assert record.logger_name == logger_name + formatted_record = json.loads(handler.format(record)) + assert formatted_record["Logger"] == logger_name def test_basic_operation(caplog, formatter): @@ -115,7 +130,7 @@ def test_basic_operation(caplog, formatter): assert details["Severity"] == 7 assert details["Type"] == "root" assert details["Pid"] == os.getpid() - assert details["Logger"] == logger_name + assert details["Logger"] == LOGGER_NAME assert details["EnvVersion"] == formatter.LOGGING_FORMAT_VERSION assert details["Fields"]["msg"] == message_text