diff --git a/docs/index.md b/docs/index.md index f5ca7cdb..4d629c39 100644 --- a/docs/index.md +++ b/docs/index.md @@ -44,7 +44,7 @@ https://docs.autopilotmonitor.com (separate repository). # Web Portal -* [Portal Navigation Prefetch & the SWA Runtime Bottleneck](web/portal-navigation-prefetch.md) - Why every navigation Link sets `prefetch={false}`: the App Router's viewport prefetch fans out one RSC request per visible link against an HTTP/1.1 Static Web Apps runtime, and its latency tail starves the six connections that also serve the document and the route chunks. Includes where browser telemetry actually lives. +* [Portal Navigation Prefetch & the SWA Runtime Bottleneck](web/portal-navigation-prefetch.md) - Why every navigation Link sets `prefetch={false}`: the App Router's viewport prefetch fans out one RSC request per visible link and the Static Web Apps SSR runtime queues them server-side into a multi-minute tail. Records the follow-up measurement (the Standard plan changed nothing; the prefetch storm was an accidental keep-alive), where browser telemetry actually lives, and why this curl build cannot be trusted for HTTP versions. # Security & Identity diff --git a/docs/log.md b/docs/log.md index fc9cc07c..df3e283d 100644 --- a/docs/log.md +++ b/docs/log.md @@ -6,9 +6,11 @@ * **Creation**: Added `agent/gather-rule-debug-log.md` — the new per-tenant setting `EnableGatherRuleDebugLog` (ConfigVersion 35 → 36, portal toggle under Settings → Agent, `EnableImeMatchLog`-style bool→path projection in `RemoteConfigMerger`). When enabled, the agent writes `%ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log`: one pipe-delimited line per evaluation decision across ten previously silent "produced nothing" exits — disabled rules, `interval` without `intervalSeconds` (never runs), the first-tick-after-one-full-interval window, phase-scope skips incl. `currentPhase=Unknown`, per-(rule, phase) dedup, empty collector results (`emitOnlyIfExists`), `on_change` hash suppression (hash prefix + streak), guard blocks, logparser per-file outcomes (position skips, parse failures with a `format=text` hint when every line fails CMTrace parsing, `maxLines`/wildcard caps), and full exception stacks that the agent log drops. 10 MB cap + one `.old` generation; no hot-reload (per-enrollment lifecycle); flag survives the offline config cache; `--run-gather-rules` always traces and echoes under `--console`; zero-rules delivery leaves a one-line file instead of nothing. Side fix: `GatherRuleExecutorHost` now passes the logger into `InformationalEventPost`, so gather-event emissions appear in the agent DEBUG log. +* **Correction + Update**: `web/portal-navigation-prefetch.md`. The HTTP/1.1 claim in the 2026-07-27 entry below is **wrong** and has been struck from the document: `portal.autopilotmonitor.com` negotiates **h2**, verified by `openssl s_client -alpn h2,http/1.1` and a .NET `HttpClient` returning `HTTP/2.0`. The false reading came from the Windows/Schannel curl build in this environment, which has no HTTP/2 support and therefore always reports `1.1` — do not use it to determine HTTP versions. There is no six-connection cap in play; the queue is server-side in the SWA SSR runtime, which does not change the fix or the evidence, only the mechanism. Added an `Outcome` section with 20 h of post-change telemetry: the Free → Standard plan change (16:02:44 UTC) produced **no measurable latency gain** once stratified by the gap to the previous request (p50 Free → Standard: `<10s` 85 → 95 ms, `5-30min` 429 → 441 ms; tail rates 1.64 %/0.374 % over 2 s/10 s vs 6 and 1 events at n = 258 against 4.2 and 1.0 expected; `browserTimings` Mann-Whitney z = −0.24, p = 0.81). The freezes were removed by `prefetch={false}` (16:34:13 UTC): worst `browserTimings.totalDuration` 225,277 → 4,856 ms. The prefetch storm was also an **accidental keep-alive** — requests under 10 s apart fell from 85 % to 46 %, and on the identical never-cacheable `/sessions/{id}` route the median rose 87 → 211 ms and p90 465 → 1,480 ms, with one 11,441 ms abandoned request (`resultCode 0`) after 517 minutes idle. Synthetic bursts warm the runtime and must not be used to benchmark this (round 1 p50 288 ms vs rounds 4–25 p50 113 ms). + ## 2026-07-27 -* **Creation**: Added `web/portal-navigation-prefetch.md` (and a `Web Portal` section to the index) — root cause of the minute-long portal freezes. `GlobalSidebar` and `Navbar` render the whole navigation on every page, so the App Router's default viewport prefetch issued one `?_rsc=` request per visible link against `portal.autopilotmonitor.com` (~10,400 in 14 days). That origin serves the document, the route chunks and the RSC payloads over **HTTP/1.1**, so the six-connection-per-origin cap applies; when the Static Web Apps managed runtime queued the prefetches (p50 91 ms, p95 896 ms, but max 234 s / 21 samples over 30 s), the in-flight prefetches held every socket and the navigation the user wanted could not get one. Measured on the 2026-07-27 17:25 CEST incident: `/admin/presence?_rsc=` 151 s, three siblings finishing within 340 ms of each other at ~37.5 s, all `200`, while the backend API answered in 1.6–2.2 s and `browserTimings` showed `networkDuration` 16 ms against `processingDuration` 225 s. Every navigation Link now sets `prefetch={false}` — these routes are client components behind `ProtectedRoute` that fetch their own data, so the prefetched RSC payload carried no benefit. The doc also records that browser telemetry lives in a **separate** App Insights resource (`AUTOPILOT_MONITOR_WEB_APPINSIGHTS_ID`) that the MCP `query_backend_logs` tool cannot reach, which is why the freezes left no trace in the backend logs. +* **Creation**: Added `web/portal-navigation-prefetch.md` (and a `Web Portal` section to the index) — root cause of the minute-long portal freezes. `GlobalSidebar` and `Navbar` render the whole navigation on every page, so the App Router's default viewport prefetch issued one `?_rsc=` request per visible link against `portal.autopilotmonitor.com` (~10,400 in 14 days). *(The original entry attributed the freeze to HTTP/1.1 and a six-connection-per-origin cap — see the 2026-07-28 correction; the queue is server-side.)* When the Static Web Apps managed runtime queued the prefetches (p50 91 ms, p95 896 ms, but max 234 s / 21 samples over 30 s), the navigation the user wanted was stuck behind that queue. Measured on the 2026-07-27 17:25 CEST incident: `/admin/presence?_rsc=` 151 s, three siblings finishing within 340 ms of each other at ~37.5 s, all `200`, while the backend API answered in 1.6–2.2 s and `browserTimings` showed `networkDuration` 16 ms against `processingDuration` 225 s. Every navigation Link now sets `prefetch={false}` — these routes are client components behind `ProtectedRoute` that fetch their own data, so the prefetched RSC payload carried no benefit. The doc also records that browser telemetry lives in a **separate** App Insights resource (`AUTOPILOT_MONITOR_WEB_APPINSIGHTS_ID`) that the MCP `query_backend_logs` tool cannot reach, which is why the freezes left no trace in the backend logs. * **Creation**: Added `backend/rule-regression-radar.md` — F3 regression radar (analyze rules only; gather rules wait for their per-batch stats dedup fix): per (tenant, rule) daily hit rate from `RuleStats`, firing only when the trailing 7-day window has ≥5 hit sessions and ≥20 evaluated sessions, the rate is ≥2× the prior 28-day baseline AND the Wilson 95 % intervals are disjoint (deterministic `MetricsMath` primitive with hand-computed test vectors). Suppressed for deleted rules, rules younger than baseline+window (`CreatedAt` grace), rules edited inside the window (`UpdatedAt`), empty baselines, and the `RuleRegressionRadarDisabled` app-setting kill switch. Alert episodes live as `ruleregression|{ruleId}` tracker rows (one bell + one `RuleFrequencyRegression` ops event per episode; numbers refreshed while active; re-armed under 1.5× baseline, on fire-stop, or by the 30-day tracker retention). On-fire dimension correlation over osBuild/model/agentVersion/imeVersion with the "correlated, not necessarily causal" wording contract. Surfaces: `regressions[]` in the rule-stats response (MCP inherits), the analyze-rules page's 30-day sparkline and regression badge. diff --git a/docs/web/portal-navigation-prefetch.md b/docs/web/portal-navigation-prefetch.md index c01fee6a..1f2e7d33 100644 --- a/docs/web/portal-navigation-prefetch.md +++ b/docs/web/portal-navigation-prefetch.md @@ -1,7 +1,7 @@ --- type: Concept title: Portal Navigation Prefetch & the SWA Runtime Bottleneck -description: Why every navigation Link in the portal sets prefetch={false} — the App Router's viewport prefetch fires one RSC request per visible link against an HTTP/1.1 Static Web Apps runtime, and its latency tail starves the connection pool that serves the document and the route chunks. +description: Why every navigation Link in the portal sets prefetch={false} — the App Router's viewport prefetch fires one RSC request per visible link, and the Static Web Apps SSR runtime queues them server-side into a multi-minute latency tail. Also records what the follow-up measurement showed about the Standard SKU and the keep-alive side effect. resource: src/Web/autopilot-monitor-web/components/GlobalSidebar.tsx tags: - web @@ -25,21 +25,26 @@ it enters the viewport. # Mechanism -Three properties combine into a portal-wide freeze: +Two properties combine into a portal-wide freeze: 1. **Fan-out.** The navigation is fully rendered on each page load, so a single navigation issues one RSC request per visible link — measured at ~10,400 requests over 14 days. -2. **Shared origin over HTTP/1.1.** `portal.autopilotmonitor.com` serves the document, the JS route - chunks *and* the RSC payloads, and it negotiates HTTP/1.1 — not HTTP/2. Browsers cap concurrent - connections per origin at six. -3. **A heavy latency tail on the SSR runtime.** RSC responses are prerendered and edge-cached +2. **A heavy latency tail on the SSR runtime.** RSC responses are prerendered and edge-cached (`x-nextjs-cache: HIT`, `s-maxage=31536000`), so the median is fast. On a cache miss or cold start - the Static Web Apps managed runtime queues them. + the Static Web Apps managed runtime queues them **server-side**, and the queue drains all at once. -When the tail hits, the in-flight prefetches hold all six connections. The document request and the -route chunks of the page the user actually wants then have no socket available, and the tab shows a -loading spinner or a blank page until the queue drains. Nothing fails — the requests eventually -return `200`, which is why the failure leaves no error trace anywhere. +The navigation the user wants is then stuck behind that queue and the tab shows a loading spinner or a +blank page until it drains. Nothing fails — the requests eventually return `200`, which is why the +failure leaves no error trace anywhere. + +> **Correction (2026-07-28).** The original version of this document named a third property: that +> `portal.autopilotmonitor.com` negotiates HTTP/1.1 and the prefetches exhaust the six-connection +> browser cap. **That is wrong.** It came from `curl -w '%{http_version}'` on a Windows build of curl +> whose Schannel backend has no HTTP/2 support, so it can only ever report `1.1`. ALPN says otherwise: +> `openssl s_client -alpn h2,http/1.1` negotiates **h2** on the portal host, confirmed by a .NET +> `HttpClient` request returning `HTTP/2.0`. There is no six-connection cap and connection starvation +> was never the mechanism — the queue is server-side. Verify HTTP versions with `openssl s_client +> -alpn` or `HttpClient`, never with this curl build. # Evidence @@ -62,6 +67,33 @@ document immediately and the browser then waited nearly four minutes for the `lo Fourteen-day distribution of RSC prefetches: n = 10,428, p50 = 91 ms, p95 = 896 ms, max = 234,230 ms, 38 over 10 s, 21 over 30 s. +# Outcome, measured 2026-07-28 + +Two changes landed within half an hour of each other on 2026-07-27: the SWA plan went Free → Standard +at 16:02:44 UTC, and `prefetch={false}` went live at 16:34:13 UTC. Twenty hours of production +telemetry separate their effects. + +**The Standard plan produced no measurable latency gain.** Latency is governed almost entirely by the +gap to the previous request — the SSR runtime cools down — so raw percentiles only measure the traffic +mix. Stratified by that gap, the two eras are indistinguishable (p50, Free → Standard): `<10s` +85 → 95 ms · `10-60s` 100 → 117 ms · `1-5min` 295 → 310 ms · `5-30min` 429 → 441 ms. Tail rates match +too: Free ran 1.64 % over 2 s and 0.374 % over 10 s (n = 10,163); Standard produced 6 and 1 events at +n = 258 against 4.2 and 1.0 expected. `browserTimings.totalDuration` by Mann-Whitney: n = 436 vs 48, +z = −0.24, **p = 0.81**. + +**The prefetch fix is what removed the freezes** — worst `browserTimings.totalDuration` fell from +225,277 ms to 4,856 ms, and the 30-second events stopped. + +**It also removed an accidental keep-alive.** The prefetch storm kept the SSR runtime warm: 85 % of +requests used to arrive less than 10 s apart, now 46 % do. On an identical never-cacheable route +(`/sessions/{id}`) the median rose from 87 ms to 211 ms and p90 from 465 ms to 1,480 ms. After 517 +minutes idle, one request took 11,441 ms and was abandoned (`resultCode 0`). The trade — minute-long +freezes gone, ~150 ms added to a cold navigation — is worth it, but it is a trade. + +Do not benchmark this with a synthetic burst. Firing requests in quick succession warms the runtime +and measures the best case: in a 25-round `curl --parallel-max 6` run, round 1 came in at p50 288 ms +and rounds 4–25 at p50 113 ms. + # Diagnosing this class of problem The backend Application Insights resource is the wrong place to look — a freeze appears there as an diff --git a/src/Web/autopilot-monitor-web/components/GlobalSidebar.tsx b/src/Web/autopilot-monitor-web/components/GlobalSidebar.tsx index fd61edb3..e10fc441 100644 --- a/src/Web/autopilot-monitor-web/components/GlobalSidebar.tsx +++ b/src/Web/autopilot-monitor-web/components/GlobalSidebar.tsx @@ -315,10 +315,9 @@ export function GlobalSidebar({ children }: { children: ReactNode }) { // Every nav Link below sets prefetch={false} on purpose. The sidebar renders the whole // navigation on every page, so the App Router's default viewport prefetch fires one RSC // request per visible link against the SWA-hosted Next.js runtime on each page load - // (measured: ~10k requests / 14 days). That host speaks HTTP/1.1, so those prefetches - // occupy the browser's 6 connections to the SAME origin that serves the document and the - // route chunks — when the runtime queues them (p95 ~0.9s but a tail reaching 150s+), the - // portal freezes until the queue drains. Every route here is a client component behind + // (measured: ~10k requests / 14 days). The SSR runtime queues that burst server-side and + // drains it all at once (p95 ~0.9s but a tail reaching 150s+), so the navigation the user + // actually wants is stuck behind it and the portal freezes. Every route here is a client component behind // ProtectedRoute that fetches its own data after mount, so the prefetched RSC payload // buys nothing. See docs/web/portal-navigation-prefetch.md. // --- Render a global nav link ---