diff --git a/config.example.yaml b/config.example.yaml index d2218bc06..184d28f31 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -133,6 +133,17 @@ cache: trusted-upload-keys: [] # - my-cache-1:abcdef0123456789...= storage: + # Maximum time the NAR read path waits on a storage presence probe before + # treating presence as undetermined (default: 5s). Keep it well below your + # reverse-proxy read timeout. The local backend's probe is an os.Stat, which + # bottoms out in an uncancellable fstatat(2): on a hard NFS mount a single one + # has been measured blocking ~57s, long enough for the proxy to abort the + # response mid-body and hand the client a 200 with a truncated body. 5s sits an + # order of magnitude above a healthy probe (8-300ms) and an order of magnitude + # below a 60s proxy timeout, so it fires only on genuine pathology. + # A timed-out probe is treated as undetermined, never as a cache miss, so it + # never becomes a spurious 404. Set to 0 to disable the bound (rollback). + stat-timeout: 5s # The local data path used for configuration and cache storage # Use this OR S3 storage (cache.storage.s3.bucket) - not both local: "/var/lib/ncps" diff --git a/nix/e2e-tests/src/client.py b/nix/e2e-tests/src/client.py index 92bfe76e4..e86bb16d6 100644 --- a/nix/e2e-tests/src/client.py +++ b/nix/e2e-tests/src/client.py @@ -14,13 +14,26 @@ import os import subprocess import sys +import time import urllib.error import urllib.request +from dataclasses import dataclass from typing import Dict, Optional, Tuple from harness_config import REPO_ROOT, VAR_NCPS +@dataclass +class TimedResponse: + """An HTTP response with its time-to-first-byte recorded.""" + + status: int + headers: Dict[str, str] + body: bytes + ttfb_seconds: float + total_seconds: float + + class Client: """Talks to a single ncps replica at ``base_url``.""" @@ -34,6 +47,37 @@ def get(self, path: str, timeout: int = 300) -> Tuple[int, Dict[str, str], bytes with urllib.request.urlopen(url, timeout=timeout) as r: return r.status, dict(r.headers), r.read() + def get_timed(self, path: str, timeout: int = 300) -> "TimedResponse": + """GET ``path``, measuring time-to-first-byte separately from completion. + + TTFB is the interval from issuing the request to the first *body* byte + arriving. That is the number a reverse proxy's read timeout actually + governs, and it is the one that mattered in production: every NAR in the + failing runs was byte-perfect but took ~57s to its first byte, so the + ingress aborted the response mid-body and the client saw a truncated 200. + Asserting only on bytes cannot see that; asserting on total duration + conflates a slow start with a large payload. + """ + url = self.base_url + "/" + path.lstrip("/") + started = time.monotonic() + with urllib.request.urlopen(url, timeout=timeout) as r: + first = r.read(1) + ttfb = time.monotonic() - started + chunks = [first] + while True: + block = r.read(1 << 20) + if not block: + break + chunks.append(block) + body = b"".join(chunks) + return TimedResponse( + status=r.status, + headers=dict(r.headers), + body=body, + ttfb_seconds=ttfb, + total_seconds=time.monotonic() - started, + ) + def head(self, path: str, timeout: int = 30) -> Tuple[int, Dict[str, str]]: url = self.base_url + "/" + path.lstrip("/") req = urllib.request.Request(url, method="HEAD") diff --git a/nix/e2e-tests/src/phases/serve.py b/nix/e2e-tests/src/phases/serve.py index 212d69f57..801f6a574 100644 --- a/nix/e2e-tests/src/phases/serve.py +++ b/nix/e2e-tests/src/phases/serve.py @@ -8,12 +8,32 @@ from __future__ import annotations +import os + from client import canonical_nar_sha256, hash_of_store_path, realise_package -from harness_config import check, section +from harness_config import check, log, section # Small package — short closure, fast to fetch through ncps. SERVE_PKG = "nixpkgs#hello" +# Budget for time-to-first-byte on a warm NAR read, in seconds. +# +# A NAR that is already in the store must begin streaming promptly. In production +# this exact path — serving a NAR already present in storage — stalled ~57s in a +# single uncancellable stat on an NFS mount, and the ingress (60s read timeout) +# aborted the response mid-body, handing the client a 200 with a truncated body. +# Every byte was correct; only the latency was wrong, so byte-comparison alone +# scored it a PASS. +# +# The budget is deliberately far below any reverse-proxy read timeout and far +# above a healthy read (8-300ms observed), so it flags pathology without being +# fragile on a loaded CI runner. +TTFB_BUDGET_SECONDS = float(os.environ.get("NCPS_E2E_TTFB_BUDGET_SECONDS", "15")) + +# The client timeout must exceed the budget, so a stall is reported as a measured +# budget violation rather than an opaque client timeout with no number attached. +TTFB_CLIENT_TIMEOUT = int(TTFB_BUDGET_SECONDS * 6) + def run(deployment, scenario) -> None: section(f"SERVE — {scenario.name}") @@ -38,5 +58,22 @@ def run(deployment, scenario) -> None: ) digests.append(digest) + # Re-fetch the now-warm NAR and measure time-to-first-byte. This is the + # production failure shape: the NAR is present and correct, but the first + # byte arrives too late to survive a reverse proxy. + timed = c.get_timed("/" + fields["URL"].lstrip("/"), timeout=TTFB_CLIENT_TIMEOUT) + log( + f"replica {i}: warm NAR ttfb={timed.ttfb_seconds:.3f}s " + f"total={timed.total_seconds:.3f}s bytes={len(timed.body)} " + f"(budget {TTFB_BUDGET_SECONDS:.1f}s)" + ) + check(timed.status == 200, f"replica {i}: warm NAR re-read returned 200") + check( + timed.ttfb_seconds < TTFB_BUDGET_SECONDS, + f"replica {i}: warm NAR time-to-first-byte {timed.ttfb_seconds:.3f}s " + f"is within the {TTFB_BUDGET_SECONDS:.1f}s budget " + f"(a byte-correct but slow response is a FAILURE, not a pass)", + ) + if len(digests) > 1: check(len(set(digests)) == 1, "all replicas served byte-identical NARs") diff --git a/nix/e2e-tests/tests/test_client_ttfb.py b/nix/e2e-tests/tests/test_client_ttfb.py new file mode 100644 index 000000000..914cd3780 --- /dev/null +++ b/nix/e2e-tests/tests/test_client_ttfb.py @@ -0,0 +1,125 @@ +"""Unit tests for the harness client's time-to-first-byte measurement. + +TTFB is the assertion that would have caught the production stall: every NAR in +the failing runs was byte-perfect, but the first byte arrived ~57s late, so the +ingress aborted the response mid-body and the client saw a truncated 200. A +harness that only compares bytes — and waits up to 900s to do it — scores that +as a PASS. These tests pin the measurement itself against a stub server whose +first byte is deliberately late. +""" + +from __future__ import annotations + +import threading +import time +from http.server import BaseHTTPRequestHandler, HTTPServer + +import pytest + +from client import Client + + +def _make_server(delay_before_first_byte: float, body: bytes): + """An HTTP server that stalls `delay` seconds before the first body byte. + + Headers (and the 200) are sent immediately, then the body is withheld. That + is exactly the production shape: the status line commits, and the stall + happens afterwards, so anything measuring only the status or the final bytes + sees nothing wrong. + """ + + class Handler(BaseHTTPRequestHandler): + protocol_version = "HTTP/1.1" + + def do_GET(self): # noqa: N802 — BaseHTTPRequestHandler's required name + self.send_response(200) + self.send_header("Content-Type", "application/octet-stream") + self.send_header("Content-Length", str(len(body))) + self.end_headers() + self.wfile.flush() + + time.sleep(delay_before_first_byte) + + self.wfile.write(body) + self.wfile.flush() + + def log_message(self, *_args): + pass # keep test output quiet + + server = HTTPServer(("127.0.0.1", 0), Handler) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + + return server, f"http://127.0.0.1:{server.server_port}" + + +def test_ttfb_measures_the_stall_not_the_payload(): + body = b"x" * 4096 + server, base = _make_server(1.0, body) + + try: + resp = Client(base).get_timed("/slow", timeout=30) + finally: + server.shutdown() + + assert resp.status == 200 + assert resp.body == body, "the body must still be delivered intact" + assert resp.ttfb_seconds >= 1.0, "TTFB must include the pre-body stall" + assert resp.total_seconds >= resp.ttfb_seconds + + +def test_fast_response_has_small_ttfb(): + body = b"y" * 4096 + server, base = _make_server(0.0, body) + + try: + resp = Client(base).get_timed("/fast", timeout=30) + finally: + server.shutdown() + + assert resp.status == 200 + assert resp.body == body + assert resp.ttfb_seconds < 1.0, "a healthy response must not be flagged as slow" + + +def test_byte_correct_but_slow_is_distinguishable_from_fast(): + """The regression guard: identical bytes, different TTFB. + + Both responses are byte-identical, so a bytes-only assertion cannot tell them + apart. TTFB can, and must. + """ + body = b"z" * 4096 + + slow_server, slow_base = _make_server(1.0, body) + fast_server, fast_base = _make_server(0.0, body) + + try: + slow = Client(slow_base).get_timed("/slow", timeout=30) + fast = Client(fast_base).get_timed("/fast", timeout=30) + finally: + slow_server.shutdown() + fast_server.shutdown() + + assert slow.body == fast.body, "precondition: the payloads are identical" + assert slow.ttfb_seconds > fast.ttfb_seconds + 0.5, ( + "a byte-correct but slow response must be distinguishable from a fast one; " + "this is the distinction the production stall hid from every existing scenario" + ) + + +@pytest.mark.parametrize("budget", [0.25]) +def test_budget_violation_is_detectable(budget): + """A declared budget must be able to fail a byte-correct response.""" + body = b"w" * 1024 + server, base = _make_server(1.0, body) + + try: + resp = Client(base).get_timed("/slow", timeout=30) + finally: + server.shutdown() + + assert resp.status == 200 + assert resp.body == body + assert resp.ttfb_seconds > budget, ( + "the stub stalls 1s against a 0.25s budget, so this must register as a violation" + ) diff --git a/nix/packages/ncps/default.nix b/nix/packages/ncps/default.nix index 35affa614..02dcca372 100644 --- a/nix/packages/ncps/default.nix +++ b/nix/packages/ncps/default.nix @@ -15,7 +15,7 @@ in if tag != "" then tag else rev; - vendorHash = "sha256-S+hZRSEpD4oxXtgoGy3J6yMX80kvf0RwK+zIRuy/kbA="; + vendorHash = "sha256-z3a7XTR5jcVsIdbvK0bOYFx7JTrRwXOEoEeUrfZf9w4="; ncpsSrc = lib.fileset.toSource { fileset = lib.fileset.unions [ diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/.openspec.yaml b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/.openspec.yaml new file mode 100644 index 000000000..e685d45e5 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-08-25 diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/design.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/design.md new file mode 100644 index 000000000..c197508a6 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/design.md @@ -0,0 +1,135 @@ +## Context + +See `proposal.md` — Why, and `investigation.md` for the captured evidence. + +The constraint that shapes everything here is a language-level one: + +```go +// pkg/storage/local/local.go — ctx is used ONLY to open a span +_, span := tracer.Start(ctx, "local.StatNar", ...) +if _, err := os.Stat(narPath); err != nil { // takes no context, cannot be cancelled + +// pkg/storage/s3 — ctx reaches the request +if _, err := s.client.StatObject(ctx, s.bucket, key, ...); err != nil { // cancellable +``` + +`os.Stat` bottoms out in `fstatat(2)`. On a `hard` NFS mount there is no way to abort it from +userspace; the goroutine — and the OS thread it is bound to — stays in the syscall until the +kernel returns. So a deadline cannot *cancel* the local probe. It can only stop the request from +*waiting* on it. + +`GetNar` calls the probe synchronously at `cache.go:1307`, inside `withReadLock`, before any +status code is written. Everything downstream is therefore blocked behind it. + +## Goals / Non-Goals + +**Goals:** + +- One bounding mechanism that works for both storage backends, without each backend + re-implementing it. +- Genuine cancellation where the backend supports it (S3), graceful abandonment where it does not + (local). +- Bound the resource cost of abandoned probes, so a storage brown-out degrades rather than + exhausts the process. +- Preserve today's behaviour exactly when storage is healthy — no added latency, no new logs. + +**Non-Goals:** + +- Making the `local` probe cancellable. It cannot be, short of moving to `io_uring` or a + process-isolated stat helper; both are disproportionate. +- Bounding every storage call. This change bounds the **presence probe on the NAR read path**. + Streaming reads and writes already stream through cancellable pipes and are out of scope. +- Introducing a general-purpose storage-timeout framework. + +## Decisions + +### D1: Bound at the cache layer, not inside each backend + +`statNarInStore` runs the backend probe on its own goroutine and selects over +`{result, deadline, ctx.Done()}`. The deadline is also pushed into the context handed to the +backend, so S3 cancels for real while local simply gets abandoned. + +*Alternative — bound inside each backend:* rejected. It would duplicate the logic per backend and +still could not cancel `os.Stat`, so the local backend would need the goroutine dance anyway. + +*Alternative — a dedicated stat worker pool:* rejected as premature. It becomes attractive only +if D2's cap is hit routinely, and D2 makes that measurable first. + +### D2: Single-flight the probe, and cap abandoned probes + +Two mechanisms bound the cost of probes nobody is waiting for: + +1. **Single-flight** per `(hash, compression)`. Concurrent requests for the same NAR share one + probe goroutine, so a stalled NAR under retry storms costs one blocked thread, not one per + client. +2. **A cap** on simultaneously-abandoned probes. Above it, `statNarInStore` returns indeterminate + immediately without launching another goroutine. This converts thread exhaustion into fast, + observable degradation. + +A gauge exports the number of abandoned probes in flight. This is the number to watch when +deciding whether the substrate needs fixing. + +### D3: A timed-out probe is indeterminate, and indeterminate is NOT absence + +The probe returns three states, not two: present, absent, indeterminate. + +- **Absent** keeps today's behaviour exactly. +- **Indeterminate** routes to the existing upstream-recovery path — the request pulls from + upstream and serves correct bytes, slower. It must never short-circuit to `404`. + +*Alternative — return `503` on indeterminate:* rejected as the default. nix treats 5xx as a +substituter failure; falling back to upstream keeps builds working. A future config knob could +offer fail-fast for operators who would rather shed load than amplify upstream traffic. + +**Guard (do not regress a known bug):** in **upload-only** mode, `GetNar` returns +`storage.ErrNotFound` to signal "we do not have it, please PUT it". An indeterminate probe MUST +NOT take that branch. Returning `ErrNotFound` on a *stalled* probe would make `nix copy` skip the +NAR upload and leave a phantom whose later reference check 404s — exactly the failure recorded in +`upload-reference-presence` and the phantom-nar work. Indeterminate in upload-only mode must +surface a retryable error instead. This needs an explicit test. + +### D4: Configuration and defaults + +A single new setting, `cache.storage.stat-timeout`, default **5s**, `0` disabling the bound +(restoring today's behaviour for rollback). 5 s is an order of magnitude above a healthy probe +(observed 8–300 ms) and an order of magnitude below the 60 s proxy read timeout, so it fires only +on genuine pathology. + +### D5: Observability + +- Histogram of probe duration for **all** probes, so slow-but-successful probes are visible before + they become timeouts. +- Counter of probe timeouts, and a gauge of abandoned probes in flight. +- `warn` log on timeout carrying the NAR hash and elapsed time. +- Span event recording the timeout. + +Counters must be primed with `Add(ctx, 0)` at startup — OTEL does not export an instrument until +its first increment, so an idle instance would otherwise show nothing (see +`metrics-exposure`). + +## Risks / Trade-offs + +- **Redundant upstream downloads while storage is stalled** → Indeterminate falls back to + upstream, so a brown-out amplifies upstream traffic. Mitigated by single-flight (D2) and made + visible by the timeout counter. Strictly preferable to serving truncated bytes. +- **Abandoned probes pin OS threads** → Go grows the thread pool when goroutines block in + syscalls. Bounded by D2's cap and surfaced by the gauge. +- **Reintroducing the phantom-NAR bug** → D3's upload-only guard, with a dedicated test. +- **Masking the real problem** → This change makes ncps survive slow storage; it does not make + storage fast. The timeout counter is the signal that the substrate still needs fixing, and the + proposal's Non-goals say so explicitly. +- **A too-low default causing spurious fallbacks on genuinely slow-but-healthy storage** → 5 s is + ~17× the slowest healthy probe observed; the duration histogram lets operators verify before + tightening. + +## Migration Plan + +Config-only; no schema or data migration. Ships with a safe default and no behaviour change on +healthy storage. **Rollback:** set `cache.storage.stat-timeout: 0` to restore unbounded waiting, +without redeploying a different image. + +## Open Questions + +- Whether to expose fail-fast (`503`) as an alternative to upstream fallback on indeterminate. + Deferrable: it is an additive config knob that changes neither the specs, this approach, nor the + task breakdown. diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/evidence.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/evidence.md new file mode 100644 index 000000000..f66deb6f0 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/evidence.md @@ -0,0 +1,102 @@ +# Measured effect of the fix + +Task 7.4. Numbers, not assertions. `investigation.md` covers how the defect was found; +this records what the fix changed. + +## Production baseline (the defect, v0.10.0-rc17) + +Measured against the two prod replicas via `kubectl port-forward`, bypassing nginx so the +number is ncps's own time-to-first-byte. Sequence: request the narinfo on replica A (A pulls +and stores the NAR), then request the NAR on replica B. + +| package | NAR size | TTFB on the non-holder replica | +| --- | ---: | ---: | +| blender | 108,662,723 B | **107.5 s** | +| openjdk17 | 349,188,671 B | **57.4 s** | +| gcc14 | **12,524 B** | **56.8 s** | +| wine64 | 66,189,221 B | **57.8 s** | +| godot_4 | 69,967,331 B | **57.5 s** | + +A 12 KB NAR at 56.8 s rules out size and bandwidth. ncps's own request log agreed +(`elapsed: 56800.09 ms`). Healthy reads on the same pods: **8–300 ms**. + +Root cause, from a goroutine dump captured mid-stall (`goroutine-stall-dump.txt`): one +`os.Stat` → `fstatat(2)` blocked ~57 s inside `statNarInStore`, with the pod otherwise idle +(81 goroutines, exactly one in `[syscall]`). The mount is `hard,timeo=600,retrans=2` — +`timeo` in deciseconds, so 60 s per RPC cycle, up to 2 retries. The observed 56.8–57.8 s and +107.5 s are one cycle and two. Exact fit. + +## Unit-level: before vs after + +`TestGetNarBoundedTimeToFirstByte` — a `StatNar` that blocks 30 s and ignores context +cancellation (modelling `os.Stat`), against a 250 ms configured bound. + +| | result | +| --- | --- | +| **Before** (field present but inert) | `GetNar` never returned; the test failed after exhausting its **10 s** budget | +| **After** | `GetNar` resolved in **1.00 s** | + +Verbatim RED output before the fix: + +```text +--- FAIL: TestGetNarBoundedTimeToFirstByte (10.01s) + GetNar did not resolve within 10s while the storage probe blocked for 30s: + a NAR request must have a bounded time-to-first-byte +``` + +## Contention: probes collapsed + +`TestStatProbeIsSingleFlighted` — 20 concurrent callers for the same NAR against a stalled +store: + +```text +20 concurrent callers produced 1 backend probe(s) +``` + +Without this, a stalled NAR under a client retry storm costs one blocked goroutine — and on +the local backend one pinned OS thread — per client. + +## No regression when storage is healthy + +- `TestStatNarInStoreFastProbeUnaffected`: a healthy probe returns the same + present/absent answers with no timeout error and no added latency. +- e2e `single-local-sqlite`, warm NAR re-read: **ttfb = 0.001 s** against a 15 s budget, PASS. +- Full unit suite (`task test`): exit 0. + +## Regression coverage added + +| test | pins | +| --- | --- | +| `TestGetNarBoundedTimeToFirstByte` | bounded time-to-first-byte | +| `TestStatNarInStoreTimeoutIsIndeterminate` | a timed-out probe is undetermined, not absent | +| `TestUploadOnlyIndeterminateIsNotNotFound` | a stall never becomes `ErrNotFound` (phantom-NAR guard) | +| `TestStatProbeDeadlineReachesBackend` | the deadline reaches the backend's context | +| `TestStatProbeIsSingleFlighted` | concurrent probes collapse | +| `TestStatNarInStoreFastProbeUnaffected` | healthy storage is unaffected | +| e2e serve phase | warm-read TTFB budget on every serving scenario | +| `tests/test_client_ttfb.py` (4) | the harness can tell byte-correct-but-slow from fast | + +## Request-level budget (found in review, PR #1479) + +CodeRabbit flagged that a request could "spend multiple probe timeouts". Verified: it +could. Bounding each probe individually was not enough, because one `GetNar` consults the +store several times. + +| | `GetNar` elapsed against a 300 ms bound | +| --- | --- | +| Per-probe bound only | **1.20 s — 4.0x** | +| With a cumulative per-request budget | **0.30 s — 1.0x** | + +At the 5 s default that was 20 s rather than 5 s; at a 15 s setting it would have put a +request back over a 60 s proxy read timeout — reintroducing the exact failure this change +fixes. Pinned by `TestRequestProbeBudgetIsCumulative`. + +The budget is scoped to probes only. It deliberately does not bound the download, which +legitimately takes far longer than any probe should. + +## What this does NOT fix + +The substrate. `ncps_storage_stat_timeout_total` is the signal: if it is non-zero in +production, storage is still stalling and the fix is converting those stalls into upstream +fallbacks rather than truncated responses. The NFS mount tuning and the move to the S3 +backend are tracked as infrastructure work, out of scope here (see `proposal.md` — Non-goals). diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/goroutine-stall-dump.txt b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/goroutine-stall-dump.txt new file mode 100644 index 000000000..ddb788cf6 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/goroutine-stall-dump.txt @@ -0,0 +1,701 @@ +goroutine 452 [running]: +runtime/pprof.writeGoroutineStacks({0x20e36c0, 0x2774c0721e0}) + runtime/pprof/pprof.go:819 +0x6b +runtime/pprof.writeGoroutine({0x20e36c0?, 0x2774c0721e0?}, 0x2774c40d748?) + runtime/pprof/pprof.go:782 +0x25 +runtime/pprof.(*Profile).WriteTo(0x32591b0?, {0x20e36c0?, 0x2774c0721e0?}, 0xc?) + runtime/pprof/pprof.go:408 +0x149 +net/http/pprof.handler.ServeHTTP({0x2774c4860d1, 0x9}, {0x20f3700, 0x2774c0721e0}, 0x2774ba5c140) + net/http/pprof/pprof.go:273 +0x52a +net/http/pprof.Index({0x20f3700, 0x2774c0721e0}, 0x2774ba5c140?) + net/http/pprof/pprof.go:397 +0xda +net/http.HandlerFunc.ServeHTTP(0x2774b8f89c0?, {0x20f3700?, 0x2774c0721e0?}, 0xd465b6?) + net/http/server.go:2284 +0x29 +net/http.(*ServeMux).ServeHTTP(0x48e2f9?, {0x20f3700, 0x2774c0721e0}, 0x2774ba5c140) + net/http/server.go:2826 +0x1c7 +net/http.serverHandler.ServeHTTP({0x2774bdd2000?}, {0x20f3700?, 0x2774c0721e0?}, 0x1?) + net/http/server.go:3309 +0x8e +net/http.(*conn).serve(0x2774bb8a090, {0x20f71f8, 0x2774ba009c0}) + net/http/server.go:2067 +0x690 +created by net/http.(*Server).Serve in goroutine 155 + net/http/server.go:3462 +0x485 + +goroutine 1 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1ba81e400, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774ba38a00?, 0x900000036?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Accept(0x2774ba38a00) + internal/poll/fd_unix.go:613 +0x28c +net.(*netFD).accept(0x2774ba38a00) + net/fd_unix.go:150 +0x29 +net.(*TCPListener).accept(0x2774be1b700) + net/tcpsock_posix.go:159 +0x1b +net.(*TCPListener).Accept(0x2774be1b700) + net/tcpsock.go:387 +0x30 +net/http.(*Server).Serve(0x2774bc0ef00, {0x20f34e0, 0x2774be1b700}) + net/http/server.go:3432 +0x30c +net/http.(*Server).ListenAndServe(0x2774bc0ef00) + net/http/server.go:3358 +0x72 +github.com/kalbasit/ncps/pkg/ncps.serveCommand.serveAction.func5({0x20f71f8, 0x2774bb3e0f0}, 0x2774bc24b08) + github.com/kalbasit/ncps/pkg/ncps/serve.go:765 +0x11d2 +github.com/urfave/cli/v3.(*Command).run(0x2774bc24b08, {0x20f71f8, 0x2774bb3e0f0}, {0x2774bde6ff0, 0x1, 0x1}) + github.com/urfave/cli/v3@v3.11.0/command_run.go:382 +0x2d9a +github.com/urfave/cli/v3.(*Command).run(0x2774bb22dc8, {0x20f71f8, 0x2774bc60ab0}, {0x2774b8d4040, 0x4, 0x4}) + github.com/urfave/cli/v3@v3.11.0/command_run.go:320 +0x2585 +github.com/urfave/cli/v3.(*Command).Run(0x2774b7841e0?, {0x20f71c0?, 0x33b89a0?}, {0x2774b8d4040?, 0x2774b884780?, 0x2774b880888?}) + github.com/urfave/cli/v3@v3.11.0/command_run.go:95 +0x25 +main.realMain() + github.com/kalbasit/ncps/main.go:23 +0xc5 +main.main() + github.com/kalbasit/ncps/main.go:12 +0x13 + +goroutine 53 [select]: +github.com/kalbasit/ncps/pkg/maxprocs.AutoMaxProcs({0x20f7230, 0x2774bb18050}, 0x6fc23ac00, {{0x20ebc70, 0x2774bca0360}, 0x0, {0x0, 0x0}, {0x2774bc81000, 0xe, ...}, ...}) + github.com/kalbasit/ncps/pkg/maxprocs/maxprocs.go:33 +0x57d +github.com/kalbasit/ncps/pkg/ncps.serveCommand.serveAction.func5.2() + github.com/kalbasit/ncps/pkg/ncps/serve.go:563 +0x7b +golang.org/x/sync/errgroup.(*Group).Go.func1() + golang.org/x/sync@v0.22.0/errgroup/errgroup.go:93 +0x50 +created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 1 + golang.org/x/sync@v0.22.0/errgroup/errgroup.go:78 +0x95 + +goroutine 55 [select, 1 minutes]: +database/sql.(*DB).connectionOpener(0x2774b867ba0, {0x20f7230, 0x2774bb18190}) + database/sql/sql.go:1261 +0x89 +created by database/sql.OpenDB in goroutine 1 + database/sql/sql.go:841 +0x130 + +goroutine 261 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e3200, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774b9f2800?, 0x2774b994000?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774b9f2800, {0x2774b994000, 0x1500, 0x1500}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774b9f2800, {0x2774b994000?, 0x48f30c?, 0x4a3d1d?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774c412040, {0x2774b994000?, 0x7fb17058a4c0?, 0x7fb1bab05fa0?}) + net/net.go:196 +0x45 +crypto/tls.(*atLeastReader).Read(0x2774c354318, {0x2774b994000?, 0x2774bda9a48?, 0x4561c8?}) + crypto/tls/conn.go:815 +0x3b +bytes.(*Buffer).ReadFrom(0x2774c1a89a8, {0x20e5780, 0x2774c354318}) + bytes/buffer.go:229 +0x98 +crypto/tls.(*Conn).readFromUntil(0x2774c1a8708, {0x20e2e60, 0x2774c412040}, 0xc8524c?) + crypto/tls/conn.go:837 +0xde +crypto/tls.(*Conn).readRecordOrCCS(0x2774c1a8708, 0x0) + crypto/tls/conn.go:626 +0x3db +crypto/tls.(*Conn).readRecord(...) + crypto/tls/conn.go:588 +crypto/tls.(*Conn).Read(0x2774c1a8708, {0x2774c0fb000, 0x1000, 0xd13740?}) + crypto/tls/conn.go:1393 +0x145 +bufio.(*Reader).Read(0x2774c17a300, {0x2774bdc62e4, 0x9, 0xd3038e?}) + bufio/bufio.go:245 +0x197 +io.ReadAtLeast({0x20e1840, 0x2774c17a300}, {0x2774bdc62e4, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +net/http.http2readFrameHeader({0x2774bdc62e4, 0x9, 0x27700000005?}, {0x20e1840?, 0x2774c17a300?}) + net/http/h2_bundle.go:1805 +0x65 +net/http.(*http2Framer).ReadFrameHeader(0x2774bdc62a0) + net/http/h2_bundle.go:2071 +0x6b +net/http.(*http2Framer).ReadFrame(0x2774bdc62a0) + net/http/h2_bundle.go:2130 +0x18 +net/http.(*http2clientConnReadLoop).run(0x2774bda9fa8) + net/http/h2_bundle.go:9550 +0xca +net/http.(*http2ClientConn).readLoop(0x2774bfdc1c0) + net/http/h2_bundle.go:9419 +0x52 +created by net/http.(*http2Transport).newClientConn in goroutine 260 + net/http/h2_bundle.go:8171 +0xda5 + +goroutine 120 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bf828b0, {0x20f7230, 0x2774bc1b680}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 11 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774be16150, {0x20f7230, 0x2774b92c5f0}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 12 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774be16180, {0x20f7230, 0x2774b9ded20}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 13 [select]: +go.opentelemetry.io/otel/sdk/trace.(*batchSpanProcessor).processQueue(0x2774bd85130) + go.opentelemetry.io/otel/sdk@v1.44.0/trace/batch_span_processor.go:327 +0x10f +go.opentelemetry.io/otel/sdk/trace.NewBatchSpanProcessor.func2() + go.opentelemetry.io/otel/sdk@v1.44.0/trace/batch_span_processor.go:127 +0x1c +sync.(*WaitGroup).Go.func1() + sync/waitgroup.go:258 +0x4a +created by sync.(*WaitGroup).Go in goroutine 1 + sync/waitgroup.go:238 +0x73 + +goroutine 146 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda0440, {0x20f7230, 0x2774bc1a460}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 147 [chan receive]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda0470, {0x20f7230, 0x2774bc1a4b0}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 148 [chan receive]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda04a0, {0x20f7230, 0x2774bc1a9b0}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 149 [select]: +go.opentelemetry.io/otel/sdk/metric.(*PeriodicReader).run(0x2774b8f8000, {0x20f7230, 0x2774bc1aa00}, 0xdf8475800) + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:199 +0x125 +go.opentelemetry.io/otel/sdk/metric.NewPeriodicReader.func2() + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:137 +0x4f +created by go.opentelemetry.io/otel/sdk/metric.NewPeriodicReader in goroutine 1 + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:135 +0x2cd + +goroutine 150 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda0a20, {0x20f7230, 0x2774bc1ad70}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 151 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda0a50, {0x20f7230, 0x2774bc1adc0}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 152 [chan receive, 1 minutes]: +google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x2774bda0a80, {0x20f7230, 0x2774bc1ae10}) + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:88 +0xe5 +created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 1 + google.golang.org/grpc@v1.82.1/internal/grpcsync/callback_serializer.go:52 +0x11a + +goroutine 153 [chan receive]: +go.opentelemetry.io/otel/sdk/log.exportSync.func1() + go.opentelemetry.io/otel/sdk/log@v0.20.0/exporter.go:136 +0x137 +created by go.opentelemetry.io/otel/sdk/log.exportSync in goroutine 1 + go.opentelemetry.io/otel/sdk/log@v0.20.0/exporter.go:134 +0xd9 + +goroutine 154 [select]: +go.opentelemetry.io/otel/sdk/log.(*BatchProcessor).poll.func1() + go.opentelemetry.io/otel/sdk/log@v0.20.0/batch.go:147 +0x10b +created by go.opentelemetry.io/otel/sdk/log.(*BatchProcessor).poll in goroutine 1 + go.opentelemetry.io/otel/sdk/log@v0.20.0/batch.go:142 +0x14a + +goroutine 155 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1ba81ee00, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774bc2a000?, 0x9004287d7?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Accept(0x2774bc2a000) + internal/poll/fd_unix.go:613 +0x28c +net.(*netFD).accept(0x2774bc2a000) + net/fd_unix.go:150 +0x29 +net.(*TCPListener).accept(0x2774bd97240) + net/tcpsock_posix.go:159 +0x1b +net.(*TCPListener).Accept(0x2774bd97240) + net/tcpsock.go:387 +0x30 +net/http.(*Server).Serve(0x2774b94c700, {0x20f34e0, 0x2774bd97240}) + net/http/server.go:3432 +0x30c +net/http.(*Server).ListenAndServe(0x2774b94c700) + net/http/server.go:3358 +0x72 +github.com/kalbasit/ncps/pkg/ncps.serveCommand.serveAction.func5.4() + github.com/kalbasit/ncps/pkg/ncps/serve.go:667 +0x25 +created by github.com/kalbasit/ncps/pkg/ncps.serveCommand.serveAction.func5 in goroutine 1 + github.com/kalbasit/ncps/pkg/ncps/serve.go:666 +0xa36 + +goroutine 156 [chan receive, 1 minutes]: +go.opentelemetry.io/otel/sdk/log.exportSync.func1() + go.opentelemetry.io/otel/sdk/log@v0.20.0/exporter.go:136 +0x137 +created by go.opentelemetry.io/otel/sdk/log.exportSync in goroutine 1 + go.opentelemetry.io/otel/sdk/log@v0.20.0/exporter.go:134 +0xd9 + +goroutine 14 [select]: +go.opentelemetry.io/otel/sdk/log.(*BatchProcessor).poll.func1() + go.opentelemetry.io/otel/sdk/log@v0.20.0/batch.go:147 +0x10b +created by go.opentelemetry.io/otel/sdk/log.(*BatchProcessor).poll in goroutine 1 + go.opentelemetry.io/otel/sdk/log@v0.20.0/batch.go:142 +0x14a + +goroutine 15 [select, 1 minutes]: +go.opentelemetry.io/otel/sdk/metric.(*PeriodicReader).run(0x2774b8f8240, {0x20f7230, 0x2774bc1aa50}, 0x34630b8a000) + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:199 +0x125 +go.opentelemetry.io/otel/sdk/metric.NewPeriodicReader.func2() + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:137 +0x4f +created by go.opentelemetry.io/otel/sdk/metric.NewPeriodicReader in goroutine 1 + go.opentelemetry.io/otel/sdk/metric@v1.44.0/periodic_reader.go:135 +0x2cd + +goroutine 162 [select]: +github.com/kalbasit/ncps/pkg/cache.New.(*HealthChecker).Start.func2() + github.com/kalbasit/ncps/pkg/cache/healthcheck/healthcheck.go:84 +0xb5 +github.com/kalbasit/ncps/pkg/analytics.SafeGo.func1() + github.com/kalbasit/ncps/pkg/analytics/analytics.go:133 +0x53 +created by github.com/kalbasit/ncps/pkg/analytics.SafeGo in goroutine 1 + github.com/kalbasit/ncps/pkg/analytics/analytics.go:126 +0x74 + +goroutine 163 [select, 1 minutes]: +github.com/kalbasit/ncps/pkg/cache.(*Cache).processHealthChanges(0x0?, {0x20f71f8, 0x2774ba01290}, 0x2774be88d90) + github.com/kalbasit/ncps/pkg/cache/cache.go:8529 +0xa5 +github.com/kalbasit/ncps/pkg/cache.New.func1() + github.com/kalbasit/ncps/pkg/cache/cache.go:788 +0x25 +github.com/kalbasit/ncps/pkg/analytics.SafeGo.func1() + github.com/kalbasit/ncps/pkg/analytics/analytics.go:133 +0x53 +created by github.com/kalbasit/ncps/pkg/analytics.SafeGo in goroutine 1 + github.com/kalbasit/ncps/pkg/analytics/analytics.go:126 +0x74 + +goroutine 141 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e3000, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774bc2a700?, 0x2774b8cc000?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774bc2a700, {0x2774b8cc000, 0x1500, 0x1500}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774bc2a700, {0x2774b8cc000?, 0x2774b8cc03f?, 0x5?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774bc9a038, {0x2774b8cc000?, 0x7fb17058a4c0?, 0x7fb1bab05fa0?}) + net/net.go:196 +0x45 +crypto/tls.(*atLeastReader).Read(0x2774c354270, {0x2774b8cc000?, 0x2774bdaca48?, 0x4561c8?}) + crypto/tls/conn.go:815 +0x3b +bytes.(*Buffer).ReadFrom(0x2774bfe0628, {0x20e5780, 0x2774c354270}) + bytes/buffer.go:229 +0x98 +crypto/tls.(*Conn).readFromUntil(0x2774bfe0388, {0x20e2e60, 0x2774bc9a038}, 0xc8524c?) + crypto/tls/conn.go:837 +0xde +crypto/tls.(*Conn).readRecordOrCCS(0x2774bfe0388, 0x0) + crypto/tls/conn.go:626 +0x3db +crypto/tls.(*Conn).readRecord(...) + crypto/tls/conn.go:588 +crypto/tls.(*Conn).Read(0x2774bfe0388, {0x2774bd9a000, 0x1000, 0xd13740?}) + crypto/tls/conn.go:1393 +0x145 +bufio.(*Reader).Read(0x2774c428960, {0x2774c1c4584, 0x9, 0xd3038e?}) + bufio/bufio.go:245 +0x197 +io.ReadAtLeast({0x20e1840, 0x2774c428960}, {0x2774c1c4584, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +net/http.http2readFrameHeader({0x2774c1c4584, 0x9, 0x27700000005?}, {0x20e1840?, 0x2774c428960?}) + net/http/h2_bundle.go:1805 +0x65 +net/http.(*http2Framer).ReadFrameHeader(0x2774c1c4540) + net/http/h2_bundle.go:2071 +0x6b +net/http.(*http2Framer).ReadFrame(0x2774c1c4540) + net/http/h2_bundle.go:2130 +0x18 +net/http.(*http2clientConnReadLoop).run(0x2774bdacfa8) + net/http/h2_bundle.go:9550 +0xca +net/http.(*http2ClientConn).readLoop(0x2774c4228c0) + net/http/h2_bundle.go:9419 +0x52 +created by net/http.(*http2Transport).newClientConn in goroutine 140 + net/http/h2_bundle.go:8171 +0xda5 + +goroutine 165 [select]: +github.com/robfig/cron/v3.(*Cron).run(0x2774bcaf5e0) + github.com/robfig/cron/v3@v3.0.1/cron.go:263 +0x4df +created by github.com/robfig/cron/v3.(*Cron).Start in goroutine 1 + github.com/robfig/cron/v3@v3.0.1/cron.go:222 +0xb6 + +goroutine 172 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1ba81e600, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774be28380?, 0x2774c3ee000?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774be28380, {0x2774c3ee000, 0xa000, 0xa000}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774be28380, {0x2774c3ee000?, 0x2774c3ee056?, 0x5?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774b782078, {0x2774c3ee000?, 0x7fb17038e9a8?, 0x7fb1bab015d0?}) + net/net.go:196 +0x45 +crypto/tls.(*atLeastReader).Read(0x2774c41abd0, {0x2774c3ee000?, 0x2774bf27a48?, 0x4561c8?}) + crypto/tls/conn.go:815 +0x3b +bytes.(*Buffer).ReadFrom(0x2774bfe10a8, {0x20e5780, 0x2774c41abd0}) + bytes/buffer.go:229 +0x98 +crypto/tls.(*Conn).readFromUntil(0x2774bfe0e08, {0x20e2e60, 0x2774b782078}, 0xc8524c?) + crypto/tls/conn.go:837 +0xde +crypto/tls.(*Conn).readRecordOrCCS(0x2774bfe0e08, 0x0) + crypto/tls/conn.go:626 +0x3db +crypto/tls.(*Conn).readRecord(...) + crypto/tls/conn.go:588 +crypto/tls.(*Conn).Read(0x2774bfe0e08, {0x2774be9c000, 0x1000, 0xd13740?}) + crypto/tls/conn.go:1393 +0x145 +bufio.(*Reader).Read(0x2774bc439e0, {0x2774bdc6204, 0x9, 0xd3038e?}) + bufio/bufio.go:245 +0x197 +io.ReadAtLeast({0x20e1840, 0x2774bc439e0}, {0x2774bdc6204, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +net/http.http2readFrameHeader({0x2774bdc6204, 0x9, 0x27700000007?}, {0x20e1840?, 0x2774bc439e0?}) + net/http/h2_bundle.go:1805 +0x65 +net/http.(*http2Framer).ReadFrameHeader(0x2774bdc61c0) + net/http/h2_bundle.go:2071 +0x6b +net/http.(*http2Framer).ReadFrame(0x2774bdc61c0) + net/http/h2_bundle.go:2130 +0x18 +net/http.(*http2clientConnReadLoop).run(0x2774bf27fa8) + net/http/h2_bundle.go:9550 +0xca +net/http.(*http2ClientConn).readLoop(0x2774bfdc380) + net/http/h2_bundle.go:9419 +0x52 +created by net/http.(*http2Transport).newClientConn in goroutine 171 + net/http/h2_bundle.go:8171 +0xda5 + +goroutine 73 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1ba81e800, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774b9f2980?, 0x2774bf30000?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774b9f2980, {0x2774bf30000, 0x1300, 0x1300}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774b9f2980, {0x2774bf30000?, 0x2774bf30186?, 0x5?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774b8821f8, {0x2774bf30000?, 0x7fb17038e9a8?, 0x7fb1bab015d0?}) + net/net.go:196 +0x45 +crypto/tls.(*atLeastReader).Read(0x2774c41acd8, {0x2774bf30000?, 0x2774bdaaa48?, 0x4561c8?}) + crypto/tls/conn.go:815 +0x3b +bytes.(*Buffer).ReadFrom(0x2774bfe02a8, {0x20e5780, 0x2774c41acd8}) + bytes/buffer.go:229 +0x98 +crypto/tls.(*Conn).readFromUntil(0x2774bfe0008, {0x20e2e60, 0x2774b8821f8}, 0xc8524c?) + crypto/tls/conn.go:837 +0xde +crypto/tls.(*Conn).readRecordOrCCS(0x2774bfe0008, 0x0) + crypto/tls/conn.go:626 +0x3db +crypto/tls.(*Conn).readRecord(...) + crypto/tls/conn.go:588 +crypto/tls.(*Conn).Read(0x2774bfe0008, {0x2774bf1b000, 0x1000, 0xd13740?}) + crypto/tls/conn.go:1393 +0x145 +bufio.(*Reader).Read(0x2774c090360, {0x2774bf3a3c4, 0x9, 0xd3038e?}) + bufio/bufio.go:245 +0x197 +io.ReadAtLeast({0x20e1840, 0x2774c090360}, {0x2774bf3a3c4, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +net/http.http2readFrameHeader({0x2774bf3a3c4, 0x9, 0x27700000005?}, {0x20e1840?, 0x2774c090360?}) + net/http/h2_bundle.go:1805 +0x65 +net/http.(*http2Framer).ReadFrameHeader(0x2774bf3a380) + net/http/h2_bundle.go:2071 +0x6b +net/http.(*http2Framer).ReadFrame(0x2774bf3a380) + net/http/h2_bundle.go:2130 +0x18 +net/http.(*http2clientConnReadLoop).run(0x2774bdaafa8) + net/http/h2_bundle.go:9550 +0xca +net/http.(*http2ClientConn).readLoop(0x2774bf3c540) + net/http/h2_bundle.go:9419 +0x52 +created by net/http.(*http2Transport).newClientConn in goroutine 72 + net/http/h2_bundle.go:8171 +0xda5 + +goroutine 198 [select, 1 minutes]: +google.golang.org/grpc/internal/resolver/dns.(*dnsResolver).watcher(0x2774bc2a580) + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:224 +0x24a +created by google.golang.org/grpc/internal/resolver/dns.(*dnsBuilder).Build in goroutine 151 + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:153 +0x319 + +goroutine 249 [select, 1 minutes]: +google.golang.org/grpc/internal/resolver/dns.(*dnsResolver).watcher(0x2774b9f2b00) + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:224 +0x24a +created by google.golang.org/grpc/internal/resolver/dns.(*dnsBuilder).Build in goroutine 11 + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:153 +0x319 + +goroutine 189 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1ba81e200, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774be28a00?, 0x2774c0b0000?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774be28a00, {0x2774c0b0000, 0x1300, 0x1300}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774be28a00, {0x2774c0b0000?, 0x2774c0b0000?, 0x5?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774b7821c0, {0x2774c0b0000?, 0x7fb1ba8685f8?, 0x7fb1bab05fa0?}) + net/net.go:196 +0x45 +crypto/tls.(*atLeastReader).Read(0x2774c0bf518, {0x2774c0b0000?, 0x2774c194a48?, 0x4561c8?}) + crypto/tls/conn.go:815 +0x3b +bytes.(*Buffer).ReadFrom(0x2774b9d5b28, {0x20e5780, 0x2774c0bf518}) + bytes/buffer.go:229 +0x98 +crypto/tls.(*Conn).readFromUntil(0x2774b9d5888, {0x20e2e60, 0x2774b7821c0}, 0xc8524c?) + crypto/tls/conn.go:837 +0xde +crypto/tls.(*Conn).readRecordOrCCS(0x2774b9d5888, 0x0) + crypto/tls/conn.go:626 +0x3db +crypto/tls.(*Conn).readRecord(...) + crypto/tls/conn.go:588 +crypto/tls.(*Conn).Read(0x2774b9d5888, {0x2774c09c000, 0x1000, 0xd13740?}) + crypto/tls/conn.go:1393 +0x145 +bufio.(*Reader).Read(0x2774bff3b60, {0x2774bdc63c4, 0x9, 0xd3038e?}) + bufio/bufio.go:245 +0x197 +io.ReadAtLeast({0x20e1840, 0x2774bff3b60}, {0x2774bdc63c4, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +net/http.http2readFrameHeader({0x2774bdc63c4, 0x9, 0x27700000005?}, {0x20e1840?, 0x2774bff3b60?}) + net/http/h2_bundle.go:1805 +0x65 +net/http.(*http2Framer).ReadFrameHeader(0x2774bdc6380) + net/http/h2_bundle.go:2071 +0x6b +net/http.(*http2Framer).ReadFrame(0x2774bdc6380) + net/http/h2_bundle.go:2130 +0x18 +net/http.(*http2clientConnReadLoop).run(0x2774c194fa8) + net/http/h2_bundle.go:9550 +0xca +net/http.(*http2ClientConn).readLoop(0x2774bfdc8c0) + net/http/h2_bundle.go:9419 +0x52 +created by net/http.(*http2Transport).newClientConn in goroutine 188 + net/http/h2_bundle.go:8171 +0xda5 + +goroutine 206 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e2c00, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x10?, 0xb?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).RawRead(0x2774bc2a900, 0x2774bda1c80) + internal/poll/fd_unix.go:710 +0x125 +net.(*rawConn).Read(0x2774bc1e578, 0x2774c2a2ca0?) + net/rawconn.go:44 +0x36 +google.golang.org/grpc/internal/transport/readyreader.(*nonBlockingReader).ReadOnReady(0x2774c1bc230, 0x2774c2a2d00?, {0x20f1678, 0x2774c1b18f0}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:114 +0xa7 +google.golang.org/grpc/internal/transport/readyreader.(*bufReadyReader).Read(0x2774b9ce1c0, {0x2774c1c4044, 0x9, 0x1ec1d20?}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:221 +0x174 +io.ReadAtLeast({0x20eafc0, 0x2774b9ce1c0}, {0x2774c1c4044, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +golang.org/x/net/http2.readFrameHeader({0x2774c1c4044, 0x9, 0x27700000000?}, {0x20eafc0?, 0x2774b9ce1c0?}) + golang.org/x/net@v0.57.0/http2/frame.go:250 +0x65 +golang.org/x/net/http2.(*Framer).ReadFrameHeader(0x2774c1c4000) + golang.org/x/net@v0.57.0/http2/frame.go:513 +0x6b +google.golang.org/grpc/internal/transport.(*framer).readFrame(0x2774bc2aa00) + google.golang.org/grpc@v1.82.1/internal/transport/http_util.go:493 +0x45 +google.golang.org/grpc/internal/transport.(*http2Client).reader(0x2774bc6ad88, 0x2774b9ce230) + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:1711 +0x1ba +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 223 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:420 +0x1e13 + +goroutine 226 [select]: +google.golang.org/grpc/internal/transport.(*controlBuffer).get(0x2774c1b62c0, 0x1) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:420 +0x10a +google.golang.org/grpc/internal/transport.(*loopyWriter).run(0x2774baf4000) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:595 +0x78 +google.golang.org/grpc/internal/transport.NewHTTP2Client.func6() + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:478 +0xd2 +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 223 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:476 +0x23db + +goroutine 209 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e2a00, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x12?, 0xb?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).RawRead(0x2774b928c80, 0x2774bf82140) + internal/poll/fd_unix.go:710 +0x125 +net.(*rawConn).Read(0x2774bc1e138, 0x2774bdabca0?) + net/rawconn.go:44 +0x36 +google.golang.org/grpc/internal/transport/readyreader.(*nonBlockingReader).ReadOnReady(0x2774c1bc370, 0x2774bdabd00?, {0x20f1678, 0x2774c1b18f0}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:114 +0xa7 +google.golang.org/grpc/internal/transport/readyreader.(*bufReadyReader).Read(0x2774b9ce150, {0x2774bd86d64, 0x9, 0x1ec1d20?}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:221 +0x174 +io.ReadAtLeast({0x20eafc0, 0x2774b9ce150}, {0x2774bd86d64, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +golang.org/x/net/http2.readFrameHeader({0x2774bd86d64, 0x9, 0x27700000000?}, {0x20eafc0?, 0x2774b9ce150?}) + golang.org/x/net@v0.57.0/http2/frame.go:250 +0x65 +golang.org/x/net/http2.(*Framer).ReadFrameHeader(0x2774bd86d20) + golang.org/x/net@v0.57.0/http2/frame.go:513 +0x6b +google.golang.org/grpc/internal/transport.(*framer).readFrame(0x2774bc2aa80) + google.golang.org/grpc@v1.82.1/internal/transport/http_util.go:493 +0x45 +google.golang.org/grpc/internal/transport.(*http2Client).reader(0x2774b982248, 0x2774b9ce2a0) + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:1711 +0x1ba +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 145 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:420 +0x1e13 + +goroutine 274 [select]: +google.golang.org/grpc/internal/transport.(*controlBuffer).get(0x2774c0ce000, 0x1) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:420 +0x10a +google.golang.org/grpc/internal/transport.(*loopyWriter).run(0x2774bb50500) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:595 +0x78 +google.golang.org/grpc/internal/transport.NewHTTP2Client.func6() + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:478 +0xd2 +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 145 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:476 +0x23db + +goroutine 367 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e2e00, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774bf10080?, 0x2774c1b6221?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774bf10080, {0x2774c1b6221, 0x1, 0x1}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774bf10080, {0x2774c1b6221?, 0x3257cb0?, 0x2774bc77770?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774c412028, {0x2774c1b6221?, 0x6922ef?, 0x2774bda5360?}) + net/net.go:196 +0x45 +net/http.(*connReader).backgroundRead(0x2774c1b6200) + net/http/server.go:702 +0x33 +created by net/http.(*connReader).startBackgroundRead in goroutine 366 + net/http/server.go:698 +0xb6 + +goroutine 366 [syscall]: +syscall.Syscall6(0x106, 0xffffffffffffff9c, 0x2774bf00240, 0x2774c42a6b8, 0x0, 0x0, 0x0) + syscall/syscall_linux.go:96 +0x39 +syscall.fstatat(0xffffffffffffff9c, {0x2774bf001e0?, 0x2774c48a810?}, 0x2774c42a6b8, 0x0) + syscall/zsyscall_linux_amd64.go:1437 +0x96 +syscall.Stat(...) + syscall/syscall_linux_amd64.go:61 +os.statNolog.func1(...) + os/stat_unix.go:32 +os.ignoringEINTR(...) + os/file_posix.go:263 +os.statNolog({0x2774bf001e0, 0x54}) + os/stat_unix.go:31 +0x52 +os.Stat({0x2774bf001e0, 0x54}) + os/stat.go:13 +0x2c +github.com/kalbasit/ncps/pkg/storage/local.(*Store).StatNar(0x2774bda16b0, {0x20f71f8, 0x2774c48a810}, {{0x2774bf38009, 0x34}, {0x2001062, 0x4}, 0x2774c48a720, 0x0, {0x0, ...}}) + github.com/kalbasit/ncps/pkg/storage/local/local.go:367 +0x731 +github.com/kalbasit/ncps/pkg/cache.(*Cache).statNarInStore(0x2774bb27790?, {0x20f71f8?, 0x2774c48a810?}, {{0x2774bf38009, 0x34}, {0x2001062, 0x4}, 0x2774c48a720, 0x0, {0x0, ...}}) + github.com/kalbasit/ncps/pkg/cache/cache.go:4954 +0xe4 +github.com/kalbasit/ncps/pkg/cache.(*Cache).HasNarInStore(...) + github.com/kalbasit/ncps/pkg/cache/cache.go:4903 +github.com/kalbasit/ncps/pkg/cache.(*Cache).GetNar.func2() + github.com/kalbasit/ncps/pkg/cache/cache.go:1307 +0x2a5 +github.com/kalbasit/ncps/pkg/cache.(*Cache).withReadLock(0x2774ba352c0, {0x20f71f8, 0x2774c48a7b0}, {0x20032c9, 0x6}, {0x2774bf38050, 0x41}, 0x2774b7d44e8) + github.com/kalbasit/ncps/pkg/cache/cache.go:7231 +0x270 +github.com/kalbasit/ncps/pkg/cache.(*Cache).GetNar(0x2774ba352c0, {0x20f71f8, 0x2774c48a780}, {{0x2774bf38009, 0x34}, {0x2001062, 0x4}, 0x2774c48a720, 0x0, {0x0, ...}}) + github.com/kalbasit/ncps/pkg/cache/cache.go:1294 +0x545 +github.com/kalbasit/ncps/pkg/server.(*Server).registerRoutes.(*Server).getNar.func4({0x7fb1705e0da0, 0x2774c1b6500}, 0x2774b9f0a00, {{0x2774bf38009, 0x34}, {0x2001062, 0x4}, 0x2774c48a720, 0x0, {0x0, ...}}) + github.com/kalbasit/ncps/pkg/server/server.go:926 +0x2e5 +github.com/kalbasit/ncps/pkg/server.(*Server).registerRoutes.(*Server).getNar.(*Server).withNarURL.func10({0x7fb1705e0da0, 0x2774c1b6500}, 0x2774b9f08c0) + github.com/kalbasit/ncps/pkg/server/server.go:871 +0x707 +net/http.HandlerFunc.ServeHTTP(0x1d971e0?, {0x7fb1705e0da0?, 0x2774c1b6500?}, 0xb?) + net/http/server.go:2284 +0x29 +github.com/go-chi/chi/v5.(*Mux).routeHTTP(0x2774bc42420, {0x7fb1705e0da0, 0x2774c1b6500}, 0x2774b9f08c0) + github.com/go-chi/chi/v5@v5.3.2/mux.go:483 +0x4ff +net/http.HandlerFunc.ServeHTTP(0x50000033bb160?, {0x7fb1705e0da0?, 0x2774c1b6500?}, 0x30?) + net/http/server.go:2284 +0x29 +github.com/kalbasit/ncps/pkg/server.(*Server).requireGetToken-fm.(*Server).requireGetToken.func1({0x7fb1705e0da0?, 0x2774c1b6500?}, 0x2774ba061c0?) + github.com/kalbasit/ncps/pkg/server/server.go:213 +0x2b7 +net/http.HandlerFunc.ServeHTTP(0x3259610?, {0x7fb1705e0da0?, 0x2774c1b6500?}, 0x0?) + net/http/server.go:2284 +0x29 +github.com/kalbasit/ncps/pkg/server.(*Server).skipTelemetryForInfraRoutes.func1.requestLogger.2({0x20f6980, 0x2774c5062a0}, 0x2774b9f08c0) + github.com/kalbasit/ncps/pkg/server/server.go:336 +0x26b +net/http.HandlerFunc.ServeHTTP(0x20f6980?, {0x20f6980?, 0x2774c5062a0?}, 0x20f71f8?) + net/http/server.go:2284 +0x29 +github.com/riandyrn/otelchi/metric.NewServerResponseBodySize.func1.1({0x20f6980?, 0x2774c506240?}, 0x2774b9f0640) + github.com/riandyrn/otelchi@v0.12.3/metric/server_response_body_size.go:32 +0xc8 +net/http.HandlerFunc.ServeHTTP(0x325f950?, {0x20f6980?, 0x2774c506240?}, 0x1?) + net/http/server.go:2284 +0x29 +github.com/riandyrn/otelchi/metric.NewServerActiveRequests.func1.1({0x20f6980, 0x2774c506240}, 0x2774b9f0640) + github.com/riandyrn/otelchi@v0.12.3/metric/server_active_requests.go:34 +0x231 +net/http.HandlerFunc.ServeHTTP(0x2774b7d5168?, {0x20f6980?, 0x2774c506240?}, 0x2774b7d51b8?) + net/http/server.go:2284 +0x29 +github.com/riandyrn/otelchi/metric.NewServerRequestDuration.func1.1({0x20f6980, 0x2774c506240}, 0x2774b9f0640) + github.com/riandyrn/otelchi@v0.12.3/metric/server_request_duration.go:40 +0xa9 +net/http.HandlerFunc.ServeHTTP(0x20f3700?, {0x20f6980?, 0x2774c506240?}, 0x2070e05?) + net/http/server.go:2284 +0x29 +github.com/riandyrn/otelchi.traceware.ServeHTTP({{{0x0, 0x0}, {0x20f3130, 0x2774bca0d38}, {0x20f7818, 0x2774bc42420}, 0x0, {0x0, 0x0, 0x0}, ...}, ...}, ...) + github.com/riandyrn/otelchi@v0.12.3/middleware.go:199 +0x1174 +github.com/kalbasit/ncps/pkg/server.(*Server).skipTelemetryForInfraRoutes.func1({0x20f3700, 0x2774c18c3c0}, 0x2774b9f0500) + github.com/kalbasit/ncps/pkg/server/server.go:184 +0x262 +net/http.HandlerFunc.ServeHTTP(0x3396fc0?, {0x20f3700?, 0x2774c18c3c0?}, 0xf?) + net/http/server.go:2284 +0x29 +github.com/kalbasit/ncps/pkg/server.recoverer.func1({0x20f3700?, 0x2774c18c3c0?}, 0x0?) + github.com/kalbasit/ncps/pkg/server/server.go:281 +0x6c +net/http.HandlerFunc.ServeHTTP(0x0?, {0x20f3700?, 0x2774c18c3c0?}, 0x2774c40d9c8?) + net/http/server.go:2284 +0x29 +github.com/go-chi/chi/v5/middleware.ClientIPFromXFF.func1.1({0x20f3700, 0x2774c18c3c0}, 0x2774b9f0500) + github.com/go-chi/chi/v5@v5.3.2/middleware/client_ip.go:114 +0x24c +net/http.HandlerFunc.ServeHTTP(0x2774bf38004?, {0x20f3700?, 0x2774c18c3c0?}, 0x130?) + net/http/server.go:2284 +0x29 +github.com/kalbasit/ncps/pkg/server.(*Server).createRouter.Heartbeat.func2.1({0x20f3700, 0x2774c18c3c0}, 0x2774b9f0500?) + github.com/go-chi/chi/v5@v5.3.2/middleware/heartbeat.go:21 +0x12d +net/http.HandlerFunc.ServeHTTP(0x20f7230?, {0x20f3700?, 0x2774c18c3c0?}, 0x3253170?) + net/http/server.go:2284 +0x29 +github.com/go-chi/chi/v5.(*Mux).ServeHTTP(0x2774bc42420, {0x20f3700, 0x2774c18c3c0}, 0x2774b9f03c0) + github.com/go-chi/chi/v5@v5.3.2/mux.go:90 +0x322 +github.com/kalbasit/ncps/pkg/server.(*Server).ServeHTTP(0x48e2f9?, {0x20f3700?, 0x2774c18c3c0?}, 0x2774c40db30?) + github.com/kalbasit/ncps/pkg/server/server.go:110 +0x25 +net/http.serverHandler.ServeHTTP({0x2774c1b6200?}, {0x20f3700?, 0x2774c18c3c0?}, 0x1?) + net/http/server.go:3309 +0x8e +net/http.(*conn).serve(0x2774c1b3dd0, {0x20f71f8, 0x2774bd9d5c0}) + net/http/server.go:2067 +0x690 +created by net/http.(*Server).Serve in goroutine 1 + net/http/server.go:3462 +0x485 + +goroutine 88 [select]: +google.golang.org/grpc/internal/resolver/dns.(*dnsResolver).watcher(0x2774c2ae400) + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:224 +0x24a +created by google.golang.org/grpc/internal/resolver/dns.(*dnsBuilder).Build in goroutine 147 + google.golang.org/grpc@v1.82.1/internal/resolver/dns/dns_resolver.go:153 +0x319 + +goroutine 419 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1703e2800, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x17?, 0xb?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).RawRead(0x2774c16b400, 0x2774bb662b0) + internal/poll/fd_unix.go:710 +0x125 +net.(*rawConn).Read(0x2774bc1e348, 0x2774bfd3ca0?) + net/rawconn.go:44 +0x36 +google.golang.org/grpc/internal/transport/readyreader.(*nonBlockingReader).ReadOnReady(0x2774c2b6550, 0x2774bfd3d00?, {0x20f1678, 0x2774c1b18f0}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:114 +0xa7 +google.golang.org/grpc/internal/transport/readyreader.(*bufReadyReader).Read(0x2774ba068c0, {0x2774bd86f24, 0x9, 0x1ec1d20?}) + google.golang.org/grpc@v1.82.1/internal/transport/readyreader/ready_reader.go:221 +0x174 +io.ReadAtLeast({0x20eafc0, 0x2774ba068c0}, {0x2774bd86f24, 0x9, 0x9}, 0x9) + io/io.go:335 +0x8e +io.ReadFull(...) + io/io.go:354 +golang.org/x/net/http2.readFrameHeader({0x2774bd86f24, 0x9, 0x27700000000?}, {0x20eafc0?, 0x2774ba068c0?}) + golang.org/x/net@v0.57.0/http2/frame.go:250 +0x65 +golang.org/x/net/http2.(*Framer).ReadFrameHeader(0x2774bd86ee0) + golang.org/x/net@v0.57.0/http2/frame.go:513 +0x6b +google.golang.org/grpc/internal/transport.(*framer).readFrame(0x2774c16b480) + google.golang.org/grpc@v1.82.1/internal/transport/http_util.go:493 +0x45 +google.golang.org/grpc/internal/transport.(*http2Client).reader(0x2774bc6b688, 0x2774ba06930) + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:1711 +0x1ba +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 405 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:420 +0x1e13 + +goroutine 406 [select]: +google.golang.org/grpc/internal/transport.(*controlBuffer).get(0x2774c158b80, 0x1) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:420 +0x10a +google.golang.org/grpc/internal/transport.(*loopyWriter).run(0x2774bc8e280) + google.golang.org/grpc@v1.82.1/internal/transport/controlbuf.go:595 +0x78 +google.golang.org/grpc/internal/transport.NewHTTP2Client.func6() + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:478 +0xd2 +created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 405 + google.golang.org/grpc@v1.82.1/internal/transport/http2_client.go:476 +0x23db + +goroutine 401 [IO wait]: +internal/poll.runtime_pollWait(0x7fb1705e0a00, 0x72) + runtime/netpoll.go:351 +0x85 +internal/poll.(*pollDesc).wait(0x2774c16b000?, 0x2774bdd2021?, 0x0) + internal/poll/fd_poll_runtime.go:84 +0x27 +internal/poll.(*pollDesc).waitRead(...) + internal/poll/fd_poll_runtime.go:89 +internal/poll.(*FD).Read(0x2774c16b000, {0x2774bdd2021, 0x1, 0x1}) + internal/poll/fd_unix.go:165 +0x2ae +net.(*netFD).Read(0x2774c16b000, {0x2774bdd2021?, 0x0?, 0x2774bc73fd0?}) + net/fd_posix.go:68 +0x25 +net.(*conn).Read(0x2774b782008, {0x2774bdd2021?, 0x1000000010000?, 0x2774bb83ab0?}) + net/net.go:196 +0x45 +net/http.(*connReader).backgroundRead(0x2774bdd2000) + net/http/server.go:702 +0x33 +created by net/http.(*connReader).startBackgroundRead in goroutine 452 + net/http/server.go:698 +0xb6 diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/investigation.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/investigation.md new file mode 100644 index 000000000..c765ca0e2 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/investigation.md @@ -0,0 +1,243 @@ +# Investigation: "Truncated zstd input" / HTTP/2 INTERNAL_ERROR on v0.10.0-rc17 + +Date: 2026-08-26. Cluster: pve-cluster-prod0, ns `ncps`, image `ghcr.io/kalbasit/ncps:v0.10.0-rc17`, +2 replicas (`ncps-5f9fc6fff8-4d45d` = 10.244.9.222, `ncps-5f9fc6fff8-w76sd` = 10.244.19.89). + +## Client symptom + +``` +error: unable to download 'https://ncps.nasreddine.com/nar/.nar.zst': + HTTP error 200 () (curl error code=92: HTTP/2 stream N reset by server (error 0x2 INTERNAL_ERROR)) +error (ignored): error: failed to read compressed data (Truncated zstd input) +``` + +## Evidence + +### 1. The stored bytes are fine +All six NARs from the failing run serve a complete, zstd-valid body on retry, with +`Content-Length` matching the narinfo `FileSize` exactly. This is **not** corruption +and **not** a compression-desync. + +### 2. nginx-ingress aborted the streams +`ingress-nginx-controller-58949cdb9-v8jmv` error log, six entries on one connection +(`*19013357`), one per failing NAR, all upstream `10.244.19.89:8501`: + +``` +[error] upstream timed out (110: Operation timed out) while reading upstream, + client: 192.168.100.10, request: "GET /nar/1w7dvc....nar.zst HTTP/2.0" +192.168.100.10 - - "GET /nar/1w7dvc....nar.zst HTTP/2.0" 200 1621071 "curl/8.21.0 Lix/2.94.2" + 57 76.111 [ncps-ncps-http] [] 10.244.19.89:8501 1621944 76.111 200 +``` + +- `body_bytes_sent` 1621071 vs `Content-Length` 1624995 -> **3924 bytes short**. +- `upstream_response_time` 76.1 s; the other five were 96.5 / 103.2 / 107.3 / 111.0 / 112.1 s. + +### 3. The proxy read timeout is 60 s, not the configured 300 s +Rendered vhost for `ncps.nasreddine.com`: + +``` +proxy_connect_timeout 5s; proxy_send_timeout 60s; proxy_read_timeout 60s; +proxy_buffering off; proxy_request_buffering off; proxy_http_version 1.1; +``` + +The Ingress carries `nginx.ingress.kubernetes.io/proxy-read-timeout: 300s`. That annotation +takes a **bare integer of seconds**; `"300s"` fails validation and is silently dropped, so the +60 s default applies. Every ncps response slower than 60 s is killed mid-flight. + +### 4. ncps itself stalls far past 60 s +ncps app log, same rollout: 15 `/nar/` requests with `elapsed` ~= 60000 ms, **8 of them with +`status: 0, bytes: 0`** -- killed at exactly the nginx timeout having emitted nothing. + +### 5. Reproduced deterministically, bypassing nginx +Port-forward straight to each pod. Request the narinfo on pod A (A pulls + stores the NAR), +then request the NAR on pod B, measuring true TTFB: + +| package | NAR size | TTFB on pod B | +|----------|-------------|---------------| +| blender | 108,662,723 | **107.5 s** | +| openjdk17| 349,188,671 | **57.4 s** | +| gcc14 | **12,524** | **56.8 s** | +| wine64 | 66,189,221 | **57.8 s** | +| godot_4 | 69,967,331 | **57.5 s** | + +`gcc14` is decisive: a **12 KB** NAR, 56.8 s to first byte. Not bandwidth, not NAR size. +ncps's own request log agrees: `elapsed: 56800.09 ms`. + +Controls: the same NAR re-fetched once cached -> 8-170 ms on both pods. Same-pod request -> 8 ms. +So neither pod is broadly slow. + +### 6. Pod B is idle and completely silent during the stall +Pod A finished the entire narinfo + NAR download **within one second** (03:17:50) -- before pod B's +request even started. Pod B's full debug log for the stall window: + +``` +03:17:49 info /nar/1yg0qcp3...nar.zst handled request <- previous request +03:18:37 debug upstream is healthy (x5, the 1-minute healthcheck tick) +03:18:48 debug /nar/1w68g6h9...nar.zst withEntTransaction: starting transaction +03:18:48 info /nar/1w68g6h9...nar.zst handled request elapsed=56800 ms +``` + +Nothing between 03:17:51 and 03:18:48. No lock-contention warning, no upstream fetch, no DB call. +The handler is parked somewhere that logs nothing and is not gated on the peer finishing. + +## Failure chain (established) + +1. A NAR GET lands on the replica that is **not** the one that pulled it (2 replicas, no session + affinity: nix fetches the narinfo, which triggers the pull, then fetches the NAR). +2. That replica's `GetNar` blocks for ~57 s (up to 107 s observed) emitting nothing. +3. nginx's 60 s `proxy_read_timeout` expires and it aborts the upstream read. +4. nginx RST_STREAMs the client's HTTP/2 stream with INTERNAL_ERROR. Because a `200` + + `Content-Length` had already gone out, nix reports `HTTP error 200` + `Truncated zstd input`. + +## Why it survived every previous fix + +Every prior change (in-flight staging, progressive chunks, compression desync, ...) targeted **which +bytes get served**. None bounded **how long a waiter may sit silent**. The existing +`staging-contention` e2e races 8 clients and asserts byte-identical NARs -- with +`urllib.request.urlopen(..., timeout=900)`. A 900 s tolerance cannot see a 57 s stall, but a +reverse proxy tolerates 60 s. Correct-but-slow reads as PASS in the harness and as a hard +failure in production. + +## Local reproduction attempt: NEGATIVE (this is the key new signal) + +Stood up the prod-shaped topology locally via `dev-scripts/run.py`: **2 replicas, redis locker, +postgres, local storage, in-flight staging on, CDC off**, backends from `nix run .#deps`. + +1. Sequential cross-replica race (narinfo on replica 0, NAR on replica 1), 5 packages: + TTFB **1.3-3.3 ms** on every one. +2. Concurrent load, 14 large packages (12 KB - 349 MB), all narinfos fired at replica 0 and all + NARs at replica 1 simultaneously: **0 / 14** with TTFB > 20 s. Worst TTFB **0.65 s**; a 349 MB + NAR began streaming cross-replica in **0.59 s**; every body byte-exact. + +So the cross-replica coordination path, in-flight streaming, the redis locker, the download lock +and the DB pool are all **exonerated** at this topology. The stall needs something prod has that +the local stack does not. + +## Prime suspect: the NFS RWX shared storage + +`ncps-storage` is a manually-provisioned RWX PV, `org.democratic-csi.node-manual`, `fsType: nfs`, +server `nfs.truenas.pve.nasreddine.com`, share `/mnt/tank/services/ncps`, +`mountOptions: [nfsvers=4, noatime]` -- no `actimeo`/`ac*` tuning, so kernel defaults apply +(`acdirmin/acdirmax` 30-60 s). + +Both replicas mount the same share. `GetNar` opens with `statNarInStore`, which stats +`/storage/nar/.nar.{zst,xz}` -- a plain `Stat` on that NFS mount, inside the request path, +with no timeout, no instrumentation and no log line. + +The measured behaviour matches an NFS attribute/dentry-cache revalidation stall exactly: + +| access | TTFB | +| --- | --- | +| pod B, first read of a file pod **A** just wrote | **56.8 - 107.5 s** | +| pod B, same file again immediately after | **8.7 ms** | +| pod A (the writer), same file | **7.9 ms** | +| either pod, file written long ago | **10 - 300 ms** | + +First cross-client access to a freshly-written file stalls; every subsequent access is cached and +instant. That is the signature, and it is independent of NAR size (12,524 bytes -> 56.8 s). + +This also matches a hazard already recorded in the project notes: prod runs the `local` storage +backend on a shared NFS RWX volume with 2 replicas, flagged previously as an anti-pattern. + +## Defects to fix + +1. **ncps** -- `GetNar` performs unbounded, uninstrumented, silent blocking storage I/O inside the + request path. There is no deadline, no first-byte budget and no log line, so a slow storage + layer becomes a truncated HTTP response instead of a fast clean error or a fallback. This is + the ncps-side bug and the one this change should fix. +2. **Infra** -- NFS RWX as shared storage between replicas. Either mount with sane `actimeo` / + `lookupcache` settings, or move to the S3 backend (already supported) for multi-replica. +3. **Infra** -- `nginx.ingress.kubernetes.io/proxy-read-timeout: "300s"` is invalid (the annotation + takes a bare integer of seconds) and is silently dropped, so the 60 s default applies. Must be + `"300"`. + +## PINNED: goroutine dump caught the stall in the act + +Ran a **standalone** `ncps-pprof` Pod (same image/config/PVC/redis/DB as prod, `PPROF_ADDR=:6060`, +third node). The managed Deployment was never touched, so Argo auto-heal had nothing to revert. + +Race: narinfo on the real pod A, NAR on `ncps-pprof`. `kicad` -- a **2,021 byte** NAR -- +stalled **56.87 s** to first byte. Goroutine dump captured mid-stall +(`goroutine-stall-dump.txt`): + +``` +goroutine 366 [syscall]: +syscall.Syscall6(0x106, ...) <- fstatat +syscall.Stat(...) +os.Stat({0x2774bf001e0, 0x54}) +github.com/kalbasit/ncps/pkg/storage/local.(*Store).StatNar local/local.go:367 +github.com/kalbasit/ncps/pkg/cache.(*Cache).statNarInStore cache/cache.go:4954 +github.com/kalbasit/ncps/pkg/cache.(*Cache).HasNarInStore cache/cache.go:4903 +github.com/kalbasit/ncps/pkg/cache.(*Cache).GetNar.func2 cache/cache.go:1307 +github.com/kalbasit/ncps/pkg/cache.(*Cache).withReadLock cache/cache.go:7231 +github.com/kalbasit/ncps/pkg/cache.(*Cache).GetNar cache/cache.go:1294 +github.com/kalbasit/ncps/pkg/server....getNar server/server.go:926 +``` + +**A single `os.Stat` on the NFS mount, blocked in `fstatat` for ~57 seconds.** + +The pod was otherwise idle: 81 goroutines, and **exactly one** in `[syscall]` -- this one. So it +is not ncps-internal contention, not the download lock, not the DB pool, not the RW lock. + +### Why ~57 s / ~107 s specifically + +Mount options: `hard,timeo=600,retrans=2` -- `timeo` is in **deciseconds**, so **60 s per RPC +timeout cycle**, with up to 2 retransmissions. Observed prod stalls: 56.8, 57.4, 57.5, 57.8 and +107.5 s -- one cycle and two cycles. Exact fit. + +### NFS client RPC counters (`/proc/self/mountstats`, same node) + +``` + WRITE: 35 35 0 35968240 3920 508 315 825 0 + LOOKUP: 20 20 0 4744 3896 0 656 657 13 + RENAME: 10 10 0 3600 1160 41285 280 41566 9 +``` +(columns: ops, trans, timeouts, bytes_sent, bytes_recv, **queue_ms**, rtt_ms, execute_ms, errors) + +RENAME: **41,285 ms of client-side queue time** against **280 ms of actual round-trip**. The +server is answering fast; the requests are sitting in the client's RPC queue. That is +client-side NFSv4 session-slot/backlog queuing, and the same queuing is what parks a LOOKUP / +GETATTR long enough to blow through `timeo`. + +Note the isolated probe earlier (idle mount, no concurrent ncps I/O) resolved a freshly-created +file cross-node in **0 s** -- the stall only appears when the mount is under concurrent ncps load. + +## Root cause + +`Cache.GetNar` calls `HasNarInStore` -> `statNarInStore` -> `os.Stat` **directly in the HTTP +request path**, on an NFS mount, with: + +- no timeout or deadline (the request context is not even consulted -- `os.Stat` cannot be + cancelled), +- no instrumentation (not a single log line or span for 57 s), +- no fallback when the storage probe is slow rather than merely absent. + +Under concurrent load the NFS client queues the RPC past `timeo=600` (60 s). ncps holds the HTTP +response open the whole time; nginx's 60 s `proxy_read_timeout` fires first, aborts the upstream +read and RST_STREAMs the client -- delivering a `200` with a truncated body, which nix reports as +`Truncated zstd input`. + +## Fixes + +1. **ncps (this change)** -- the storage-presence probe must not be able to hang a request: + put a deadline on it, run it off the request goroutine so the context can cancel the wait, + instrument it (log + span + metric) so a slow probe is visible instead of silent, and decide + what to serve when the probe times out rather than blocking indefinitely. A NAR request must + have a bounded time-to-first-byte. +2. **Infra** -- NFS RWX shared between replicas is the wrong substrate for this access pattern. + Move multi-replica to the S3 backend (already supported), or at minimum lower `timeo`, raise + the session slot count, and investigate why the client backlog reaches 41 s. +3. **Infra** -- `nginx.ingress.kubernetes.io/proxy-read-timeout: "300s"` is invalid (bare integer + seconds required), silently dropped, so the 60 s default applies. Must be `"300"`. + +## Test strategy + +The local (non-NFS) topology cannot reproduce this -- 0/14 slow, worst TTFB 0.65 s. A test that +races replicas over local disk is green and worthless; that is precisely why the existing +`staging-contention` scenario (which tolerates `timeout=900`) never caught it. + +The regression test must therefore inject a **slow storage backend** rather than rely on real +NFS: a store wrapper whose `StatNar` blocks for N seconds, asserting that `GetNar` still produces +a first byte (or a clean error) within a bounded budget well under N. That is a deterministic +unit/integration test. The e2e layer should additionally assert **time-to-first-byte**, not just +byte-correctness, so a correct-but-slow response can never pass again. diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/proposal.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/proposal.md new file mode 100644 index 000000000..e0a1438b5 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/proposal.md @@ -0,0 +1,60 @@ +## Why + +Production ncps (v0.10.0-rc17) answers NAR requests with `HTTP 200` and a truncated body; nix +reports `Truncated zstd input` and `curl error 92: HTTP/2 stream reset by server`. A goroutine +dump captured mid-stall proves the cause: `GetNar`'s storage-presence probe blocks for ~57 s in a +single uncancellable `fstatat` syscall, and the ingress's 60 s `proxy_read_timeout` aborts the +stream first. A 2,021-byte NAR took 56.87 s to first byte. See `investigation.md` and +`goroutine-stall-dump.txt`. + +ncps places no bound on a NAR request's time-to-first-byte, and emits no log, span, or metric +while it waits. A slow storage layer therefore becomes silent data corruption at the client +instead of a fast, honest error. + +## What Changes + +- The storage presence probe used by `GetNar` gains a **deadline**. When it expires, the request + resolves promptly instead of blocking indefinitely. +- The probe runs so that the **request context can abandon the wait**. `os.Stat` takes no context + and cannot be cancelled, so the local backend must not block the request goroutine on it. +- A NAR request gains a **bounded time-to-first-byte**: either bytes begin flowing or the request + fails cleanly, always well inside a reverse proxy's read timeout. +- The probe becomes **observable**: a slow or timed-out probe emits a log line, span, and metric + rather than 57 s of silence. +- Regression coverage: a store wrapper whose `StatNar` blocks for N seconds, asserting `GetNar` + still yields a first byte or a clean error within a budget far below N; and an e2e scenario + asserting time-to-first-byte rather than byte-correctness alone. + +## Non-goals + +- Fixing the NFS substrate. Mount tuning (`nconnect`), and migrating multi-replica deployments to + the S3 backend, are infrastructure work tracked outside this change. +- Correcting the invalid `nginx.ingress.kubernetes.io/proxy-read-timeout: "300s"` annotation + (deployment repo). +- Making slow storage fast. This change bounds and surfaces the latency; it does not remove it. +- Changing the default storage backend or deprecating the `local` backend. +- Altering CDC, chunking, in-flight staging, or download-coordination behaviour. + +## Capabilities + +### New Capabilities + +- `nar-serving-latency-bounds`: bounded time-to-first-byte for NAR requests, a deadline on the + storage presence probe, and the observability required to distinguish a slow probe from an + absent asset. + +### Modified Capabilities + +- `unified-e2e-harness`: gains a scenario requirement asserting time-to-first-byte on NAR reads, + so a correct-but-slow response is a FAIL rather than a PASS. + +## Impact + +- **Code**: `pkg/cache/cache.go` (`GetNar`, `HasNarInStore`, `statNarInStore`), + `pkg/storage/local` (`StatNar`), plus test scaffolding and the e2e harness assertions. +- **I/O**: unchanged in volume. The same presence probes are issued; only their wait is bounded. +- **Network latency**: strictly improved. Requests that would have hung ~57 s and been killed by + the proxy now resolve inside the budget. +- **Memory**: a bounded probe that outlives its deadline leaves one goroutine (and, for the + uncancellable `os.Stat`, one OS thread) parked until the syscall returns. This is bounded by + concurrent NAR requests against stalled storage and must be capped and measured in `design.md`. diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/nar-serving-latency-bounds/spec.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/nar-serving-latency-bounds/spec.md new file mode 100644 index 000000000..0dd6f2100 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/nar-serving-latency-bounds/spec.md @@ -0,0 +1,112 @@ +## Purpose + +Guarantees that a NAR request resolves within a bounded time regardless of how slow the storage +layer is, so a stalled storage probe can never be delivered to a client as a truncated success, +and so slow storage is visible in logs and metrics instead of silent. + +## ADDED Requirements + +### Requirement: NAR requests MUST have a bounded time-to-first-byte + +A NAR request SHALL either begin emitting response body bytes, or terminate with an explicit +error status, within a configured time-to-first-byte budget — regardless of how long the storage +layer takes to answer a presence probe. The budget SHALL default to a value comfortably below the +read timeout of a typical reverse proxy (60 s), and SHALL be configurable. Configuring it to zero +SHALL disable the bound entirely, restoring unbounded waiting; that is a deliberate operator +rollback switch and the only case in which the bounds below do not apply. + +A NAR response that has already committed a `200` status and a `Content-Length` SHALL NOT be +allowed to stall such that an intermediary aborts it mid-body; the truncated-success outcome is +the failure this requirement exists to prevent. + +#### Scenario: Storage presence probe stalls far beyond the budget + +- **WHEN** a client requests a NAR +- **AND** the storage backend's presence probe blocks for 120 s +- **AND** the configured time-to-first-byte budget is 10 s +- **THEN** the request MUST resolve within approximately the budget, not 120 s +- **AND** the client MUST receive either the first body byte or a non-2xx status +- **AND** the client MUST NOT receive a `200` whose body is shorter than its declared `Content-Length` + +#### Scenario: Several stalled probes in one request share the budget + +- **WHEN** a single NAR request consults storage more than once (the pre-check, the + servability lookup, and again after download coordination) +- **AND** every one of those probes stalls +- **THEN** the request MUST still resolve within approximately one budget, not one budget + per probe +- **AND** the total MUST NOT scale with the number of probes the read path happens to make + +#### Scenario: The bound is explicitly disabled + +- **WHEN** the probe bound is configured to zero +- **THEN** probes SHALL wait without a bound, restoring the pre-change behaviour +- **AND** this SHALL be treated as an explicit operator opt-out for rollback, not as a violation + of the bounded-latency requirements above + +#### Scenario: Fast storage is unaffected + +- **WHEN** a client requests a NAR that is present in storage +- **AND** the presence probe returns promptly +- **THEN** the response MUST be served exactly as before, with no added latency +- **AND** no timeout-related log, metric, or error MUST be emitted + +### Requirement: The storage presence probe MUST NOT block a request past its deadline + +The storage presence probe issued while serving a NAR SHALL be bounded by a deadline. When the +deadline expires the request SHALL stop waiting on the probe and proceed to resolve, even when +the underlying probe cannot itself be cancelled. + +A backend whose probe honours `context.Context` SHALL have the deadline propagated into the +probe so the underlying operation is genuinely cancelled. A backend whose probe cannot observe +context cancellation SHALL NOT hold the request goroutine hostage to it. + +#### Scenario: Context-aware backend cancels the probe + +- **WHEN** the storage backend's presence probe accepts a context +- **AND** the probe deadline expires +- **THEN** the probe operation MUST be cancelled +- **AND** no resources MUST remain reserved for it beyond the cancellation + +#### Scenario: Uncancellable probe does not pin the request + +- **WHEN** the storage backend's presence probe cannot observe context cancellation +- **AND** the probe deadline expires while the probe is still blocked +- **THEN** the request MUST proceed without waiting for the probe to return +- **AND** the abandoned probe MUST NOT prevent the request from resolving + +### Requirement: A timed-out presence probe MUST NOT be reported as asset absence + +A presence probe that times out SHALL be treated as an indeterminate result, never as a +determination that the asset is absent. Reporting a stalled probe as absence would silently +convert a slow read into a redundant re-download or a spurious 404. + +#### Scenario: Timed-out probe is distinguished from a genuine miss + +- **WHEN** the presence probe for a NAR times out +- **THEN** the outcome MUST be classified as indeterminate, distinct from "not present" +- **AND** the request MUST NOT return `404 Not Found` on the strength of the timeout alone + +#### Scenario: Genuine absence is still reported as absence + +- **WHEN** the presence probe completes promptly and reports the asset is not in storage +- **THEN** the existing cache-miss behaviour MUST apply unchanged + +### Requirement: Slow and timed-out storage probes MUST be observable + +A presence probe that exceeds a warning threshold, or that exceeds its deadline, SHALL emit +diagnostic output. Silence during a multi-second stall is itself a defect: the production +incident this change addresses produced 57 s of stall with no log line, span, or metric. + +#### Scenario: A stalled probe is logged and measured + +- **WHEN** a presence probe exceeds its deadline +- **THEN** a log record MUST be emitted identifying the NAR and the elapsed time +- **AND** a metric counting probe timeouts MUST be incremented +- **AND** the tracing span for the probe MUST record the timeout + +#### Scenario: Probe latency is recorded for successful probes + +- **WHEN** a presence probe completes successfully +- **THEN** its duration MUST be recorded so slow-but-successful probes are visible before they + become timeouts diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/unified-e2e-harness/spec.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/unified-e2e-harness/spec.md new file mode 100644 index 000000000..e1161e50a --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/specs/unified-e2e-harness/spec.md @@ -0,0 +1,46 @@ +## ADDED Requirements + +### Requirement: NAR read latency assertion + +The harness SHALL assert **time-to-first-byte** on NAR reads, not only byte-correctness, in the +serve phase that every serving scenario runs. A response that is byte-exact but arrives too +slowly to survive a reverse proxy's read timeout MUST be reported as a FAILURE. + +The assertion SHALL cover a **warm** read — a NAR already present in storage — because that is +the path that failed in production: the NAR was present and every byte was correct, and only the +latency was wrong. + +The scenario SHALL measure the interval between issuing the NAR request and receiving the first +body byte, and SHALL fail unless that interval is strictly less than a declared budget, so a measurement +exactly equal to the budget FAILS (the implementation compares with `<`). The budget SHALL be far +below any per-request read timeout used by the harness client, so that a stall is caught by the +assertion rather than by a client timeout. + +This closes the gap that allowed the production stall to pass every existing scenario: the +in-flight staging contention scenario reads NARs with a 900 s client timeout and asserts only +that the bytes match, so a 57 s stall scored as a PASS. + +#### Scenario: Slow first byte fails the scenario + +- **WHEN** the harness requests a NAR already present in storage +- **AND** the first body byte arrives later than the declared time-to-first-byte budget +- **THEN** the scenario MUST report FAIL +- **AND** the failure message MUST report the measured time-to-first-byte and the budget + +#### Scenario: Byte-correct but slow is not a pass + +- **WHEN** a NAR response is byte-identical to the canonical NAR +- **AND** its time-to-first-byte exceeds the budget +- **THEN** the scenario MUST report FAIL, not PASS + +#### Scenario: Fast and correct passes + +- **WHEN** a NAR response is byte-identical to the canonical NAR +- **AND** its time-to-first-byte is within the budget +- **THEN** the scenario MUST report PASS + +#### Scenario: Client timeout is not the assertion mechanism + +- **WHEN** the harness measures time-to-first-byte +- **THEN** the per-request client timeout MUST be larger than the budget +- **AND** a stall MUST be reported as a budget violation with a measured value, never as an opaque client timeout diff --git a/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/tasks.md b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/tasks.md new file mode 100644 index 000000000..1b3e29c10 --- /dev/null +++ b/openspec/changes/archive/2026-08-27-fix-nar-serve-stall-proxy-timeout/tasks.md @@ -0,0 +1,80 @@ +## 1. RED: prove the defect before changing behaviour + +- [x] 1.1 Add a `slowStore` test double wrapping a `NarStore` whose `StatNar` blocks for a + configurable duration (and optionally ignores context, mimicking `os.Stat`); verify with a + direct unit test that the double blocks and unblocks as configured. +- [x] 1.2 Write a RED test asserting `GetNar` returns a first byte or an error within a short + budget while `slowStore.StatNar` blocks far longer; verify it FAILS against current `main` + with a timeout, and record the observed failure in the commit message. +- [x] 1.3 Write a RED test asserting a timed-out probe is classified indeterminate and does NOT + produce `404`; verify it fails today because a stalled probe never returns a classification + at all. +- [x] 1.4 Write a RED test asserting that in **upload-only** mode an indeterminate probe does NOT + return `storage.ErrNotFound` (design D3 guard, prevents re-introducing the phantom-NAR + bug); verify it fails today. + +## 2. Configuration + +- [x] 2.1 Add `cache.storage.stat-timeout` (flag + env + YAML, default `5s`, `0` disables) + threaded to the cache; verify with a config unit test covering default, override and the + disabling `0` value. +- [x] 2.2 Document the new setting in `config.example.yaml` with the rationale for 5s; verify by + loading the example config in the existing config test. + +## 3. GREEN: bound the storage presence probe + +- [x] 3.1 Introduce a three-state probe result (present / absent / indeterminate) at the + `statNarInStore` boundary, leaving today's two states behaviourally identical; verify + existing cache tests still pass unchanged. +- [x] 3.2 Run the backend probe on its own goroutine in `statNarInStore`, selecting over + result / deadline / `ctx.Done()` (design D1); verify test 1.2 turns GREEN. +- [x] 3.3 Propagate the deadline into the context passed to the backend so the S3 backend + genuinely cancels; verify the backend receives a deadline-carrying context and is cancelled + at it. NOTE: asserted against a context-recording store double rather than a live S3 bucket + — the property owned by this codebase is that ncps *supplies* a cancellable context; whether + MinIO/Garage honours it is their contract and would need live infrastructure to assert. +- [x] 3.4 Wire `GetNar` to route indeterminate to the existing upstream-recovery path, never to + `404`; verify tests 1.3 and 1.4 turn GREEN. + +## 4. Bound the cost of abandoned probes + +- [x] 4.1 Single-flight the probe per `(hash, compression)` so concurrent requests for the same + NAR share one probe goroutine; verify with a test that N concurrent `GetNar` calls against a + stalled store create exactly one backend probe. +- [x] 4.2 Cap simultaneously-abandoned probes, returning indeterminate immediately once exhausted + (design D2); verify with a test that the cap is respected and no additional goroutines are + launched beyond it. + +## 5. Observability + +- [x] 5.1 Record a probe-duration histogram for all probes plus a timeout counter and an + in-flight-abandoned gauge, priming counters with `Add(ctx, 0)` at startup; verify the + instruments appear on `/metrics` on an idle instance. +- [x] 5.2 Emit a `warn` log with NAR hash and elapsed time, and a span event, on probe timeout; + verify with a test asserting the log record is produced on timeout and absent on a fast + probe. + +## 6. e2e: assert time-to-first-byte, not just bytes + +- [x] 6.1 Add time-to-first-byte measurement to the harness NAR client (first-byte timestamp + distinct from full-body completion); verify with a harness pytest against a stub server that + delays its first byte. +- [x] 6.2 Assert TTFB against a declared budget on a warm NAR read, with a client timeout + strictly larger than the budget so a stall reports a measured violation rather than an + opaque timeout. NOTE: implemented in the shared `serve` phase rather than as a separate + catalog entry, so every serving scenario carries the assertion. Verified by running + `--mode local --scenario single-local-sqlite`: `warm NAR ttfb=0.001s (budget 15.0s)`, PASS. +- [x] 6.3 Cover the TTFB measurement in the `e2e-harness-unit` flake check. NOTE: no + `config.nix` entry is needed — the assertion lives in the shared `serve` phase, so the + existing catalog entries all exercise it. Verified: `nix build .#checks.x86_64-linux.e2e-harness-unit` + passes, 70 tests including the 4 new TTFB tests. + +## 7. Verification and close-out + +- [x] 7.1 Confirm the four RED tests from group 1 are GREEN and re-run the full unit suite; + verify `task test` exits zero. +- [x] 7.2 Run `task fmt` and `task lint`; verify both exit zero. +- [x] 7.3 Run `openspec validate fix-nar-serve-stall-proxy-timeout --no-interactive --strict`; + verify it reports the change valid. +- [x] 7.4 Record in the change directory the measured TTFB under a simulated stall (before/after), + so the fix's effect is evidenced rather than asserted. diff --git a/openspec/specs/nar-serving-latency-bounds/spec.md b/openspec/specs/nar-serving-latency-bounds/spec.md new file mode 100644 index 000000000..7edce4c86 --- /dev/null +++ b/openspec/specs/nar-serving-latency-bounds/spec.md @@ -0,0 +1,114 @@ +# NAR Serving Latency Bounds + +## Purpose + +Guarantees that a NAR request resolves within a bounded time regardless of how slow the storage +layer is, so a stalled storage probe can never be delivered to a client as a truncated success, +and so slow storage is visible in logs and metrics instead of silent. + +## Requirements + +### Requirement: NAR requests MUST have a bounded time-to-first-byte + +A NAR request SHALL either begin emitting response body bytes, or terminate with an explicit +error status, within a configured time-to-first-byte budget — regardless of how long the storage +layer takes to answer a presence probe. The budget SHALL default to a value comfortably below the +read timeout of a typical reverse proxy (60 s), and SHALL be configurable. Configuring it to zero +SHALL disable the bound entirely, restoring unbounded waiting; that is a deliberate operator +rollback switch and the only case in which the bounds below do not apply. + +A NAR response that has already committed a `200` status and a `Content-Length` SHALL NOT be +allowed to stall such that an intermediary aborts it mid-body; the truncated-success outcome is +the failure this requirement exists to prevent. + +#### Scenario: Storage presence probe stalls far beyond the budget + +- **WHEN** a client requests a NAR +- **AND** the storage backend's presence probe blocks for 120 s +- **AND** the configured time-to-first-byte budget is 10 s +- **THEN** the request MUST resolve within approximately the budget, not 120 s +- **AND** the client MUST receive either the first body byte or a non-2xx status +- **AND** the client MUST NOT receive a `200` whose body is shorter than its declared `Content-Length` + +#### Scenario: Several stalled probes in one request share the budget + +- **WHEN** a single NAR request consults storage more than once (the pre-check, the + servability lookup, and again after download coordination) +- **AND** every one of those probes stalls +- **THEN** the request MUST still resolve within approximately one budget, not one budget + per probe +- **AND** the total MUST NOT scale with the number of probes the read path happens to make + +#### Scenario: The bound is explicitly disabled + +- **WHEN** the probe bound is configured to zero +- **THEN** probes SHALL wait without a bound, restoring the pre-change behaviour +- **AND** this SHALL be treated as an explicit operator opt-out for rollback, not as a violation + of the bounded-latency requirements above + +#### Scenario: Fast storage is unaffected + +- **WHEN** a client requests a NAR that is present in storage +- **AND** the presence probe returns promptly +- **THEN** the response MUST be served exactly as before, with no added latency +- **AND** no timeout-related log, metric, or error MUST be emitted + +### Requirement: The storage presence probe MUST NOT block a request past its deadline + +The storage presence probe issued while serving a NAR SHALL be bounded by a deadline. When the +deadline expires the request SHALL stop waiting on the probe and proceed to resolve, even when +the underlying probe cannot itself be cancelled. + +A backend whose probe honours `context.Context` SHALL have the deadline propagated into the +probe so the underlying operation is genuinely cancelled. A backend whose probe cannot observe +context cancellation SHALL NOT hold the request goroutine hostage to it. + +#### Scenario: Context-aware backend cancels the probe + +- **WHEN** the storage backend's presence probe accepts a context +- **AND** the probe deadline expires +- **THEN** the probe operation MUST be cancelled +- **AND** no resources MUST remain reserved for it beyond the cancellation + +#### Scenario: Uncancellable probe does not pin the request + +- **WHEN** the storage backend's presence probe cannot observe context cancellation +- **AND** the probe deadline expires while the probe is still blocked +- **THEN** the request MUST proceed without waiting for the probe to return +- **AND** the abandoned probe MUST NOT prevent the request from resolving + +### Requirement: A timed-out presence probe MUST NOT be reported as asset absence + +A presence probe that times out SHALL be treated as an indeterminate result, never as a +determination that the asset is absent. Reporting a stalled probe as absence would silently +convert a slow read into a redundant re-download or a spurious 404. + +#### Scenario: Timed-out probe is distinguished from a genuine miss + +- **WHEN** the presence probe for a NAR times out +- **THEN** the outcome MUST be classified as indeterminate, distinct from "not present" +- **AND** the request MUST NOT return `404 Not Found` on the strength of the timeout alone + +#### Scenario: Genuine absence is still reported as absence + +- **WHEN** the presence probe completes promptly and reports the asset is not in storage +- **THEN** the existing cache-miss behaviour MUST apply unchanged + +### Requirement: Slow and timed-out storage probes MUST be observable + +A presence probe that exceeds a warning threshold, or that exceeds its deadline, SHALL emit +diagnostic output. Silence during a multi-second stall is itself a defect: the production +incident this change addresses produced 57 s of stall with no log line, span, or metric. + +#### Scenario: A stalled probe is logged and measured + +- **WHEN** a presence probe exceeds its deadline +- **THEN** a log record MUST be emitted identifying the NAR and the elapsed time +- **AND** a metric counting probe timeouts MUST be incremented +- **AND** the tracing span for the probe MUST record the timeout + +#### Scenario: Probe latency is recorded for successful probes + +- **WHEN** a presence probe completes successfully +- **THEN** its duration MUST be recorded so slow-but-successful probes are visible before they + become timeouts diff --git a/openspec/specs/unified-e2e-harness/spec.md b/openspec/specs/unified-e2e-harness/spec.md index ac71c267f..65062576d 100644 --- a/openspec/specs/unified-e2e-harness/spec.md +++ b/openspec/specs/unified-e2e-harness/spec.md @@ -256,3 +256,48 @@ The harness MUST isolate the S3 storage backend per scenario in `kubernetes` mod - **WHEN** the harness validates S3 storage for a scenario by counting `store/chunk/` - **THEN** the count reflects only objects that scenario wrote and does not pass on chunks left by a previously-run scenario + +### Requirement: NAR read latency assertion + +The harness SHALL assert **time-to-first-byte** on NAR reads, not only byte-correctness, in the +serve phase that every serving scenario runs. A response that is byte-exact but arrives too +slowly to survive a reverse proxy's read timeout MUST be reported as a FAILURE. + +The assertion SHALL cover a **warm** read — a NAR already present in storage — because that is +the path that failed in production: the NAR was present and every byte was correct, and only the +latency was wrong. + +The scenario SHALL measure the interval between issuing the NAR request and receiving the first +body byte, and SHALL fail unless that interval is strictly less than a declared budget, so a measurement +exactly equal to the budget FAILS (the implementation compares with `<`). The budget SHALL be far +below any per-request read timeout used by the harness client, so that a stall is caught by the +assertion rather than by a client timeout. + +This closes the gap that allowed the production stall to pass every existing scenario: the +in-flight staging contention scenario reads NARs with a 900 s client timeout and asserts only +that the bytes match, so a 57 s stall scored as a PASS. + +#### Scenario: Slow first byte fails the scenario + +- **WHEN** the harness requests a NAR already present in storage +- **AND** the first body byte arrives later than the declared time-to-first-byte budget +- **THEN** the scenario MUST report FAIL +- **AND** the failure message MUST report the measured time-to-first-byte and the budget + +#### Scenario: Byte-correct but slow is not a pass + +- **WHEN** a NAR response is byte-identical to the canonical NAR +- **AND** its time-to-first-byte exceeds the budget +- **THEN** the scenario MUST report FAIL, not PASS + +#### Scenario: Fast and correct passes + +- **WHEN** a NAR response is byte-identical to the canonical NAR +- **AND** its time-to-first-byte is within the budget +- **THEN** the scenario MUST report PASS + +#### Scenario: Client timeout is not the assertion mechanism + +- **WHEN** the harness measures time-to-first-byte +- **THEN** the per-request client timeout MUST be larger than the budget +- **AND** a stall MUST be reported as a budget violation with a measured value, never as an opaque client timeout diff --git a/pkg/cache/cache.go b/pkg/cache/cache.go index f642186bd..630dfb2e3 100644 --- a/pkg/cache/cache.go +++ b/pkg/cache/cache.go @@ -16,6 +16,7 @@ import ( "strconv" "strings" "sync" + "sync/atomic" "time" "github.com/nix-community/go-nix/pkg/narinfo" @@ -27,6 +28,7 @@ import ( "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" + "golang.org/x/sync/singleflight" entchunk "github.com/kalbasit/ncps/ent/chunk" entconfigentry "github.com/kalbasit/ncps/ent/configentry" @@ -175,6 +177,13 @@ var ( // reconstructed from chunks do not match the recorded NarHash or size. ErrNarHashMismatch = errors.New("reconstructed nar does not match recorded hash or size") + // ErrStatTimeout indicates a storage presence probe did not answer within the + // configured bound, so presence could not be determined. It is deliberately + // NOT a "not found": callers MUST treat it as undeterminable and MUST NOT + // convert it into a 404 or a confirmed absence. See storage.NarStore.StatNar + // for the (false, err) contract this participates in. + ErrStatTimeout = errors.New("storage presence probe timed out; presence undetermined") + // ErrMissingChunk is returned by MigrateChunksToNar when one or more chunks // referenced by the nar_file are absent from the chunk store or the DB. The // NAR cannot be reconstructed and should be purged so it can be re-fetched. @@ -249,6 +258,17 @@ var ( // Download coordination metrics //nolint:gochecknoglobals // package-level OTel metric instrument, initialized once in init() and reused. downloadCoordinationFallbackTotal metric.Int64Counter + + // Storage presence-probe metrics. The duration histogram covers every probe, + // so slow-but-successful storage is visible before it degrades into timeouts. + //nolint:gochecknoglobals // package-level OTel metric instrument, initialized once in init() and reused. + storageStatDuration metric.Float64Histogram + + //nolint:gochecknoglobals // package-level OTel metric instrument, initialized once in init() and reused. + storageStatTimeoutTotal metric.Int64Counter + + //nolint:gochecknoglobals // package-level OTel metric instrument, initialized once in init() and reused. + storageStatInFlight metric.Int64UpDownCounter ) //nolint:gochecknoinits @@ -426,6 +446,39 @@ func init() { if err != nil { panic(err) } + + storageStatDuration, err = meter.Float64Histogram( + "ncps_storage_stat_duration_seconds", + metric.WithDescription("Duration of storage presence probes on the NAR read path"), + metric.WithUnit("s"), + ) + if err != nil { + panic(err) + } + + storageStatTimeoutTotal, err = meter.Int64Counter( + "ncps_storage_stat_timeout_total", + metric.WithDescription( + "Counts storage presence probes abandoned without a determination, by reason "+ + "(deadline, capacity, budget_exhausted).", + ), + metric.WithUnit("{event}"), + ) + if err != nil { + panic(err) + } + + storageStatInFlight, err = meter.Int64UpDownCounter( + "ncps_storage_stat_in_flight", + metric.WithDescription( + "Storage presence probes currently running, including those already abandoned "+ + "by their request and still blocked in the backend.", + ), + metric.WithUnit("{probe}"), + ) + if err != nil { + panic(err) + } } // PrimeMetrics records a zero-valued measurement on every counter instrument in @@ -449,6 +502,7 @@ func PrimeMetrics(ctx context.Context) { lruBytesFreedTotal, backgroundMigrationObjectsTotal, downloadCoordinationFallbackTotal, + storageStatTimeoutTotal, } for _, c := range counters { @@ -534,6 +588,22 @@ type Cache struct { // storage can raise or lower it (and align it with their gateway timeout). chunkWaitTimeout time.Duration + // statTimeout bounds how long the NAR read path waits on a storage presence + // probe before treating the result as undeterminable. Protected by statMu. + // Defaults to defaultStatTimeout; a non-positive value disables the bound and + // restores unbounded waiting. + statMu sync.RWMutex + statTimeout time.Duration + + // inFlightStatProbes counts presence probes currently running, including any + // a request has already abandoned. Bounded by maxInFlightStatProbes. + inFlightStatProbes atomic.Int64 + + // statProbeGroup collapses concurrent presence probes for the same object into + // a single backend call, so a stalled NAR under a retry storm costs one blocked + // goroutine rather than one per client. + statProbeGroup singleflight.Group + // upstreamJobs is used to store in-progress jobs for pulling nars from // upstream cache so incoming requests for the same nar can find and wait // for jobs. Protected by upstreamJobsMu for local synchronization. @@ -753,6 +823,7 @@ func New( downloadPollTimeout: downloadPollTimeout, cacheLockTTL: cacheLockTTL, chunkWaitTimeout: defaultChunkWaitTimeout, + statTimeout: defaultStatTimeout, upstreamJobs: make(map[string]*downloadState), upstreamCaches: make([]*upstream.Cache, 0), recordAgeIgnoreTouch: recordAgeIgnoreTouch, @@ -1291,6 +1362,17 @@ func (c *Cache) GetNar(ctx context.Context, narURL nar.URL) (nar.URL, int64, io. reader io.ReadCloser ) + // Open one cumulative probe budget for this request. Every presence probe below + // spends from it, so a request cannot accumulate several full probe timeouts. + ctx = withStatBudget(ctx, c.getStatTimeout()) + + // presenceUndetermined records that the storage probe timed out rather than + // answering. It is NOT a cache miss: the NAR may well be present. The request + // still proceeds down the upstream-recovery path so the client gets correct + // bytes, but the distinction has to survive to the end of the call — see the + // not-found conversion after withReadLock returns. + var presenceUndetermined bool + err := c.withReadLock(ctx, "GetNar", narJobKey(narURL.Hash), func() error { ctx = narURL. NewLogger(*zerolog.Ctx(ctx)). @@ -1320,7 +1402,12 @@ func (c *Cache) GetNar(ctx context.Context, narURL nar.URL) (nar.URL, int64, io. // repeat the HasNarInStore stat and nar_file lookup already done here. hasNar, finished, err := c.narServability(ctx, narURL) if err != nil { - return err + if !errors.Is(err, ErrStatTimeout) { + return err + } + + presenceUndetermined = true + hasNar, finished = false, false } // When a local download job is already active, prefer the faster temp-file @@ -1368,6 +1455,16 @@ func (c *Cache) GetNar(ctx context.Context, narURL nar.URL) (nar.URL, int64, io. // If so, we return ErrNotFound immediately to let the client know we don't have it locally, // triggering the PUT (push) operation. if IsUploadOnly(ctx) { + // A stalled probe is not a miss. Returning ErrNotFound here would tell the + // client "we do not have it, please PUT it"; if the NAR is in fact present + // the client skips the upload and leaves a phantom whose later reference + // check 404s. Surface a retryable error instead so the client retries. + if presenceUndetermined { + metricAttrs = append(metricAttrs, attribute.String("result", "undetermined")) + + return fmt.Errorf("cannot confirm nar absence for upload: %w", ErrStatTimeout) + } + metricAttrs = append(metricAttrs, attribute.String("result", "miss")) return storage.ErrNotFound @@ -1696,6 +1793,19 @@ func (c *Cache) GetNar(ctx context.Context, narURL nar.URL) (nar.URL, int64, io. return nil }) + + // Never report "not found" off the back of a probe we never got an answer from. + // Presence was undetermined and upstream recovery could not produce the NAR + // either, so absence was never established — the NAR may be sitting in the store + // behind a stalled stat. The server maps storage.ErrNotFound to 404, and a 404 + // here would tell a client to stop looking (and, for `nix copy`, to skip the + // upload and leave a phantom). Surface the undetermined error so the client + // retries instead. + if err != nil && presenceUndetermined && + (errors.Is(err, storage.ErrNotFound) || errors.Is(err, upstream.ErrNotFound)) { + err = fmt.Errorf("cannot confirm nar absence: %w", ErrStatTimeout) + } + if err != nil { return narURL, 0, nil, err } @@ -4802,7 +4912,27 @@ func (c *Cache) isServable(ctx context.Context, narURL nar.URL) (bool, error) { // by a failed download) is a cache miss that must trigger an upstream (re-)download, // never a terminal 404. func (c *Cache) narServability(ctx context.Context, narURL nar.URL) (servable, finished bool, err error) { - if c.HasNarInStore(ctx, narURL) { + // Use statNarInStore, not HasNarInStore: the latter collapses an undeterminable + // probe into "absent", which would let a *stalled* storage probe masquerade as a + // confirmed cache miss. Callers distinguish the two — see GetNar's handling of + // ErrStatTimeout, which must never become a 404. + present, statErr := c.statNarInStore(ctx, narURL) + if statErr != nil { + // Only a timed-out probe is genuinely undeterminable and must be surfaced: + // HasNarInStore would collapse it into "absent", letting a stalled probe + // masquerade as a confirmed cache miss (and, in upload-only mode, as a 404 + // that creates a phantom NAR). Every other stat error keeps its historical + // treatment — fall through as not-in-store — because those are deterministic + // answers (e.g. a malformed nar URL that can never name a stored object) + // rather than storage ambiguity. Revisiting them is out of scope here. + if errors.Is(statErr, ErrStatTimeout) { + return false, false, fmt.Errorf("could not determine nar presence in store: %w", statErr) + } + + present = false + } + + if present { return true, true, nil } @@ -4940,7 +5070,7 @@ func (c *Cache) statNarInStore(ctx context.Context, narURL nar.URL) (bool, error candURL := narURL candURL.Compression = comp - present, err := c.narStore.StatNar(ctx, candURL) + present, err := c.boundedStatNar(ctx, candURL) if err != nil { return false, err } @@ -4951,7 +5081,201 @@ func (c *Cache) statNarInStore(ctx context.Context, narURL nar.URL) (bool, error } } - return c.narStore.StatNar(ctx, narURL) + return c.boundedStatNar(ctx, narURL) +} + +// maxInFlightStatProbes caps how many storage presence probes may be running at +// once, counting those a request has already abandoned and which are still +// blocked inside the backend. +// +// A healthy probe returns in milliseconds (8-300ms observed on both backends), so +// under normal load this count stays near zero no matter how many NAR requests are +// in flight — only *stalled* probes accumulate. The cap therefore bounds the cost +// of a storage brown-out without constraining healthy concurrency. It matters +// because a probe abandoned on the local backend is blocked in an uncancellable +// fstatat(2), pinning an OS thread until the kernel returns. +const maxInFlightStatProbes = 256 + +// statBudgetKey carries a per-request deadline for the CUMULATIVE time spent on +// storage presence probes. +type statBudgetKey struct{} + +// withStatBudget starts a per-request probe budget if one is not already running. +// +// Bounding each probe individually is not enough: a single GetNar consults the +// store several times (the pre-check, the servability lookup, and again after +// coordination), so N stalled probes cost N x statTimeout. Measured at 4x the +// configured bound before this budget existed, which at a 15s setting would put a +// request back over a 60s proxy timeout — the very failure this change fixes. +// +// The budget is deliberately scoped to probes only. It must not bound the download +// itself: a large NAR legitimately takes far longer than any probe should. +func withStatBudget(ctx context.Context, d time.Duration) context.Context { + if d <= 0 { + return ctx + } + + if _, ok := ctx.Value(statBudgetKey{}).(time.Time); ok { + return ctx + } + + return context.WithValue(ctx, statBudgetKey{}, time.Now().Add(d)) +} + +// statBudgetRemaining returns how much of the request's probe budget is left, +// clamped to fallback. Without a budget on the context it returns fallback, so a +// caller outside the NAR read path keeps the plain per-probe bound. +func statBudgetRemaining(ctx context.Context, fallback time.Duration) time.Duration { + deadline, ok := ctx.Value(statBudgetKey{}).(time.Time) + if !ok { + return fallback + } + + remaining := time.Until(deadline) + if remaining > fallback { + return fallback + } + + return remaining +} + +// statProbeResult carries a presence probe's outcome back from its goroutine. +type statProbeResult struct { + present bool + err error +} + +// boundedStatNar runs a storage presence probe under the configured bound. +// +// The probe runs on its own goroutine because it cannot be relied upon to observe +// context cancellation: the local backend's StatNar bottoms out in os.Stat -> +// fstatat(2), which takes no context and cannot be aborted from userspace. On a +// hard NFS mount a single such call was measured blocking ~57s, long enough for a +// reverse proxy to abort the response mid-body and hand the client a 200 with a +// truncated body. A deadline therefore cannot *cancel* the local probe; it can +// only stop the request from *waiting* on it. +// +// The deadline is still propagated into the context handed to the backend, so a +// context-aware backend (S3) genuinely cancels its request rather than merely +// being abandoned. +// +// A bound that expires yields ErrStatTimeout — undeterminable, never a confirmed +// absence. See the storage.NarStore.StatNar contract. +func (c *Cache) boundedStatNar(ctx context.Context, narURL nar.URL) (bool, error) { + configured := c.getStatTimeout() + if configured <= 0 { + // The bound is disabled: preserve the historical unbounded behaviour. + return c.narStore.StatNar(ctx, narURL) + } + + // Spend from the request's cumulative probe budget, not a fresh per-probe one, + // so several stalled probes in one request cannot sum past the bound. + timeout := statBudgetRemaining(ctx, configured) + if timeout <= 0 { + storageStatTimeoutTotal.Add(ctx, 1, + metric.WithAttributes(attribute.String("reason", "budget_exhausted"))) + + return false, fmt.Errorf("%w: request probe budget exhausted", ErrStatTimeout) + } + + // Collapse concurrent probes for the same object onto one backend call. The + // shared call is deliberately detached from any single caller's context: one + // request walking away must not cancel a probe the others are still waiting on. + // It stays bounded by its own deadline, which is what a context-aware backend + // (S3) uses to cancel for real. + resCh := c.statProbeGroup.DoChan(narURL.String(), func() (any, error) { + if !c.acquireStatProbeSlot() { + return nil, fmt.Errorf("%w: %d probes already in flight", + ErrStatTimeout, maxInFlightStatProbes) + } + defer c.releaseStatProbeSlot() + + probeCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), timeout) + defer cancel() + + probeStart := time.Now() + + present, err := c.narStore.StatNar(probeCtx, narURL) + + storageStatDuration.Record(probeCtx, time.Since(probeStart).Seconds()) + + return statProbeResult{present: present, err: err}, nil + }) + + timer := time.NewTimer(timeout) + defer timer.Stop() + + start := time.Now() + + select { + case shared := <-resCh: + if shared.Err != nil { + if errors.Is(shared.Err, ErrStatTimeout) { + storageStatTimeoutTotal.Add(ctx, 1, + metric.WithAttributes(attribute.String("reason", "capacity"))) + + zerolog.Ctx(ctx).Warn(). + Str("nar_url", narURL.String()). + Int("in_flight", maxInFlightStatProbes). + Msg("storage presence probes saturated; reporting presence as undetermined") + } + + return false, shared.Err + } + + res, ok := shared.Val.(statProbeResult) + if !ok { + return false, fmt.Errorf("%w: unexpected probe result type", ErrStatTimeout) + } + + return res.present, res.err + case <-ctx.Done(): + // The caller went away: report that rather than a probe timeout. + return false, ctx.Err() + case <-timer.C: + elapsed := time.Since(start) + + storageStatTimeoutTotal.Add(ctx, 1, + metric.WithAttributes(attribute.String("reason", "deadline"))) + + trace.SpanFromContext(ctx).AddEvent("storage.stat.timeout", trace.WithAttributes( + attribute.String("nar_url", narURL.String()), + attribute.Float64("elapsed_seconds", elapsed.Seconds()), + )) + + zerolog.Ctx(ctx).Warn(). + Str("nar_url", narURL.String()). + Dur("elapsed", elapsed). + Dur("timeout", timeout). + Msg("storage presence probe timed out; presence undetermined") + + return false, fmt.Errorf("%w after %s", ErrStatTimeout, elapsed) + } +} + +// acquireStatProbeSlot reserves one of the maxInFlightStatProbes slots, returning +// false when they are exhausted so the caller fails fast instead of parking +// another goroutine (and, on the local backend, another OS thread). +func (c *Cache) acquireStatProbeSlot() bool { + for { + cur := c.inFlightStatProbes.Load() + if cur >= maxInFlightStatProbes { + return false + } + + if c.inFlightStatProbes.CompareAndSwap(cur, cur+1) { + storageStatInFlight.Add(context.Background(), 1) + + return true + } + } +} + +// releaseStatProbeSlot returns a slot once the backend finally answers, however +// long after the request gave up waiting for it. +func (c *Cache) releaseStatProbeSlot() { + c.inFlightStatProbes.Add(-1) + storageStatInFlight.Add(context.Background(), -1) } func (c *Cache) signNarInfo(ctx context.Context, hash string, narInfo *narinfo.NarInfo) error { @@ -8958,6 +9282,33 @@ func (c *Cache) streamChunksWithPrefetch(ctx context.Context, w io.Writer, chunk // chunk surfaces as a retryable error rather than a gateway 504. const defaultChunkWaitTimeout = 30 * time.Second +// defaultStatTimeout is the default bound on how long the NAR read path waits on +// a storage presence probe before treating the result as undeterminable. +// +// It sits an order of magnitude above a healthy probe (8-300ms observed against +// both the local and S3 backends) and an order of magnitude below the 60s read +// timeout of a typical reverse proxy, so it fires only on genuine pathology — +// while still resolving the request long before an intermediary would abort it +// mid-body and hand the client a truncated success. +const defaultStatTimeout = 5 * time.Second + +// SetStatTimeout overrides the bound on storage presence probes used by the NAR +// read path. A non-positive value disables the bound, restoring unbounded waiting +// (the pre-change behaviour, kept as a rollback escape hatch). +func (c *Cache) SetStatTimeout(d time.Duration) { + c.statMu.Lock() + c.statTimeout = d + c.statMu.Unlock() +} + +// getStatTimeout returns the currently configured presence-probe bound. +func (c *Cache) getStatTimeout() time.Duration { + c.statMu.RLock() + defer c.statMu.RUnlock() + + return c.statTimeout +} + // SetChunkWaitTimeout overrides the per-chunk wait bound used by progressive CDC // streaming. A non-positive value resets it to defaultChunkWaitTimeout. Operators // on high-latency storage can raise it; those behind a short gateway timeout can diff --git a/pkg/cache/nar_stat_timeout_internal_test.go b/pkg/cache/nar_stat_timeout_internal_test.go new file mode 100644 index 000000000..2de838a1e --- /dev/null +++ b/pkg/cache/nar_stat_timeout_internal_test.go @@ -0,0 +1,714 @@ +package cache + +import ( + "bytes" + "context" + "io" + "strings" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/kalbasit/ncps/pkg/nar" + "github.com/kalbasit/ncps/pkg/storage" + "github.com/kalbasit/ncps/pkg/storage/local" + "github.com/kalbasit/ncps/testdata" +) + +// slowStatStore wraps a NarStore and delays StatNar, modelling a storage backend +// whose presence probe is slow. +// +// ignoreCtx models the local backend: os.Stat bottoms out in fstatat(2), which +// takes no context and cannot be aborted from userspace, so the delay is served +// with an uninterruptible sleep. With ignoreCtx false it models the S3 backend, +// whose StatObject does observe context cancellation. +type slowStatStore struct { + storage.NarStore + + delay time.Duration + ignoreCtx bool + statCalls atomic.Int64 +} + +func (s *slowStatStore) StatNar(ctx context.Context, narURL nar.URL) (bool, error) { + s.statCalls.Add(1) + + if s.ignoreCtx { + time.Sleep(s.delay) + + return s.NarStore.StatNar(ctx, narURL) + } + + select { + case <-time.After(s.delay): + return s.NarStore.StatNar(ctx, narURL) + case <-ctx.Done(): + return false, ctx.Err() + } +} + +func (s *slowStatStore) HasNar(ctx context.Context, narURL nar.URL) bool { + present, _ := s.StatNar(ctx, narURL) + + return present +} + +// TestSlowStatStoreBlocksAsConfigured verifies the test double itself (task 1.1): +// it must actually block for the configured delay, and must honour context +// cancellation only when it is not modelling the uncancellable local backend. +func TestSlowStatStoreBlocksAsConfigured(t *testing.T) { + t.Parallel() + + t.Run("blocks for the configured delay", func(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 200 * time.Millisecond} + }) + + store, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + start := time.Now() + _, err := store.StatNar(newContext(), nar.URL{Hash: testdata.Nar1.NarHash}) + require.NoError(t, err) + + assert.GreaterOrEqual(t, time.Since(start), 200*time.Millisecond) + assert.Equal(t, int64(1), store.statCalls.Load()) + }) + + t.Run("context-aware double unblocks on cancellation", func(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 30 * time.Second} + }) + + store, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + ctx, cancel := context.WithTimeout(newContext(), 100*time.Millisecond) + defer cancel() + + start := time.Now() + _, err := store.StatNar(ctx, nar.URL{Hash: testdata.Nar1.NarHash}) + + require.Error(t, err) + assert.Less(t, time.Since(start), 5*time.Second) + }) + + t.Run("uncancellable double ignores cancellation", func(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 300 * time.Millisecond, ignoreCtx: true} + }) + + store, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + ctx, cancel := context.WithTimeout(newContext(), 10*time.Millisecond) + defer cancel() + + start := time.Now() + _, _ = store.StatNar(ctx, nar.URL{Hash: testdata.Nar1.NarHash}) + + // The sleep is not interruptible, so it runs to completion despite the + // cancelled context. This is the property that makes the local backend + // impossible to cancel and forces the request to abandon it instead. + assert.GreaterOrEqual(t, time.Since(start), 300*time.Millisecond) + }) +} + +// TestGetNarBoundedTimeToFirstByte is the regression test for the production +// stall: GetNar MUST resolve within the configured stat timeout even when the +// storage presence probe blocks for far longer and cannot be cancelled. +// +// Evidence this reproduces: a goroutine dump taken against ncps v0.10.0-rc17 +// caught a request parked in a single uncancellable fstatat(2) for ~57s inside +// statNarInStore, while the ingress aborted the stream at its 60s read timeout +// and delivered the client a 200 with a truncated body. +func TestGetNarBoundedTimeToFirstByte(t *testing.T) { + t.Parallel() + + const ( + statTimeout = 250 * time.Millisecond + probeDelay = 30 * time.Second + budget = 10 * time.Second + ) + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: probeDelay, ignoreCtx: true} + }) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + + // Put the NAR through the underlying store directly so the write is not + // itself delayed by the slow probe. + inner, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + _, err := inner.PutNar( + newContext(), narURL, io.NopCloser(strings.NewReader(testdata.Nar1.NarText)), -1, + ) + require.NoError(t, err) + + c.SetStatTimeout(statTimeout) + + done := make(chan struct{}) + + var ( + getErr error + readErr error + rc io.ReadCloser + firstByte time.Duration + ) + + start := time.Now() + + go func() { + defer close(done) + + _, _, rc, getErr = c.GetNar(newContext(), narURL) + if getErr != nil || rc == nil { + return + } + + // Time to FIRST BYTE, not time for GetNar to return. GetNar hands back a + // reader, and that reader's first Read can block independently of the call + // returning — so timing only the return would let a response that stalls on + // its first read pass a test named for time-to-first-byte. + buf := make([]byte, 1) + _, readErr = io.ReadFull(rc, buf) + firstByte = time.Since(start) + }() + + select { + case <-done: + case <-time.After(budget): + t.Fatalf("GetNar did not resolve within %s while the storage probe blocked for %s: "+ + "a NAR request must have a bounded time-to-first-byte", budget, probeDelay) + } + + if rc != nil { + defer rc.Close() + } + + elapsed := time.Since(start) + t.Logf("GetNar resolved in %s (probe delay %s, stat timeout %s, err=%v)", + elapsed, probeDelay, statTimeout, getErr) + + assert.Less(t, elapsed, budget, + "GetNar must resolve well inside a reverse proxy read timeout") + + // Either bytes or a clean error is acceptable; a silent hang is not. + if getErr == nil { + require.NotNil(t, rc) + require.NoError(t, readErr, "the served body must be readable") + assert.Less(t, firstByte, budget, + "the FIRST BYTE must arrive within the budget, not merely the GetNar call returning") + + t.Logf("first byte arrived in %s", firstByte) + } +} + +// TestStatNarInStoreTimeoutIsIndeterminate asserts a timed-out presence probe is +// classified as undeterminable — (false, err) — and never as a confirmed absence +// — (false, nil). Reporting a stalled probe as absence would silently convert a +// slow read into a redundant re-download or a spurious 404. +func TestStatNarInStoreTimeoutIsIndeterminate(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 30 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(250 * time.Millisecond) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + + type result struct { + present bool + err error + } + + ch := make(chan result, 1) + + go func() { + present, err := c.statNarInStore(newContext(), narURL) + ch <- result{present, err} + }() + + select { + case got := <-ch: + assert.False(t, got.present, "a timed-out probe must not report presence") + require.Error(t, got.err, + "a timed-out probe must be undeterminable (false, err), never a confirmed absence (false, nil)") + require.ErrorIs(t, got.err, ErrStatTimeout) + case <-time.After(10 * time.Second): + t.Fatal("statNarInStore did not return within 10s; the probe bound is not applied") + } +} + +// TestStatNarInStoreFastProbeUnaffected pins the no-regression half: a healthy +// store must behave exactly as before, with no timeout error and no added latency. +func TestStatNarInStoreFastProbeUnaffected(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { return s }) + c.SetStatTimeout(5 * time.Second) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + + present, err := c.statNarInStore(newContext(), narURL) + require.NoError(t, err) + assert.False(t, present, "nothing was stored yet: this is a confirmed absence") + + require.NoError(t, c.PutNar(newContext(), narURL, io.NopCloser(strings.NewReader(testdata.Nar1.NarText)))) + + present, err = c.statNarInStore(newContext(), narURL) + require.NoError(t, err) + assert.True(t, present) +} + +// TestUploadOnlyIndeterminateIsNotNotFound is the guard against re-introducing the +// phantom-NAR bug (design.md D3). +// +// In upload-only mode GetNar returns storage.ErrNotFound to tell the client "we do +// not have it, please PUT it". If a *stalled* probe took that branch, `nix copy` +// would skip the NAR upload and leave a phantom whose later reference check 404s. +// An undeterminable probe must therefore surface a retryable error instead. +func TestUploadOnlyIndeterminateIsNotNotFound(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 30 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(250 * time.Millisecond) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + + // Store the bytes underneath the slow probe: the NAR really is present, so + // reporting "not found" here would be actively wrong as well as harmful. + inner, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + _, err := inner.PutNar( + newContext(), narURL, io.NopCloser(strings.NewReader(testdata.Nar1.NarText)), -1, + ) + require.NoError(t, err) + + ch := make(chan error, 1) + + go func() { + _, _, rc, getErr := c.GetNar(WithUploadOnly(newContext()), narURL) + if rc != nil { + _ = rc.Close() + } + + ch <- getErr + }() + + select { + case getErr := <-ch: + require.NotErrorIs(t, getErr, storage.ErrNotFound, + "an undeterminable probe must not be reported as ErrNotFound in upload-only mode: "+ + "the client would skip the upload and leave a phantom NAR") + case <-time.After(10 * time.Second): + t.Fatal("GetNar did not resolve within 10s in upload-only mode") + } +} + +// TestStatProbeIsSingleFlighted asserts concurrent requests for the same NAR +// collapse onto one backend probe (design D2). Without this, a stalled NAR under +// a client retry storm costs one blocked goroutine — and on the local backend one +// pinned OS thread — per client. +func TestStatProbeIsSingleFlighted(t *testing.T) { + t.Parallel() + + const callers = 20 + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 2 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(200 * time.Millisecond) + + store, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + // A single explicit compression means statNarInStore probes exactly one key. + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: nar.CompressionTypeXz} + + var wg sync.WaitGroup + + for range callers { + wg.Add(1) + + go func() { + defer wg.Done() + + _, _ = c.statNarInStore(newContext(), narURL) + }() + } + + wg.Wait() + + got := store.statCalls.Load() + t.Logf("%d concurrent callers produced %d backend probe(s)", callers, got) + + assert.Less(t, got, int64(callers), + "concurrent probes for the same NAR must be collapsed, not issued per caller") + assert.LessOrEqual(t, got, int64(2), + "a single in-flight window should produce at most one shared probe") +} + +// ctxRecordingStore records what context the backend actually received, so the +// deadline-propagation contract can be asserted directly rather than inferred. +type ctxRecordingStore struct { + storage.NarStore + + delay time.Duration + sawDeadline atomic.Bool + sawCancel atomic.Bool + done chan struct{} +} + +func (s *ctxRecordingStore) StatNar(ctx context.Context, narURL nar.URL) (bool, error) { + if _, ok := ctx.Deadline(); ok { + s.sawDeadline.Store(true) + } + + defer close(s.done) + + select { + case <-time.After(s.delay): + return s.NarStore.StatNar(ctx, narURL) + case <-ctx.Done(): + s.sawCancel.Store(true) + + return false, ctx.Err() + } +} + +// TestStatProbeDeadlineReachesBackend asserts the probe bound is propagated into +// the context handed to the storage backend, so a context-aware backend (S3, +// whose StatObject takes a context) genuinely cancels its request instead of +// merely being abandoned. +// +// This is asserted against a recording double rather than a live S3 bucket on +// purpose: the property under test is that *ncps* supplies a cancellable, +// deadline-carrying context. Whether MinIO/Garage honours a cancelled context is +// their contract, not this codebase's, and asserting it would need live +// infrastructure to test something we do not control. +func TestStatProbeDeadlineReachesBackend(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &ctxRecordingStore{NarStore: s, delay: 30 * time.Second, done: make(chan struct{})} + }) + c.SetStatTimeout(200 * time.Millisecond) + + store, ok := c.narStore.(*ctxRecordingStore) + require.True(t, ok) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: nar.CompressionTypeXz} + + _, err := c.statNarInStore(newContext(), narURL) + require.ErrorIs(t, err, ErrStatTimeout) + + // The probe goroutine outlives the caller; wait for it to observe cancellation. + select { + case <-store.done: + case <-time.After(10 * time.Second): + t.Fatal("backend probe never returned after the deadline expired") + } + + assert.True(t, store.sawDeadline.Load(), + "the backend must receive a context carrying the probe deadline") + assert.True(t, store.sawCancel.Load(), + "a context-aware backend must be cancelled at the deadline, not merely abandoned") +} + +// TestStalledProbeIsLogged asserts a stalled probe is not silent. +// +// Silence is itself the defect this change addresses: in production a request +// spent ~57s inside one storage probe and emitted no log line, span or metric +// for the entire stall, which is why the cause took so long to find. A healthy +// probe must stay quiet, so the signal means something. +func TestStalledProbeIsLogged(t *testing.T) { + t.Parallel() + + newLoggingCtx := func(buf *bytes.Buffer) context.Context { + return zerolog.New(buf).With().Logger().WithContext(context.Background()) + } + + t.Run("timed-out probe emits a warning naming the NAR and elapsed time", func(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 30 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(200 * time.Millisecond) + + var buf bytes.Buffer + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: nar.CompressionTypeXz} + + _, err := c.statNarInStore(newLoggingCtx(&buf), narURL) + require.ErrorIs(t, err, ErrStatTimeout) + + logged := buf.String() + assert.Contains(t, logged, "storage presence probe timed out") + assert.Contains(t, logged, testdata.Nar1.NarHash, "the log must name the NAR") + assert.Contains(t, logged, `"elapsed"`, "the log must report how long it waited") + assert.Contains(t, logged, `"warn"`) + }) + + t.Run("fast probe stays silent", func(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { return s }) + c.SetStatTimeout(5 * time.Second) + + var buf bytes.Buffer + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: nar.CompressionTypeXz} + + _, err := c.statNarInStore(newLoggingCtx(&buf), narURL) + require.NoError(t, err) + + assert.NotContains(t, buf.String(), "storage presence probe timed out", + "a healthy probe must not emit a timeout warning") + }) +} + +// TestTimeoutIsNotReportedAsNotFound covers the non-upload-only half of the +// "a timed-out probe is not an absence" requirement: the ordinary read path must +// not turn a stalled probe into a 404 either. The server maps storage.ErrNotFound +// to 404, so surfacing it here would tell a client the NAR does not exist when in +// fact it was never checked. +func TestTimeoutIsNotReportedAsNotFound(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 30 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(250 * time.Millisecond) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + + inner, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + _, err := inner.PutNar( + newContext(), narURL, io.NopCloser(strings.NewReader(testdata.Nar1.NarText)), -1, + ) + require.NoError(t, err) + + ch := make(chan error, 1) + + go func() { + _, _, rc, getErr := c.GetNar(newContext(), narURL) + if rc != nil { + _ = rc.Close() + } + + ch <- getErr + }() + + select { + case getErr := <-ch: + require.NotErrorIs(t, getErr, storage.ErrNotFound, + "a stalled probe must never surface as a 404: the NAR was not checked, not absent") + case <-time.After(10 * time.Second): + t.Fatal("GetNar did not resolve within 10s") + } +} + +// TestRequestProbeBudgetIsCumulative pins the request-level bound. +// +// Bounding each probe individually is not sufficient. A single GetNar consults the +// store several times — the pre-check, the servability lookup, and again after +// download coordination — so N stalled probes cost N x statTimeout unless they +// share one budget. Measured at 4.0x the configured bound before the budget +// existed; at a 15s setting that would put a request back over a 60s proxy read +// timeout, reintroducing the exact production failure this change fixes. +func TestRequestProbeBudgetIsCumulative(t *testing.T) { + t.Parallel() + + const statTimeout = 300 * time.Millisecond + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &slowStatStore{NarStore: s, delay: 60 * time.Second, ignoreCtx: true} + }) + c.SetStatTimeout(statTimeout) + + inner, ok := c.narStore.(*slowStatStore) + require.True(t, ok) + + // Compression:none makes statNarInStore consider several candidate URLs, and + // GetNar consults the store more than once, so this is the worst case. + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: nar.CompressionTypeNone} + + _, err := inner.PutNar( + newContext(), narURL, io.NopCloser(strings.NewReader(testdata.Nar1.NarText)), -1, + ) + require.NoError(t, err) + + done := make(chan struct{}) + start := time.Now() + + go func() { + defer close(done) + + _, _, rc, _ := c.GetNar(newContext(), narURL) + if rc != nil { + _ = rc.Close() + } + }() + + select { + case <-done: + case <-time.After(30 * time.Second): + t.Fatal("GetNar never returned") + } + + elapsed := time.Since(start) + t.Logf("GetNar spent %v against a %v cumulative budget (%.1fx)", + elapsed, statTimeout, float64(elapsed)/float64(statTimeout)) + + // Generous slack for scheduling, but far below the 2x that would prove the + // budget is per-probe rather than per-request. + assert.Less(t, elapsed, 2*statTimeout, + "a request must not accumulate multiple full probe timeouts") +} + +// TestServedNarFirstByteIsPrompt exercises the first-byte path that +// TestGetNarBoundedTimeToFirstByte cannot reach. +// +// When the probe times out, GetNar returns an error and there is no reader, so +// the first-byte assertion there is dormant. This test serves a NAR for real and +// times the first Read, so "time to first byte" is measured against actual bytes +// rather than against GetNar merely returning. +// +// Scope note: this bounds the presence probe, which is what the change addresses. +// A reader that stalls mid-body for some other reason (slow storage reads rather +// than a slow presence probe) is a different source of latency and is deliberately +// not claimed to be covered here. +func TestServedNarFirstByteIsPrompt(t *testing.T) { + t.Parallel() + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { return s }) + c.SetStatTimeout(5 * time.Second) + + narURL := nar.URL{Hash: testdata.Nar1.NarHash, Compression: testdata.Nar1.NarCompression} + require.NoError(t, c.PutNar(newContext(), narURL, + io.NopCloser(strings.NewReader(testdata.Nar1.NarText)))) + + start := time.Now() + + _, _, rc, err := c.GetNar(newContext(), narURL) + require.NoError(t, err) + require.NotNil(t, rc) + + defer rc.Close() + + buf := make([]byte, 1) + _, err = io.ReadFull(rc, buf) + require.NoError(t, err, "the first byte must be readable") + + firstByte := time.Since(start) + t.Logf("first byte of a served NAR arrived in %s", firstByte) + + assert.Less(t, firstByte, 5*time.Second, + "a NAR present in storage must yield its first byte promptly") + + rest, err := io.ReadAll(rc) + require.NoError(t, err) + assert.Equal(t, testdata.Nar1.NarText, string(buf)+string(rest), + "the served body must be intact, not merely prompt") +} + +// concurrencyTrackingStore records the high-water mark of probes blocked inside +// the backend at the same instant. +type concurrencyTrackingStore struct { + storage.NarStore + + delay time.Duration + inFlite atomic.Int64 + peak atomic.Int64 +} + +func (s *concurrencyTrackingStore) StatNar(ctx context.Context, narURL nar.URL) (bool, error) { + cur := s.inFlite.Add(1) + for { + peak := s.peak.Load() + if cur <= peak || s.peak.CompareAndSwap(peak, cur) { + break + } + } + + defer s.inFlite.Add(-1) + + time.Sleep(s.delay) // uncancellable, like os.Stat + + return s.NarStore.StatNar(ctx, narURL) +} + +func (s *concurrencyTrackingStore) HasNar(ctx context.Context, narURL nar.URL) bool { + present, _ := s.StatNar(ctx, narURL) + + return present +} + +// TestStatProbeCapBoundsUniqueKeyBurst covers the case single-flight does NOT +// help with: a burst of DISTINCT NAR hashes. +// +// Deduplication collapses concurrent probes for the *same* object, but a burst of +// unique keys is one probe each, and on the local backend every one of those is a +// blocked, uncancellable syscall holding an OS thread. maxInFlightStatProbes is +// what bounds that, and this test is what proves the bound holds — without it the +// cap was an untested assertion. +func TestStatProbeCapBoundsUniqueKeyBurst(t *testing.T) { + t.Parallel() + + const burst = maxInFlightStatProbes + 64 + + c := newServableTestCache(t, func(s *local.Store) storage.NarStore { + return &concurrencyTrackingStore{NarStore: s, delay: 2 * time.Second} + }) + c.SetStatTimeout(200 * time.Millisecond) + + store, ok := c.narStore.(*concurrencyTrackingStore) + require.True(t, ok) + + var wg sync.WaitGroup + + for i := range burst { + wg.Add(1) + + go func(i int) { + defer wg.Done() + + // Distinct hashes: single-flight cannot collapse these. + hash := testdata.Nar1.NarHash[:len(testdata.Nar1.NarHash)-3] + + string(rune('a'+i%26)) + string(rune('a'+(i/26)%26)) + string(rune('a'+(i/676)%26)) + + _, _ = c.statNarInStore(newContext(), + nar.URL{Hash: hash, Compression: nar.CompressionTypeXz}) + }(i) + } + + wg.Wait() + + peak := store.peak.Load() + t.Logf("%d unique-key probes produced a peak of %d concurrently blocked backend probes (cap %d)", + burst, peak, maxInFlightStatProbes) + + assert.LessOrEqual(t, peak, int64(maxInFlightStatProbes), + "concurrently blocked backend probes must never exceed the cap") +} diff --git a/pkg/ncps/metrics_prime_test.go b/pkg/ncps/metrics_prime_test.go index 7b948350f..33d236038 100644 --- a/pkg/ncps/metrics_prime_test.go +++ b/pkg/ncps/metrics_prime_test.go @@ -69,6 +69,7 @@ func TestPrimedCountersExposedAtZero(t *testing.T) { "ncps_lru_bytes_freed_total", "ncps_background_migration_objects_total", "ncps_download_coordination_fallback_total", + "ncps_storage_stat_timeout_total", "ncps_lock_acquisitions_total", "ncps_lock_failures_total", "ncps_lock_retry_attempts_total", diff --git a/pkg/ncps/serve.go b/pkg/ncps/serve.go index 8cca2fc88..b3942df1c 100644 --- a/pkg/ncps/serve.go +++ b/pkg/ncps/serve.go @@ -452,6 +452,16 @@ func serveCommand( Sources: flagSources("cache.cdc.chunk-wait-timeout", "CACHE_CDC_CHUNK_WAIT_TIMEOUT"), Value: 30 * time.Second, }, + &cli.DurationFlag{ + Name: "cache-storage-stat-timeout", + Usage: "Max time the NAR read path waits on a storage presence probe before treating " + + "presence as undetermined. Keep it below your reverse-proxy read timeout: on a hard " + + "NFS mount a single uncancellable stat has been measured blocking ~57s, long enough " + + "for the proxy to abort the response mid-body and hand the client a truncated 200. " + + "Set to 0 to disable the bound and restore unbounded waiting.", + Sources: flagSources("cache.storage.stat-timeout", "CACHE_STORAGE_STAT_TIMEOUT"), + Value: 5 * time.Second, + }, // In-flight NAR staging flags (change serve-whole-nar-in-flight). &cli.BoolFlag{ Name: "cache-inflight-staging-enabled", @@ -1248,6 +1258,8 @@ func createCache( c.SetChunkWaitTimeout(cmd.Duration("cache-cdc-chunk-wait-timeout")) + c.SetStatTimeout(cmd.Duration("cache-storage-stat-timeout")) + // Configure lazy chunking cdcLazyChunkingEnabled := cmd.Bool("cache-cdc-lazy-chunking-enabled")