Module 7: Observability Latency And Evals In Production

3. Hands-on: CloudWatch Logs and Metrics for the extractor

Next →

Description

This lesson builds observability/structured_log.py — a minimal, dependency-free structured logger, instrumenting extract-shipment-manifest-fields with JSON lines instead of the free-text print(f"...") pattern process-shipment-manifest (inherited) already uses. The logger itself is pure Python code: it really ran to write this lesson, over two fixed, deterministic invocations, and every "What to expect" block in that part is literal output. What follows — reading those logs with awslocal logs filter-log-events, publishing a custom metric with awslocal cloudwatch put-metric-data — is representative, for the exact same reason sre-and-incident-response-guide, Module 3, lessons 3 and 4 already declared: with no LOCALSTACK_AUTH_TOKEN exported, the LocalStack container doesn't start in this specific environment, so no awslocal command ran against a live LocalStack. CloudWatch Logs and Metrics are confirmed on the Hobby plan — the limitation belongs to this writing environment, not the service.

Connection to the module

Lesson 2 promised three SLIs; this lesson builds the instrumentation that, in production, would feed all three — it doesn't calculate any SLI yet (that's lesson 4). Lesson 4 is going to reuse the same event vocabulary this lesson's logger defines (ManifestParseFailedReceived, GuardrailBlocked, ShipmentWritten), applied this time over a much larger, 100% literal test set.

Analogy: an airplane's black box, not a notepad

A pilot who writes, by hand, in a notepad, "all normal, landed fine" at the end of every flight leaves a record — but one no automated system can read, compare across flights, or sum into a dashboard. A real airplane's black box records structured events: a fixed field for altitude, one for speed, one for every alarm that sounded, each in an exact, predictable format, no matter which flight it is. print(f"Invalid manifest {key}: {errors}") — the pattern process-shipment-manifest already uses, inherited from aws-serverless-and-containers-guide — is the notepad: readable to a human, but fragile for a machine, because any wording change breaks any script that tries to extract data from that text with a regular expression. structured_log.py, this lesson's logger, is the black box: every line is a JSON object with an event field from a fixed, closed vocabulary, plus whatever fields that specific event needs — never free text a human wrote with another human in mind.

Step 1 — The structured logger, complete

observability/structured_log.py, at the root of andes-cargo-infra/:

#!/usr/bin/env python3
"""structured_log.py -- a small, dependency-free structured logging helper
for extract-shipment-manifest-fields.

Every call to log_event() prints exactly one JSON object per line to stdout
-- the format Lambda's runtime captures verbatim into
/aws/lambda/extract-shipment-manifest-fields, the same CloudWatch Logs group
naming convention aws-core-services-guide already established for
process-shipment-manifest (/aws/lambda/<function-name>).

Why JSON-per-line instead of process-shipment-manifest's plain
print(f"...") pattern (Module 1, lesson 3): a structured line is queryable
with CloudWatch Logs Insights field extraction and with a CloudWatch Logs
metric filter's JSON pattern syntax (Step 3 of this lesson), without
depending on a fragile string match -- exactly the gap Module 7, lesson 4's
escalation-rate script sidesteps entirely by never parsing log text at all
(it computes straight from parse_manifest(), never from a log line).

Never uses random. requestId and every other per-invocation value are
passed in explicitly by the caller -- this module never reads
datetime.now() or any other non-deterministic source itself, so a test can
assert on an exact, fixed log line.
"""

from __future__ import annotations

import json
import sys


def log_event(event: str, **fields) -> None:
    """Print one structured JSON log line to stdout. `event` is a short,
    fixed name (e.g. "ManifestParseFailedReceived", "GuardrailBlocked",
    "ShipmentWritten") -- always one of a known, closed set, never a
    free-text message, so a CloudWatch Logs Insights query or a metric
    filter can match it exactly, without a fragile regex over prose."""
    record = {"event": event, **fields}
    print(json.dumps(record, sort_keys=True), file=sys.stdout)

log_event() doesn't decide what to log or when — that decision lives in the handler, in Step 2. Its only job is guaranteeing that, no matter who calls it, the resulting line is valid JSON, with keys in the same order (sort_keys=True), so two lines of the same event type are byte-for-byte diffable whenever their data matches.

Step 2 — The closed event vocabulary, and where each one lives in handler.py

