diff --git a/lore/1-tasks/backlog/0215_BUG_deployed-lambda-never-issues-the-usdt-pivot.md b/lore/1-tasks/backlog/0215_BUG_deployed-lambda-never-issues-the-usdt-pivot.md index f70ea768..cc837003 100644 --- a/lore/1-tasks/backlog/0215_BUG_deployed-lambda-never-issues-the-usdt-pivot.md +++ b/lore/1-tasks/backlog/0215_BUG_deployed-lambda-never-issues-the-usdt-pivot.md @@ -1,6 +1,6 @@ --- id: "0215" -title: "Every enrichment invocation fails on the XLM pivot with BadResponse('') — the USDT pivot is never reached, and the drain only advances because ClickHouse finishes after the client gives up" +title: "Caddy's response_header_timeout of 30s cuts every enrichment pivot at 30.0s — the pass has failed on EVERY invocation since 2026-07-26 and nothing reported it" type: BUG status: backlog related_adr: [] @@ -44,6 +44,75 @@ history: collapses into 0111; measure the actual timeout (client vs the Caddy mTLS proxy) before deciding. Also re-priced 0214: its latched alarm was hiding a continuous failure, and it is the only signal that could have caught this. + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + ROOT CAUSE CONFIRMED — Caddy `response_header_timeout 30s`. Measured 18/18 + at exactly 30.0 s between `query_start_time` and the client error. CH and + our client are both exonerated by measurement (all four CH socket/HTTP + timeouts are 7200 with changed=1; the client sets no request timeout at + all). Onset 2026-07-26 matches the table crossing 30 s after cleanup was + disabled ~07-20. ⛔ RETRACTS the "probably collapses into 0111" note above: + 0111 would clear the symptom but leaves the limit armed, silent, and + applying to every other caller including BE. Fix is two halves — BE raises + the Caddy knob, we add `max_execution_time` per-caller because + `max_execution_time = 0` today and Caddy's 30 s was accidentally the only + bound. Sequence the timeout FIRST so 0111 has a clean baseline to measure + against. + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + BE REPLIED AND CONFIRMED — they are deploying the bump. They verified the + 30 s from Caddy's admin API (the in-memory value the process enforces), + not from the file, and they hold an independent alibi for the 2026-07-26 + onset: no restart since 06-29, last deploy 07-06, config unchanged since + 07-02. Two things change on our side. (1) The mechanism is TIME TO FIRST + BYTE, not a property of INSERT ... SELECT — they were bitten on 07-02 by a + plain heavy SELECT — which widens the affected class to every statement + that computes before it emits, and puts the 26.4 s oracle insert next in + line. (2) Our "Caddy was the only bound on a runaway" rationale for half 2 + is RETRACTED as stated; keep max_execution_time for BE's better reason — + a typed exception with an error code instead of an empty body. Also + recorded: their single-file bind mount pins an inode, so an edit plus a + reload would have been a phantom deploy. Verification protocol agreed — + they ping post-deploy, we confirm from CloudWatch and query_log. + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + BEFORE-STATE RECORDED, and it changed the finding. Two discoveries. (1) The + 30 s ceiling cuts TWO statements, not one — the oracle statement (p95 + 28.7 s, max 37 s, 737.6M rows read) crosses 2-6 times/day and 38 times on + 08-15, and because the oracle tier runs FIRST those invocations issue no + peg or pivot work at all. Confirmed by counting the same event two ways: + oracle-over-30s matches (72 minus peg runs) exactly on six consecutive + days. So the earlier "next in line, a matter of weeks" framing was wrong, + as was an in-session guess blaming 08-14/15's low peg counts on the 0182 + window. (2) max_execution_time resolved per profile — it is 30 on + read_only (so prices_reader, our API, is already bounded server-side) and + ABSENT on prices_write_ddl, so the worker really is unbounded and half 2's + premise holds. It also proves half 2 must live in the client: the Lambda + and the operator CLIs share the single prices_writer user, so no + server-side setting can give them different ceilings. + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + FIXED AND VERIFIED. BE deployed at 14:46:18 UTC with the --force-recreate; + zero BadResponse since, a 46.4 s XLM pivot returned to the client, and the + USDT pivot ran on the schedule for the first time ever (1,895 rows, then + ~17/batch — so the "USDT backlog" of 0209/0212 was ~1,900 rows and the leg + was simply never asked). Three ACs now green. The new bottleneck is ours + and was predicted here before the deploy: Lambda 300 s, 3 batches per + attempt, ~2.16M rows/day (3x baseline, ~258 days for the XLM leg) — so 0111 + is still required. Two new findings: 36% of every invocation is spent in + the oracle tier draining a few hundred rows out of a 737M-row scan, which + is the sharpest 0111 argument yet; and the coarse sweep behind main.rs:167's + `?` has NEVER executed, starving 0114's remedy — spawned as 0218. The peg + statement's constant 1,236 rows/batch spawned as 0219. Remaining here: + max_execution_time per-caller, and the two guard tests. --- # Every invocation fails on the XLM pivot, so the USDT pivot is never reached @@ -178,67 +247,420 @@ confirm it exactly: peg 72/day, XLM pivot 72/day, oracle 192/day. ⛔ **NOT the Lambda timeout.** Zero `Task timed out` in 48 h. `Timeout` is 300 s, `MemorySize` 512 MB. -### Likely cause — a 30-45 s read/idle timeout, hit by one statement only - -| statement | avg | survives? | -|---|---|---| -| peg | 14.4 s | ✅ | -| oracle | 26.4 s | ✅ | -| **XLM pivot** | **45.6 s** | ❌ | +### ✅ ROOT CAUSE — `response_header_timeout 30s` in Caddy -The XLM pivot is the only statement over ~30 s, and it is the only one that -fails. An `INSERT … SELECT` sends no bytes while it runs, so a proxy **idle** -timeout fits well. Two candidates, both unmeasured: +`/srv/app/infra-hetzner/Caddyfile`, the `reverse_proxy clickhouse:8123` transport +block: -1. the `clickhouse` crate client's HTTP timeout, and -2. the **Caddy mTLS reverse proxy** in front of ClickHouse on the Hetzner host. +``` +dial_timeout 10s +response_header_timeout 30s ← this one +read_timeout 7200s +write_timeout 7200s +``` -⚠️ `BadResponse("")` is a known-opaque driver error in this codebase — see the -`FreezeDenied` doc comment in `ch_enrich.rs`, where the same empty-body symptom -was a missing GRANT, diagnosable only by replaying the statement over curl. -**Do not assume "timeout" without measuring it**; replay the XLM pivot over curl -and watch where it dies. +`response_header_timeout` bounds how long the **upstream may take to send its +first response byte**. An `INSERT … SELECT` sends nothing until it completes. The +XLM pivot runs **43.6-47.3 s**. So Caddy severs the connection at 30 s, every +time, and the Rust client sees an empty body — `BadResponse("")`. -### ⚠️ This probably collapses into [[0111]] +**Measured 18/18, gap exactly 30.0 s** (`query_start_time` from `system.query_log` +against the CloudWatch error timestamp, 6 h window, 2026-08-21): -If the cause is duration, the fix is not here. Bound the scan -([[0111]] option 1), the XLM pivot drops from 45.6 s to ~1 s, the pass stops -failing, and the USDT pivot is reached for the first time. **Measure the timeout -before choosing** — if it is a proxy setting the two are independent, and if it -is duration then this task is a symptom and should be closed into 0111. +| query_start | client error (UTC) | gap | +|---|---|---| +| 06:19:30 | 06:20:00 | 30.0 | +| 07:22:35 | 07:23:05 | 30.0 | +| 08:26:35 | 08:27:05 | 30.0 | +| 09:27:52 | 09:28:22 | 30.0 | +| 11:27:57 | 11:28:27 | 30.0 | + +…and every other sample identical. + +**Onset matches the mechanism.** Failures begin 2026-07-26 (6 that day, 67 the +next, then a flat 72/day for 26 days). Cleanup was disabled ~2026-07-20 and the +table began growing from 14.0M rows; by 07-26 the pivot had crossed 30 s and it +has never dropped back under, because the table only grew (736.46M now). + +**Both other layers are exonerated, by measurement:** + +- **ClickHouse.** `http_send_timeout`, `http_receive_timeout`, `send_timeout`, + `receive_timeout` are all **7200** with `changed = 1` — deliberately raised. + The only 30 in `system.settings` is `http_headers_read_timeout`, which bounds + reading the *request* headers. +- **Our client.** `mtls.rs` sets no request timeout at all — only + `pool_idle_timeout(8s)` and `pool_max_idle_per_host(2)`. hyper's legacy client + has no default. It was never going to give up on its own. + +⚠️ **The Caddyfile's own comment shows how this happened.** It states the policy +— *"Timeouts cover the longest legitimate analytical … 7200 s window"* — and +sets `read_timeout`/`write_timeout` accordingly. `response_header_timeout` at 30 s +is the one knob inconsistent with that policy. Its stated rationale ("tighter +than the CH-side timeout so Caddy releases the upstream") is correct for a +streaming `SELECT`, where headers arrive in milliseconds, and simply does not +apply to `INSERT … SELECT`. + +## ✅ BE CONFIRMED IT 2026-08-21 — and found the trap that would have voided the fix + +They checked the box, agreed the change, and are shipping it. Three things in +their reply change or harden this task; a fourth is worth stealing outright. + +### 1. The 30 s is enforced — verified from the running process, not the file + +They read it out of **Caddy's admin API** — the in-memory value the process is +actually executing: `"response_header_timeout": 30000000000` (30 s in ns). That +is the strongest confirmation available, and it matches our 18/18 measurement at +exactly 30.0 s. We were measuring a real limit, not a config artifact. + +### 2. The 2026-07-26 onset is ours, and now has an independent alibi + +Caddy has **not restarted since 2026-06-29**, last deploy **07-06**, config +unchanged since **07-02**. Nothing happened on their side on 07-26. The +growth-crossing explanation recorded above is therefore no longer our inference +alone — it is the only surviving one. + +### 3. ⚠️ CORRECTION — the mechanism is TIME TO FIRST BYTE, not `INSERT … SELECT` + +This task framed the limit as something `INSERT … SELECT` runs into. That is too +narrow. **The same limit bit BE on 2026-07-02 on a plain heavy `SELECT`** — a +~6 min scan over ~9.5 bn rows, 504 to the client while the query kept running +server-side, identical signature. Conversely a *streaming* `SELECT` returns +headers in milliseconds and may then grind for two hours untouched. + +So the affected class is **every statement that computes before it emits its +first byte** — our pivots and peg INSERTs, `count_candidates`, any aggregating +`SELECT`, and every operator-CLI statement of that shape. The discriminator is +buffering, not the verb. + +🔴 **The oracle insert is not "next in line" — it is ALREADY crossing.** Measured +the same day: p95 **28.7 s**, max **37 s**, 2-6 crossings/day and **38 on +08-15**. See the baseline section below, which confirms it to the row. A second +statement class has been failing this whole time and would have been written off +as a network blip. + +### 4. 🔴 THE FINDING TO STEAL — a single-file bind mount pins an inode + +**The bump alone would not have been enough.** Their Caddyfile is bind-mounted as +a **single file**, and a single-file mount pins an *inode*. Their deploy writes +via rsync (temp + rename), which replaces the inode. So since 2026-07-06 the +container has been reading a file that no longer exists at that path — host inode +`16777224`, container inode `16777223`, dated 07-02. Both copies happen to say +the same thing, so nothing broke. + +But **editing the file and running `caddy reload` would have been a phantom +deploy**: repo green, box green, limit still 30 s, and this outage continuing +behind a closed ticket. They are shipping the change with a one-time +`--force-recreate` plus a deploy fix so the inode stops drifting, and they verify +from the admin API — *"the file already lied once"*. + +➡️ **Generalise it.** Same failure family as [[0141]] (a stale lambda artifact +where every signal read success) and `cdk synth` running `dist/` instead of +`src/`: **verify the state the running process holds, never the file you edited.** +Three independent instances now — a standing rule, not a war story. + +### 5. Their deploy touches the shared proxy + +`--force-recreate` drops every mTLS connection for a few seconds. Harmless for the +hourly Lambda; **do not have a long operator CLI statement in flight during their +window** (sdex-backfill, coarse-repair, the 0182 runner). Ask for the window. + +### ⚠️ Scope is wider than this task + +The ceiling applies to **every** statement through that proxy that buffers before +it emits — our operator CLIs (sdex-backfill, coarse-repair, the 0182 runner, all +on the same mTLS client) and **BE's own queries**, since it is their shared host. +Any of them taking over 30 s to first byte dies the same silent way; BE's +2026-07-02 `SELECT` is the confirmed second instance (see BE's reply, §3 above). + +### ⛔ It does NOT collapse into [[0111]] — earlier guess retracted + +0111 option 1 would drop the pivot to ~3-4 s and clear the symptom incidentally. +That is not a reason to skip the timeout fix: + +1. **The trap stays armed.** The limit remains, invisible, and silent. The next + thing on that path to exceed 30 s repeats this outage. +2. **It fixes one caller.** Every other tool and BE keep the ceiling. +3. **The hazard is the FAILURE MODE, not the 30 s.** ClickHouse succeeds, the + client errors, the rows land, nothing reports it. Staying under the line does + not change that. +4. 🔴 **Ordering — this decides the sequence.** Bounding the scan first changes + two things at once (cost drops AND failures stop), so 0111's before/after + cannot be attributed. Fix the timeout first for a clean baseline. + +**Where the real guarantee comes from.** No fixed ceiling can be guaranteed +un-hit. Today the statement's duration scales with **total table size**, which +grows without bound, so *any* limit is crossed eventually. After 0111 option 1 it +scales with **one partition**, which is bounded. That structural change — not a +bigger number — is the guarantee. ### Why nobody saw it [[0214]] — the enrichment errors alarm latched 24 days ago and never re-notified. A continuous, every-invocation failure produced no page. -## Implementation - -- ✅ **The source is EXONERATED — done 2026-08-21.** `reference_ids_helpers` - asserts `full.pivot_ids() == vec![5, 7]` and `peg_sql_never_pegs_usdt` asserts - `IN (3)`; both green (39 unit tests pass). Feature flags are not involved — - nothing on the pivot path is `#[cfg]`-gated beyond `#[cfg(test)]`. So the code - emits two pivots and the deployed artifact emits one. **Do not go looking for a - source bug.** -- ⚠️ **Close the coverage gap that let this hide.** The tests cover - `pivot_ids()` and `pivot_sql()` *separately*; NOTHING asserts that - `enrich_peg_pivot_step` issues **two** statements. That assertion — count the - statements one step sends, against a local CH — is what would have caught this, - and it is the reason a green suite coexisted with a dark quote leg for 8 days. -- Rebuild from a verified-clean tree, redeploy, and confirm by reading the - **emitted SQL** — not `strings`, not `LastModified`, not deploy exit status - ([[oracle-writers-span-two-stacks]]). Both artifact-level checks looked healthy - while the artifact was wrong. -- Rebuild, then verify **on the emitted SQL**, not on `strings` or - `LastModified` — both looked healthy while the artifact was wrong. Redeploy and - confirm by **measurement**, never by deploy exit status - ([[oracle-writers-span-two-stacks]]). -- Add a guard so a silently-absent reference is refused rather than reported - healthy. 0204's gap 4 already carries `resolved_legs` in its metric row for - exactly this reason; the enrichment pass has no equivalent. -- ⚠️ The enrichment Lambda ships from `eventbridge-stack`, which is where - `CleanupRule` lives. Check `describe-rule` **before and after** the deploy - ([[cleanup-rule-shreds-backfill-output]], [[0200]]). +## Implementation — two halves, two owners + +### Half 1 — BE's config, one line + +`response_header_timeout` **30s → 7200s**, aligning it with `read_timeout`, +`write_timeout` and the policy the file's own comment states. Not a loosening of +their policy — a correction of the one setting that contradicts it. ⚠️ Shared +host, shared config: **request it, never edit it ourselves.** + +### Half 2 — ours, and it needs nothing from BE + +⛔ **The original rationale here is RETRACTED — BE refuted it, 2026-08-21.** This +section used to argue: *"Caddy's 30 s was accidentally the only bound on a runaway +query, so removing it leaves a two-hour hole."* BE's counter is correct and is the +cleanest statement of the asymmetry the Caddyfile comment only hinted at: + +> A runaway query **streams**, so it sailed past the 30 s already. What died was +> precisely the statement doing the work and buffering its result. The limit was +> never a safeguard — it selected the exact opposite of what it looks like it +> selects. + +⚠️ **One amendment, which makes half 2 more necessary rather than less.** BE's +point holds for streaming `SELECT`s. A runaway `INSERT … SELECT`, or a runaway +aggregation, buffers — and *that* is our entire workload. So for the enrichment +path the 30 s genuinely was the only bound, and after the bump nothing bounds it: +`max_execution_time` is **0** (unlimited, unchanged). + +**Keep half 2, for BE's better reason.** Set `max_execution_time` **on our +client**. ClickHouse then enforces it and **throws a real exception with an error +code** the worker logs, rather than an empty body indistinguishable from a network +blip. `timeout_overflow_mode` is already `throw`. The value is in the *failure +mode* — hazard 3 below — not in restoring a ceiling. + +⚠️ **It must be per-caller, not a constant.** ~120 s suits the scheduled Lambda +(2.6x headroom over today's 45.6 s worst, inside the 300 s Lambda budget so a +runaway surfaces as a clean CH error rather than a Lambda timeout). The operator +CLIs legitimately run far longer statements — a single global value breaks them +and reintroduces this failure class from the other direction. + +### Also + +- Make an empty-body error distinguishable in the logs from an ordinary network + failure, so a recurrence is diagnosable without a 26-day archaeology dig. +- Track worst statement duration against the configured ceiling as a metric, so + drift toward the limit is visible before it crosses. +- ⚠️ Both `system.settings` readings were taken as `default` via CHQ. The worker + connects as `prices_writer`, an XML user that can carry a different profile. + Confirm against `system.settings_profile_elements` before telling BE "there is + no bound". + +## 📌 BASELINE — recorded 2026-08-21, BEFORE BE's deploy + +Captured deliberately while the ceiling is still armed, because every AC here and +in [[0111]] says "recorded before/after" and this state is unrecoverable once the +bump lands. Read from `system.query_log` and `system.parts` only — no `FINAL` +scan of the hot table. + +### Table + +| | | +|---|---| +| `price_ohlcv_1m` | **736,707,689 rows / 18.45 GiB / 102 partitions / 322 parts** | + +### Statements on `price_ohlcv_1m`, 7 days + +| stmt | runs/day | avg | max | rows read | written/run | +|---|---|---|---|---|---| +| **XLM pivot** | 72 | **45.6 s** | 49.5 s | 687.6 M | **exactly 10,000** | +| **oracle** (`oracle_prices` join) | ~190 | 26.2 s (p95 **28.7**) | **37 s** | **737.6 M** | ~600-1,100 | +| peg | 66-72 | 14.4 s | 15.4 s | 423.0 M | ~1,237 | +| USDT pivot | **0 — absent from all 7 days** | | | | | + +`BadResponse("")` in CloudWatch: **144 in 48 h = exactly 3/hour**, one per XLM +pivot run. The XLM pivot writes **exactly `batch_size`** every run (440,000/44, +660,000/66, 720,000/72 — perfectly linear), so it is `LIMIT`-bound every time and +has never exhausted its candidates. + +## 🔴 The ceiling cuts TWO statements, not one — and the second one was missed + +⚠️ **Corrects this task's own framing.** The oracle statement is not "next in +line" behind the XLM pivot; **it has been dying too**, and because the oracle +tier runs FIRST, an invocation that dies there issues **no peg and no pivot work +at all**. + +Confirmed by counting the same event two ways. If an oracle statement exceeds +30 s, `?` aborts the pass before the peg-pivot tier, so peg runs must fall short +of the 72 invocations/day (1 EventBridge + 2 async retries) by exactly that many: + +| date | oracle `> 30 s` | peg runs | 72 − peg | | +|---|---|---|---|---| +| 08-20 | 0 | 72 | 0 | ✅ | +| 08-19 | 2 | 70 | 2 | ✅ | +| 08-18 | 6 | 66 | 6 | ✅ | +| 08-17 | 5 | 67 | 5 | ✅ | +| 08-16 | 5 | 67 | 5 | ✅ | +| **08-15** | **38** | **34** | **38** | ✅ | + +Six consecutive exact matches, including a day where the oracle ran ~2.5 s slower +(p50 28.4 s vs 26.0) and 38 of 181 statements crossed. That is not correlation. + +⛔ **Also corrects an in-session guess:** 08-14/08-15's low peg counts were +attributed to the 0172/0182 window. Wrong — same mechanism, worse day. + +**The oracle statement is a load-sensitive coin flip at the line**: p50 26.0-26.4, +**p95 28.7**, max 37, against 30. What varies day to day is cluster load, not +table size. And it reads **737.6 M rows — the whole table** — so 0111's growth +argument applies to it identically, and it will cross more often, not less. + +`oracle_prices` (the `ASOF LEFT JOIN` target, `ch_enrich.rs:794`) appears in no +other statement, so the classification is exact. + +## ✅ `max_execution_time` resolved per profile — the worker IS unbounded + +The earlier reading was taken as `default` and this task flagged it as unverified +(the worker connects as `prices_writer`, an XML user with its own profile). +Resolved from `system.settings_profile_elements`: + +| profile | users | `max_execution_time` | +|---|---|---| +| `read_only` | `api_reader`, `dev_read`, **`prices_reader`** | **30** | +| `prices_write_ddl` | **`prices_writer`** | **absent** | + +`prices_write_ddl` carries nine elements — memory, insert-block sizes, all four +7200 s socket timeouts — and **no execution bound**; unlike `dict_loader` it does +not inherit `default` either. **So half 2's premise holds: the worker and every +operator CLI run unbounded.** + +Two things fall out that were previously assertions: + +- **Our read path is already bounded at 30 s, server-side, by ClickHouse.** So + `prices_reader` gets a real `TIMEOUT_EXCEEDED` where `prices_writer` gets an + empty body. The failure asymmetry this task is about was already half-solved on + the API side — half 2 extends an existing house policy rather than inventing + one, and 30 is that policy's number. +- 🔴 **It must live in the client, and now there is a hard reason.** The + scheduled Lambda and the operator CLIs **share the single `prices_writer` + user**, so there is no server-side place to give them different ceilings. A + profile-level setting cannot express this. + +## Verification after BE's deploy — agreed protocol, and what to expect + +BE ping the thread once deployed; we confirm from our side. That two-sided check +is the hardest signal available, and it is deliberately **not** a re-read of the +config file. + +Confirm in this order: + +1. `Clickhouse(BadResponse(""))` stops in `/aws/lambda/prices-production-enrichment`. +2. `CAST(111 AS UInt32) AS ref_asset_id` appears in `system.query_log` on the + hourly schedule — the USDT pivot issued for the first time. +3. `peg_insert : pivot_insert` moves **1:1 → 1:2**. +4. USDT pivot `written_rows > 0` on `price_ohlcv_1m`, recorded before/after. + +### ⚠️ Predict this now, so it is not misread as a new defect + +With the 30 s gone, the binding constraint becomes the **Lambda's 300 s**. A +peg-pivot batch is ~14 s peg + ~46 s XLM pivot + the (cheap, sort-key-pruned) +USDT pivot + ~8 s `count_candidates` ≈ **70 s**, after the oracle tier has taken +its share. So expect roughly **3-4 batches of the configured 20** per invocation, +then `Task timed out` — and [[0026]]'s `EnrichmentPassDurationMs` alarm firing +where it has been silent. + +That is progress, not a fix: a **visible** failure signal replacing an invisible +one, ~3-4x the drain rate, and USDT unblocked. It is **not** the pass completing. +[[0111]]'s "20 batches → ~4.8 M rows/day → ~116 days" was always conditional on +bounding the scan; **the Caddy fix alone does not buy it.** Sequence unchanged: +their fix → clean baseline → 0111. + +⚠️ **Tell BE about the load change.** Today the pass dies after one batch, so it +scans ~72 times/day. Completing passes will scan several times that on a disk we +share and are 3.3% of — the same disk BE filled on 2026-08-13, costing an 11.5 h +ingest stall. It is a courtesy heads-up, and it is a second argument for taking +0111 immediately after. + +## ✅ FIXED AND VERIFIED — 2026-08-21 14:46:18 UTC + +BE deployed the bump (`response_header_timeout` 30s → 7200s) with the one-time +`--force-recreate` their inode finding required. Verified from our side inside +the hour, against the baseline recorded above. + +### The proof is two adjacent lines + +``` +15:20:17 pivot_xlm 46.4 s 10000 rows QueryFinish +15:20:31 pivot_usdt 13.6 s 1895 rows QueryFinish +``` + +A **46.4 s statement returned to the client and execution continued.** That has +been impossible since 2026-07-26. The second line is the first `_1m` row ever +priced by the USDT pivot on the schedule. + +| check | baseline | after | +|---|---|---| +| `BadResponse("")` | 3/hour for 26 days | **0** | +| XLM pivot | 45.6 s, client cut at 30.0 s | 43.4-46.7 s, **all `QueryFinish`, all returned** | +| USDT pivot | **absent from every scheduled run** | **6 runs**, 1,895 rows then ~17/batch | +| peg : pivot | 1:1 | **1:2** | +| peg-pivot batches per attempt | 1, then death | **3** | +| oracle | 2-6 crossings/day killed the pass | 25.1-27.8 s, all completing | + +⚠️ **The USDT backlog was ~1,900 rows — not a backlog at all.** Its first batch +wrote 1,895 and every batch since writes ~17. The leg was never behind, it was +never being *asked*. This closes the substance of [[0209]] and [[0212]]: their +premise was a throughput limit, and the truth was an unreached statement. The +USDT pivot also costs **13.6 s, not 46 s**, because `quote_asset_id = 111` prunes +on the sort key's 2nd column — the XLM pivot is expensive because XLM-quoted rows +*are* the table, not because pivots are expensive. + +### The new bottleneck is ours: the Lambda's 300 s + +``` +REPORT … Duration: 300000.00 ms Memory Size: 512 MB Max Memory Used: 54 MB Status: timeout +``` + +All three attempts, one shared `RequestId` (async retry 1 + 2). **Predicted in +this task before the deploy and confirmed to the batch count** — 3 peg-pivot +batches per attempt at ~72 s each (peg 14 + XLM pivot 45 + USDT pivot 13.6). + +⚠️ `Status: timeout` is a **field on the REPORT line**, not a separate +`Task timed out` message, on `provided:al2023`. Grepping for the old string +returns zero and reads as "no timeouts". It produced a wrong reading here; don't +repeat it. + +**Memory is 54 MB of 512 MB** — the pass is purely time-bound, so raising memory +buys nothing. + +### Throughput — 3x, and still not enough + +| | baseline | after | +|---|---|---| +| XLM pivot runs | 3/hour | **9/hour** (3 attempts × 3 batches) | +| rows/day | 720 K | **~2.16 M** | +| XLM backlog (556.78 M) | ~774 days | **~258 days** | + +Candidate counts corroborate: 656,569,249 → 656,535,211 → 656,506,042 across the +three attempts, ~30 K each, matching 3 × `batch_size` exactly. + +🔴 **36% of every invocation is spent in the oracle tier** — 105-108 s of the +300 s, draining **499, 517 and 3,564 candidates**. Three statements, each reading +the full 737 M-row table. This is the sharpest single argument for [[0111]] +option 1 yet recorded: the pass spends over a third of its budget scanning the +whole table to find a few hundred rows. + +### 🔴 The coarse sweep has NEVER run — [[0114]]'s remedy is starved + +`main.rs:167` is `let stats = pass.run().await?;` and the sweep sits **after** it, +so it is unreachable both ways: before the fix `run()` returned `Err` and `?` +propagated; now the Lambda is killed inside `run()`. `"enrichment pass complete"` +appears in none of the three attempts, and no `"coarse sweep complete"` line +exists in the window. + +Its budget arithmetic cannot save it either — `budget = min(120 s, deadline − now +− 60 s)`, and a pass that runs to the hard deadline leaves that at **0**. + +Spawned as **[[0218]]**. It matters because 0114 — the coarse tables carrying no +USD values — is the defect [[0111]] itself calls "more serious and outranking". + +### Observation spawned as [[0219]] + +The peg statement writes **exactly 1,236 rows on every batch**, eight consecutive +identical counts, and the baseline shows the same (54,414/44 = 1,236.7). New rows +would vary. It looks like the same rows are re-selected and re-written every +batch, inflating `version` for no gain. Pre-existing — not caused by this fix. ## Acceptance Criteria @@ -246,11 +668,22 @@ re-notified. A continuous, every-invocation failure produced no page. excludes USDT, both green (2026-08-21). The defect is the artifact. - [ ] A test asserts `enrich_peg_pivot_step` issues TWO pivot statements, so a silently-narrowed pivot set fails the suite instead of the quote leg. -- [ ] After the fix, `system.query_log` shows `CAST(111 AS UInt32) AS +- [x] After the fix, `system.query_log` shows `CAST(111 AS UInt32) AS ref_asset_id` running on the hourly schedule, outside any hand-run window. -- [ ] `peg_insert : pivot_insert` reaches 1:2 on `price_ohlcv_1m`. -- [ ] USDT-quoted `_1m` rows are measurably written — `written_rows > 0` on the - USDT pivot, recorded before/after. + **Six runs from 15:20:31 UTC, 2026-08-21.** +- [x] `peg_insert : pivot_insert` reaches 1:2 on `price_ohlcv_1m`. **Verified + 2026-08-21 — every peg is followed by an XLM pivot and a USDT pivot.** +- [x] USDT-quoted `_1m` rows are measurably written — `written_rows > 0` on the + USDT pivot, recorded before/after. **Before: 0 across all history. After: + 1,895 on the first batch, ~17/batch since.** +- [ ] `max_execution_time` is set per-caller on our client, and an exceeded bound + produces a logged ClickHouse exception — verified by inducing, not inferred. +- [ ] BE confirm the bump is live **from Caddy's admin API**, not from the + Caddyfile — their single-file bind mount desynced the two once already, and + a file-only check cannot tell a real deploy from a phantom one. +- [ ] We confirm the errors stopped from CloudWatch and `system.query_log`, and + report it back in the thread. Two-sided, because neither side alone can see + both halves. - [ ] `CleanupRule` verified `DISABLED` before and after the deploy. - [ ] A missing reference asset fails loudly instead of silently narrowing `pivot_ids()`. diff --git a/lore/1-tasks/backlog/0218_BUG_coarse-sweep-never-executes-starved-behind-the-1m-pass.md b/lore/1-tasks/backlog/0218_BUG_coarse-sweep-never-executes-starved-behind-the-1m-pass.md new file mode 100644 index 00000000..81db359a --- /dev/null +++ b/lore/1-tasks/backlog/0218_BUG_coarse-sweep-never-executes-starved-behind-the-1m-pass.md @@ -0,0 +1,106 @@ +--- +id: "0218" +title: "The coarse-table sweep has never executed — it sits behind the 1m pass's `?` and is starved by the Lambda deadline" +type: BUG +status: backlog +related_adr: [] +related_tasks: ["0215", "0114", "0111", "0026"] +tags: ["priority-high", "effort-small", "enrichment", "observability", "data-correctness", "milestone-M2"] +milestone: 2 +links: + - "../../../packages/enrichment-worker/src/main.rs" +history: + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + Spawned from 0215's post-fix verification. Found by reading the CloudWatch + log of three consecutive invocations: no "enrichment pass complete" line + and no "coarse sweep complete" line in any of them. Not a regression from + the Caddy fix — the sweep was unreachable before it too, for a different + reason. +--- + +# The coarse sweep is unreachable, and has been on both sides of the fix + +## Summary + +`main.rs:167` is `let stats = pass.run().await?;`. The recurring coarse-table +sweep — [[0114]]'s remedy for the coarse tables carrying no USD values — sits +**after** that `?`. It has therefore never executed in production: + +| period | why it never runs | +|---|---| +| ← 2026-08-21 14:46 | `run()` returned `Err(BadResponse(""))` on every invocation ([[0215]]); `?` propagated and the sweep was skipped | +| 2026-08-21 14:46 → | `run()` no longer errors, but the 1m pass consumes the whole budget and the Lambda is killed **inside** it (`Status: timeout`, `Duration: 300000.00 ms`) | + +Confirmed by absence in CloudWatch across three consecutive attempts +(`RequestId 198d7653-…`, 15:17-15:36 UTC): neither +`"enrichment pass complete"` nor `"coarse sweep complete"` appears. + +## The budget arithmetic cannot rescue it + +`main.rs:195-203`: + +```rust +const MARGIN_MS: u64 = 60_000; +let remaining_ms = lambda_deadline_ms.saturating_sub(now_ms).saturating_sub(MARGIN_MS); +let budget_ms = sweep_budget_secs.saturating_mul(1_000).min(remaining_ms); +``` + +The design is sound in isolation — the sweep defers rather than blowing the +timeout. But it assumes the 1m pass *returns*. A pass that runs to the hard +deadline leaves `remaining_ms` saturated at **0**, so even if the code were +reached the sweep would do nothing. The two failure modes compound. + +⚠️ **The `time_budget_secs: 120` in the startup log is aspirational.** It is +logged from config at cold start (`main.rs:135`), so `"coarse sweep config +enabled=true tables=5 max_batches=20 time_budget_secs=120"` appears on every +invocation and reads like the sweep is configured and running. It is neither. + +## Why this is worth its own task rather than a note on 0111 + +[[0111]] will free the budget, and that is necessary — but it is not sufficient +and it is not the whole defect: + +1. **The failure is silent by construction.** The sweep's own errors are + deliberately swallowed (`"coarse sweep failed (non-fatal)"`), which is correct + for a best-effort stage — but there is no signal distinguishing *swept + nothing*, *swept and failed*, and *never reached*. All three look identical + from outside. +2. **It is starved by design, not by accident.** Any stage placed after an + unbounded stage in a fixed budget gets whatever is left, which is zero when + the first stage is time-bound. Fixing 0111 makes it work *today*; the next + growth in the 1m pass silently starves it again. +3. **It gates [[0114]]**, which [[0111]] itself calls "the more serious defect" + that "outranks this task". + +## Implementation — options to cost + +1. **Separate schedule.** Move the sweep to its own EventBridge rule and Lambda + so it has an independent budget and cannot be starved by the 1m pass. Cleanest + and removes the coupling permanently. +2. **Run it first, bounded.** Give the sweep its 120 s before the 1m pass rather + than after. Preserves one Lambda, but inverts which stage absorbs the squeeze. +3. **Keep the order, add a floor.** Reserve the sweep's budget up front and make + the 1m pass respect the reduced deadline. Smallest change; still one Lambda. + +Option 1 is preferred and is the only one that survives future growth in the 1m +pass. Note that all three depend on the pass not running to the hard deadline — +so [[0111]] is a prerequisite for the sweep doing useful work, whichever is +chosen. + +## Acceptance Criteria + +- [ ] `"coarse sweep complete"` appears in CloudWatch on a recurring schedule, + with `rows_enriched` recorded before/after. +- [ ] A stage that is never *reached* is distinguishable in logs and metrics from + one that ran and found nothing — verified by inducing, not inferred. +- [ ] The sweep's budget cannot be reduced to zero by the preceding stage. +- [ ] `EnrichmentPassDurationMs` and the sweep's own metric are both published on + an invocation that hits the Lambda deadline, so a starved run is visible. + +## Out of scope + +- The full-table scan that consumes the budget — that is [[0111]]. +- The coarse tables' missing USD values themselves — that is [[0114]]. diff --git a/lore/1-tasks/backlog/0219_BUG_peg-statement-rewrites-the-same-1236-rows-every-batch.md b/lore/1-tasks/backlog/0219_BUG_peg-statement-rewrites-the-same-1236-rows-every-batch.md new file mode 100644 index 00000000..d9b659bf --- /dev/null +++ b/lore/1-tasks/backlog/0219_BUG_peg-statement-rewrites-the-same-1236-rows-every-batch.md @@ -0,0 +1,86 @@ +--- +id: "0219" +title: "The peg statement writes exactly 1,236 rows on every batch — the same rows, re-selected and re-versioned forever" +type: BUG +status: backlog +related_adr: [] +related_tasks: ["0215", "0111", "0212", "0182"] +tags: ["priority-medium", "effort-small", "enrichment", "clickhouse", "data-correctness"] +milestone: 2 +links: + - "../../../packages/enrichment-worker/src/ch_enrich.rs" +history: + - date: 2026-08-21 + status: backlog + who: okarcz + note: > + Spawned from 0215's post-fix verification. Pre-existing and unrelated to + the Caddy fix — the same constant appears in the 7-day baseline taken + before it. Recorded as an observation with a falsifiable next step, not a + diagnosis. +--- + +# The peg statement's written_rows is a constant, and constants are suspicious + +## Summary + +`peg_sql` writes **exactly 1,236 rows on every single batch**. Eight consecutive +batches on 2026-08-21 (15:19:31 → 15:35:09), all `1236`. The pre-fix baseline +shows the same figure averaged: 54,414 written over 44 runs = **1,236.7**. + +Genuinely new candidates would vary batch to batch — the XLM pivot's `10000` is +constant for a known reason (it is `LIMIT`-bound by `batch_size`), but 1,236 is +not any configured limit. + +**The likely reading:** the same ~1,236 rows are re-selected and re-written every +batch, each write incrementing `version` on a `ReplacingMergeTree` without +changing the outcome. If so it is pure waste — write amplification and merge +pressure on a shared cluster — and it means the peg leg has been making **no +forward progress at all**, which the run counts alone cannot show. + +## Why it plausibly loops + +`enrich_batch`-family statements use the widened candidate filter +(`volume_quote_usd = 0 OR close_usd = 0`) with `volume_quote_usd` written +**once** (`if(volume_quote_usd > 0, …)`, `ch_enrich.rs:789`). A row that ends a +pass with `close_usd` set but `volume_quote_usd` still `0` therefore stays +eligible forever: it matches the candidate filter on the `volume_quote_usd = 0` +arm, gets re-written, and its `volume_quote_usd` is deliberately not touched. + +⚠️ **This is a hypothesis with an obvious alternative** — 1,236 could be a real +steady-state arrival rate of newly-ingested peg-quoted candles. Do not act on the +loop reading until the identity check below is run. + +## First step — cheap and decisive + +Compare the row *identities* across two consecutive batches. If they are the same +rows, it is a loop; if disjoint, it is arrival rate: + +```sql +SELECT timestamp, asset_id, quote_asset_id, source, version +FROM prices.price_ohlcv_1m FINAL +WHERE quote_asset_id IN (3) AND close_usd > 0 +ORDER BY version DESC +LIMIT 20; +``` + +A cluster of rows carrying a `version` far above the ingest baseline is the +signature. `run_peg_pivot_tier`'s no-progress guard +(`ch_enrich.rs:942`) only breaks when `count_candidates` stops falling overall — +the XLM pivot's 10,000/batch keeps it falling, so a stalled peg leg is masked. + +## Acceptance Criteria + +- [ ] Established by measurement whether the 1,236 rows are the same rows each + batch or newly-arrived ones. +- [ ] If a loop: the rows are made ineligible once enriched, or excluded from the + candidate filter, and `written_rows` is shown to vary afterwards. +- [ ] `version` inflation on the affected rows is quantified before/after. +- [ ] A per-leg no-progress signal exists, so one stalled leg is not masked by + another leg's progress. + +## Out of scope + +- The `volume_quote_usd` write-once semantics themselves, which are deliberate + and depeg-aware ([[0182]]) — this task asks whether the *candidate filter* + should still re-admit those rows, not whether the column should be rewritten.