temp mp_logging module for testing

mpcontribs-api/Dockerfile

@@ -42,6 +42,7 @@ COPY main.py .
 COPY maintenance.py .
 COPY docker-entrypoint.sh .
 COPY gunicorn.conf.py .
+COPY mp_logging mp_logging
 RUN chmod +x main.py scripts/start.sh scripts/start_rq.sh docker-entrypoint.sh
 
 ARG VERSION
@@ -52,7 +53,7 @@ ENV DD_SERVICE=contribs-apis \
   DD_TRACE_OTEL_ENABLED=false \
   DD_MAIN_PACKAGE=mpcontribs-api
 
-LABEL com.datadoghq.ad.logs='[{"source": "gunicorn", "service": "contribs-apis"}]'
+LABEL com.datadoghq.ad.logs='[{"source": "mp-backend", "service": "contribs-apis"}]'
 EXPOSE 10000 10002 10003 10005 20000
 ENTRYPOINT ["/app/docker-entrypoint.sh"]
 CMD ["/usr/bin/supervisord", "-c", "supervisord.conf"]

mpcontribs-api/gunicorn.conf.py

@@ -1,15 +1,26 @@
 import ddtrace.auto  # noqa: F401
 import os
 
+from mp_logging import gunicorn_logconfig_dict
+
 bind = "0.0.0.0:{}".format(os.getenv("API_PORT"))
 worker_class = "gevent"
 workers = os.getenv("NWORKERS")
 statsd_host = "{}:8125".format(os.getenv("DD_AGENT_HOST"))
+
+# gunicorn's own error and access logs go through the same structured logging
+# config as the application (see `mp_logging`). Applied in the master before
+# forking; the access log formatter maps gunicorn's atoms to Datadog's
+# standard HTTP attributes, so the format string itself is only a fallback.
+logconfig_dict = gunicorn_logconfig_dict(
+    app_loggers=("mpcontribs",),
+    # supervisord sets FLASK_DEBUG to "True" / "False"
+    debug=os.getenv("FLASK_DEBUG", "").strip().lower() in ("1", "true", "yes"),
+)
 accesslog = "-"
 errorlog = "-"
-access_log_format = '{}/{}: %(h)s %(t)s %(m)s %(U)s?%(q)s %(H)s %(s)s %(b)s "%(f)s" "%(a)s" %(D)s %(p)s %({{x-consumer-id}}i)s'.format(
-    os.getenv("SUPERVISOR_GROUP_NAME"), os.getenv("SUPERVISOR_PROCESS_NAME")
-)
+access_log_format = '%(h)s %(m)s %(U)s %(q)s %(s)s %(B)s %(D)s "%(f)s" "%(a)s"'
+
 max_requests = os.getenv("MAX_REQUESTS")
 max_requests_jitter = os.getenv("MAX_REQUESTS_JITTER")
 proc_name = os.getenv("SUPERVISOR_PROCESS_NAME")

mpcontribs-api/main.py

@@ -7,6 +7,9 @@
 from supervisor.options import ClientOptions
 from supervisor.supervisorctl import Controller
 
+from mp_logging import configure_logging
+
+configure_logging(app_loggers=("__main__",))
 logger = logging.getLogger(__name__)
 client = boto3.client('ecs')
 
@@ -26,7 +29,7 @@ def start(program):
 
 if metadata_uri:
     # in AWS Fargate with potentially multiple tasks
-    logger.debug("METADATA URI", metadata_uri)
+    logger.debug("Task metadata", extra={"metadata_uri": metadata_uri})
     r = requests.get(metadata_uri)
     labels = r.json()["Labels"]
     prefix = "com.amazonaws.ecs"
@@ -42,7 +45,14 @@ def start(program):
         ntasks += int(v == version)
 
     start_rq = ntasks == 1  # this task included in metadata response
-    logger.info(f"TASKS {ntasks}/{len(tasks)} -> START RQ {start_rq}")
+    logger.info(
+        "RQ workers decision",
+        extra={
+            "tasks.current": ntasks,
+            "tasks.total": len(tasks),
+            "start_rq": start_rq,
+        },
+    )
 
 if start_rq:
     start("rq:*")

