From 8d568f833e2a48992cf27ad43e9d5df20dea0286 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Mon, 5 Aug 2024 13:03:16 +0200 Subject: [PATCH 1/7] Replace ctms.web logger by logging --- ctms/app.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/ctms/app.py b/ctms/app.py index d14e7426..967577c0 100644 --- a/ctms/app.py +++ b/ctms/app.py @@ -1,7 +1,8 @@ +import logging import sys import time -import structlog + import uvicorn from dockerflow.fastapi import router as dockerflow_router from dockerflow.fastapi.middleware import RequestIdMiddleware @@ -22,6 +23,9 @@ ) from .routers import contacts, platform + +web_logger = logging.getLogger("ctms.web") + app = FastAPI( title="ConTact Management System (CTMS)", description="CTMS API (work in progress)", @@ -68,11 +72,10 @@ async def log_request_middleware(request: Request, call_next): context.update({"status_code": status_code, "duration_s": duration_s}) emit_response_metrics(context, get_metrics()) - logger = structlog.get_logger("ctms.web") if response is None: - logger.error(log_line, **context) + web_logger.error(log_line, **context) else: - logger.info(log_line, **context) + web_logger.info(log_line, **context) return response From ecfc7268721bcd96d7fd2033fc978dc7c3b98533 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Mon, 5 Aug 2024 13:18:49 +0200 Subject: [PATCH 2/7] Untangle metrics from log context --- ctms/app.py | 12 ++++++++++-- ctms/metrics.py | 14 +++++++------- 2 files changed, 17 insertions(+), 9 deletions(-) diff --git a/ctms/app.py b/ctms/app.py index 967577c0..ac359b0a 100644 --- a/ctms/app.py +++ b/ctms/app.py @@ -69,9 +69,17 @@ async def log_request_middleware(request: Request, call_next): log_line = get_log_line(request, status_code, context.get("client_id")) duration = time.monotonic() - start_time duration_s = round(duration, 3) - context.update({"status_code": status_code, "duration_s": duration_s}) - emit_response_metrics(context, get_metrics()) + emit_response_metrics( + path_template=context.get("path_template"), + method=context["method"], + duration_s=duration_s, + status_code=status_code, + client_id=context.get("client_id"), + metrics=get_metrics(), + ) + + context.update({"status_code": status_code, "duration_s": duration_s}) if response is None: web_logger.error(log_line, **context) else: diff --git a/ctms/metrics.py b/ctms/metrics.py index 82679496..9c3224a5 100644 --- a/ctms/metrics.py +++ b/ctms/metrics.py @@ -1,7 +1,7 @@ """Prometheus metrics for instrumentation and monitoring.""" from itertools import product -from typing import Any, Type, cast +from typing import Any, Optional, Type, cast from fastapi import FastAPI from fastapi.security import HTTPBasic @@ -142,21 +142,22 @@ def init_metrics_labels( def emit_response_metrics( - context: dict[str, Any], metrics: dict[str, Counter | Histogram] + path_template: Optional[str], + method: str, + duration_s: float, + status_code: int, + client_id: Optional[str], + metrics: dict[str, Counter | Histogram], ) -> None: """Emit metrics for a response.""" if not metrics: return - path_template = context.get("path_template") if not path_template: # If no path_template, then it is not a known route, probably a 404. # Don't emit a metric, which will add noise to data return - method = context["method"] - duration_s = context["duration_s"] - status_code = context["status_code"] status_code_family = str(status_code)[0] + "xx" counter = cast(Counter, metrics["requests"]) @@ -174,7 +175,6 @@ def emit_response_metrics( status_code_family=status_code_family, ).observe(duration_s) - client_id = context.get("client_id") if client_id: counter = cast(Counter, metrics["api_requests"]) counter.labels( From 0b894935011b15865f23f09ea5d13a9b4ef1b4b5 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Mon, 5 Aug 2024 16:49:43 +0200 Subject: [PATCH 3/7] Replace structlog with logging --- ctms/app.py | 4 +- ctms/log.py | 61 +++------------- poetry.lock | 21 +----- pyproject.toml | 1 - tests/unit/routers/contacts/test_api_post.py | 11 +-- tests/unit/routers/contacts/test_api_put.py | 10 +-- tests/unit/routers/test_platform.py | 20 +++--- tests/unit/test_auth.py | 69 ++++++++++-------- tests/unit/test_log.py | 76 ++++++++++---------- 9 files changed, 109 insertions(+), 164 deletions(-) diff --git a/ctms/app.py b/ctms/app.py index ac359b0a..b4a47d51 100644 --- a/ctms/app.py +++ b/ctms/app.py @@ -81,9 +81,9 @@ async def log_request_middleware(request: Request, call_next): context.update({"status_code": status_code, "duration_s": duration_s}) if response is None: - web_logger.error(log_line, **context) + web_logger.error(log_line, extra=context) else: - web_logger.info(log_line, **context) + web_logger.info(log_line, extra=context) return response diff --git a/ctms/log.py b/ctms/log.py index 181f633f..792d12c7 100644 --- a/ctms/log.py +++ b/ctms/log.py @@ -5,11 +5,9 @@ import sys from typing import Any, Dict, List, Optional -import structlog from dockerflow.logging import request_id_context from fastapi import Request from starlette.routing import Match -from structlog.types import Processor def configure_logging( @@ -22,17 +20,6 @@ def configure_logging( :param logging_level: The logging level, such as DEBUG or INFO. :param log_sqlalchemy: Include SQLAlchemy engine logs, such as SQL statements """ - - if use_mozlog: - structlog_fmt_prep: Processor = structlog.stdlib.render_to_log_kwargs - structlog_dev_processors: List[Processor] = [] - else: - structlog_fmt_prep = structlog.stdlib.ProcessorFormatter.wrap_for_formatter - structlog_dev_processors = [ - structlog.stdlib.add_logger_name, - structlog.stdlib.add_log_level, - structlog.processors.TimeStamper(fmt="iso"), - ] logging_config = { "version": 1, "disable_existing_loggers": False, @@ -42,46 +29,34 @@ def configure_logging( }, }, "formatters": { - "dev_console": { - "()": structlog.stdlib.ProcessorFormatter, - "processor": structlog.dev.ConsoleRenderer(colors=True), - "foreign_pre_chain": structlog_dev_processors, - }, "mozlog_json": { "()": "dockerflow.logging.JsonLogFormatter", "logger_name": "ctms", }, + "text": { + "format": "%(asctime)s %(levelname)-8s [%(rid)s] %(name)-15s %(message)s", + "datefmt": "%Y-%m-%d %H:%M:%S", + }, }, "handlers": { - "humans": { + "console": { + "level": logging_level, "class": "logging.StreamHandler", - "stream": sys.stdout, - "formatter": "dev_console", - "level": logging.DEBUG, "filters": ["request_id"], + "formatter": "mozlog_json" if use_mozlog else "text", + "stream": sys.stdout, }, "null": { "class": "logging.NullHandler", }, - "mozlog": { - "class": "logging.StreamHandler", - "stream": sys.stdout, - "formatter": "mozlog_json", - "level": logging.DEBUG, - "filters": ["request_id"], - }, - }, - "root": { - "handlers": ["mozlog" if use_mozlog else "humans"], - "level": logging_level, }, "loggers": { + "": {"handlers": ["console"], "level": logging_level}, "alembic": {"level": logging_level}, "ctms": {"level": logging_level}, "uvicorn": {"level": logging_level}, "uvicorn.access": {"handlers": ["null"], "propagate": False}, "sqlalchemy.engine": { - "handlers": ["mozlog" if use_mozlog else "humans"], "level": logging_level if log_sqlalchemy else logging.WARNING, "propagate": False, }, @@ -89,24 +64,6 @@ def configure_logging( } logging.config.dictConfig(logging_config) - structlog_processors: List[Processor] = [structlog.stdlib.filter_by_level] - structlog_processors.extend(structlog_dev_processors) - structlog_processors.extend( - [ - structlog.stdlib.PositionalArgumentsFormatter(), - structlog.processors.StackInfoRenderer(), - structlog.processors.format_exc_info, - structlog.processors.UnicodeDecoder(), - structlog_fmt_prep, - ] - ) - structlog.configure( - processors=structlog_processors, - context_class=dict, - logger_factory=structlog.stdlib.LoggerFactory(), - wrapper_class=structlog.stdlib.BoundLogger, - cache_logger_on_first_use=True, - ) return logging_config diff --git a/poetry.lock b/poetry.lock index 07add3a6..fecb7f2a 100644 --- a/poetry.lock +++ b/poetry.lock @@ -1,4 +1,4 @@ -# This file is automatically @generated by Poetry 1.8.3 and should not be changed by hand. +# This file is automatically @generated by Poetry 1.7.1 and should not be changed by hand. [[package]] name = "alabaster" @@ -2238,23 +2238,6 @@ files = [ [package.dependencies] pbr = ">=2.0.0,<2.1.0 || >2.1.0" -[[package]] -name = "structlog" -version = "24.4.0" -description = "Structured Logging for Python" -optional = false -python-versions = ">=3.8" -files = [ - {file = "structlog-24.4.0-py3-none-any.whl", hash = "sha256:597f61e80a91cc0749a9fd2a098ed76715a1c8a01f73e336b746504d1aad7610"}, - {file = "structlog-24.4.0.tar.gz", hash = "sha256:b27bfecede327a6d2da5fbc96bd859f114ecc398a6389d664f62085ee7ae6fc4"}, -] - -[package.extras] -dev = ["freezegun (>=0.2.8)", "mypy (>=1.4)", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "rich", "simplejson", "twisted"] -docs = ["cogapp", "furo", "myst-parser", "sphinx", "sphinx-notfound-page", "sphinxcontrib-mermaid", "sphinxext-opengraph", "twisted"] -tests = ["freezegun (>=0.2.8)", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "simplejson"] -typing = ["mypy (>=1.4)", "rich", "twisted"] - [[package]] name = "types-python-dateutil" version = "2.9.0.20240316" @@ -2568,4 +2551,4 @@ files = [ [metadata] lock-version = "2.0" python-versions = "^3.12.1" -content-hash = "e51302f9def969e6ccadaec1eb136fd2ae0c35b3e49eb71389845376668cb1ce" +content-hash = "a7ed7cc2114074357c76aeffb8fb98e2b9bce55ec3eb0d8b810b55ec957fa4c0" diff --git a/pyproject.toml b/pyproject.toml index aeb3fb3c..9d2ba114 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -27,7 +27,6 @@ dockerflow = {extras = ["fastapi"], version = "^2024.4.2"} sentry-sdk = "^2.11.0" lxml = "^5.2.2" prometheus-client = "0.20.0" -structlog = "^24.4.0" colorama = "^0.4.6" psycopg2 = "^2.9.9" google-auth = "^2.32.0" diff --git a/tests/unit/routers/contacts/test_api_post.py b/tests/unit/routers/contacts/test_api_post.py index 942e704a..ae31e36d 100644 --- a/tests/unit/routers/contacts/test_api_post.py +++ b/tests/unit/routers/contacts/test_api_post.py @@ -1,9 +1,9 @@ """Unit tests for POST /ctms (create record)""" +import logging from uuid import UUID import pytest -from structlog.testing import capture_logs from tests.unit.conftest import SAMPLE_CONTACT_PARAMS @@ -120,12 +120,13 @@ def _change_primary_email(contact): _compare_written_contacts(saved_contacts[0], orig_sample, email_id) -def test_create_with_non_json_is_error(client): +def test_create_with_non_json_is_error(client, caplog): """When non-JSON is posted /ctms, a 422 is returned""" data = b"this is not JSON" - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = client.post("/ctms", content=data) + assert resp.status_code == 422 assert resp.json()["detail"][0]["msg"] == "JSON decode error" - assert len(cap_logs) == 1 - assert "trace" not in cap_logs[0] + assert len(caplog.records) == 1 + assert not hasattr(caplog.records[0], "trace") diff --git a/tests/unit/routers/contacts/test_api_put.py b/tests/unit/routers/contacts/test_api_put.py index bd16e441..37ff4a46 100644 --- a/tests/unit/routers/contacts/test_api_put.py +++ b/tests/unit/routers/contacts/test_api_put.py @@ -1,9 +1,9 @@ """Unit tests for PUT /ctms/{email_id} (Create or update)""" +import logging from uuid import UUID, uuid4 import pytest -from structlog.testing import capture_logs from ctms.schemas import ContactPutSchema from tests.unit.conftest import SAMPLE_CONTACT_PARAMS @@ -128,13 +128,13 @@ def _change_primary_email(contact): _compare_written_contacts(saved_contacts[0], orig_sample, email_id) -def test_put_with_not_json_is_error(client, dbsession): +def test_put_with_not_json_is_error(client, dbsession, caplog): """Calling PUT with a text body is a 422 validation error.""" email_id = str(uuid4()) data = b"make a contact please" - with capture_logs() as caplogs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = client.put(f"/ctms/{email_id}", content=data) assert resp.status_code == 422 assert resp.json()["detail"][0]["msg"] == "JSON decode error" - assert len(caplogs) == 1 - assert "trace" not in caplogs[0] + assert len(caplog.records) == 1 + assert not hasattr(caplog.records[0], "trace") diff --git a/tests/unit/routers/test_platform.py b/tests/unit/routers/test_platform.py index 3e3d89f7..e3a38419 100644 --- a/tests/unit/routers/test_platform.py +++ b/tests/unit/routers/test_platform.py @@ -1,24 +1,24 @@ import json +import logging from pathlib import Path from unittest import mock import pytest from sqlalchemy.exc import TimeoutError as SQATimeoutError -from structlog.testing import capture_logs from ctms.app import app -def test_read_root(anon_client): +def test_read_root(anon_client, caplog): """The site root redirects to the Swagger docs""" - with capture_logs() as caplogs: + with caplog.at_level(level=logging.INFO, logger="ctms.web"): resp = anon_client.get("/") assert resp.status_code == 200 assert len(resp.history) == 1 prev_resp = resp.history[0] assert prev_resp.status_code == 307 # Temporary Redirect assert prev_resp.headers["location"] == "./docs" - assert len(caplogs) == 2 + assert len(caplog.records) == 2 def test_read_version(anon_client): @@ -53,9 +53,9 @@ def test_crash_unauthorized(anon_client): assert resp.json() == {"detail": "Not authenticated"} -def test_read_heartbeat(anon_client): +def test_read_heartbeat(anon_client, caplog): """The platform calls /__heartbeat__ to check backing services.""" - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = anon_client.get("/__heartbeat__") assert resp.status_code == 200 data = resp.json() @@ -64,7 +64,7 @@ def test_read_heartbeat(anon_client): "details": {}, "status": "ok", } - assert len(cap_logs) == 1 + assert len(caplog.messages) == 1 @mock.patch("ctms.routers.platform.SessionLocal") @@ -99,9 +99,9 @@ def test_read_health(anon_client): assert resp.status_code == 200 -def test_get_metrics(anon_client, setup_metrics): +def test_get_metrics(anon_client, setup_metrics, caplog): """An anonoymous user can request metrics.""" - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = anon_client.get("/metrics") assert resp.status_code == 200 - assert len(cap_logs) == 1 + assert len(caplog.messages) == 1 diff --git a/tests/unit/test_auth.py b/tests/unit/test_auth.py index 45029b56..1408495d 100644 --- a/tests/unit/test_auth.py +++ b/tests/unit/test_auth.py @@ -1,11 +1,11 @@ """Test authentication""" from datetime import datetime, timedelta, timezone +import logging import pytest from jose import jwt from requests.auth import HTTPBasicAuth -from structlog.testing import capture_logs from ctms.app import app from ctms.auth import create_access_token, hash_password, verify_password @@ -121,53 +121,55 @@ def test_post_token_fails_wrong_grant(anon_client, client_id_and_secret): } -def test_post_token_fails_no_credentials(anon_client): +def test_post_token_fails_no_credentials(anon_client, caplog): """If no credentials are passed, token generation fails.""" - with capture_logs() as caplog: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = anon_client.post("/token", data={"grant_type": "client_credentials"}) assert resp.status_code == 400 assert resp.json() == {"detail": "Incorrect username or password"} - assert caplog[0]["token_fail"] == "No credentials" + assert caplog.records[0].token_fail == "No credentials" -def test_post_token_fails_unknown_api_client(anon_client, client_id_and_secret): +def test_post_token_fails_unknown_api_client(anon_client, client_id_and_secret, caplog): """Authentication failes on unknown api_client ID.""" good_id, good_secret = client_id_and_secret - with capture_logs() as caplog: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = anon_client.post( "/token", auth=HTTPBasicAuth(good_id + "x", good_secret) ) assert resp.status_code == 400 assert resp.json() == {"detail": "Incorrect username or password"} - assert caplog[0]["token_creds_from"] == "header" - assert caplog[0]["token_fail"] == "No client record" + assert caplog.records[0].token_creds_from == "header" + assert caplog.records[0].token_fail == "No client record" -def test_post_token_fails_bad_credentials(anon_client, client_id_and_secret): +def test_post_token_fails_bad_credentials(anon_client, client_id_and_secret, caplog): """Authentication fails on bad credentials.""" good_id, good_secret = client_id_and_secret - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.post( "/token", auth=HTTPBasicAuth(good_id, good_secret + "x") ) assert resp.status_code == 400 assert resp.json() == {"detail": "Incorrect username or password"} - assert caplog[0]["token_creds_from"] == "header" - assert caplog[0]["token_fail"] == "Bad credentials" + assert caplog.records[0].token_creds_from == "header" + assert caplog.records[0].token_fail == "Bad credentials" -def test_post_token_fails_disabled_client(dbsession, anon_client, client_id_and_secret): +def test_post_token_fails_disabled_client( + dbsession, anon_client, client_id_and_secret, caplog +): """Authentication fails when the client is disabled.""" client_id, client_secret = client_id_and_secret api_client = get_api_client_by_id(dbsession, client_id) api_client.enabled = False dbsession.commit() - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.post("/token", auth=HTTPBasicAuth(client_id, client_secret)) assert resp.status_code == 400 assert resp.json() == {"detail": "Incorrect username or password"} - assert caplog[0]["token_creds_from"] == "header" - assert caplog[0]["token_fail"] == "Client disabled" + assert caplog.records[0].token_creds_from == "header" + assert caplog.records[0].token_fail == "Client disabled" def test_get_ctms_with_token( @@ -215,7 +217,7 @@ def test_successful_login_tracks_last_access( def test_get_ctms_with_invalid_token_fails( - email_factory, anon_client, test_token_settings, client_id_and_secret + email_factory, anon_client, test_token_settings, client_id_and_secret, caplog ): """Calling an authenticated API with an invalid token is an error""" email = email_factory() @@ -226,36 +228,36 @@ def test_get_ctms_with_invalid_token_fails( secret_key="secret_key_from_other_deploy", # pragma: allowlist secret expires_delta=test_token_settings["expires_delta"], ) - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.get( f"/ctms/{email.email_id}", headers={"Authorization": f"Bearer {token}"}, ) assert resp.status_code == 401 assert resp.json() == {"detail": "Could not validate credentials"} - assert caplog[0]["auth_fail"] == "No or bad token" + assert caplog.records[0].auth_fail == "No or bad token" def test_get_ctms_with_invalid_namespace_fails( - email_factory, anon_client, test_token_settings, client_id_and_secret + email_factory, anon_client, test_token_settings, client_id_and_secret, caplog ): """Calling an authenticated API with an unexpected namespace is an error""" email = email_factory() client_id = client_id_and_secret[0] token = create_access_token({"sub": f"unknown:{client_id}"}, **test_token_settings) - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.get( f"/ctms/{email.email_id}", headers={"Authorization": f"Bearer {token}"}, ) assert resp.status_code == 401 assert resp.json() == {"detail": "Could not validate credentials"} - assert caplog[0]["auth_fail"] == "Bad namespace" + assert caplog.records[0].auth_fail == "Bad namespace" def test_get_ctms_with_unknown_client_fails( - email_factory, anon_client, test_token_settings, client_id_and_secret + email_factory, anon_client, test_token_settings, client_id_and_secret, caplog ): """A token with an unknown (deleted?) API client name is an error""" email = email_factory() @@ -264,18 +266,18 @@ def test_get_ctms_with_unknown_client_fails( token = create_access_token( {"sub": f"api_client:not_{client_id}"}, **test_token_settings ) - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.get( f"/ctms/{email.email_id}", headers={"Authorization": f"Bearer {token}"}, ) assert resp.status_code == 401 assert resp.json() == {"detail": "Could not validate credentials"} - assert caplog[0]["auth_fail"] == "No client record" + assert caplog.records[0].auth_fail == "No client record" def test_get_ctms_with_expired_token_fails( - email_factory, anon_client, test_token_settings, client_id_and_secret + email_factory, anon_client, test_token_settings, client_id_and_secret, caplog ): """Calling an authenticated API with an expired token is an error""" email = email_factory() @@ -285,18 +287,23 @@ def test_get_ctms_with_expired_token_fails( token = create_access_token( {"sub": f"api_client:{client_id}"}, **test_token_settings, now=yesterday ) - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.get( f"/ctms/{email.email_id}", headers={"Authorization": f"Bearer {token}"}, ) assert resp.status_code == 401 assert resp.json() == {"detail": "Could not validate credentials"} - assert caplog[0]["auth_fail"] == "No or bad token" + assert caplog.records[0].auth_fail == "No or bad token" def test_get_ctms_with_disabled_client_fails( - dbsession, email_factory, anon_client, test_token_settings, client_id_and_secret + dbsession, + email_factory, + anon_client, + test_token_settings, + client_id_and_secret, + caplog, ): """Calling an authenticated API with a valid token for an expired client is an error.""" email = email_factory() @@ -309,14 +316,14 @@ def test_get_ctms_with_disabled_client_fails( api_client.enabled = False dbsession.commit() - with capture_logs() as caplog: + with caplog.at_level(logging.INFO): resp = anon_client.get( f"/ctms/{email.email_id}", headers={"Authorization": f"Bearer {token}"}, ) assert resp.status_code == 400 assert resp.json() == {"detail": "API Client has been disabled"} - assert caplog[0]["auth_fail"] == "Client disabled" + assert caplog.records[0].auth_fail == "Client disabled" def test_hashed_passwords(): diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index dc0df2e0..b57dedab 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -1,37 +1,39 @@ # -*- coding: utf-8 -*- """Tests for logging helpers""" +import logging from unittest.mock import patch import pytest from requests.auth import HTTPBasicAuth -from structlog.testing import capture_logs +from dockerflow.logging import JsonLogFormatter from ctms.log import configure_logging -def test_request_log(client, email_factory): +def test_request_log(client, email_factory, caplog): """A request is logged.""" email = email_factory() email_id = str(email.email_id) - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = client.get( f"/ctms/{email_id}", headers={ "X-Request-Id": "foo-bar", }, ) + assert resp.status_code == 200 - assert len(cap_logs) == 1 - log = cap_logs[0] - assert "duration_s" in log + assert len(caplog.records) == 1 + log = caplog.records[0] + assert hasattr(log, "duration_s") expected_log = { "client_allowed": True, "client_host": "testclient", "client_id": "test_client", - "duration_s": log["duration_s"], - "event": f"testclient:50000 test_client 'GET /ctms/{email_id} HTTP/1.1' 200", + "duration_s": log.duration_s, + "msg": f"testclient:50000 test_client 'GET /ctms/{email_id} HTTP/1.1' 200", "headers": { "host": "testserver", "user-agent": "testclient", @@ -40,7 +42,6 @@ def test_request_log(client, email_factory): "connection": "keep-alive", "x-request-id": "foo-bar", }, - "log_level": "info", "method": "GET", "path": f"/ctms/{email_id}", "path_params": {"email_id": email_id}, @@ -48,13 +49,14 @@ def test_request_log(client, email_factory): "status_code": 200, "rid": "foo-bar", } - assert log == expected_log + fmtr = JsonLogFormatter() + assert fmtr.convert_record(log)["Fields"] == expected_log -def test_token_request_log(anon_client, client_id_and_secret): +def test_token_request_log(anon_client, client_id_and_secret, caplog): """A token request log has omitted headers.""" client_id, client_secret = client_id_and_secret - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = anon_client.post( "/token", data={"grant_type": "client_credentials"}, @@ -62,44 +64,43 @@ def test_token_request_log(anon_client, client_id_and_secret): cookies={"csrftoken": "0WzT-base64-string"}, ) assert resp.status_code == 200 - assert len(cap_logs) == 1 - log = cap_logs[0] - assert log["client_id"] == client_id - assert log["token_creds_from"] == "header" - assert log["headers"]["authorization"] == "[OMITTED]" - assert log["headers"]["content-length"] == "29" - assert log["headers"]["cookie"] == "[OMITTED]" + assert len(caplog.records) == 1 + log = caplog.records[0] + assert log.client_id == client_id + assert log.token_creds_from == "header" + assert log.headers["authorization"] == "[OMITTED]" + assert log.headers["content-length"] == "29" + assert log.headers["cookie"] == "[OMITTED]" -def test_log_omits_emails(client, email_factory): +def test_log_omits_emails(client, email_factory, caplog): """The logger omits emails from query params.""" email = email_factory(with_fxa=True) url = ( f"/ctms?primary_email={email.primary_email}&fxa_primary_email={email.fxa.primary_email}" f"&email_id={email.email_id}" ) - with capture_logs() as cap_logs: + with caplog.at_level(logging.INFO, logger="ctms.web"): resp = client.get(url) assert resp.status_code == 200 - assert len(cap_logs) == 1 - log = cap_logs[0] - assert log["query"] == { + assert len(caplog.records) == 1 + log = caplog.records[0] + assert log.query == { "email_id": str(email.email_id), "fxa_primary_email": "[OMITTED]", "primary_email": "[OMITTED]", } -def test_log_crash(client): +def test_log_crash(client, caplog): """Exceptions are logged.""" path = "/__crash__" - with pytest.raises(RuntimeError), capture_logs() as cap_logs: + with pytest.raises(RuntimeError), caplog.at_level(logging.ERROR): client.get(path) - assert len(cap_logs) == 1 - log = cap_logs[0] - assert log["log_level"] == "error" - assert "rid" in log - assert log["event"] == "testclient:50000 test_client 'GET /__crash__ HTTP/1.1' 500" + assert len(caplog.records) == 1 + log = caplog.records[0] + assert hasattr(log, "rid") and log.rid is not None + assert log.msg == "testclient:50000 test_client 'GET /__crash__ HTTP/1.1' 500" @pytest.mark.parametrize( @@ -113,11 +114,8 @@ def test_configure_logging(use_mozlog, logging_level): with patch("ctms.log.logging.config.dictConfig") as mock_dc: configure_logging(use_mozlog, logging_level) mock_dc.assert_called_once() - args = mock_dc.mock_calls[0].args - assert len(args) == 1 - if use_mozlog: - handlers = ["mozlog"] - else: - handlers = ["humans"] - assert args[0]["root"] == {"handlers": handlers, "level": logging_level} - assert args[0]["loggers"]["ctms"]["level"] == logging_level + (args,) = mock_dc.mock_calls[0].args + assert ( + args["handlers"]["console"]["formatter"] == "mozlog" if use_mozlog else "text" + ) + assert args["loggers"]["ctms"]["level"] == logging_level From 57ec3ac35585cc6fe769829c50d99fe73bef3fc7 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Tue, 6 Aug 2024 15:44:29 +0200 Subject: [PATCH 4/7] Move log initialization to app.py --- asgi.py | 7 +--- ctms/app.py | 4 +- ctms/log.py | 95 +++++++++++++++++++----------------------- tests/unit/test_log.py | 20 --------- 4 files changed, 47 insertions(+), 79 deletions(-) diff --git a/asgi.py b/asgi.py index 238bc0c8..3b4a7966 100644 --- a/asgi.py +++ b/asgi.py @@ -1,22 +1,17 @@ import uvicorn from ctms.config import Settings -from ctms.log import configure_logging settings = Settings() if __name__ == "__main__": - logging_config = configure_logging( - settings.use_mozlog, settings.logging_level.name, settings.log_sqlalchemy - ) - server = uvicorn.Server( uvicorn.Config( "ctms.app:app", host=settings.host, port=settings.port, - log_config=logging_config, + log_config=None, ) ) server.run() diff --git a/ctms/app.py b/ctms/app.py index b4a47d51..6e1e8a5e 100644 --- a/ctms/app.py +++ b/ctms/app.py @@ -12,7 +12,7 @@ from .config import get_version from .database import SessionLocal from .exception_capture import init_sentry -from .log import context_from_request, get_log_line +from .log import CONFIG as LOG_CONFIG, context_from_request, get_log_line from .metrics import ( METRICS_REGISTRY, emit_response_metrics, @@ -24,6 +24,8 @@ from .routers import contacts, platform +logging.config.dictConfig(LOG_CONFIG) + web_logger = logging.getLogger("ctms.web") app = FastAPI( diff --git a/ctms/log.py b/ctms/log.py index 792d12c7..d302bac6 100644 --- a/ctms/log.py +++ b/ctms/log.py @@ -1,70 +1,61 @@ """Logging configuration""" import logging -import logging.config import sys -from typing import Any, Dict, List, Optional +from typing import Any, Dict, Optional from dockerflow.logging import request_id_context from fastapi import Request from starlette.routing import Match +from ctms.config import Settings -def configure_logging( - use_mozlog: bool = True, logging_level: str = "INFO", log_sqlalchemy: bool = False -) -> dict: - """Configure Python logging. +settings = Settings() - :param use_mozlog: If True, use MozLog format, appropriate for deployments. - If False, format logs for human consumption. - :param logging_level: The logging level, such as DEBUG or INFO. - :param log_sqlalchemy: Include SQLAlchemy engine logs, such as SQL statements - """ - logging_config = { - "version": 1, - "disable_existing_loggers": False, - "filters": { - "request_id": { - "()": "dockerflow.logging.RequestIdLogFilter", - }, +CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "filters": { + "request_id": { + "()": "dockerflow.logging.RequestIdLogFilter", }, - "formatters": { - "mozlog_json": { - "()": "dockerflow.logging.JsonLogFormatter", - "logger_name": "ctms", - }, - "text": { - "format": "%(asctime)s %(levelname)-8s [%(rid)s] %(name)-15s %(message)s", - "datefmt": "%Y-%m-%d %H:%M:%S", - }, + }, + "formatters": { + "mozlog_json": { + "()": "dockerflow.logging.JsonLogFormatter", + "logger_name": "ctms", }, - "handlers": { - "console": { - "level": logging_level, - "class": "logging.StreamHandler", - "filters": ["request_id"], - "formatter": "mozlog_json" if use_mozlog else "text", - "stream": sys.stdout, - }, - "null": { - "class": "logging.NullHandler", - }, + "text": { + "format": "%(asctime)s %(levelname)-8s [%(rid)s] %(name)-15s %(message)s", + "datefmt": "%Y-%m-%d %H:%M:%S", }, - "loggers": { - "": {"handlers": ["console"], "level": logging_level}, - "alembic": {"level": logging_level}, - "ctms": {"level": logging_level}, - "uvicorn": {"level": logging_level}, - "uvicorn.access": {"handlers": ["null"], "propagate": False}, - "sqlalchemy.engine": { - "level": logging_level if log_sqlalchemy else logging.WARNING, - "propagate": False, - }, + }, + "handlers": { + "console": { + "level": settings.logging_level.name, + "class": "logging.StreamHandler", + "filters": ["request_id"], + "formatter": "mozlog_json" if settings.use_mozlog else "text", + "stream": sys.stdout, }, - } - logging.config.dictConfig(logging_config) - - return logging_config + "null": { + "class": "logging.NullHandler", + }, + }, + "loggers": { + "": {"handlers": ["console"]}, + "request.summary": {"level": logging.INFO}, + "ctms": {"level": logging.DEBUG}, + "uvicorn": {"level": logging.INFO}, + "uvicorn.access": {"handlers": ["null"], "propagate": False}, + "sqlalchemy.engine": { + "level": settings.logging_level.name + if settings.log_sqlalchemy + else logging.WARNING, + "propagate": False, + }, + }, +} def context_from_request(request: Request) -> Dict: diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index b57dedab..b0f7bb60 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -8,8 +8,6 @@ from requests.auth import HTTPBasicAuth from dockerflow.logging import JsonLogFormatter -from ctms.log import configure_logging - def test_request_log(client, email_factory, caplog): """A request is logged.""" @@ -101,21 +99,3 @@ def test_log_crash(client, caplog): log = caplog.records[0] assert hasattr(log, "rid") and log.rid is not None assert log.msg == "testclient:50000 test_client 'GET /__crash__ HTTP/1.1' 500" - - -@pytest.mark.parametrize( - "use_mozlog,logging_level", - ( - (True, "INFO"), - (False, "WARNING"), - ), -) -def test_configure_logging(use_mozlog, logging_level): - with patch("ctms.log.logging.config.dictConfig") as mock_dc: - configure_logging(use_mozlog, logging_level) - mock_dc.assert_called_once() - (args,) = mock_dc.mock_calls[0].args - assert ( - args["handlers"]["console"]["formatter"] == "mozlog" if use_mozlog else "text" - ) - assert args["loggers"]["ctms"]["level"] == logging_level From 32a85824e0650199767af3c2aeb7c903ba5c9463 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Tue, 6 Aug 2024 17:01:20 +0200 Subject: [PATCH 5/7] Do not reconfigure logs using Alembic config --- migrations/env.py | 3 ++- tests/unit/conftest.py | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/migrations/env.py b/migrations/env.py index 9667898b..cefb04e8 100644 --- a/migrations/env.py +++ b/migrations/env.py @@ -14,7 +14,8 @@ # Interpret the config file for Python logging. # This line sets up loggers basically. -fileConfig(config.config_file_name) +if not context.config.attributes.get("unit-tests", False): + fileConfig(config.config_file_name) # add your model's MetaData object here # for 'autogenerate' support diff --git a/tests/unit/conftest.py b/tests/unit/conftest.py index 15c877a1..09fbb59c 100644 --- a/tests/unit/conftest.py +++ b/tests/unit/conftest.py @@ -113,7 +113,7 @@ def engine(pytestconfig): ) cfg = alembic_config.Config(os.path.join(APP_FOLDER, "alembic.ini")) - + cfg.attributes["unit-tests"] = True cfg.attributes["connection"] = test_engine alembic_command.upgrade(cfg, "head") From 2f73014ad33c5fad2a36955b97a5c43428c87c90 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Tue, 6 Aug 2024 17:18:01 +0200 Subject: [PATCH 6/7] Run ruff manually to sort imports --- ctms/app.py | 5 ++--- tests/unit/test_auth.py | 2 +- tests/unit/test_log.py | 2 +- 3 files changed, 4 insertions(+), 5 deletions(-) diff --git a/ctms/app.py b/ctms/app.py index 6e1e8a5e..b276c42a 100644 --- a/ctms/app.py +++ b/ctms/app.py @@ -2,7 +2,6 @@ import sys import time - import uvicorn from dockerflow.fastapi import router as dockerflow_router from dockerflow.fastapi.middleware import RequestIdMiddleware @@ -12,7 +11,8 @@ from .config import get_version from .database import SessionLocal from .exception_capture import init_sentry -from .log import CONFIG as LOG_CONFIG, context_from_request, get_log_line +from .log import CONFIG as LOG_CONFIG +from .log import context_from_request, get_log_line from .metrics import ( METRICS_REGISTRY, emit_response_metrics, @@ -23,7 +23,6 @@ ) from .routers import contacts, platform - logging.config.dictConfig(LOG_CONFIG) web_logger = logging.getLogger("ctms.web") diff --git a/tests/unit/test_auth.py b/tests/unit/test_auth.py index 1408495d..f24ebcd1 100644 --- a/tests/unit/test_auth.py +++ b/tests/unit/test_auth.py @@ -1,7 +1,7 @@ """Test authentication""" -from datetime import datetime, timedelta, timezone import logging +from datetime import datetime, timedelta, timezone import pytest from jose import jwt diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index b0f7bb60..a266f36a 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -5,8 +5,8 @@ from unittest.mock import patch import pytest -from requests.auth import HTTPBasicAuth from dockerflow.logging import JsonLogFormatter +from requests.auth import HTTPBasicAuth def test_request_log(client, email_factory, caplog): From 5b520922fde730c74dac727b89114aef8d80bc6c Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Wed, 7 Aug 2024 17:05:10 +0200 Subject: [PATCH 7/7] @grahamalama review --- migrations/env.py | 2 ++ tests/unit/routers/contacts/test_api_post.py | 2 +- tests/unit/routers/contacts/test_api_put.py | 2 +- 3 files changed, 4 insertions(+), 2 deletions(-) diff --git a/migrations/env.py b/migrations/env.py index cefb04e8..d4ca9fa8 100644 --- a/migrations/env.py +++ b/migrations/env.py @@ -14,6 +14,8 @@ # Interpret the config file for Python logging. # This line sets up loggers basically. +# We don't want this logging setup during unit tests, +# see `alembic_command.upgrade(cfg, "head")` in `conftest.py`. if not context.config.attributes.get("unit-tests", False): fileConfig(config.config_file_name) diff --git a/tests/unit/routers/contacts/test_api_post.py b/tests/unit/routers/contacts/test_api_post.py index ae31e36d..90c48144 100644 --- a/tests/unit/routers/contacts/test_api_post.py +++ b/tests/unit/routers/contacts/test_api_post.py @@ -129,4 +129,4 @@ def test_create_with_non_json_is_error(client, caplog): assert resp.status_code == 422 assert resp.json()["detail"][0]["msg"] == "JSON decode error" assert len(caplog.records) == 1 - assert not hasattr(caplog.records[0], "trace") + assert caplog.records[0].status_code == 422 diff --git a/tests/unit/routers/contacts/test_api_put.py b/tests/unit/routers/contacts/test_api_put.py index 37ff4a46..594b644a 100644 --- a/tests/unit/routers/contacts/test_api_put.py +++ b/tests/unit/routers/contacts/test_api_put.py @@ -137,4 +137,4 @@ def test_put_with_not_json_is_error(client, dbsession, caplog): assert resp.status_code == 422 assert resp.json()["detail"][0]["msg"] == "JSON decode error" assert len(caplog.records) == 1 - assert not hasattr(caplog.records[0], "trace") + assert caplog.records[0].status_code == 422