ELI 137 - fix & test logging from Lambda

.gitignore

@@ -41,4 +41,5 @@ localstack_data/
 sandbox/specification/*
 /volume/*
 /coverage.xml
+/integration-test-results.xml
 /specification/tmp/*

README.md

@@ -71,10 +71,10 @@ The following software packages, or their equivalents, are expected to be instal
 
 | Variable                | Default                 | Description                                                                                                                                                            |
 |-------------------------|-------------------------|------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
-| `DYNAMODB_ENDPOINT`     | `http://localhost:4566` | Endpoint for the app to access DynamoDB                                                                                                                                |
-| `AWS_REGION`            | `eu-west-1`             | AWS Region                                                                                                                                                             |
-| `AWS_ACCESS_KEY`        | `dummy_key`             | AWS Access Key                                                                                                                                                         |
+| `AWS_ACCESS_KEY_ID`     | `dummy_key`             | AWS Access Key                                                                                                                                                         |
+| `AWS_DEFAULT_REGION`    | `eu-west-1`             | AWS Region                                                                                                                                                             |
 | `AWS_SECRET_ACCESS_KEY` | `dummy_secret`          | AWS Secret Access Key                                                                                                                                                  |
+| `DYNAMODB_ENDPOINT`     | `http://localhost:4566` | Endpoint for the app to access DynamoDB                                                                                                                                |
 | `LOG_LEVEL`             | `WARNING`               | Logging level. Must be one of `DEBUG`, `INFO`, `WARNING`, `ERROR` or `CRITICAL` as per [Logging Levels](https://docs.python.org/3/library/logging.html#logging-levels) |
 
 ## Usage

src/eligibility_signposting_api/app.py

@@ -24,7 +24,9 @@ def main() -> None:  # pragma: no cover
 
 def lambda_handler(event: LambdaEvent, context: LambdaContext) -> dict[str, Any]:  # pragma: no cover
     """Run the Flask app as an AWS Lambda."""
-    handler = Mangum(WsgiToAsgi(create_app()))
+    app = create_app()
+    app.debug = config()["log_level"] == logging.DEBUG
+    handler = Mangum(WsgiToAsgi(app), lifespan="off")
     return handler(event, context)
 
 
@@ -38,10 +40,10 @@ def create_app() -> Flask:
     app.register_error_handler(Exception, handle_exception)
 
     # Set up dependency injection using wireup
-    container = wireup.create_sync_container(service_modules=[services, repos], parameters={**config(), **app.config})
+    container = wireup.create_sync_container(service_modules=[services, repos], parameters={**app.config, **config()})
     wireup.integration.flask.setup(container, app)
 
-    logger.info("app ready")
+    logger.info("app ready", extra={"config": {**app.config, **config()}})
     return app
 
 

src/eligibility_signposting_api/config.py

@@ -1,5 +1,6 @@
 import logging
 import os
+from collections.abc import Sequence
 from functools import lru_cache
 from typing import Any, NewType
 
@@ -16,17 +17,22 @@
 @lru_cache
 def config() -> dict[str, Any]:
     return {
+        "aws_access_key_id": AwsAccessKey(os.getenv("AWS_ACCESS_KEY_ID", "dummy_key")),
+        "aws_default_region": AwsRegion(os.getenv("AWS_DEFAULT_REGION", "eu-west-1")),
         "dynamodb_endpoint": URL(os.getenv("DYNAMODB_ENDPOINT", "http://localhost:4566")),
-        "aws_region": AwsRegion(os.getenv("AWS_REGION", "eu-west-1")),
-        "aws_access_key_id": AwsAccessKey(os.getenv("AWS_ACCESS_KEY", "dummy_key")),
         "aws_secret_access_key": AwsSecretAccessKey(os.getenv("AWS_SECRET_ACCESS_KEY", "dummy_secret")),
         "log_level": LOG_LEVEL,
     }
 
 
-def init_logging() -> None:
+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)
     handler = logging.StreamHandler()
     handler.setFormatter(formatter)
-    logging.basicConfig(level=LOG_LEVEL, format=log_format, handlers=[handler])
+    logging.root.handlers = []  # Clear any existing handlers
+    logging.root.setLevel(LOG_LEVEL)  # Set log level
+    logging.root.addHandler(handler)  # Add handler
+
+    for q in quieten:
+        logging.getLogger(q).setLevel(logging.WARNING)

src/eligibility_signposting_api/repos/factory.py

@@ -13,12 +13,12 @@
 
 @service
 def boto3_session_factory(
-    aws_region: Annotated[AwsRegion, Inject(param="aws_region")],
+    aws_default_region: Annotated[AwsRegion, Inject(param="aws_default_region")],
     aws_access_key_id: Annotated[AwsAccessKey, Inject(param="aws_access_key_id")],
     aws_secret_access_key: Annotated[AwsSecretAccessKey, Inject(param="aws_secret_access_key")],
 ) -> Session:
     return Session(
-        aws_access_key_id=aws_access_key_id, aws_secret_access_key=aws_secret_access_key, region_name=aws_region
+        aws_access_key_id=aws_access_key_id, aws_secret_access_key=aws_secret_access_key, region_name=aws_default_region
     )
 
 

src/eligibility_signposting_api/repos/person_repo.py

@@ -36,4 +36,6 @@ def get_person(self, name: Name) -> Person:
             message = f"Person not found with name {name}"
             raise NotFoundError(message)
 
-        return Person.model_validate(dynamo_response.get("Item"))
+        person = Person.model_validate(dynamo_response.get("Item"))
+        logger.debug("returning person %s", person, extra={"person": person})
+        return person

src/eligibility_signposting_api/views/hello.py

@@ -22,5 +22,6 @@ def hello_world(person_service: Injected[PersonService], name: Name | None = Non
         hello_response = HelloResponse(status=HTTPStatus.OK, message=f"Hello {nickname}!")
         return hello_response.model_dump()
     except UnknownPersonError:
+        logger.debug("name %r not found", name, extra={"name_": name})
         problem = Problem(title="Name not found", status=HTTPStatus.NOT_FOUND, detail=f"Name {name} not found.")
         return make_response(problem.model_dump(), HTTPStatus.NOT_FOUND)

tests/integration/conftest.py

@@ -1,13 +1,14 @@
+import json
 import logging
 import os
 from collections.abc import Generator
 from pathlib import Path
 from typing import TYPE_CHECKING, Any
 
-import boto3
 import httpx
 import pytest
 import stamina
+from boto3 import Session
 from boto3.resources.base import ServiceResource
 from botocore.client import BaseClient
 from httpx import RequestError
@@ -49,46 +50,94 @@ def is_responsive(url: URL) -> bool:
 
 
 @pytest.fixture(scope="session")
-def lambda_client(localstack: URL) -> BaseClient:
-    return boto3.client(
-        "lambda",
-        endpoint_url=str(localstack),
-        region_name=AWS_REGION,
-        aws_access_key_id="fake",
-        aws_secret_access_key="fake",
-    )
+def boto3_session() -> Session:
+    return Session(aws_access_key_id="fake", aws_secret_access_key="fake", region_name=AWS_REGION)
 
 
 @pytest.fixture(scope="session")
-def dynamodb_client(localstack: URL) -> BaseClient:
-    return boto3.client(
-        "dynamodb",
-        endpoint_url=str(localstack),
-        region_name=AWS_REGION,
-        aws_access_key_id="fake",
-        aws_secret_access_key="fake",
-    )
+def lambda_client(boto3_session: Session, localstack: URL) -> BaseClient:
+    return boto3_session.client("lambda", endpoint_url=str(localstack))
+
+
+@pytest.fixture(scope="session")
+def dynamodb_client(boto3_session: Session, localstack: URL) -> BaseClient:
+    return boto3_session.client("dynamodb", endpoint_url=str(localstack))
+
+
+@pytest.fixture(scope="session")
+def dynamodb_resource(boto3_session: Session, localstack: URL) -> ServiceResource:
+    return boto3_session.resource("dynamodb", endpoint_url=str(localstack))
+
+
+@pytest.fixture(scope="session")
+def logs_client(boto3_session: Session, localstack: URL) -> BaseClient:
+    return boto3_session.client("logs", endpoint_url=str(localstack))
 
 
 @pytest.fixture(scope="session")
-def dynamodb_resource(localstack: URL) -> ServiceResource:
-    return boto3.resource(
-        "dynamodb",
-        endpoint_url=str(localstack),
-        region_name=AWS_REGION,
-        aws_access_key_id="fake",
-        aws_secret_access_key="fake",
+def iam_client(boto3_session: Session, localstack: URL) -> BaseClient:
+    return boto3_session.client("iam", endpoint_url=str(localstack))
+
+
+@pytest.fixture(scope="session")
+def s3_client(boto3_session: Session, localstack: URL) -> BaseClient:
+    return boto3_session.client("s3", endpoint_url=str(localstack))
+
+
+@pytest.fixture(scope="session")
+def iam_role(iam_client: BaseClient) -> Generator[str]:
+    role_name = "LambdaExecutionRole"
+    policy_name = "LambdaCloudWatchPolicy"
+
+    # Define IAM Trust Policy for Lambda Execution Role
+    trust_policy = {
+        "Version": "2012-10-17",
+        "Statement": [
+            {"Effect": "Allow", "Principal": {"Service": "lambda.amazonaws.com"}, "Action": "sts:AssumeRole"}
+        ],
+    }
+
+    # Create IAM Role
+    role = iam_client.create_role(
+        RoleName=role_name,
+        AssumeRolePolicyDocument=json.dumps(trust_policy),
+        Description="Role for Lambda execution with CloudWatch logging permissions",
     )
 
+    # Define IAM Policy for CloudWatch Logs
+    log_policy = {
+        "Version": "2012-10-17",
+        "Statement": [
+            {
+                "Effect": "Allow",
+                "Action": ["logs:CreateLogGroup", "logs:CreateLogStream", "logs:PutLogEvents"],
+                "Resource": "arn:aws:logs:*:*:*",
+            }
+        ],
+    }
+
+    # Create the IAM Policy
+    policy = iam_client.create_policy(PolicyName=policy_name, PolicyDocument=json.dumps(log_policy))
+    policy_arn = policy["Policy"]["Arn"]
+
+    # Attach Policy to Role
+    iam_client.attach_role_policy(RoleName=role_name, PolicyArn=policy_arn)
+
+    yield role["Role"]["Arn"]
+
+    iam_client.detach_role_policy(RoleName=role_name, PolicyArn=policy_arn)
+    iam_client.delete_policy(PolicyArn=policy_arn)
+    iam_client.delete_role(RoleName=role_name)
+
 
 @pytest.fixture(scope="session")
-def flask_function(lambda_client: BaseClient) -> str:
-    function_name = "flask_function"
+def flask_function(lambda_client: BaseClient, iam_role: str) -> Generator[str]:
+    function_name = "eligibility_signposting_api"
     with Path("dist/lambda.zip").open("rb") as zipfile:
         lambda_client.create_function(
             FunctionName=function_name,
             Runtime="python3.13",
-            Role="arn:aws:iam::123456789012:role/test-role",
+            Role=iam_role,
             Handler="eligibility_signposting_api.app.lambda_handler",
             Code={"ZipFile": zipfile.read()},
             Architectures=["x86_64"],
@@ -97,13 +146,15 @@ def flask_function(lambda_client: BaseClient) -> str:
                 "Variables": {
                     "DYNAMODB_ENDPOINT": os.getenv("LOCALSTACK_INTERNAL_ENDPOINT", "http://localstack:4566/"),
                     "AWS_REGION": AWS_REGION,
+                    "LOG_LEVEL": "DEBUG",
                 }
             },
         )
     logger.info("loaded zip")
     wait_for_function_active(function_name, lambda_client)
     logger.info("function active")
-    return function_name
+    yield function_name
+    lambda_client.delete_function(FunctionName=function_name)
 
 
 @pytest.fixture(scope="session")

tests/integration/lambda/test_app_running_as_lambda.py

@@ -1,3 +1,4 @@
+import base64
 import json
 import logging
 from collections.abc import Generator
@@ -6,10 +7,12 @@
 
 import httpx
 import pytest
+import stamina
 from botocore.client import BaseClient
+from botocore.exceptions import ClientError
 from brunns.matchers.data import json_matching as is_json_that
 from brunns.matchers.response import is_response
-from hamcrest import assert_that, contains_string, has_entries
+from hamcrest import assert_that, contains_string, has_entries, has_item
 from yarl import URL
 
 from eligibility_signposting_api.model.person import Person
@@ -48,14 +51,18 @@ def test_install_and_call_lambda_flask(lambda_client: BaseClient, flask_function
         FunctionName=flask_function,
         InvocationType="RequestResponse",
         Payload=json.dumps(request_payload),
+        LogType="Tail",
     )
+    log_output = base64.b64decode(response["LogResult"]).decode("utf-8")
 
     # Then
     assert_that(response, has_entries(StatusCode=HTTPStatus.OK))
     response_payload = json.loads(response["Payload"].read().decode("utf-8"))
     logger.info(response_payload)
     assert_that(response_payload, has_entries(statusCode=HTTPStatus.OK, body=contains_string("Hello")))
 
+    assert_that(log_output, contains_string("app created"))
+
 
 def test_install_and_call_flask_lambda_over_http(flask_function_url: URL):
     """Given lambda installed into localstack, run it via http"""
@@ -87,3 +94,42 @@ def test_install_and_call_flask_lambda_with_nickname_over_http(flask_function_ur
         .with_status_code(HTTPStatus.OK)
         .and_body(is_json_that(has_entries(message="Hello Ash!", status=HTTPStatus.OK))),
     )
+
+
+def test_install_and_call_flask_lambda_with_unknown_name(
+    flask_function_url: URL, flask_function: str, logs_client: BaseClient
+):
+    """Given lambda installed into localstack, run it via http, with a name nonexistent specified"""
+    # Given
+
+    # When
+    response = httpx.get(str(flask_function_url / "hello" / "fred"), timeout=30)
+
+    # Then
+    assert_that(
+        response,
+        is_response()
+        .with_status_code(HTTPStatus.NOT_FOUND)
+        .and_body(
+            is_json_that(
+                has_entries(title="Name not found", detail="Name fred not found.", status=HTTPStatus.NOT_FOUND)
+            )
+        ),
+    )
+
+    messages = get_log_messages(flask_function, logs_client)
+    assert_that(messages, has_item(contains_string("name 'fred' not found")))
+
+
+def get_log_messages(flask_function: str, logs_client: BaseClient) -> list[str]:
+    for attempt in stamina.retry_context(on=ClientError, attempts=20, timeout=120):
+        with attempt:
+            log_streams = logs_client.describe_log_streams(
+                logGroupName=f"/aws/lambda/{flask_function}", orderBy="LastEventTime", descending=True
+            )
+    assert log_streams["logStreams"] != []
+    log_stream_name = log_streams["logStreams"][0]["logStreamName"]
+    log_events = logs_client.get_log_events(
+        logGroupName=f"/aws/lambda/{flask_function}", logStreamName=log_stream_name, limit=100
+    )
+    return [e["message"] for e in log_events["events"]]