mpcontribs-api/mp_logging/__init__.py

@@ -0,0 +1,41 @@
+from __future__ import annotations
+
+from .config import (
+    ACCESS_LOGGERS,
+    HANDLER,
+    build_logging_config,
+    configure_logging,
+    gunicorn_logconfig_dict,
+)
+from .context import (
+    RequestContextFilter,
+    bind_request_context,
+    get_request_context,
+    request_fields,
+    reset_request_context,
+    update_request_context,
+)
+from .formatters import (
+    LOG_RECORD_BUILTIN_ATTRS,
+    ConsoleFormatter,
+    DatadogStructuredFormatter,
+    access_log_fields,
+)
+
+__all__ = [
+    "ACCESS_LOGGERS",
+    "HANDLER",
+    "LOG_RECORD_BUILTIN_ATTRS",
+    "ConsoleFormatter",
+    "DatadogStructuredFormatter",
+    "RequestContextFilter",
+    "access_log_fields",
+    "bind_request_context",
+    "build_logging_config",
+    "configure_logging",
+    "get_request_context",
+    "gunicorn_logconfig_dict",
+    "request_fields",
+    "reset_request_context",
+    "update_request_context",
+]

mpcontribs-api/mp_logging/config.py

@@ -0,0 +1,173 @@
+"""`logging.config.dictConfig` configuration shared by MP backend processes."""
+
+from __future__ import annotations
+
+import copy
+import logging
+import logging.config
+import os
+from collections.abc import Iterable, Mapping
+from typing import Any, Literal
+
+from .formatters import (
+    ASGI_ACCESS_LOGGER,
+    GUNICORN_ACCESS_LOGGER,
+    TORNADO_ACCESS_LOGGER,
+)
+
+LogFormat = Literal["json", "console"]
+
+# Names are prefixed so they don't clash with the names other tools use when
+# this config is merged into theirs (e.g. traitlets' "console" formatter)
+HANDLER = "mp_stderr"
+
+# This package's import path (it is copied into each service's own package)
+_PKG = __name__.rsplit(".", 1)[0]
+
+# Loggers that write access logs: always INFO, straight to the handler
+ACCESS_LOGGERS = (GUNICORN_ACCESS_LOGGER, ASGI_ACCESS_LOGGER)
+
+# output key: LogRecord attribute (or "message" / "timestamp")
+FMT_KEYS = {
+    "level": "levelname",
+    "message": "message",
+    "timestamp": "timestamp",
+    "logger.name": "name",
+    "logger.module": "module",
+    "logger.function": "funcName",
+    "logger.line": "lineno",
+    "logger.thread_name": "threadName",
+    "process.pid": "process",
+}
+
+_BASE_CONFIG: dict[str, Any] = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "filters": {
+        "request_context": {"()": f"{_PKG}.context.RequestContextFilter"},
+    },
+    "formatters": {
+        "mp_json": {
+            "()": f"{_PKG}.formatters.DatadogStructuredFormatter",
+            "fmt_keys": FMT_KEYS,
+        },
+        "mp_console": {"()": f"{_PKG}.formatters.ConsoleFormatter"},
+    },
+    "handlers": {
+        "mp_stderr": {
+            "class": "logging.StreamHandler",
+            "formatter": "mp_json",
+            "filters": ["request_context"],
+            "stream": "ext://sys.stderr",
+        },
+    },
+    "loggers": {
+        # gunicorn's (and uvicorn's) own loggers don't propagate, so they need
+        # the handler directly
+        "gunicorn.error": {"level": "INFO", "handlers": [HANDLER], "propagate": False},
+        "uvicorn.error": {"level": "INFO", "handlers": [HANDLER], "propagate": False},
+    },
+    # Everything else (third-party libraries, captured warnings):
+    # WARNING and up (overridable with MP_LOG_LEVEL)
+    "root": {"level": "WARNING", "handlers": [HANDLER]},
+}
+
+
+def _level_name(level: int | str) -> str:
+    if isinstance(level, int):
+        return logging.getLevelName(level)
+    name = level.strip().upper()
+    if name == "WARN":
+        name = "WARNING"
+    if not isinstance(logging.getLevelName(name), int):
+        raise ValueError(f"Unknown log level {level!r}")
+    return name
+
+
+def build_logging_config(
+    *,
+    app_loggers: Iterable[str] = (),
+    access_loggers: Iterable[str] = ACCESS_LOGGERS,
+    extra_loggers: Mapping[str, Mapping[str, Any]] | None = None,
+    fmt: LogFormat | None = None,
+    level: int | str | None = None,
+    app_level: int | str | None = None,
+    debug: bool = False,
+) -> dict[str, Any]:
+    """The `logging.config.dictConfig` dict for a service.
+
+    Arguments left as None come from env vars.
+
+    Args:
+        app_loggers : the service's own loggers (e.g. "mpcontribs"), logged at
+            `app_level` instead of the root level
+        access_loggers : loggers that write access logs (INFO, not propagated)
+        extra_loggers : extra per-logger config, applied last
+        fmt : "json" or "console" (`MP_LOG_FORMAT`, default "json")
+        level : root level (`MP_LOG_LEVEL`, default WARNING)
+        app_level : level for `app_loggers` (`MP_APP_LOG_LEVEL`, default
+            INFO, or DEBUG if `debug`)
+        debug : log the service's own loggers at DEBUG unless `app_level`
+            is set
+
+    Returns:
+        dict for `logging.config.dictConfig` (a fresh copy, safe to modify)
+    """
+    fmt = fmt or os.environ.get("MP_LOG_FORMAT") or "json"  # type: ignore[assignment]
+    if fmt not in ("json", "console"):
+        raise ValueError(f"Unknown log format {fmt!r}, expected 'json' or 'console'")
+    level = _level_name(level or os.environ.get("MP_LOG_LEVEL") or "WARNING")
+    app_level = _level_name(
+        app_level
+        or os.environ.get("MP_APP_LOG_LEVEL")
+        or ("DEBUG" if debug else "INFO")
+    )
+
+    config = copy.deepcopy(_BASE_CONFIG)
+    config["handlers"][HANDLER]["formatter"] = f"mp_{fmt}"
+    config["root"]["level"] = level
+    loggers = config["loggers"]
+    for name in access_loggers:
+        loggers[name] = {"level": "INFO", "handlers": [HANDLER], "propagate": False}
+    for name in app_loggers:
+        loggers.setdefault(name, {})["level"] = app_level
+    for name, overrides in (extra_loggers or {}).items():
+        loggers.setdefault(name, {}).update(copy.deepcopy(dict(overrides)))
+    return config
+
+
+def configure_logging(**kwargs: Any) -> dict[str, Any]:
+    """Configure logging for the process. Safe to call more than once.
+
+    Python warnings are captured into the `py.warnings` logger, so they are
+    formatted like everything else. See `build_logging_config` for the
+    arguments.
+
+    Returns:
+        the applied config
+    """
+    config = build_logging_config(**kwargs)
+    logging.config.dictConfig(config)
+    logging.captureWarnings(True)
+    return config
+
+
+def gunicorn_logconfig_dict(**kwargs: Any) -> dict[str, Any]:
+    """Config for gunicorn's `logconfig_dict` setting (in `gunicorn.conf.py`).
+
+    Applied by gunicorn in the master before forking, so gunicorn's own error
+    and access logs use the same handlers and formatters as the application.
+    Only imports this package, not the application.
+    """
+    return build_logging_config(**kwargs)
+
+
+__all__ = [
+    "ACCESS_LOGGERS",
+    "FMT_KEYS",
+    "HANDLER",
+    "TORNADO_ACCESS_LOGGER",
+    "build_logging_config",
+    "configure_logging",
+    "gunicorn_logconfig_dict",
+]