From d4d9addbd5798b233a6b54b35c6a851c55f1be56 Mon Sep 17 00:00:00 2001 From: karczuRF Date: Fri, 21 Aug 2026 14:06:57 +0200 Subject: [PATCH 1/4] docs(lore-0215): root cause is Caddy's 30s response_header_timeout Measured 18/18 at exactly 30.0s between query_start_time and the client error. response_header_timeout bounds time-to-first-byte from upstream, and an INSERT ... SELECT sends nothing until it completes, so the 43.6-47.3s XLM pivot is severed every time and the client sees an empty body. Both other layers are exonerated by measurement. All four ClickHouse socket and HTTP timeouts are 7200 with changed=1; the only 30 in system.settings bounds reading request headers. Our client sets no request timeout at all, only pool_idle_timeout. Onset 2026-07-26 matches the table crossing 30s after cleanup was disabled around 07-20, and it never came back under because the table only grew. Retracts the earlier note that this collapses into 0111. Bounding the scan would clear the symptom but leaves the limit armed and silent, fixes one caller out of many including BE's own queries, and contaminates 0111's own before/after measurement. Sequence the timeout first. The fix is two halves with two owners: BE raises the Caddy knob to match the policy their own comment states, and we set max_execution_time per-caller, because it is 0 today and Caddy's 30s was accidentally the only bound on a runaway query. --- ...oyed-lambda-never-issues-the-usdt-pivot.md | 181 +++++++++++++----- 1 file changed, 130 insertions(+), 51 deletions(-) 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..aee4b87d 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,22 @@ 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. --- # Every invocation fails on the XLM pivot, so the USDT pivot is never reached @@ -178,67 +194,128 @@ 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 +### ✅ ROOT CAUSE — `response_header_timeout 30s` in Caddy -| statement | avg | survives? | -|---|---|---| -| peg | 14.4 s | ✅ | -| oracle | 26.4 s | ✅ | -| **XLM pivot** | **45.6 s** | ❌ | +`/srv/app/infra-hetzner/Caddyfile`, the `reverse_proxy clickhouse:8123` transport +block: -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: - -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`. + +### ⚠️ Scope is wider than this task + +The ceiling applies to **every** long statement through that proxy — 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. + +### ⛔ 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 + +Caddy's 30 s was accidentally the only bound on a runaway query: +`max_execution_time` is **0** (unlimited, unchanged). Removing Caddy's ceiling +without replacing it leaves a two-hour hole. + +Set `max_execution_time` **on our client** instead. 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`. + +⚠️ **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". ## Acceptance Criteria @@ -251,6 +328,8 @@ re-notified. A continuous, every-invocation failure produced no page. - [ ] `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. +- [ ] `max_execution_time` is set per-caller on our client, and an exceeded bound + produces a logged ClickHouse exception — verified by inducing, not inferred. - [ ] `CleanupRule` verified `DISABLED` before and after the deploy. - [ ] A missing reference asset fails loudly instead of silently narrowing `pivot_ids()`. From c2d3da5245980eab57a51fdefafe0ba73fce0c9d Mon Sep 17 00:00:00 2001 From: karczuRF Date: Fri, 21 Aug 2026 16:15:12 +0200 Subject: [PATCH 2/4] docs(lore-0215): record BE's confirmation of the Caddy root cause BE verified the 30s from Caddy's admin API rather than the Caddyfile, and hold an independent alibi for the 2026-07-26 onset (no restart since 06-29, config unchanged since 07-02), so the growth-crossing explanation is now the only surviving one. Two corrections to this task. The mechanism is time to first byte, not a property of INSERT ... SELECT - BE hit the same limit on a plain heavy SELECT on 07-02 - which widens the affected class to every statement that buffers before it emits, and puts the 26.4s oracle insert next in line. And the "Caddy was the only bound on a runaway" rationale for half 2 is retracted: a runaway streams and always passed. max_execution_time stays, for BE's better reason - a typed exception instead of an empty body. Also records their single-file bind mount pinning an inode, which would have made a file edit plus reload a phantom deploy; the agreed two-sided verification protocol; and the prediction that the Lambda's 300s becomes the binding constraint next, so a completing-but-timing-out pass is not misread as a new defect. --- ...oyed-lambda-never-issues-the-usdt-pivot.md | 158 ++++++++++++++++-- 1 file changed, 147 insertions(+), 11 deletions(-) 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 aee4b87d..395fd76e 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 @@ -60,6 +60,24 @@ history: `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. --- # Every invocation fails on the XLM pivot, so the USDT pivot is never reached @@ -247,12 +265,76 @@ 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 was next in line.** It averages **26.4 s** against a 30 s +ceiling, on a table growing ~10.9 M rows per 13 days. Had this gone unfound, a +second caller would have crossed within weeks — and would have looked like a new, +unrelated defect rather than the same one. + +### 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** long statement through that proxy — 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. +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 @@ -291,14 +373,27 @@ host, shared config: **request it, never edit it ourselves.** ### Half 2 — ours, and it needs nothing from BE -Caddy's 30 s was accidentally the only bound on a runaway query: -`max_execution_time` is **0** (unlimited, unchanged). Removing Caddy's ceiling -without replacing it leaves a two-hour hole. +⛔ **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. -Set `max_execution_time` **on our client** instead. 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`. +⚠️ **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 @@ -317,6 +412,41 @@ and reintroduces this failure class from the other direction. Confirm against `system.settings_profile_elements` before telling BE "there is no bound". +## 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. + ## Acceptance Criteria - [x] The source is shown correct — `pivot_ids() == [xlm, usdt]` and the peg @@ -330,6 +460,12 @@ and reintroduces this failure class from the other direction. USDT pivot, recorded before/after. - [ ] `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()`. From 8e428339e793391ddb27e63afa21c7dfe8469a8d Mon Sep 17 00:00:00 2001 From: karczuRF Date: Fri, 21 Aug 2026 16:40:50 +0200 Subject: [PATCH 3/4] docs(lore-0215): record the before-state, and a second cut statement Baseline captured while the ceiling is still armed, because it is unrecoverable after BE's deploy: 736,707,689 rows / 18.45 GiB / 102 partitions, the four statement classes with durations and rows read, and 144 BadResponse errors in 48h - exactly one per XLM pivot run. It changed the finding. The 30s cuts TWO statements, not one. The oracle statement sits at p95 28.7s against the line and crosses 2-6 times a day, 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. Retracts this task's own "next in line, a matter of weeks" framing, and a guess that blamed 08-14/15's low peg counts on the 0182 window. Also resolves the max_execution_time question the task flagged as unverified: 30 on read_only, absent on prices_write_ddl. The worker is genuinely unbounded, so half 2's premise holds - and since the Lambda and the operator CLIs share one prices_writer user, no server-side setting can give them different ceilings, which is why it must live in the client. --- ...oyed-lambda-never-issues-the-usdt-pivot.md | 116 +++++++++++++++++- 1 file changed, 112 insertions(+), 4 deletions(-) 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 395fd76e..b250db10 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 @@ -78,6 +78,24 @@ history: 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. --- # Every invocation fails on the XLM pivot, so the USDT pivot is never reached @@ -297,10 +315,11 @@ 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 was next in line.** It averages **26.4 s** against a 30 s -ceiling, on a table growing ~10.9 M rows per 13 days. Had this gone unfound, a -second caller would have crossed within weeks — and would have looked like a new, -unrelated defect rather than the same one. +🔴 **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 @@ -412,6 +431,95 @@ and reintroduces this failure class from the other direction. 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 From 4b4829015228382a92425129da285eb8dc911d79 Mon Sep 17 00:00:00 2001 From: karczuRF Date: Fri, 21 Aug 2026 17:48:00 +0200 Subject: [PATCH 4/4] docs(lore-0215): fixed and verified, and two findings it surfaced BE deployed at 14:46:18 UTC. Zero BadResponse since, a 46.4s XLM pivot returned to the client, and the USDT pivot ran on the schedule for the first time ever - 1,895 rows on its first batch, ~17/batch since. Three acceptance criteria are now green. That last number reframes 0209 and 0212: the "USDT backlog" was ~1,900 rows. The leg was never behind, it was never being asked. The new bottleneck is ours and was predicted here before the deploy - Lambda 300s, three peg-pivot batches per attempt, ~2.16M rows/day against 720K. Three times the drain, ~258 days for the XLM leg, so 0111 stands. Two findings from the same log. 36% of every invocation is spent in the oracle tier draining a few hundred candidates out of a 737M-row scan, which is the sharpest argument for 0111 option 1 so far. And the coarse sweep sits behind main.rs:167's `?`, so it has never executed on either side of the fix, starving 0114's remedy - spawned as 0218. The peg statement's constant 1,236 rows per batch spawned as 0219. --- ...oyed-lambda-never-issues-the-usdt-pivot.md | 118 +++++++++++++++++- ...ver-executes-starved-behind-the-1m-pass.md | 106 ++++++++++++++++ ...rewrites-the-same-1236-rows-every-batch.md | 86 +++++++++++++ 3 files changed, 306 insertions(+), 4 deletions(-) create mode 100644 lore/1-tasks/backlog/0218_BUG_coarse-sweep-never-executes-starved-behind-the-1m-pass.md create mode 100644 lore/1-tasks/backlog/0219_BUG_peg-statement-rewrites-the-same-1236-rows-every-batch.md 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 b250db10..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 @@ -96,6 +96,23 @@ history: 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 @@ -555,17 +572,110 @@ share and are 3.3% of — the same disk BE filled on 2026-08-13, costing an 11.5 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 - [x] The source is shown correct — `pivot_ids() == [xlm, usdt]` and the peg 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 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.