From a47461dd6887e5960b495eaa9d812e875a60ddc1 Mon Sep 17 00:00:00 2001 From: karthikeyannhs <174426205+Karthikeyannhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 10:20:24 +0100 Subject: [PATCH 1/6] add lambda request id in logs events --- src/eligibility_signposting_api/app.py | 3 +++ src/eligibility_signposting_api/config/config.py | 10 +++++++++- src/eligibility_signposting_api/contextvars_manager.py | 3 +++ 3 files changed, 15 insertions(+), 1 deletion(-) create mode 100644 src/eligibility_signposting_api/contextvars_manager.py diff --git a/src/eligibility_signposting_api/app.py b/src/eligibility_signposting_api/app.py index 6246a807c..8a74890ba 100644 --- a/src/eligibility_signposting_api/app.py +++ b/src/eligibility_signposting_api/app.py @@ -11,6 +11,7 @@ from eligibility_signposting_api.common.error_handler import handle_exception from eligibility_signposting_api.common.request_validator import validate_request_params from eligibility_signposting_api.config.config import config, init_logging +from eligibility_signposting_api.contextvars_manager import request_id_var from eligibility_signposting_api.views import eligibility_blueprint init_logging() @@ -25,6 +26,8 @@ def main() -> None: # pragma: no cover @validate_request_params() def lambda_handler(event: LambdaEvent, context: LambdaContext) -> dict[str, Any]: # pragma: no cover + request_id_var.set(context.aws_request_id) + """Run the Flask app as an AWS Lambda.""" app = create_app() app.debug = config()["log_level"] == logging.DEBUG diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index 722e90133..f1dafe65f 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -7,6 +7,7 @@ from pythonjsonlogger.json import JsonFormatter from yarl import URL +from eligibility_signposting_api.contextvars_manager import request_id_var from eligibility_signposting_api.repos.campaign_repo import BucketName from eligibility_signposting_api.repos.person_repo import TableName @@ -59,9 +60,16 @@ def config() -> dict[str, Any]: } +class LoggingJsonFormatter(logging.Formatter): + def format(self, record: logging.LogRecord) -> str: + # Insert request_id from contextvar for every log record + record.request_id = request_id_var.get() or "-" + return super().format(record) + + def init_logging(quieten: Sequence[str] = ("asyncio", "botocore", "boto3", "mangum", "urllib3")) -> None: log_format = "%(asctime)s %(levelname)-8s %(name)s %(module)s.py:%(funcName)s():%(lineno)d %(message)s" - formatter = JsonFormatter(log_format) + formatter = LoggingJsonFormatter(log_format) handler = logging.StreamHandler() handler.setFormatter(formatter) logging.root.handlers = [] # Clear any existing handlers diff --git a/src/eligibility_signposting_api/contextvars_manager.py b/src/eligibility_signposting_api/contextvars_manager.py new file mode 100644 index 000000000..db4d46f81 --- /dev/null +++ b/src/eligibility_signposting_api/contextvars_manager.py @@ -0,0 +1,3 @@ +from contextvars import ContextVar + +request_id_var: ContextVar[str | None] = ContextVar("request_id", default=None) From bdf24eed356bdce297c4f79160afb718495b9a87 Mon Sep 17 00:00:00 2001 From: karthikeyannhs <174426205+Karthikeyannhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 12:08:10 +0100 Subject: [PATCH 2/6] linting fix --- src/eligibility_signposting_api/config/config.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index f1dafe65f..9591fd422 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -4,7 +4,6 @@ from functools import cache from typing import Any, NewType -from pythonjsonlogger.json import JsonFormatter from yarl import URL from eligibility_signposting_api.contextvars_manager import request_id_var From adc998be52332f8692b0b80d76fe09fcd196204b Mon Sep 17 00:00:00 2001 From: karthikeyannhs <174426205+Karthikeyannhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 12:49:23 +0100 Subject: [PATCH 3/6] revoked custom formatter and reapplied JsonFormatter --- .../config/config.py | 21 ++++++++++--------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index 9591fd422..837e81511 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -4,6 +4,7 @@ from functools import cache from typing import Any, NewType +from pythonjsonlogger.json import JsonFormatter from yarl import URL from eligibility_signposting_api.contextvars_manager import request_id_var @@ -59,21 +60,21 @@ def config() -> dict[str, Any]: } -class LoggingJsonFormatter(logging.Formatter): - def format(self, record: logging.LogRecord) -> str: - # Insert request_id from contextvar for every log record - record.request_id = request_id_var.get() or "-" - return super().format(record) +class EnrichedJsonFormatter(JsonFormatter): + def add_fields(self, log_record: dict[str, Any], record: logging.LogRecord, message_dict: dict[str, Any]) -> None: + super().add_fields(log_record, record, message_dict) + log_record["request_id"] = request_id_var.get() or "-" def init_logging(quieten: Sequence[str] = ("asyncio", "botocore", "boto3", "mangum", "urllib3")) -> None: - log_format = "%(asctime)s %(levelname)-8s %(name)s %(module)s.py:%(funcName)s():%(lineno)d %(message)s" - formatter = LoggingJsonFormatter(log_format) + log_format = "%(asctime)s %(levelname)s %(name)s %(module)s %(funcName)s %(lineno)d %(message)s" + formatter = EnrichedJsonFormatter(log_format) handler = logging.StreamHandler() handler.setFormatter(formatter) - logging.root.handlers = [] # Clear any existing handlers - logging.root.setLevel(LOG_LEVEL) # Set log level - logging.root.addHandler(handler) # Add handler + + logging.root.handlers = [] # Remove default handlers + logging.root.setLevel(LOG_LEVEL) + logging.root.addHandler(handler) for q in quieten: logging.getLogger(q).setLevel(logging.WARNING) From 60e125b72651d09b2b702a87323a15f0eefa922c Mon Sep 17 00:00:00 2001 From: karthikeyannhs <174426205+Karthikeyannhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 13:02:50 +0100 Subject: [PATCH 4/6] revoked formatting --- src/eligibility_signposting_api/config/config.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index 837e81511..ffac087dc 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -67,7 +67,7 @@ def add_fields(self, log_record: dict[str, Any], record: logging.LogRecord, mess def init_logging(quieten: Sequence[str] = ("asyncio", "botocore", "boto3", "mangum", "urllib3")) -> None: - log_format = "%(asctime)s %(levelname)s %(name)s %(module)s %(funcName)s %(lineno)d %(message)s" + log_format = "%(asctime)s %(levelname)-8s %(name)s %(module)s.py:%(funcName)s():%(lineno)d %(message)s" formatter = EnrichedJsonFormatter(log_format) handler = logging.StreamHandler() handler.setFormatter(formatter) From 7ba99daebb2df2f02c6a5ca215b11d2a3a6b321f Mon Sep 17 00:00:00 2001 From: karthikeyannhs <174426205+Karthikeyannhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 13:19:04 +0100 Subject: [PATCH 5/6] added wrapper for registering requestid --- src/eligibility_signposting_api/app.py | 5 ++--- .../common/contextvars_manager.py | 20 +++++++++++++++++++ .../config/config.py | 2 +- .../contextvars_manager.py | 3 --- 4 files changed, 23 insertions(+), 7 deletions(-) create mode 100644 src/eligibility_signposting_api/common/contextvars_manager.py delete mode 100644 src/eligibility_signposting_api/contextvars_manager.py diff --git a/src/eligibility_signposting_api/app.py b/src/eligibility_signposting_api/app.py index 8a74890ba..13709f217 100644 --- a/src/eligibility_signposting_api/app.py +++ b/src/eligibility_signposting_api/app.py @@ -8,10 +8,10 @@ from mangum.types import LambdaContext, LambdaEvent from eligibility_signposting_api import audit, repos, services +from eligibility_signposting_api.common.contextvars_manager import get_request_id_for_logging from eligibility_signposting_api.common.error_handler import handle_exception from eligibility_signposting_api.common.request_validator import validate_request_params from eligibility_signposting_api.config.config import config, init_logging -from eligibility_signposting_api.contextvars_manager import request_id_var from eligibility_signposting_api.views import eligibility_blueprint init_logging() @@ -24,10 +24,9 @@ def main() -> None: # pragma: no cover app.run(debug=config()["log_level"] == logging.DEBUG) +@get_request_id_for_logging() @validate_request_params() def lambda_handler(event: LambdaEvent, context: LambdaContext) -> dict[str, Any]: # pragma: no cover - request_id_var.set(context.aws_request_id) - """Run the Flask app as an AWS Lambda.""" app = create_app() app.debug = config()["log_level"] == logging.DEBUG diff --git a/src/eligibility_signposting_api/common/contextvars_manager.py b/src/eligibility_signposting_api/common/contextvars_manager.py new file mode 100644 index 000000000..1dc90f0b1 --- /dev/null +++ b/src/eligibility_signposting_api/common/contextvars_manager.py @@ -0,0 +1,20 @@ +from collections.abc import Callable +from contextvars import ContextVar +from functools import wraps +from typing import Any + +from mangum.types import LambdaContext, LambdaEvent + +request_id_var: ContextVar[str | None] = ContextVar("request_id", default=None) + + +def get_request_id_for_logging() -> Callable: + def decorator(func: Callable) -> Callable: + @wraps(func) + def wrapper(event: LambdaEvent, context: LambdaContext) -> dict[str, Any] | None: + request_id_var.set(context.aws_request_id) + return func(event, context) + + return wrapper + + return decorator diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index ffac087dc..e052ffcc6 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -7,7 +7,7 @@ from pythonjsonlogger.json import JsonFormatter from yarl import URL -from eligibility_signposting_api.contextvars_manager import request_id_var +from eligibility_signposting_api.common.contextvars_manager import request_id_var from eligibility_signposting_api.repos.campaign_repo import BucketName from eligibility_signposting_api.repos.person_repo import TableName diff --git a/src/eligibility_signposting_api/contextvars_manager.py b/src/eligibility_signposting_api/contextvars_manager.py deleted file mode 100644 index db4d46f81..000000000 --- a/src/eligibility_signposting_api/contextvars_manager.py +++ /dev/null @@ -1,3 +0,0 @@ -from contextvars import ContextVar - -request_id_var: ContextVar[str | None] = ContextVar("request_id", default=None) From aaacf6a751c3a13b895db36466a0a9f853d61bd2 Mon Sep 17 00:00:00 2001 From: Shweta <216860557+shweta-nhs@users.noreply.github.com> Date: Tue, 22 Jul 2025 15:40:44 +0100 Subject: [PATCH 6/6] Adds unit tests for log format --- src/eligibility_signposting_api/app.py | 6 +- .../audit/audit_models.py | 2 +- .../common/contextvars_manager.py | 20 --- .../config/config.py | 23 ---- .../logging/__init__.py | 0 .../logging/logs_manager.py | 48 +++++++ tests/unit/logging/__init__.py | 0 tests/unit/logging/test_logs_manager.py | 120 ++++++++++++++++++ 8 files changed, 172 insertions(+), 47 deletions(-) delete mode 100644 src/eligibility_signposting_api/common/contextvars_manager.py create mode 100644 src/eligibility_signposting_api/logging/__init__.py create mode 100644 src/eligibility_signposting_api/logging/logs_manager.py create mode 100644 tests/unit/logging/__init__.py create mode 100644 tests/unit/logging/test_logs_manager.py diff --git a/src/eligibility_signposting_api/app.py b/src/eligibility_signposting_api/app.py index 13709f217..70375fafe 100644 --- a/src/eligibility_signposting_api/app.py +++ b/src/eligibility_signposting_api/app.py @@ -8,10 +8,10 @@ from mangum.types import LambdaContext, LambdaEvent from eligibility_signposting_api import audit, repos, services -from eligibility_signposting_api.common.contextvars_manager import get_request_id_for_logging from eligibility_signposting_api.common.error_handler import handle_exception from eligibility_signposting_api.common.request_validator import validate_request_params -from eligibility_signposting_api.config.config import config, init_logging +from eligibility_signposting_api.config.config import config +from eligibility_signposting_api.logging.logs_manager import add_request_id_to_logs, init_logging from eligibility_signposting_api.views import eligibility_blueprint init_logging() @@ -24,7 +24,7 @@ def main() -> None: # pragma: no cover app.run(debug=config()["log_level"] == logging.DEBUG) -@get_request_id_for_logging() +@add_request_id_to_logs() @validate_request_params() def lambda_handler(event: LambdaEvent, context: LambdaContext) -> dict[str, Any]: # pragma: no cover """Run the Flask app as an AWS Lambda.""" diff --git a/src/eligibility_signposting_api/audit/audit_models.py b/src/eligibility_signposting_api/audit/audit_models.py index 17467130f..d80409a8c 100644 --- a/src/eligibility_signposting_api/audit/audit_models.py +++ b/src/eligibility_signposting_api/audit/audit_models.py @@ -86,7 +86,7 @@ class AuditCondition(CamelCaseBaseModel): class ResponseAuditData(CamelCaseBaseModel): response_id: UUID | None = None - last_updated: str | None = None + last_updated: datetime | None = None condition: list[AuditCondition] = Field(default_factory=list) diff --git a/src/eligibility_signposting_api/common/contextvars_manager.py b/src/eligibility_signposting_api/common/contextvars_manager.py deleted file mode 100644 index 1dc90f0b1..000000000 --- a/src/eligibility_signposting_api/common/contextvars_manager.py +++ /dev/null @@ -1,20 +0,0 @@ -from collections.abc import Callable -from contextvars import ContextVar -from functools import wraps -from typing import Any - -from mangum.types import LambdaContext, LambdaEvent - -request_id_var: ContextVar[str | None] = ContextVar("request_id", default=None) - - -def get_request_id_for_logging() -> Callable: - def decorator(func: Callable) -> Callable: - @wraps(func) - def wrapper(event: LambdaEvent, context: LambdaContext) -> dict[str, Any] | None: - request_id_var.set(context.aws_request_id) - return func(event, context) - - return wrapper - - return decorator diff --git a/src/eligibility_signposting_api/config/config.py b/src/eligibility_signposting_api/config/config.py index e052ffcc6..49faeff6b 100644 --- a/src/eligibility_signposting_api/config/config.py +++ b/src/eligibility_signposting_api/config/config.py @@ -1,13 +1,10 @@ import logging import os -from collections.abc import Sequence from functools import cache from typing import Any, NewType -from pythonjsonlogger.json import JsonFormatter from yarl import URL -from eligibility_signposting_api.common.contextvars_manager import request_id_var from eligibility_signposting_api.repos.campaign_repo import BucketName from eligibility_signposting_api.repos.person_repo import TableName @@ -58,23 +55,3 @@ def config() -> dict[str, Any]: "kinesis_audit_stream_to_s3": kinesis_audit_stream_to_s3, "log_level": log_level, } - - -class EnrichedJsonFormatter(JsonFormatter): - def add_fields(self, log_record: dict[str, Any], record: logging.LogRecord, message_dict: dict[str, Any]) -> None: - super().add_fields(log_record, record, message_dict) - log_record["request_id"] = request_id_var.get() or "-" - - -def init_logging(quieten: Sequence[str] = ("asyncio", "botocore", "boto3", "mangum", "urllib3")) -> None: - log_format = "%(asctime)s %(levelname)-8s %(name)s %(module)s.py:%(funcName)s():%(lineno)d %(message)s" - formatter = EnrichedJsonFormatter(log_format) - handler = logging.StreamHandler() - handler.setFormatter(formatter) - - logging.root.handlers = [] # Remove default handlers - logging.root.setLevel(LOG_LEVEL) - logging.root.addHandler(handler) - - for q in quieten: - logging.getLogger(q).setLevel(logging.WARNING) diff --git a/src/eligibility_signposting_api/logging/__init__.py b/src/eligibility_signposting_api/logging/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/src/eligibility_signposting_api/logging/logs_manager.py b/src/eligibility_signposting_api/logging/logs_manager.py new file mode 100644 index 000000000..093c06dda --- /dev/null +++ b/src/eligibility_signposting_api/logging/logs_manager.py @@ -0,0 +1,48 @@ +import logging +from collections.abc import Callable, Sequence +from contextvars import ContextVar +from functools import wraps +from typing import Any + +from mangum.types import LambdaContext, LambdaEvent +from pythonjsonlogger.json import JsonFormatter + +from eligibility_signposting_api.config.config import LOG_LEVEL + +request_id_context_var: ContextVar[str | None] = ContextVar("request_id", default=None) + +LOG_FORMAT = "%(asctime)s %(levelname)-8s %(name)s %(module)s.py:%(funcName)s():%(lineno)d %(message)s" + + +def add_request_id_to_logs() -> Callable: + def decorator(func: Callable) -> Callable: + @wraps(func) + def wrapper(event: LambdaEvent, context: LambdaContext) -> dict[str, Any] | None: + aws_request_id = request_id_context_var.set(context.aws_request_id) + try: + return func(event, context) + finally: + request_id_context_var.reset(aws_request_id) + + return wrapper + + return decorator + + +class EnrichedJsonFormatter(JsonFormatter): + def add_fields(self, log_record: dict[str, Any], record: logging.LogRecord, message_dict: dict[str, Any]) -> None: + log_record["request_id"] = request_id_context_var.get() or "-" + super().add_fields(log_record, record, message_dict) + + +def init_logging(quieten: Sequence[str] = ("asyncio", "botocore", "boto3", "mangum", "urllib3")) -> None: + formatter = EnrichedJsonFormatter(LOG_FORMAT) + handler = logging.StreamHandler() + handler.setFormatter(formatter) + + logging.root.handlers = [] # Remove default handlers + logging.root.setLevel(LOG_LEVEL) + logging.root.addHandler(handler) + + for q in quieten: + logging.getLogger(q).setLevel(logging.WARNING) diff --git a/tests/unit/logging/__init__.py b/tests/unit/logging/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/tests/unit/logging/test_logs_manager.py b/tests/unit/logging/test_logs_manager.py new file mode 100644 index 000000000..eb9c38a6c --- /dev/null +++ b/tests/unit/logging/test_logs_manager.py @@ -0,0 +1,120 @@ +import io +import json +import logging +import threading +from http import HTTPStatus +from unittest.mock import MagicMock, Mock + +import pytest +from mangum.types import LambdaContext + +from eligibility_signposting_api.logging.logs_manager import ( + LOG_FORMAT, + EnrichedJsonFormatter, + add_request_id_to_logs, + request_id_context_var, +) + + +def test_decorator_sets_request_id_in_context(): + test_request_id = "test-id-12345" + mock_context = MagicMock() + mock_context.aws_request_id = test_request_id + + @add_request_id_to_logs() + def decorated_handler(event, context): # noqa : ARG001 + return request_id_context_var.get() + + result = decorated_handler({}, mock_context) + + assert result == test_request_id + + +def test_decorator_preserves_function_return_value(): + expected_result = {"statusCode": 200, "body": "Success"} + mock_context = MagicMock() + mock_context.aws_request_id = "any-id" + + @add_request_id_to_logs() + def decorated_handler(event, context): # noqa : ARG001 + return expected_result + + result = decorated_handler({}, mock_context) + + assert result == expected_result + + +def test_request_id_context_is_properly_isolated(): + results = {} + + @add_request_id_to_logs() + def decorated_handler(event, context): # noqa : ARG001 + rid = request_id_context_var.get() + results[threading.current_thread().name] = rid + return rid + + def thread_func(name, rid): # noqa : ARG001 + mock_context = MagicMock(aws_request_id=rid) + decorated_handler({}, mock_context) + + threads = [ + threading.Thread(target=thread_func, name="Thread-A", args=("Thread-A", "id-A")), + threading.Thread(target=thread_func, name="Thread-B", args=("Thread-B", "id-B")), + threading.Thread(target=thread_func, name="Thread-C", args=("Thread-C", "id-C")), + ] + + for t in threads: + t.start() + for t in threads: + t.join() + + assert results["Thread-A"] == "id-A" + assert request_id_context_var.get() is None + + assert results["Thread-B"] == "id-B" + assert request_id_context_var.get() is None + + assert results["Thread-C"] == "id-C" + assert request_id_context_var.get() is None + + +@pytest.fixture +def lambda_context(): + context = Mock(spec=LambdaContext) + context.aws_request_id = "test-request-id" + return context + + +def test_enriched_json_formatter_adds_all_fields(lambda_context): + @add_request_id_to_logs() + def test_handler(event, context): # noqa : ARG001 + logger = logging.getLogger("test_logger") + logger.info("Test log inside handler") + return HTTPStatus.OK + + log_stream = io.StringIO() + handler = logging.StreamHandler(log_stream) + handler.setFormatter(EnrichedJsonFormatter(LOG_FORMAT)) + + test_logger = logging.getLogger("test_logger") + test_logger.handlers = [] + test_logger.addHandler(handler) + test_logger.setLevel(logging.INFO) + + result = test_handler({}, lambda_context) + log_output = log_stream.getvalue() + + test_logger.removeHandler(handler) + + assert result == HTTPStatus.OK + logged_json = json.loads(log_output) + + assert logged_json["request_id"] == lambda_context.aws_request_id + assert "asctime" in logged_json + assert logged_json["levelname"] == "INFO" + assert logged_json["name"] == "test_logger" + assert logged_json["module"] == "test_logs_manager" + assert logged_json["funcName"] == "test_handler" + assert "lineno" in logged_json + assert logged_json["message"] == "Test log inside handler" + assert request_id_context_var.get() is None