diff --git a/docs/deploy/XX-logs-traces.md b/docs/deploy/XX-logs-traces.md index 6928dcbf..46119fae 100644 --- a/docs/deploy/XX-logs-traces.md +++ b/docs/deploy/XX-logs-traces.md @@ -8,16 +8,20 @@ FireFighter uses the [logging](https://docs.python.org/3/library/logging.html) m #### Production JSON -FireFighter logs to stdout using a [JSON formatter][firefighter.logging.custom_json_formatter.CustomJsonFormatter]. +FireFighter logs to stdout using [loggia](https://github.com/ManoManoTech/loggia) and its [JSON Formatter][loggia.stdlib_formatters.json_formatter.CustomJsonFormatter]. The JSON formats adheres to DataDog's [JSON log format](https://docs.datadoghq.com/logs/log_collection/python/?tab=standard#json-format). #### Development -In development mode, FireFighter logs to the console using a [Pretty formatter][firefighter.logging.pretty_formatter.PrettyFormatter] +In development mode, FireFighter logs to the console using [loggia](https://github.com/ManoManoTech/loggia)'s [Pretty formatter][loggia.stdlib_formatters.pretty_formatter.PrettyFormatter] ### Further Configuration +You should check [loggia's documentation](https://manomanotech.github.io/loggia/latest/config/) for more details. + +Loggia can mostly be configured using environment variables. + You can configure the logging manually by editing the `LOGGING` Python setting, or by running your configuration code in your custom settings. ## Tracing diff --git a/docs/reference/logging.md b/docs/reference/logging.md deleted file mode 100644 index 57d47ebd..00000000 --- a/docs/reference/logging.md +++ /dev/null @@ -1,2 +0,0 @@ - -::: firefighter.logging diff --git a/mkdocs.yml b/mkdocs.yml index b9b08b25..886c3387 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -129,7 +129,6 @@ nav: - slack: reference/slack.md - jira_app: reference/jira_app.md - raid: reference/raid.md - - logging: reference/logging.md markdown_extensions: @@ -203,6 +202,7 @@ plugins: - url: https://docs.djangoproject.com/en/4.2/_objects/ base_url: https://docs.djangoproject.com/en/4.2/ domains: [std, py] + - https://manomanotech.github.io/loggia/latest/objects.inv paths: [src] # search packages in the src folder options: docstring_options: diff --git a/pdm.lock b/pdm.lock index 4a888e00..02f19c0e 100644 --- a/pdm.lock +++ b/pdm.lock @@ -5,7 +5,7 @@ groups = ["default", "dev", "docs", "tests", "types", "docs-img"] strategy = ["cross_platform", "static_urls"] lock_version = "4.4.1" -content_hash = "sha256:0561fdb9ea10f173e9a102ca7b1518a0bb63f2698ce58b981c0137a97a67bed7" +content_hash = "sha256:7dc85e5efd760b3be0afab63cc27aa1f7bae1d93b8dd59dab279f30b69740c49" [[package]] name = "aiohappyeyeballs" @@ -1800,6 +1800,19 @@ files = [ {url = "https://files.pythonhosted.org/packages/ff/e1/99a7ec68b892c9b8c6212617f54e7e9b0304d47edad8c0ff043ae3aeb1a9/lazy_object_proxy-1.10.0-cp311-cp311-macosx_10_9_x86_64.whl", hash = "sha256:fec03caabbc6b59ea4a638bee5fce7117be8e99a4103d9d5ad77f15d6f81020c"}, ] +[[package]] +name = "loggia" +version = "0.3.1" +requires_python = ">=3.9" +summary = "A convenient logging configuration manager for Python's standard logging library and Loguru." +dependencies = [ + "python-json-logger>=2.0.7", +] +files = [ + {url = "https://files.pythonhosted.org/packages/14/96/f2a12aa2998517f5c2daa3d3c1a8accb0b76fa98b1a2c636a797fe9bae6e/loggia-0.3.1.tar.gz", hash = "sha256:6e6525819688e79e833c15d390af0d3f334c30080cd4e114667cb62192c23d09"}, + {url = "https://files.pythonhosted.org/packages/9d/96/b11e39dfd2d36ced3a03e250513290ff7b9575d67b5bf4cf13e2ee4797f5/loggia-0.3.1-py3-none-any.whl", hash = "sha256:f7b6b21ec129bbeb39332f61e6bea2a08443a2d0185b2aecb0ca51b5f77bfa45"}, +] + [[package]] name = "markdown" version = "3.7" diff --git a/pyproject.toml b/pyproject.toml index a099c978..9871862f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -46,6 +46,7 @@ dependencies = [ "aiohttp>=3.9.1", # Transitive dependency of slack_sdk "nh3>=0.2.15", "django-import-export>=4.0.0", + "loggia>=0.3.0", ] requires-python = ">=3.11,<4.0" license = {file = "LICENSE"} diff --git a/src/firefighter/firefighter/settings/components/logging.py b/src/firefighter/firefighter/settings/components/logging.py index aa8a5273..515bbe53 100644 --- a/src/firefighter/firefighter/settings/components/logging.py +++ b/src/firefighter/firefighter/settings/components/logging.py @@ -1,14 +1,16 @@ from __future__ import annotations -from logging import Filter, Formatter, LogRecord -from typing import Any +from logging import Filter, LogRecord +from typing import TYPE_CHECKING -from firefighter.firefighter.settings.settings_utils import ENV, config -from firefighter.logging.custom_json_formatter import ( - CustomJsonEncoder, - CustomJsonFormatter, -) -from firefighter.logging.pretty_formatter import PrettyFormatter +from loggia.conf import FlexibleFlag, LoggerConfiguration +from loggia.logger import initialize +from loggia.utils.logrecordutils import STANDARD_FIELDS, popattr + +from firefighter.firefighter.settings.settings_utils import ENV + +if TYPE_CHECKING: + from collections.abc import Iterable class AccessLogFilter(Filter): @@ -32,74 +34,41 @@ def filter(self, record: LogRecord) -> bool: return True -def get_json_formatter() -> dict[str, type[Formatter] | Any]: - attr_whitelist = {"name", "levelname", "pathname", "lineno", "funcName"} - attrs = [x for x in CustomJsonFormatter.RESERVED_ATTRS if x not in attr_whitelist] - return { - "()": CustomJsonFormatter, - "json_indent": None, - "json_encoder": CustomJsonEncoder, - "reserved_attrs": attrs, - "timestamp": True, - } - - -base_level = "DEBUG" if ENV == "dev" else "INFO" -base_level_override = config("LOG_LEVEL", cast=str, default="") -if base_level_override and base_level_override != "": - base_level = base_level_override.upper() +class RemoveExtraDev(Filter): + def __init__(self, name: str = "", to_ignore: Iterable[str] = ()) -> None: + self.to_ignore = to_ignore + super().__init__(name) -formatter: dict[str, type[Formatter] | Any] -formatter = {"()": PrettyFormatter} if ENV == "dev" else get_json_formatter() + def filter(self, record: LogRecord) -> bool: + for extra in set(record.__dict__.keys() - STANDARD_FIELDS) & set( + self.to_ignore + ): + popattr(record, extra, None) + return True -FF_LOGGING = { - "version": 1, - "disable_existing_loggers": False, - "formatters": { - "dynamicfmt": formatter, - }, - "handlers": { - "console": {"class": "logging.StreamHandler", "formatter": "dynamicfmt"}, - }, - "loggers": { - "django": { - "handlers": ["console"], - "propagate": False, - }, - "watchfiles.main": {"level": "INFO"}, - "django.utils.autoreload": {"level": "INFO"}, - "django.request": {"handlers": ["console"], "propagate": False}, - "django.server": {"handlers": ["console"], "propagate": False}, - "django.template": {"handlers": ["console"], "propagate": False}, - "django.db.backends": { - "handlers": ["console"], - "propagate": False, - "level": base_level, - }, - "django.db.backends.schema": {"handlers": ["console"], "propagate": False}, - "gunicorn.access": { - "handlers": ["console"], - "filters": ["accessfilter"], - "propagate": False, - }, - "gunicorn.error": {"handlers": ["console"], "propagate": False}, - "ddtrace": { - "handlers": ["console"], - "level": "WARNING", - }, - "faker.factory": { - "level": "INFO", - }, - "fsevents": { - "level": "INFO", - }, - }, - "filters": {"accessfilter": {"()": AccessLogFilter}}, - "root": { - "handlers": ["console"], - "level": base_level, - "propagate": False, - }, -} -LOGGING = FF_LOGGING +# Explicitely tell Django that we don't want to use its default logging config +LOGGING_CONFIG: None = None +log_cfg = LoggerConfiguration() +log_cfg.capture_loguru = FlexibleFlag.DISABLED +# From https://docs.djangoproject.com/en/4.2/ref/logging/#django-s-default-logging-configuration +if ENV == "dev": + log_cfg.set_logger_level("django", "INFO") + log_cfg.set_logger_level("django.db.backends", "DEBUG") + log_cfg.set_logger_level("django.server", "INFO") + log_cfg.set_logger_level("ddtrace", "WARNING") + log_cfg.set_logger_level("faker.factory", "INFO") + log_cfg.set_logger_level("fsevents", "INFO") + log_cfg.set_logger_level("celery.utils.functional", "INFO") + log_cfg.set_logger_level("celery.bootsteps", "INFO") + log_cfg.set_logger_level("psycopg.pq", "INFO") + log_cfg.add_log_filter("gunicorn.access", AccessLogFilter()) + log_cfg.add_log_filter( + "django.server", + RemoveExtraDev(to_ignore=("server_time", "status_code", "request")), + ) + log_cfg.add_log_filter( + "django.db.backends", + RemoveExtraDev(to_ignore=("params", "alias", "sql", "duration")), + ) +initialize(log_cfg) diff --git a/src/firefighter/logging/__init__.py b/src/firefighter/logging/__init__.py deleted file mode 100644 index 5a4f230b..00000000 --- a/src/firefighter/logging/__init__.py +++ /dev/null @@ -1 +0,0 @@ -"""Custom logging formatter for the Firefighter project.""" diff --git a/src/firefighter/logging/custom_json_formatter.py b/src/firefighter/logging/custom_json_formatter.py deleted file mode 100644 index 3b885ca2..00000000 --- a/src/firefighter/logging/custom_json_formatter.py +++ /dev/null @@ -1,159 +0,0 @@ -from __future__ import annotations - -import os -import re -from contextlib import suppress -from socket import socket -from typing import TYPE_CHECKING, Any - -from django.conf import settings -from pythonjsonlogger.jsonlogger import RESERVED_ATTRS, JsonEncoder, JsonFormatter - -if TYPE_CHECKING: - from logging import LogRecord - -DD_TRACE_ENABLED = os.environ.get("DD_TRACE_ENABLED") -if DD_TRACE_ENABLED: - from ddtrace import tracer -GUNICORN_KEY_RE = re.compile("{([^}]+)}") - - -def del_if_possible(obj: dict[str, Any], key: str) -> None: - with suppress(KeyError): - del obj[key] - - -def del_many_if_possible(obj: dict[str, Any], keys: list[str]) -> None: - for key in keys: - del_if_possible(obj, key) - - -def mv_attr(obj: dict[str, Any], src_key: str, dst_key: str) -> None: - if src_key in obj: - obj[dst_key] = obj[src_key] - del obj[src_key] - - -class CustomJsonEncoder(JsonEncoder): - def encode(self, o: Any) -> str: - if isinstance(o, socket): - return super().encode({"socket": {"peer": o.getpeername()}}) - return super().encode(o) - - -class CustomJsonFormatter(JsonFormatter): - """Custom JSON formatter for Python loggin, with Datadog specific attributes.""" - - RESERVED_ATTRS = RESERVED_ATTRS - - def __init__(self, *args: Any, **kwargs: Any) -> None: - self.FF_USER_ID_HEADER: str = settings.FF_USER_ID_HEADER - super().__init__(*args, **kwargs) # type: ignore[no-untyped-call] - - def add_fields( - self, - log_record: dict[str, Any], - record: LogRecord, - message_dict: dict[str, Any], - ) -> None: - # XXX probably send empty message dict and merge it ourselves instead of top level - super().add_fields(log_record, record, message_dict) - - # Cleanup: just don't log cookies - if "cookie" in log_record: - log_record["cookie"] = "STRIPPED_AT_EMISSION" - if DD_TRACE_ENABLED: - span = tracer.current_span() - trace_id, span_id = (span.trace_id, span.span_id) if span else (None, None) - - # add ids to structlog event dictionary - log_record["dd.trace_id"] = str(trace_id or 0) - log_record["dd.span_id"] = str(span_id or 0) - - # Normalisation: Datadog source code attributes - log_record["logger.name"] = record.name - log_record["logger.thread_name"] = record.threadName - log_record["logger.method_name"] = record.funcName - mv_attr(log_record, "pathname", "logger.path_name") - mv_attr(log_record, "lineno", "logger.lineno") - del_if_possible(log_record, "name") - del_if_possible(log_record, "funcName") - - # Normalisation: Datadog severity - if "levelname" in log_record: - log_record["status"] = log_record["levelname"] - del log_record["levelname"] - - # Normalisation: Datadog duration (in nanoseconds) - log_record["duration"] = record.msecs * 1000000 - - # Normalization: Datadog stack trace - if "exc_info" in log_record: - exc_info_lines = log_record["exc_info"].split("\n") - log_record["error.stack"] = "\n".join(exc_info_lines[0:-1]) - log_record["error.message"] = exc_info_lines[-1] - if log_record["error.message"]: - log_record["error.kind"] = log_record["error.message"].split(":")[0] - del log_record["exc_info"] - - # Cleanup and expansion of gunicorn specific log attributes - if "gunicorn" in log_record["logger.name"]: - if hasattr(record.args, "items"): - for k, v in record.args.items(): # type: ignore[union-attr] - if "{" not in k or k.startswith("{http_"): - continue - m = GUNICORN_KEY_RE.search(k) - if m: - log_record[m[1]] = v - else: - log_record["args.type"] = str(type(record.args)) - log_record["args"] = str(record.args) - - # Normalization: Datadog user - mv_attr(log_record, self.FF_USER_ID_HEADER, "usr.id") - - # Normalisation: Datadog HTTP Attributes - mv_attr(log_record, "raw_uri", "http.uri") - mv_attr(log_record, "request_method", "http.method") - mv_attr(log_record, "referer", "http.referer") - mv_attr(log_record, "user_agent", "http.useragent") - mv_attr(log_record, "server_protocol", "http.version") - - header_attributes = [ - "accept", - "accept-encoding", - "accept-language", - "access-control-allow-origin", - "cache-control", - "connection", - "content_length", - "content-encoding", - "content-length", - "content-type", - "cookie", - "etag", - "pragma", - ] - xtra_ks = [k for k in log_record if k.startswith(("x-", "sec-", "mm-"))] - header_attributes.extend(xtra_ks) - for header_attr in header_attributes: - mv_attr(log_record, header_attr, f"http.headers.{header_attr}") - - # Normalisation: DataDog Client IP - - # Cleanup useless attributes - del_many_if_possible( - log_record, - [ - "gunicorn.socket", - "wsgi.file_wrapper", - "wsgi.input_terminated", - "wsgi.multiprocess", - "wsgi.multithread", - "wsgi.run_once", - "wsgi.url_scheme", - "wsgi.version", - "wsgi.errors", - "wsgi.input", - ], - ) diff --git a/src/firefighter/logging/pretty_formatter.py b/src/firefighter/logging/pretty_formatter.py deleted file mode 100644 index f1830546..00000000 --- a/src/firefighter/logging/pretty_formatter.py +++ /dev/null @@ -1,73 +0,0 @@ -from __future__ import annotations - -import logging -from functools import cache -from typing import Final - -COLORS: dict[str, str] = { - "Forest Green": "#086e3f", - "Emerald Green": "#58ad72", - "Lint": "#4bd676", - "Pale Lint": "#75e097", - "Fuchsia": "#fb4570", - "Hot Pink": "#fb6b90", - "Pink": "#fb8da0", - "Pink White": "#efebe0", - "Red": "#ed4040", - "Ivory": "#f1ece4", - "Nude": "#c3b090", - "Sand Dollar": "#de943a", - "Tan": "#92794f", - "Blue Gray": "#8da7c4", - "Sky": "#ace1fc", - "Stone Blue": "#8da7c4", - "White Blue": "#e5ddfc", -} - -PALETTES = { - logging.DEBUG: ["Blue Gray", "Sky", "Stone Blue", "White Blue"], - logging.INFO: ["Forest Green", "Lint", "Emerald Green", "Pale Lint"], - logging.WARNING: ["Nude", "Tan", "Nude", "Sand Dollar"], - logging.ERROR: ["Hot Pink", "Fuchsia", "Pink", "Red"], - logging.CRITICAL: ["Hot Pink", "Fuchsia", "Pink", "Red"], -} -# pylint: disable=consider-using-f-string - -_ANSI_END: Final[str] = "\x1b[0m" - - -def _html_to_triple_dec(html_code: str) -> list[int]: - return [int(x, 16) for x in (html_code[1:3], html_code[3:5], html_code[5:8])] - - -@cache -def _ansi_fg(name: str) -> str: - html_code = COLORS[name] - return "\x1b[38;2;{};{};{}m".format(*_html_to_triple_dec(html_code)) - - -class PrettyFormatter(logging.Formatter): - """A custom logging formatter that formats log records with colors and a pretty output, for local development. - - Opiniated about what is pretty. - - Attributes: - _style (logging._STYLES): The logging style used for formatting. - _fmt (str): The logging format string used for formatting. - """ - - def _set_format(self, fmt: str, style: str = "%") -> None: - self._style = logging._STYLES[style][0](fmt) # type: ignore[operator] # noqa: SLF001 # Mysticism 🤔 - self._fmt = self._style._fmt # noqa: SLF001 - - def format(self, record: logging.LogRecord) -> str: - # Reference attributes: https://docs.python.org/3/library/logging.html#logrecord-attributes - palette = PALETTES.get(record.levelno, PALETTES[logging.DEBUG]) - self._set_format( - f"{_ansi_fg(palette[0])}%(asctime)s " - f"{_ansi_fg(palette[1])}%(levelname)-8s " - f"{_ansi_fg(palette[2])}%(name)s:%(lineno)d " - f"{_ansi_fg(palette[3])}%(message)s" - f"{_ANSI_END}" - ) - return super().format(record) diff --git a/tests/test_firefighter/test_logging.py b/tests/test_firefighter/test_logging.py deleted file mode 100644 index 4fdf9537..00000000 --- a/tests/test_firefighter/test_logging.py +++ /dev/null @@ -1,29 +0,0 @@ -from __future__ import annotations - -import pytest - - -def test_json_logging(caplog: pytest.LogCaptureFixture, capsys, settings) -> None: - """This test ensures that JSON logging is working.""" - # ruff: noqa: PLC0415 - import logging - - from firefighter.firefighter.settings.components.logging import ( - get_json_formatter, - ) - - caplog.set_level(logging.INFO) - # Override the current logging settings - settings.LOGGING["formatters"]["dynamicfmt"] = get_json_formatter() - - from logging import config - - config.dictConfig(settings.LOGGING) - logger = logging.getLogger(__name__) - - logger.info("Testing now.") - - captured = capsys.readouterr() - assert '{"message": "Testing now.",' in captured.err - # XXX Make more testing assertion about our expected JSON log output and its format. - # This is a bit tricky as it is in Gunicorn logs.