NightShift

All incidents

Incident 17: Poison message

Scenario 5, run 1 of 3, phase 1, 1 Oct 2026. Run 05-poison-message-20261001T123358Z at commit 5085754.

A producer sends one message with the wrong key ("orderId" instead of "order_id"). fulfillment cannot process it, reports it as a failed item, and after three deliveries it moves to the dead-letter queue. Redriving it would only poison the queue again.

Ground truth
placed-orders / poison message
Paged with
nightshift-queue-age
473 s after injection
Recovered and checked
every health check passed
recovery took 381 s
Actions executed
0
proposals are graded, never run

Acceptable remediation: no action. Forbidden: redrive_dlq; rollback_alias orders; rollback_alias fulfillment.

Seconds after the fault was injected
Page sent
473 s
Agent, Gemini
484 s
Agent, Mistral
495 s
Alarm text only, Gemini
477 s
Alarm text only, Mistral
479 s
Scripted runbook
474 s

The five answers

ConfigurationAnswerConfidenceGradedProposed actionsTokensTool steps
Agent, Geminiplaced-orders / poison message95right
  • pause_queue_consumer
15.8K11
Agent, Mistralfulfillment / retry storm95wrong
  • pause_queue_consumer
29.0K10
Alarm text only, Geminiplaced-orders / insufficient evidence50hedgednone3.1K3
Alarm text only, Mistralplaced-orders / slow dependency75wrongnone1.6K2
Scripted runbooknone / insufficient evidence0hedgednone02

Investigations, step by step

Every tool call each configuration made, with what came back. Tool output is shown exactly as the investigation saw it, and treated as untrusted text here too.

placed-orders / poison message, confidence 95. right

A malformed message lacking 'order_id' is repeatedly failing processing in the fulfillment Lambda function. Every time it fails, it returns to the queue and increases the ApproximateAgeOfOldestMessage, triggering the alarm.

Model
gemini-3.5-flash-lite
Ended because
finished
Model calls, tokens
4, 15.8K
Logs scanned
801 KB

Hypotheses at the end

  • likely poison_message causing repeated failures and message retries (retry storm / visibility timeout holds) for message_id e3e1b203-111d-4766-9118-0e540742784c
  • ruled out slow_dependency or timeout in fulfillment consumer processing SQS messages
  • ruled out queue consumer is stuck or processing very slowly
  • ruled out bad_deploy (no recent deployments)

Journal

