docs(0215): root cause is Caddy's 30s response_header_timeout - #240
Merged
karczuRF merged 4 commits intoAug 21, 2026
Merged
Conversation
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.
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.
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.
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.
karczuRF
deleted the
docs/0215_caddy-response-header-timeout-root-cause
branch
August 21, 2026 15:51
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
response_header_timeout 30s(/srv/app/infra-hetzner/Caddyfile, thereverse_proxy clickhouse:8123transport) bounds time-to-first-byte from upstream. AnINSERT … SELECTsends nothing until it completes, and the XLM pivot runs 43.6–47.3 s — so Caddy severs it every time and the client seesBadResponse(""). Measured 18/18, gap exactly 30.0 s.changed = 1; the only 30 insystem.settingsbounds reading request headers. Our client sets no request timeout at all — onlypool_idle_timeout(8s).QueryFinish, and the rows land, so every data-level signal reads normal.max_execution_timeper-caller, because it is0today and Caddy's 30 s was accidentally the only bound on a runaway query.