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..337a194 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. @@ -58,9 +72,10 @@ class JsonLogFormatter(logging.Formatter): "levelname", "levelno", "lineno", + "logger_name", + "message", "module", "msecs", - "message", "msg", "name", "pathname", @@ -75,15 +90,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 +111,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 +150,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..6e39ff6 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() @@ -20,19 +20,24 @@ def _reset_logging(): reload(logging) -logger_name = "tests" -formatter = JsonLogFormatter(logger_name=logger_name) +pytestmark = pytest.mark.usefixtures("_reset_logging") +LOGGER_NAME = "tests" -def assert_records(records): + +@pytest.fixture() +def formatter(): + return MozlogFormatter(logger_name=LOGGER_NAME) + + +def assert_records(formatter, records): assert len(records) == 1 details = json.loads(formatter.format(records[0])) jsonschema.validate(details, JSON_LOGGING_SCHEMA) return details -@pytest.mark.usefixtures("_reset_logging") -def test_initialization_from_ini(caplog, tmpdir): +def test_initialization_from_ini(tmpdir): ini_content = textwrap.dedent( """ [loggers] @@ -42,37 +47,82 @@ 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 == 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 + + 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) + handler.setFormatter(formatter) + + logger = logging.getLogger("test") + logger.addHandler(handler) + logger.warning("hey") + [record] = caplog.records -def test_basic_operation(caplog): + 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): + logger_name = "logger_name_handler" + handler = MozlogHandler(name=logger_name) + formatter = MozlogFormatter(logger_name="logger_name_formatter") + handler.setFormatter(formatter) + + logger = logging.getLogger("test") + logger.addHandler(handler) + + logger.warning("hey") + [record] = caplog.records + + 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): """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(formatter, caplog.records) + assert details == formatter.convert_record(caplog.records[0]) assert "Timestamp" in details @@ -80,16 +130,16 @@ def test_basic_operation(caplog): 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 -def test_custom_paramters(caplog): +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(caplog.records) + details = assert_records(formatter, caplog.records) assert details == formatter.convert_record(caplog.records[0]) assert details["Type"] == "tests.test_logging" @@ -98,13 +148,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, 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(caplog.records) + details = assert_records(formatter, caplog.records) assert details["Type"] == "tests.test_logging" assert details["Severity"] == 4 @@ -112,13 +162,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, formatter): """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(formatter, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -127,14 +177,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, 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(caplog.records) + details = assert_records(formatter, caplog.records) assert details["Severity"] == 3 assert details["Fields"]["msg"] == "there was an error" @@ -142,13 +192,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, 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(formatter, caplog.records) assert "msg" not in details["Fields"] assert formatter.is_value_jsonlike('{"spam": "eggs"}') @@ -156,6 +206,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 73a008c..53709a8 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(): @@ -108,8 +108,9 @@ 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(JsonLogFormatter()) + caplog.handler.setFormatter(MozlogFormatter()) app = create_app() @@ -194,6 +195,7 @@ def return_error(): }, } + def test_heartbeat_sync(client): @checks.register def sync_ok(): @@ -226,6 +228,7 @@ def test_heartbeat_mixed_sync(client): @checks.register def sync_ok(): return [] + @checks.register async def async_ok(): return []