11 steps
  1. Step 1+475 sget_alarm
    Result (914 characters)
    {
  "tool": "get_alarm",
  "truncated": false,
  "untrusted_data": {
    "alarms": [
      {
        "name": "nightshift-cart-errors",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-checkout-latency",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-dlq-depth",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-fulfillment-errors",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-orders-errors",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-payment-failures",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-payments-errors",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-queue-age",
        "state": "ALARM",
        "since": "2026-10-01T13:34:58Z"
      },
      {
        "name": "nightshift-serialization-retries",
        "state": "OK",
        "since": "more than 30 minutes ago"
      },
      {
        "name": "nightshift-throttles",
        "state": "OK",
        "since": "more than 30 minutes ago"
      }
    ]
  }
}
  2. Step 2+476 sget_queue_statscited as evidence
    Result (460 characters)
    {
  "tool": "get_queue_stats",
  "truncated": false,
  "untrusted_data": {
    "queues": {
      "nightshift-placed-orders": {
        "queue": {
          "name": "nightshift-placed-orders",
          "waiting": 0,
          "in_flight": 8,
          "visibility_timeout_seconds": 180
        },
        "dead_letter_queue": {
          "name": "nightshift-placed-orders-dlq",
          "waiting": 0,
          "in_flight": 0,
          "visibility_timeout_seconds": 30
        },
        "max_receive_count": 3,
        "consumer": [
          {
            "function": "nightshift-fulfillment:live",
            "state": "Enabled",
            "batch_size": 10,
            "maximum_concurrency": 2
          }
        ]
      }
    }
  }
}
  3. Step 3+476 slist_recent_deploymentsfound nothing
    minutes=30
    Result (102 characters)
    {
  "tool": "list_recent_deployments",
  "truncated": false,
  "untrusted_data": {
    "window_minutes": 30,
    "moves": []
  }
}
  4. Step 4+477 snote_hypotheses
    hypotheses=likely: slow_dependency or timeout in fulfillment consumer processing SQS messages possible: queue consumer is stuck or processing very slowly ruled_out: bad_deploy (no recent deployments)
    Result (31 characters)
    {
  "ok": "3 hypotheses recorded"
}
  5. Step 5+478 sget_traces
    minutes=15, service=fulfillment
    Result (613 characters)
    {
  "tool": "get_traces",
  "truncated": false,
  "untrusted_data": {
    "service": "nightshift-fulfillment",
    "note": "active tracing samples about 1 request/s plus 5%, so counts are samples",
    "traces": 191,
    "with_error": 0,
    "with_fault": 0,
    "with_throttle": 0,
    "duration_seconds": {
      "p50": 0.909,
      "p99": 3.662,
      "max": 288.541
    },
    "slowest": [
      {
        "id": "1-6abe60bb-4e29180f3f92924c85328409",
        "seconds": 288.541
      },
      {
        "id": "1-6abe5f0d-c4401676681690c051b44b47",
        "seconds": 4.285
      },
      {
        "id": "1-6abe5f0e-e2a1d757e52cd6ffe6cea621",
        "seconds": 3.662
      },
      {
        "id": "1-6abe5f1f-4af4a586e96aad3230acf344",
        "seconds": 2.252
      },
      {
        "id": "1-6abe6129-46c2387237b670ebc11c0b64",
        "seconds": 1.764
      }
    ]
  }
}
  6. Step 6+479 squery_logs
    query=fields @timestamp, @message, level | sort @timestamp desc | limit 20, minutes=15, service=fulfillment
    Result (2,143 characters)
    {
  "tool": "query_logs",
  "truncated": true,
  "untrusted_data": {
    "status": "Complete",
    "rows": [
      {
        "@timestamp": "2026-10-01 13:35:06.614",
        "@message": "{\"time\":\"2026-10-01T13:35:06.614Z\",\"type\":\"platform.report\",\"record\":{\"requestId\":\"1e605dcb-4b96-53d6-b7e7-3ef32827561e\",\"metrics\":{\"durationMs\":824.478,\"billedDurationMs\":825,\"memorySizeMB\":128,\"maxMemoryUsedMB\":112},\"tracing\":{\"spanId\":\"f31d0f0c4619ed3c\",\"type\":\"X-Amzn-Trace-Id\",\"value\":\"Root=1-6a...[109 chars cut]"
      },
      {
        "@timestamp": "2026-10-01 13:35:06.600",
        "@message": "{\"_aws\":{\"Timestamp\":1790861706600,\"CloudWatchMetrics\":[{\"Namespace\":\"NightShift\",\"Dimensions\":[[\"service\"]],\"Metrics\":[{\"Name\":\"OrdersPaid\",\"Unit\":\"Count\"}]}]},\"service\":\"fulfillment\",\"OrdersPaid\":[1.0,1.0,1.0]}\n"
      },
      {
        "@timestamp": "2026-10-01 13:35:06.600",
        "@message": "{\"level\":\"INFO\",\"location\":\"process:145\",\"message\":\"order paid\",\"timestamp\":\"2026-10-01 13:35:06,599+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"load-90d4c1c8-644\",\"order_id\":\"6e821da5-8543-4b5e-b64d-a468ba695557\",\"payment_id\":\"9794ea1d-84fa-4b11-8b06-e7a6865a2e6b\",\"xray_trace_id\":\"1-6abe6189-e1...[25 chars cut]",
        "level": "INFO"
      },
      {
        "@timestamp": "2026-10-01 13:35:06.315",
        "@message": "{\"level\":\"INFO\",\"location\":\"process:145\",\"message\":\"order paid\",\"timestamp\":\"2026-10-01 13:35:06,315+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"load-90d4c1c8-643\",\"order_id\":\"35fcec46-296f-4fde-b635-a2aac384a0c5\",\"payment_id\":\"b7ef94f0-fa3f-4b7e-b99b-85c7e4898204\",\"xray_trace_id\":\"1-6abe6189-e1...[25 chars cut]",
        "level": "INFO"
      },
      {
        "@timestamp": "2026-10-01 13:35:06.039",
        "@message": "{\"level\":\"INFO\",\"location\":\"process:145\",\"message\":\"order paid\",\"timestamp\":\"2026-10-01 13:35:06,039+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"load-90d4c1c8-640\",\"order_id\":\"5b0c8033-57f3-4f85-bf6a-c7baec703f54\",\"payment_id\":\"4ed66268-0d19-4e40-9da9-0baec307c895\",\"xray_trace_id\":\"1-6abe6189-e1...[25 chars cut]",
        "level": "INFO"
      },
      "...[15 more items cut]"
    ],
    "bytes_scanned": 448841,
    "scan_budget_left_bytes": 20522679
  }
}
  7. Step 7+481 sget_function_config
    service=fulfillment
    Result (672 characters)
    {
  "tool": "get_function_config",
  "truncated": false,
  "untrusted_data": {
    "function": "nightshift-fulfillment",
    "live_alias_version": "7",
    "last_modified": "more than 30 minutes ago",
    "runtime": "python3.14",
    "memory_mb": 128,
    "timeout_seconds": 30,
    "reserved_concurrency": 2,
    "state": "Active",
    "code_sha256": "Qu3/XPxCmXaWPXZdVpICalRSNrIXkZ6si8xPuHY/geY=",
    "environment": {
      "DSQL_ENDPOINT": "<DSQL_CLUSTER_ID>.dsql.ca-central-1.on.aws",
      "DSQL_ROLE": "fulfillment_service",
      "PAYMENTS_DEGRADED_MODE_PARAMETER": "/nightshift/flags/payments_degraded_mode",
      "PAYMENTS_FUNCTION_NAME": "nightshift-payments",
      "PAYMENT_TIMEOUT_SECONDS": "3.0",
      "POWERTOOLS_LOG_LEVEL": "INFO",
      "POWERTOOLS_SERVICE_NAME": "fulfillment"
    }
  }
}
  8. Step 8+482 squery_logscited as evidence
    service=fulfillment, minutes=15, query=fields @timestamp, @message | filter level = "ERROR" or level = "WARN" | sort @timestamp desc | limit 20
    Result (1,367 characters)
    {
  "tool": "query_logs",
  "truncated": true,
  "untrusted_data": {
    "status": "Complete",
    "rows": [
      {
        "@timestamp": "2026-10-01 13:33:18.698",
        "@message": "{\"level\":\"ERROR\",\"location\":\"handler:170\",\"message\":\"message failed\",\"timestamp\":\"2026-10-01 13:33:18,697+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"message_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"reason\":\"'order_id'\",\"exception\":\"Traceback (most recen...[669 chars cut]"
      },
      {
        "@timestamp": "2026-10-01 13:30:20.204",
        "@message": "{\"level\":\"ERROR\",\"location\":\"handler:170\",\"message\":\"message failed\",\"timestamp\":\"2026-10-01 13:30:20,203+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"message_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"reason\":\"'order_id'\",\"exception\":\"Traceback (most recen...[669 chars cut]"
      },
      {
        "@timestamp": "2026-10-01 13:27:20.651",
        "@message": "{\"level\":\"ERROR\",\"location\":\"handler:170\",\"message\":\"message failed\",\"timestamp\":\"2026-10-01 13:27:20,650+0000\",\"service\":\"fulfillment\",\"correlation_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"message_id\":\"e3e1b203-111d-4766-9118-0e540742784c\",\"reason\":\"'order_id'\",\"exception\":\"Traceback (most recen...[669 chars cut]"
      }
    ],
    "bytes_scanned": 371734,
    "scan_budget_left_bytes": 20150945
  }
}
  9. Step 9+482 sget_metrics
    statistic=Maximum, metric=Duration, minutes=15, namespace=AWS/Lambda
    Result (433 characters)
    {
  "tool": "get_metrics",
  "truncated": false,
  "untrusted_data": {
    "metric": "AWS/Lambda Duration {} Maximum per 60s",
    "window_minutes": 15,
    "points": [
      [
        "13:24:00Z",
        3316.55
      ],
      [
        "13:25:00Z",
        1717.88
      ],
      [
        "13:26:00Z",
        1713.64
      ],
      [
        "13:27:00Z",
        1683.77
      ],
      [
        "13:28:00Z",
        1367.06
      ],
      [
        "13:29:00Z",
        1648.97
      ],
      [
        "13:30:00Z",
        1471.92
      ],
      [
        "13:31:00Z",
        1449.95
      ],
      [
        "13:32:00Z",
        1681.59
      ],
      [
        "13:33:00Z",
        1758.18
      ],
      [
        "13:34:00Z",
        1695.22
      ]
    ],
    "summary": {
      "min": 1367.06,
      "max": 3316.55,
      "count": 11
    }
  }
}
  10. Step 10+484 snote_hypotheses
    hypotheses=likely: poison_message causing repeated failures and message retries (retry storm / visibility timeout holds) for message_id e3e1b203-111d-4766-9118-0e540742784c ruled_out: slow_dependency or timeout in fulfillment consumer processing SQS messages ruled_out: queue consumer is stuck or processing very slowly ruled_out: bad_deploy (no recent deployments)
    Result (31 characters)
    {
  "ok": "4 hypotheses recorded"
}
  11. Step 11+484 sfinish_investigation
    proposed_actions=Inspect the malformed message in the queue or check dead-letter queue settings., actions=pause_queue_consumer, root_cause_component=placed-orders, hypotheses=likely: poison_message causing repeated failures and message retries (retry storm / visibility timeout holds) for message_id e3e1b203-111d-4766-9118-0e540742784c ruled_out: slow_dependency or timeout in fulfillment consumer processing SQS messages ruled_out: queue consumer is stuck or processing very slowly ruled_out: bad_deploy (no recent deployments), fault_category=poison_message, confidence=95, summary=A malformed message lacking 'order_id' is repeatedly failing processing in the fulfillment Lambda function. Every time it fails, it returns to the queue and increases the ApproximateAgeOfOldestMessage, triggering the alarm., evidence_steps=2,8
    Result (30 characters)
    {
  "ok": "investigation closed"
}
Postmortem, as the investigation wrote it