extract-shipment-manifest-fields/handler.py (Module 1, lesson 4; the .zip this guide's Module 5, lesson 6 already signed with cosign) calls log_event() at three fixed points in its flow — never a fourth, never an improvised message mid-function:

EventWhen it's emittedFields
ManifestParseFailedReceivedUpon receiving the ManifestParseFailed event (Module 1, lesson 3), before any other processingrequestId, manifestKey
PiiRedactedBeforeInvokeOnly if pre_invoke_checks.py (Module 4, lesson 5) found PII in the raw textrequestId, entityCounts (the same dict ScrubResult.entity_counts already produces)
GuardrailBlockedIf post_invoke_checks.py (Module 4, lesson 6) rejects the candidate — real or representativerequestId, reason, errors (the same tuple ValidationResult.errors already produces)
ShipmentWrittenIf the candidate passes schema validation, right before write_shipment_record()requestId, shipmentId

Notice something important: every event reuses a data type that already exists — entity_counts from pre_invoke_checks.py, errors from post_invoke_checks.py. The logger never invents its own representation of "what went wrong"; it relies, without duplicating logic, on the two custom checks Module 4 already built and already tested with pytest.

This is the excerpt of handler.py this lesson instruments — only the lines relevant to logging, not the complete file (this guide's Module 5, lesson 6 already fixed the exact size and hash of the .zip before this instrumentation; any real change to handler.py from here on would require re-signing it with cosign, a step outside this lesson's scope):

# extract-shipment-manifest-fields/handler.py -- excerpt: the three
# log_event() call sites this lesson adds.

from observability.structured_log import log_event
from guardrails.pre_invoke_checks import scrub_pii
from guardrails.post_invoke_checks import validate_shipment_fields


def handler(event, context):
    manifest_key = event["detail"]["manifestKey"]
    raw_text = event["detail"]["rawText"]
    request_id = context.aws_request_id

    log_event("ManifestParseFailedReceived", requestId=request_id, manifestKey=manifest_key)

    pii_result = scrub_pii(raw_text)  # Module 4, lesson 5
    if pii_result.found_pii:
        log_event("PiiRedactedBeforeInvoke", requestId=request_id, entityCounts=pii_result.entity_counts)

    # candidate = invoke_bedrock(pii_result.redacted_text)  -- never called
    # in this $0 lab; see Module 7, lesson 7 for why. What follows uses a
    # REPRESENTATIVE candidate, hand-built and labeled as such.
    candidate = get_representative_candidate(manifest_key)

    validation = validate_shipment_fields(candidate)  # Module 4, lesson 6
    if not validation.is_valid:
        log_event("GuardrailBlocked", requestId=request_id, reason="schema", errors=list(validation.errors))
        return {"statusCode": 422}

    write_shipment_record(candidate, manifest_key)
    log_event("ShipmentWritten", requestId=request_id, shipmentId=candidate["shipmentId"])
    return {"statusCode": 200}

Step 3 — Running the logger, for real, over two fixed invocations

Two invocations, deterministic, each with a fixed requestId (never generated with uuid4() on the fly) — the same "fixed test events" discipline Module 1, lesson 3 already used for shipments 4471/4472/4473:

Invocation 1 — manifest 4471, no PII, a complete representative candidate (writes to Shipments). Invocation 2 — manifest 4473, with an incidental email and phone number (the same text from Module 4, lesson 5), an incomplete representative candidate (the custom guardrail blocks it).

from guardrails.pre_invoke_checks import scrub_pii
from guardrails.post_invoke_checks import validate_shipment_fields
from observability.structured_log import log_event

# --- Invocation 1: shipment 4471, clean text, successful write -----------
REQUEST_ID_1 = "5b6f3e2a-8c91-4d7a-b0e5-1f9c2a6d8b34"
MANIFEST_1 = "shipmentId=4471\noriginCountry=Peru\ndestinationCountry=Chile\ncarrier=AndesExpress\nweightKg=120"

log_event("ManifestParseFailedReceived", requestId=REQUEST_ID_1, manifestKey="manifests/year=2026/month=08/shipment-4471-manifest.txt")
pii_1 = scrub_pii(MANIFEST_1)
if pii_1.found_pii:
    log_event("PiiRedactedBeforeInvoke", requestId=REQUEST_ID_1, entityCounts=pii_1.entity_counts)

candidate_1 = {  # REPRESENTATIVE -- Module 7, lesson 7
    "shipmentId": "4471", "originCountry": "Peru", "destinationCountry": "Chile",
    "carrier": "AndesExpress", "weightKg": "120",
}
validation_1 = validate_shipment_fields(candidate_1)
if not validation_1.is_valid:
    log_event("GuardrailBlocked", requestId=REQUEST_ID_1, reason="schema", errors=list(validation_1.errors))
else:
    log_event("ShipmentWritten", requestId=REQUEST_ID_1, shipmentId=candidate_1["shipmentId"])

# --- Invocation 2: shipment 4473, PII in the text, incomplete candidate --
REQUEST_ID_2 = "c8e42d15-9a3b-4f8e-b6c1-7d2a4e9f3b58"
MANIFEST_2 = "Hi team, following up on shipment AC-4473. Contact me at ana.rojas@andescargo.com or call +51 987 654 321 if you need anything. RutaSur handles pickup Friday."

log_event("ManifestParseFailedReceived", requestId=REQUEST_ID_2, manifestKey="manifests/year=2026/month=08/shipment-4473-manifest.txt")
pii_2 = scrub_pii(MANIFEST_2)
if pii_2.found_pii:
    log_event("PiiRedactedBeforeInvoke", requestId=REQUEST_ID_2, entityCounts=pii_2.entity_counts)

candidate_2 = {  # REPRESENTATIVE -- deliberately incomplete, Module 7, lesson 7
    "shipmentId": "4473", "originCountry": "Chile", "destinationCountry": "Peru", "carrier": "RutaSur",
}
validation_2 = validate_shipment_fields(candidate_2)
if not validation_2.is_valid:
    log_event("GuardrailBlocked", requestId=REQUEST_ID_2, reason="schema", errors=list(validation_2.errors))
else:
    log_event("ShipmentWritten", requestId=REQUEST_ID_2, shipmentId=candidate_2["shipmentId"])
python3 observability/drive_handler_logging.py

What to expect (literal — really run, this same guide's environment):

{"event": "ManifestParseFailedReceived", "manifestKey": "manifests/year=2026/month=08/shipment-4471-manifest.txt", "requestId": "5b6f3e2a-8c91-4d7a-b0e5-1f9c2a6d8b34"}
{"event": "ShipmentWritten", "requestId": "5b6f3e2a-8c91-4d7a-b0e5-1f9c2a6d8b34", "shipmentId": "4471"}
{"event": "ManifestParseFailedReceived", "manifestKey": "manifests/year=2026/month=08/shipment-4473-manifest.txt", "requestId": "c8e42d15-9a3b-4f8e-b6c1-7d2a4e9f3b58"}
{"entityCounts": {"EMAIL": 1, "PHONE": 1}, "event": "PiiRedactedBeforeInvoke", "requestId": "c8e42d15-9a3b-4f8e-b6c1-7d2a4e9f3b58"}
{"errors": ["missing required field(s): weightKg"], "event": "GuardrailBlocked", "reason": "schema", "requestId": "c8e42d15-9a3b-4f8e-b6c1-7d2a4e9f3b58"}

Five lines, four distinct event types, both invocations complete from start to finish. Notice Invocation 1: PiiRedactedBeforeInvoke never shows up — 4471's key=value text has no email or phone number, so pii_1.found_pii is False, and that line's if never fires. Nothing gets logged "just in case"; every event shows up exactly when, and only when, the real condition that triggers it occurred. Run twice, this output is identical, byte for byte — no requestId generated on the fly, no varying timestamp.

Step 4 — Reading these logs with awslocal, representative

In production, each of Step 3's five lines would reach /aws/lambda/extract-shipment-manifest-fields — the same automatic log group name Lambda already assigns to any function, the convention aws-core-services-guide, Module 6 already established for process-shipment-manifest. Querying them with a structured filter:

awslocal logs filter-log-events \
  --log-group-name /aws/lambda/extract-shipment-manifest-fields \
  --filter-pattern '{ $.event = "GuardrailBlocked" }' \
  --start-time 2026-08-14T14:00:00Z \
  --end-time 2026-08-14T15:00:00Z

What to expect (representative — with no LOCALSTACK_AUTH_TOKEN, the LocalStack container doesn't start in this specific environment; CloudWatch Logs is confirmed on the Hobby plan, the exact same limitation sre-and-incident-response-guide, Module 3, lesson 4 already declared):

{
    "events": [
        {
            "logStreamName": "2026/08/14/[$LATEST]7f2a9c4e1b8d3f6a0c5e9b2d4a7f1c83",
            "timestamp": 1786732815041,
            "message": "{\"errors\": [\"missing required field(s): weightKg\"], \"event\": \"GuardrailBlocked\", \"reason\": \"schema\", \"requestId\": \"c8e42d15-9a3b-4f8e-b6c1-7d2a4e9f3b58\"}\n",
            "ingestionTime": 1786732815488,
            "eventId": "39234501234567890123456789012345678901"
        }
    ],
    "searchedLogStreams": [
        { "logStreamName": "2026/08/14/[$LATEST]7f2a9c4e1b8d3f6a0c5e9b2d4a7f1c83", "searchedCompletely": true }
    ]
}

--filter-pattern '{ $.event = "GuardrailBlocked" }' is CloudWatch Logs' real JSON filter syntax — not an invention of this lesson; it finds exactly one of the five lines, Invocation 2's, because it's the only one with "event": "GuardrailBlocked". This is exactly a structured log's advantage over a free-text one: the filter doesn't have to guess where a message starts and ends — the event key says so, unambiguously.

Step 5 — From structured logs to a metric, with a metric filter

A PutMetricFilter on the log group automatically converts every line that matches a pattern into a CloudWatch data point — with no application code having to explicitly call put-metric-data on every invocation:

awslocal logs put-metric-filter \
  --log-group-name /aws/lambda/extract-shipment-manifest-fields \
  --filter-name guardrail-blocked-count \
  --filter-pattern '{ $.event = "GuardrailBlocked" }' \
  --metric-transformations \
    metricName=GuardrailBlockedCount,metricNamespace=AndesCargo/GenAI,metricValue=1,defaultValue=0

What to expect (representative, same reason as Step 4):

(no output -- put-metric-filter returns nothing on success, the same behavior the AWS CLI confirms for this command)

awslocal cloudwatch get-metric-statistics \
  --namespace AndesCargo/GenAI \
  --metric-name GuardrailBlockedCount \
  --start-time 2026-08-14T14:00:00Z \
  --end-time 2026-08-14T15:00:00Z \
  --period 3600 \
  --statistics Sum

What to expect (representative, same reason):

{
    "Label": "GuardrailBlockedCount",
    "Datapoints": [
        { "Timestamp": "2026-08-14T14:00:00+00:00", "Sum": 1.0, "Unit": "Count" }
    ]
}

Sum: 1.0 — matches, exactly, Step 3's one GuardrailBlocked line out of five. This is the complete mechanism that, in production, would automatically feed lesson 2's SLI 3 (guardrail block rate), with no one having to read logs by hand: every GuardrailBlocked increments GuardrailBlockedCount; every ManifestParseFailedReceived would increment an equivalent TotalInvocationsCount; dividing the two, on a dashboard, is the live block rate.

Common mistakes

Logging the manifest's complete raw text inside a structured event (carrying over the print(f"...") habit). What happens: someone, instrumenting their own handler.py, adds rawText=raw_text to the log_event("ManifestParseFailedReceived", ...) call, thinking "more context is better." How to spot it: if your ManifestParseFailedReceived log line includes a logistics partner's complete email body. How to fix it: Step 2's table precisely declares exactly which fields each event carries — manifestKey (a reference, not the content), never the raw text. Logging business content without first going through pre_invoke_checks.py (which runs after, not before, this specific event) risks writing unredacted PII directly into CloudWatch Logs, a destination no guardrail in this guide protects.

Confusing the free-text --filter-pattern (?"Invalid manifest", the pattern sre-and-incident-response-guide used for plain-text logs) with this lesson's JSON syntax ({ $.event = "..." }) (mixing two different log formats). What happens: someone, familiar with the sibling guide's Module 3, tries to use '?"GuardrailBlocked"' against this lesson's structured logs. How to spot it: if your filter uses double quotes with a question mark instead of the { $.field = value } syntax. How to fix it: the ? syntax searches for a text substring in a free-text log — it would, in fact, still work against this lesson's structured logs too, because "GuardrailBlocked" is still a substring of the JSON — but the { $.event = "GuardrailBlocked" } syntax is strictly more precise: it filters by a specific field's exact value, without depending on any other part of the JSON happening to contain the same word. Use the field syntax whenever the log is JSON — that's precisely why this lesson built a structured logger in the first place.

Presenting Step 4 or Step 5's output as if this environment's LocalStack had really produced it (losing the "representative" label). What happens: someone copies Step 5's JSON and describes it as "I confirmed the metric in CloudWatch." How to spot it: if your description of this lesson doesn't mention, anywhere, the absence of LOCALSTACK_AUTH_TOKEN. How to fix it: this guide's discipline, and sre-and-incident-response-guide's before it, is explicit: Step 3 — the logger itself, running pure Python — is literal; Steps 4 and 5 — any awslocal command — are representative in this specific environment, precisely built on CloudWatch's real, confirmed behavior on the Hobby plan, never presented as executed here.

Exercises

Exercise 1 — Run observability/drive_handler_logging.py yourself and count how many output lines you get. Before running it, predict the number using Step 2's table and Step 3's two invocations.

See solution

Five lines: Invocation 1 produces two (ManifestParseFailedReceived, ShipmentWritten — no PII, no block); Invocation 2 produces three (ManifestParseFailedReceived, PiiRedactedBeforeInvoke, GuardrailBlocked — the incidental email/phone triggers the second event, the incomplete candidate triggers the third instead of a ShipmentWritten). The total, 2 + 3 = 5, matches exactly Step 3's literal output.

Exercise 2 — Design the CloudWatch Logs --filter-pattern that would specifically find lines where entityCounts.EMAIL is greater than zero. Use Step 4's JSON syntax as a reference.

See solution

{ $.entityCounts.EMAIL > 0 } — CloudWatch Logs' JSON syntax supports nested field access with dot notation ($.entityCounts.EMAIL) and numeric comparison operators, exactly like AWS's official documentation's { $.statusCode >= 500 } example. Against Step 3's output, this pattern would find exactly Invocation 2's PiiRedactedBeforeInvoke line (entityCounts.EMAIL: 1), and no other — the rest of the lines don't even have the entityCounts key, so the comparison never evaluates true for them.

Exercise 3 — Explain why structured_log.py never raises an exception if log_event() receives a field that isn't JSON-serializable (an arbitrary Python object, for example). Is this a strength or a weakness of this lesson's design?

See solution

Actually, structured_log.py does raise an exception in that case — Python's standard library's json.dumps() raises a TypeError if any of the dict's values isn't serializable (an object with no compatible __str__/__repr__ method, for example). This is a deliberate strength, not an oversight: a logger that silently dropped or truncated a non-serializable field would be hiding a programming error — someone passed the wrong data type to log_event() — at exactly the moment it would be easiest to catch and fix it, before that error propagates to production. Compare this to pre_invoke_checks.py's design decision (Module 4, lesson 5), which never raises an exception for PII-free text — that decision makes sense because "no PII found" is a normal, expected outcome — while "passing a non-serializable object to a logger" isn't. Every script in this guide fails loudly where silence would hide a bug, and fails silently (or simply does nothing) where silence is the correct behavior.

Summary and next step

This lesson built observability/structured_log.py, a one-function JSON logger, and ran it for real over two fixed, deterministic invocations, producing five literal lines that cover this module's closed vocabulary's four event types. You confirmed, with real output, that every event shows up exactly when its condition is met, never "just in case." You saw, with the exact same honesty sre-and-incident-response-guide already established, why reading those logs with awslocal logs filter-log-events and turning them into a metric with awslocal logs put-metric-filter is representative in this specific environment — with no LOCALSTACK_AUTH_TOKEN — even though CloudWatch Logs/Metrics are confirmed on the Hobby plan.

Before moving on you should be able to: name the closed vocabulary's four events and when each one is emitted; write a JSON --filter-pattern for a new nested field; and explain the difference between the free-text filter syntax (?"...") and the JSON syntax ({ $.field = value }).

Lesson 4 leaves CloudWatch behind entirely and calculates, with pure Python code, run over a fixed set of 50 test events, this guide's only 100% literal SLI: the escalation rate.

Resources

  1. AWS Docs — Filter pattern syntax for metric filters, subscription filters, filter log events, and Live Tail — the exact source for the JSON { $.field = value } syntax used in this lesson's Steps 4 and 5.
  2. AWS Docs — PutMetricFilter — official reference for Step 5's command.
  3. sre-and-incident-response-guide, Module 3, lessons 3 and 4 — the exact precedent for "representative logs/metrics in this environment, without LOCALSTACK_AUTH_TOKEN," reconfirmed here without re-investigating it.
  4. This same course, Module 4, lessons 5 and 6 — the origin of scrub_pii() and validate_shipment_fields(), reused unchanged in this lesson's Step 3.
  5. This same course, Module 5, lesson 6 — the origin of extract-shipment-manifest-fields's signed .zip, and the reason this lesson shows only a handler.py excerpt, not the complete file.
← Previous2. SLIs for an AI workload: escalation, latency, guardrail block rateNext →4. Hands-on: the escalation rate metric