Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 30 additions & 0 deletions lore/1-tasks/active/0220_CHORE_0111-duration-soak-to-2026-08-31.md
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,36 @@ at **300,000 / 300,338 ms** on 2026-08-21, which is what re-opened 0111.
Stage split inside an invocation: 1m pass ~7.2 s, historical sweep ~0.5 s, coarse
sweep ~21 s. Peak Lambda memory **52-54 MB of 512 MB**.

## Daily log

### 2026-08-25 17:41 UTC — day 2 of 8, clean on all three metrics

24 consecutive hourly datapoints, no gaps.

| metric | reading | criterion |
|---|---|---|
| `Duration` max | **6,057 – 10,807 ms** | ≪ 240,000 ms — peak is 4.5% of threshold |
| `Invocations` | **1.0/hour**, all 24 | 1/hour ✅ |
| `Errors` | **0.0/hour**, all 24 | 0/hour ✅ |

Alarm `prices-production-enrichment-duration-near-timeout` = `OK`, with
`StateUpdatedTimestamp` still **2026-08-24T08:31:25** — unchanged since the
hand-off baseline, so it has not flapped in between.

No sign of the 3-invocations / 3-errors pattern.

🔑 **The baseline above is stale, and a future check must not read today's 8 s
against it as an unexplained change.** The hand-off recorded ~27,000 ms with a
stage split of "1m pass ~7.2 s, historical sweep ~0.5 s, **coarse sweep ~21 s**".
[[0218]] moved that coarse sweep into its own Lambda on 2026-08-24, so the ~21 s
left this function. What remains — 6-11 s — matches the 1m-pass plus
historical-sweep figures almost exactly. The drop is the split showing up in the
metric, not a new improvement to chase.

⚠️ Still outstanding for the soak: the **demonstrated-write-load** criterion. A
quiet week does not count. It needs to land in only one of the six remaining
checks; prefer a weekday afternoon over a Sunday.

## The daily check