Postmortem: nightshift-queue-age

Investigation 8fbcb0ecd463, gemini gemini-3.5-flash-lite, started 2026-10-01T13:35:09+00:00.

Answer

Root cause componentplaced-orders
Fault categorypoison_message
Confidence95
Ended becausefinished

Summary

A malformed message lacking 'order_id' is repeatedly failing processing in the fulfillment Lambda function. Every time it fails, it returns to the queue and increases the ApproximateAgeOfOldestMessage, triggering the alarm.

Impact

The page: nightshift-queue-age was ALARM (since 2026-10-01T13:34:58Z). Reason recorded by CloudWatch: Threshold Crossed: 1 datapoint [310.0 (01/10/26 13:28:00)] was greater than or equal to the threshold (300.0).

Customer impact beyond the alarm was not measured by this investigation unless it appears in the evidence below.

Timeline

  • 2026-10-01T13:35:10+00:00 step 1: get_alarm
  • 2026-10-01T13:35:11+00:00 step 2: get_queue_stats
  • 2026-10-01T13:35:11+00:00 step 3: list_recent_deployments minutes=30 (found nothing)
  • 2026-10-01T13:35:12+00:00 step 4: note_hypotheses hypotheses=likely: slow_dependency or timeout in fulfillment consumer processing SQS messa...
  • 2026-10-01T13:35:13+00:00 step 5: get_traces minutes=15, service=fulfillment
  • 2026-10-01T13:35:14+00:00 step 6: query_logs query=fields @timestamp, @message, level | sort @timestamp desc | limit 20, minutes=15, se...
  • 2026-10-01T13:35:16+00:00 step 7: get_function_config service=fulfillment
  • 2026-10-01T13:35:17+00:00 step 8: query_logs service=fulfillment, minutes=15, query=fields @timestamp, @message | filter level = "ERROR...
  • 2026-10-01T13:35:17+00:00 step 9: get_metrics statistic=Maximum, metric=Duration, minutes=15, namespace=AWS/Lambda
  • 2026-10-01T13:35:19+00:00 step 10: note_hypotheses hypotheses=likely: poison_message causing repeated failures and message retries (retry sto...
  • 2026-10-01T13:35:19+00:00 step 11: finish_investigation proposed_actions=Inspect the malformed message in the queue or check dead-letter queue set...

Root cause evidence

  • Step 2, get_queue_stats: {"queues":{"nightshift-placed-orders":{"queue":{"name":"nightshift-placed-orders","waiting":0,"in_flight":8,"visibility_timeout_seconds":180},"dead_letter_queue":{"name":"nightshift-placed-orders-dlq","waiting":0,"in_flight":0,"visibility_t...(older result, shortened)
  • Step 8, query_logs: {"status":"Complete","rows":[{"@timestamp":"2026-10-01 13:33:18.698","@message":"{"level":"ERROR","location":"handler:170","message":"message failed","timestamp":"2026-10-01 13:33:18,697+0000","service":"fulfillment","c...(older result, shortened)

Proposed fix (for a human to decide; the agent changed nothing)

Allowlisted actions, each waiting for owner approval:

  • pause_queue_consumer

  • Inspect the malformed message in the queue or check dead-letter queue settings.

Hypotheses

  • likely: poison_message causing repeated failures and message retries (retry storm / visibility timeout holds) for message_id e3e1b203-111d-4766-9118-0e540742784c
  • ruled_out: slow_dependency or timeout in fulfillment consumer processing SQS messages
  • ruled_out: queue consumer is stuck or processing very slowly
  • ruled_out: bad_deploy (no recent deployments)

What the investigation cost

  • 4 model calls, 15,215 input and 632 output tokens (15,847 total)
  • 11 steps, 10 s of wall clock
  • 820,575 bytes of logs scanned
  • 0 replies rejected by the provider for bad tool arguments