diff --git a/CHANGELOG.md b/CHANGELOG.md index 42779fa..47c22ac 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,7 +5,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/). ## Unreleased ### Security -- Upgraded `werkzeug`, `flask`, and `pytest` to address potential CVE vulnerabilities. +- Upgraded `werkzeug`, `flask`, and `pytest` to address potential CVE vulnerabilities + +### Added +- Added Elastic Common Schema (ECS) conformant JSON logging ## 10.5.0 - 2026-03-19 ### Breaking diff --git a/README.md b/README.md index 5c78c78..d8f9dac 100644 --- a/README.md +++ b/README.md @@ -14,6 +14,7 @@ Find the docs at https://disyinformationssysteme.github.io/cadenza-analytics-pyt * Shapely * requests-toolbelt * chardet +* ecs-logging ## Installation: The simplest way to install `cadenzaanalytics` is from the [Python Package Index (PyPI)](https://pypi.org/project/cadenzaanalytics/) using the package installer [pip](https://pypi.org/project/pip/). diff --git a/docs/intro.md b/docs/intro.md index 0e30d3f..6d991de 100644 --- a/docs/intro.md +++ b/docs/intro.md @@ -645,6 +645,7 @@ The service provides a root endpoint (`/`) that lists all registered extensions. `cadenzaanalytics` is built on top of Flask, which in turn uses standard Python logging. This logger can also be used to log your own messages for your Analytics Extension, or define your own logger according to [standard Python logging](https://docs.python.org/3/howto/logging.html#). +`cadenzaanalytics` configures the root logger, so this also applies to log output from dependent packages (e.g. Flask, Werkzeug) and from any logger used in your Analytics Extension, as long as it propagates to root, which is the default in standard Python logging. The default log level of the `cadenzaanalytics` module is `INFO`. To change the log level, set the environment variable `CADENZAANALYTICS_LOG_LVL` accordingly, e.g. @@ -652,6 +653,18 @@ To change the log level, set the environment variable `CADENZAANALYTICS_LOG_LVL` export CADENZAANALYTICS_LOG_LVL='DEBUG' ``` +The default log format is a human-readable, gunicorn-like line format. +To switch to [Elastic Common Schema](https://www.elastic.co/guide/en/ecs/current/index.html) (ECS) conformant JSON logging, which is well suited for log aggregation in container deployments, set the environment variable `CADENZAANALYTICS_LOG_FORMAT` to `ecs`, e.g. +```console +export CADENZAANALYTICS_LOG_FORMAT='ecs' +``` +Every log line then additionally carries a `service.name` of `cadenzaanalytics` and a `service.version` matching the installed package version. + +If deployed behind [gunicorn](https://gunicorn.org/), this configuration also covers gunicorn's own worker-level log lines (e.g. access log lines, worker exit messages), automatically and without any gunicorn-side configuration. +The one exception is gunicorn's master process, which logs its own startup, shutdown, and signal-handling messages before an analytics extension is loaded, and therefore always in gunicorn's own default format. +This gap is specific to gunicorn's master/worker process architecture. +WSGI servers without that split, such as [Waitress](https://docs.pylonsproject.org/projects/waitress/en/stable/), log every message in the configured format with no exception. + # Deployment diff --git a/pyproject.toml b/pyproject.toml index dbd45d0..195bd9f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -32,6 +32,7 @@ chardet = "5.2.0" Shapely = "2.1.2" pytest = "9.0.3" tzlocal = "5.3.1" +ecs-logging = "2.3.0" [project] name = "cadenzaanalytics" diff --git a/src/cadenzaanalytics/__init__.py b/src/cadenzaanalytics/__init__.py index 455a45a..1e2d2e4 100644 --- a/src/cadenzaanalytics/__init__.py +++ b/src/cadenzaanalytics/__init__.py @@ -7,11 +7,9 @@ .. include:: ../../docs/intro.md """ -import os -from logging.config import dictConfig - from cadenzaanalytics.cadenza_analytics_extension import CadenzaAnalyticsExtension from cadenzaanalytics.cadenza_analytics_extension_service import CadenzaAnalyticsExtensionService +from cadenzaanalytics.logging_config import configure_logging from cadenzaanalytics.data.analytics_extension import AnalyticsExtension from cadenzaanalytics.data.attribute_group import AttributeGroup @@ -40,21 +38,4 @@ from cadenzaanalytics.version import __version__ -# Logging configuration, format similar to gunicorn -dictConfig({ - 'disable_existing_loggers': False, - 'version': 1, - 'formatters': {'default': { - 'format': '[%(asctime)s] [%(process)d] [%(levelname)s] [%(module)s] %(message)s', - 'datefmt': '%Y-%m-%d %H:%M:%S %z' - }}, - 'handlers': {'wsgi': { - 'class': 'logging.StreamHandler', - 'stream': 'ext://flask.logging.wsgi_errors_stream', - 'formatter': 'default' - }}, - 'root': { - 'level': os.environ.get('CADENZAANALYTICS_LOG_LVL', 'INFO'), - 'handlers': ['wsgi'] - } -}) +configure_logging() diff --git a/src/cadenzaanalytics/logging_config.py b/src/cadenzaanalytics/logging_config.py new file mode 100644 index 0000000..07444f9 --- /dev/null +++ b/src/cadenzaanalytics/logging_config.py @@ -0,0 +1,79 @@ +"""Configures logging for the `cadenzaanalytics` package. + +The configured handler is attached to the root logger, and `disable_existing_loggers` is left `False`, so this +also governs log output from dependent packages (e.g. Flask, Werkzeug) and from analytics extensions built with +`cadenzaanalytics`, as long as their loggers propagate to root, which is the default in standard Python logging. +""" +import os +from logging.config import dictConfig +from typing import Any, Dict + +import ecs_logging + +from cadenzaanalytics.version import __version__ + +_PLAIN_FORMATTER_CONFIG = { + 'format': '[%(asctime)s] [%(process)d] [%(levelname)s] [%(module)s] %(message)s', + 'datefmt': '%Y-%m-%d %H:%M:%S %z' +} + + +class CadenzaEcsFormatter(ecs_logging.StdlibFormatter): + """An `ecs_logging.StdlibFormatter` that additionally stamps every record with `service.name` + and `service.version`, identifying the `cadenzaanalytics` version that produced the log line.""" + + def format_to_ecs(self, record) -> Dict[str, Any]: + result = super().format_to_ecs(record) + result.setdefault('service', {})['name'] = 'cadenzaanalytics' + result['service']['version'] = __version__ + return result + + +def configure_logging() -> None: + """Configure the root logger from the `CADENZAANALYTICS_LOG_LVL` and `CADENZAANALYTICS_LOG_FORMAT` + environment variables. + + `CADENZAANALYTICS_LOG_LVL` sets the root log level (default `INFO`). + `CADENZAANALYTICS_LOG_FORMAT` selects the output format: `plain` (default) for a human-readable, + gunicorn-like line format, or `ecs` for Elastic Common Schema (ECS) conformant JSON, suited for + log aggregation in container deployments. + + Raises + ------ + ValueError + If `CADENZAANALYTICS_LOG_FORMAT` is set to a value other than `plain` or `ecs`. + """ + log_format = os.environ.get('CADENZAANALYTICS_LOG_FORMAT', 'plain').lower() + + if log_format == 'plain': + formatter_config = _PLAIN_FORMATTER_CONFIG + elif log_format == 'ecs': + formatter_config = {'()': CadenzaEcsFormatter} + else: + raise ValueError( + f'Invalid CADENZAANALYTICS_LOG_FORMAT "{log_format}". Supported values are "plain" and "ecs".' + ) + + log_level = os.environ.get('CADENZAANALYTICS_LOG_LVL', 'INFO').upper() + + dictConfig({ + 'disable_existing_loggers': False, + 'version': 1, + 'formatters': {'default': formatter_config}, + 'handlers': {'wsgi': { + 'class': 'logging.StreamHandler', + 'stream': 'ext://flask.logging.wsgi_errors_stream', + 'formatter': 'default' + }}, + 'root': { + 'level': log_level, + 'handlers': ['wsgi'] + }, + # gunicorn configures 'gunicorn.error'/'gunicorn.access' with its own handlers and + # propagate=False before this module is imported; re-pointing them at our own handler here + # keeps gunicorn's own logs in the same format, without requiring any gunicorn-side configuration. + 'loggers': { + 'gunicorn.error': {'level': log_level, 'handlers': ['wsgi'], 'propagate': False}, + 'gunicorn.access': {'level': log_level, 'handlers': ['wsgi'], 'propagate': False} + } + }) diff --git a/src/cadenzaanalytics/tests/test_logging_config.py b/src/cadenzaanalytics/tests/test_logging_config.py new file mode 100644 index 0000000..1afaed5 --- /dev/null +++ b/src/cadenzaanalytics/tests/test_logging_config.py @@ -0,0 +1,74 @@ +"""Unit tests for logging configuration.""" +import json +import logging + +import pytest +from cadenzaanalytics.logging_config import configure_logging + + +class TestLoggingConfig: + """Test suite for configure_logging.""" + + def teardown_method(self): + """Reset logger state so tests don't leak configuration into one another.""" + for name in (None, 'gunicorn.error', 'gunicorn.access'): + logger = logging.getLogger(name) + logger.handlers = [] + logger.propagate = True + + def test_invalid_log_format_raises(self, monkeypatch): + """An unsupported CADENZAANALYTICS_LOG_FORMAT value should raise a ValueError.""" + monkeypatch.setenv('CADENZAANALYTICS_LOG_FORMAT', 'bogus') + with pytest.raises(ValueError, match='CADENZAANALYTICS_LOG_FORMAT'): + configure_logging() + + def test_ecs_format_produces_ecs_json(self, monkeypatch, capsys): + """The 'ecs' format should produce ECS-conformant JSON, stamped with the service name/version.""" + monkeypatch.setenv('CADENZAANALYTICS_LOG_FORMAT', 'ecs') + configure_logging() + + logging.getLogger('some.dependency').warning('dependency warning') + + record = json.loads(capsys.readouterr().err.strip()) + assert record['message'] == 'dependency warning' + # per the ECS logging spec, '@timestamp', 'log.level' and 'message' stay flat/dotted top-level keys + assert record['log.level'] == 'warning' + assert record['log']['logger'] == 'some.dependency' + assert record['service']['name'] == 'cadenzaanalytics' + + def test_plain_format_is_not_json(self, monkeypatch, capsys): + """The default 'plain' format should produce a human-readable line, not JSON.""" + monkeypatch.delenv('CADENZAANALYTICS_LOG_FORMAT', raising=False) + configure_logging() + + logging.getLogger('some.dependency').warning('dependency warning') + + line = capsys.readouterr().err.strip() + assert 'dependency warning' in line + with pytest.raises(json.JSONDecodeError): + json.loads(line) + + def test_log_level_is_case_insensitive(self, monkeypatch): + """CADENZAANALYTICS_LOG_LVL should be accepted regardless of case, since logging.setLevel() + only recognizes uppercase level names and would otherwise raise a ValueError.""" + monkeypatch.setenv('CADENZAANALYTICS_LOG_LVL', 'debug') + configure_logging() + + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + def test_gunicorn_loggers_are_repointed_at_our_handler(self, monkeypatch, capsys): + """gunicorn attaches its own handlers to 'gunicorn.error'/'gunicorn.access' with propagate=False + before the app is imported; configure_logging() must re-point them at our own handler so gunicorn's + own log lines come out in the configured format too, without any gunicorn-side configuration.""" + gunicorn_access = logging.getLogger('gunicorn.access') + gunicorn_access.propagate = False + gunicorn_access.addHandler(logging.StreamHandler()) + + monkeypatch.setenv('CADENZAANALYTICS_LOG_FORMAT', 'ecs') + configure_logging() + + gunicorn_access.info('127.0.0.1 - - "GET / HTTP/1.1" 200 -') + + record = json.loads(capsys.readouterr().err.strip()) + assert record['log']['logger'] == 'gunicorn.access' + assert record['service']['name'] == 'cadenzaanalytics'