```bash
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
id: "0222"
title: "The coarse-sweep no-invocations alarm did not fire after three genuinely empty hours — the instrument that detects a dead schedule is slower than its config claims"
type: BUG
status: active
status: completed
related_adr: []
related_tasks: ["0218", "0204", "0220"]
tags: [layer-infra, priority-high, effort-small, observability, cloudwatch, alarms, ops]
Expand Down Expand Up @@ -74,6 +74,46 @@ history:
remedy has different semantics; spawned separately. One AC added: watch the
2/2 ledger-processor alarm for ~2 h post-deploy, since its flap risk was
mitigated on judgement rather than measurement.
- date: 2026-08-25
status: active
who: okarcz
note: >
Deployed to production and AC 4 induced the same hour. All six
no-invocations alarms now evaluate `FILL(invocations, 0)`; the temp alarm
`tmp-0222-fill-p300` went OK to ALARM at 17:46:28 UTC on a trailing gap and
was deleted before the next :30 run. The induction ran at `Period=300`
rather than the 900 written into AC 4 - at 900 the third empty bucket
completes exactly at :30, racing the next sweep run, so 900 is a less
reliable test rather than a stricter one. AC 4 restated accordingly.
Two findings came out of the `stateReasonData` that are larger than the
tick: evaluation windows are query-anchored and slide rather than aligning
to the clock, which falsifies the bucket reasoning used for the earlier
control run; and on the corrected baseline FILL detects silence roughly an
order of magnitude faster than the raw form. AC 7 still open - the
ledger-processor flap watch is a single `describe-alarm-history` read on
2026-08-26, since history persists.
- date: 2026-08-26
status: completed
who: okarcz
note: >
AC 7 closed on the overnight read and the task completed. 7 of 7 criteria
resolved — 5 ticked as written, AC 4's Period and AC 5 restated rather than
ticked, with the reasoning recorded in both cases.
The `2/2` ledger-processor flap did NOT materialise: zero state transitions
in the 13.5 h since the 17:32 deploy, `StateUpdatedTimestamp` still
2026-07-09, and the only retained history item is the ConfigurationUpdate
at 17:31:40. The OK was checked for substance rather than taken at face
value — 56 of 56 expected 900 s buckets, 155-161 invocations each, FILL
output byte-identical to raw with no filled buckets.
🔑 Finding 4 added: a hand-run `get-metric-data` FILL query whose window
ends in the FUTURE fabricates a trailing gap — 19 consecutive zero buckets
that read exactly like a 4h45m ingestion halt. Bound the window at `now`.
It also strengthens the 2/2 judgement call: if future buckets fill as
zeros, an incomplete current bucket does too.
Shipped: PR #247 (the FILL fix, deployed 2026-08-25 17:32 UTC), PR #250
(deploy + induction record). Six no-invocations alarms converted to metric
math, zero left on the legacy single-metric form. Follow-up [[0223]]
already spawned for the NOT_BREACHING siblings.
---

# The no-invocations alarm did not fire after three empty hours
Expand Down Expand Up @@ -436,6 +476,102 @@ the rest unchanged at `3/3`.
- Verify by inducing, on the standard [[0218]] set for itself — and the induction
must now be cheap enough to repeat, which is part of what the fix buys.

## Deploy + induction record — 2026-08-25

### Deployed

`Prices-production-Observability` **alone**, 17:32 UTC, 11.68 s. Only
`observability-stack.ts` changed, so [[0218]]'s "EventBridge before
Observability" ordering does not apply — every function the alarms name already
exists.

`cdk diff` was exactly the change and nothing else: six alarms swapping
single-metric → metric-math, plus `ledger-processor` `1/1 → 2/2` and its
description. No portal / Discord OAuth / Secrets / Compute / ApiGateway
resources, no replacements, and no hidden-changes footer, so no `--strict`
re-read was needed.

⚠️ The `S3?SNS?SQS` in the diff's **removed** description is the known non-ASCII
mangling of the currently-deployed text being read back. The `[+]` side renders
`S3→SNS→SQS` correctly. Text only, not a change.

`prices-production-cleanup` read `DISABLED` **before and after** the deploy.
`prices-production-coarse-sweep` read `ENABLED cron(30 * * * ? *)` after.

Post-deploy, all six converted and all `OK`:

| alarm | eval | expression | period |
|---|---|---|---|
| `enrichment-no-invocations` | 3/3 | `FILL(invocations, 0)` | 3600 |
| `coarse-sweep-no-invocations` | 3/3 | `FILL(invocations, 0)` | 3600 |
| `backfill-freshness-probe-no-invocations` | 3/3 | `FILL(invocations, 0)` | 900 |
| `rollup-freshness-probe-no-invocations` | 3/3 | `FILL(invocations, 0)` | 900 |
| `mtls-notafter-probe-no-invocations` | 3/3 | `FILL(invocations, 0)` | 86400 |
| `ledger-processor-no-invocations` | **2/2** | `FILL(invocations, 0)` | 900 |

### AC 4 — INDUCED 2026-08-25, and this is the first *alarm* evidence

`tmp-0222-fill-p300` — identical to the deployed coarse-sweep alarm except in
`Period` — created 17:36 UTC just after the `:30` run, **no `--alarm-actions`**,
so nobody was paged. Deleted 17:47, before the 18:30 run; `describe-alarms
--alarm-name-prefix tmp-0222` returned empty afterwards.

```
17:36:10 INSUFFICIENT_DATA (birth state)
17:37:28 INSUFFICIENT_DATA → OK
17:46:28 OK → ALARM
```

The `OK` at 17:37 is a real evaluation, not inertia: its window still held the
17:30 run, so one of three datapoints was non-breaching against
`DatapointsToAlarm: 3`. Everything before today was `get-metric-data`, which
proves FILL's *behaviour*; this proves a CloudWatch **alarm** built on it
transitions.

### 🔑 Finding 1 — evaluation windows are query-anchored and slide

From `stateReasonData` on the two transitions:

| query | window start | buckets evaluated |
|---|---|---|
| 17:37:28 | 17:22:00 | 17:22 `0.0`, **17:27 `1.0`**, 17:32 `0.0` |
| 17:46:28 | 17:31:00 | 17:31 `0.0`, 17:36 `0.0`, 17:41 `0.0` |

The 17:30 run lands in a bucket **starting 17:27**, and the next evaluation's
window starts at **17:31**. Buckets re-anchor to each query rather than to
`:00/:05/:10`.

⚠️ **This falsifies the reasoning used for the earlier control run** in RESULT
above, which computed condition-met from clock-aligned buckets (`12:35-40,
12:40-45, 12:45-50`). The correct baseline is *when the last run ages out of the
sliding window*. The 6m51s figure is left in place as recorded, but should not be
read as measured against a correct baseline.

### 🔑 Finding 2 — FILL detects silence far faster, on the corrected baseline

| form | last run | window clear | breached | lag |
|---|---|---|---|---|
| raw single-metric | 12:30 | 12:45 | 12:56:51 | **~11m51s** |
| `FILL(invocations, 0)` | 17:30 | 17:45 | 17:46:28 | **~1m28s** |

Same function, same dimension, same `Period=300`, same `3/3`. The only difference
is FILL.

⚠️ **Indicative, not a measured constant.** The earlier run's `stateReasonData`
was never captured, so its window alignment is inferred rather than read. Do not
quote the ratio as an established figure.

### ⚠️ Finding 3 — the review's flap concern has its first supporting evidence

The newest bucket in the breaching evaluation (17:41–17:46) closed **28 seconds**
before the query that read it as `0.0`. Nothing was genuinely invoked, so this is
not a reproduction — but an alarm reading a bucket that fresh is exactly the
window in which a late-publishing `Invocations` datapoint would be counted as a
zero.

That is evidence *for* the `2/2` change on `ledger-processor`, which was made on
judgement alone and explicitly recorded as such. It does not settle it; AC 7 does.

## Acceptance Criteria

- [x] The lag between a function going idle and the alarm breaching is
Expand All @@ -447,14 +583,24 @@ the rest unchanged at `3/3`.
- [x] The remedy removes the dependency on CloudWatch's missing-data semantics
rather than tuning around them.
→ `FILL(invocations, 0)` in `addWorkerHealthAlarms`; synth verified, five
alarms convert. **Not yet deployed or induced.**
- [ ] If unacceptable, a remedy ships and is verified by inducing the silence,
alarms convert (six with the hand-rolled ledger-processor).
**Deployed to production 2026-08-25 17:32 UTC and induced the same hour** —
see the deploy record above.
- [x] If unacceptable, a remedy ships and is verified by inducing the silence,
not by reading the config.
→ Cheap proxy induction, ~45 min, no schedule touched: a temp alarm using
`FILL(invocations, 0)` at `Period=900`, `3/3`, on the coarse sweep, created
just after a `:30` run. Everything so far is `get-metric-data`, which
proves FILL's behaviour but NOT that a CloudWatch **alarm** built on it
transitions. That gap is what this closes.
→ Shipped 17:32 UTC, induced 17:36-17:47 UTC. `tmp-0222-fill-p300` went
**`OK → ALARM` at 17:46:28** on a trailing gap, no schedule touched and no
actions attached. ⚠️ **Run at `Period=300`, not the `900` written above —
restated, see below.**

⚠️ **AC 4's `Period=900` restated.** As written the proxy alarm was to run at
`Period=900`, `3/3`. That needs 45 minutes of silence, which puts the third
empty bucket at exactly `:30` — the moment the next sweep run lands. It races
the very thing it measures, so 900 is a *less reliable* test rather than a
stricter one. `Period=300` tests the same unproven proposition — that a
metric-math alarm built on FILL transitions — inside a 15-minute gap the
schedule reliably provides. Restated and agreed before the run, not after it.
Same restate-don't-tick pattern as this task's AC 5 and [[0218]]'s AC 4.
- [x] ~~[[0218]] AC 2 state 3 becomes inducible within a window a person can
actually sit through~~ — **RESTATED, not ticked as written.** See
"AC 5 restated" below.
Expand All @@ -467,10 +613,73 @@ the rest unchanged at `3/3`.
Same class as `EnrichmentBacklogAlarm`. FILL does not help; the remedy has
different semantics (a duration alarm must not fire because nothing ran)
and is spawned separately rather than folded in here.
- [ ] The `2/2` ledger-processor change is watched for ~2 h after deploy.
- [x] The `2/2` ledger-processor change is watched for ~2 h after deploy.
Its flap risk was mitigated on a judgement, not a measurement — post-deploy
is when a flap would show, and finding out from `describe-alarm-history`
beats finding out from a 3am page.
→ **NO FLAP.** Read 2026-08-26 07:0x UTC, covering the whole 13.5 h
overnight window since the 17:32 deploy. **Zero `OK → ALARM → OK` cycles**
— in fact zero state transitions of any kind. See "AC 7 — the overnight
read" below.

```bash
aws cloudwatch describe-alarm-history \
--alarm-name prices-production-ledger-processor-no-invocations \
--history-item-type StateUpdate --max-records 20 --region eu-central-1 \
--query 'AlarmHistoryItems[].[Timestamp,HistorySummary]' --output text
```

## AC 7 — the overnight read, 2026-08-26 07:0x UTC

The flap did not happen. `describe-alarm-history --history-item-type StateUpdate`
returned **empty**, and the discriminator that empty is a *result* rather than a
typo'd alarm name is `describe-alarms`:

```
prices-production-ledger-processor-no-invocations OK 2/2 threshold 1.0 breaching
StateUpdatedTimestamp 2026-07-09T08:35:18Z
ConfigurationUpdate 2026-08-25T17:31:40Z <- the deploy
```

The only retained history item is the config update at **17:31:40**, matching the
deploy record. `StateUpdatedTimestamp` is **2026-07-09** — six weeks before the
change — so the alarm held `OK` straight through the conversion and did not even
produce the settling `INSUFFICIENT_DATA → OK` this AC predicted. Updating an
alarm's metric did not reset its state.

### The `OK` is substantive, not vacuous

A green reading is worth nothing on its own — the standing lesson from
`usd-peg-applied` and from `EnrichmentBacklogAlarm`. So the datapoints were read
directly, `17:00 → 07:00`, `Period=900`:

| series | n | range |
|---|---|---|
| `raw` | **56 of 56** expected buckets | **155 – 161** |
| `FILL(raw, 0)` | **56**, byte-identical | zero filled buckets |

Live ingestion ran continuously at ~1 invocation every 5.6 s. The alarm is
reading real non-breaching datapoints, so `OK` means "healthy", not "blind".

### ⚠️ Finding 4 — a FILL query whose window ends in the *future* fabricates a halt

The first version of the check above ran to an end-time of `12:00Z` while the
clock read `07:02Z`. `FILL` synthesised zeros across the ~5 hours of **future**
window, returning **19 consecutive empty 15-minute buckets on a trailing gap** —
output indistinguishable from a genuine 4h45m ingestion halt, and very nearly
reported as one.

That is the documented "FILL extends past the last datapoint" behaviour working
exactly as specified. The operational rule it implies:

🔑 **Bound a hand-run `get-metric-data` FILL window at `now`.** A future end-time
manufactures the exact signal you are testing for. Always `date -u` first.

The alarms themselves are unaffected — an alarm's window always ends at ~now —
but this sharpens the case for the `2/2` change rather than weakening it: if
*future* buckets fill as zeros, an **incomplete** current bucket does too, which
is the flap mechanism Finding 3 caught at 28 seconds. `1/1` on a FILL alarm would
be a live page waiting to happen.

## AC 5 restated — the criterion asked for something unachievable

Expand Down
Loading