Add temporary timing diagnostics for slow requests and the access-log import job

This commit is contained in:
marvin
2026-09-19 23:24:19 -04:00
parent bf524e5835
commit 40a68b3b96
5 changed files with 38 additions and 4 deletions
+2
View File
@@ -214,3 +214,5 @@ Roughly in priority order:
`v0.16.42` finds and fixes the real, dominant cause of the site-wide slowness reported after v0.16.41: a live Network-tab capture from the user's own browser showed a flood of requests to `/api/logs/prune/preview`, some queued for over 15 seconds, with unrelated requests (`/api/dashboard`, `/api/system/health`, `/api/system/security`, `/api/system/storage`) stuck at nearly identical multi-second times in the same batch -- the signature of one blocking operation stalling everything behind it, not several independently slow endpoints. Root cause: `renderRetentionPreview()`'s `setInterval(..., 2000)` polls that endpoint every 2 seconds forever, on every page of the app, not just Administration -> Logs & retention, because its "does the panel exist" guard checks a `<section>` that's written into `index.html` from page load and only ever CSS-hidden -- so the guard was always true, everywhere. There was also no protection against a new poll firing while a previous one was still in flight, so once the server answered slower than 2 seconds even once, requests piled up and never caught back up. Compounding it: `previewPruneEvents()` runs five synchronous SQLite COUNT queries, and one of them (`audit_events`) had no index at all -- a full table scan, every call -- and because this app's SQLite queries run synchronously, that scan doesn't just slow its own request, it blocks the entire Node process for every other request being served at that moment. Fixed on both sides: `renderRetentionPreview()` and the sibling `renderRetentionRunStatus()` (previously also running unconditionally every 500ms) now check that the retention panel is actually visible, not just present in the DOM, before doing any work, and an in-flight guard stops a new preview poll from starting until the last one has landed; `audit_events` now has the same `(instance_id, created_at)` index every sibling events table already had. Together these should remove the vast majority of the "8-10 seconds to load a simple page" behavior reported after v0.16.41 -- that fix (deduplicating certificate-inventory work) was real but minor by comparison to this one.
`v0.16.43` scopes page refreshes to the page actually being viewed, instead of every refresh across the entire app unconditionally re-fetching everything -- Hosted Sites, Proxy Hosts, Redirects, Streams, Access Lists, Groups, the full Dashboard snapshot, and Certificates -- regardless of which single page triggered it. This was confirmed directly from the user's own account of the behavior ("if I'm on Hosted Sites and click refresh, it appears the whole entire site refreshes") and traced to a single shared `refresh()` function that every action in the app called: creating or editing a hosted site or proxy, toggling one on or off, deleting an entry, saving gateway settings, and re-syncing the gateway all ran the identical 8-endpoint fetch no matter which page initiated it. `refresh()` and its endpoints are now built from one shared map (`REFRESH_ENDPOINTS`), and a new `refreshCurrentView()` fetches only the state keys a `VIEW_REFRESH_KEYS` table says the active view actually renders -- Hosted Sites now refetches just `sites`, Proxy Hosts just `proxies`, Streaming just `streams`, Redirects just `redirects`, Access Lists just `accessLists` and `groups`. Every action listed above that's only ever reachable from one specific view (creating/editing/toggling/deleting a hosted site or proxy) now calls `refreshCurrentView()` instead of the full `refresh()`. Overview keeps the full, unscoped fetch deliberately: its attention list and the sidebar's per-section counts summarize the whole gateway, not one section of it, so scoping it would defeat the page's purpose; the initial page load (`boot()`) and the gateway re-sync button (only reachable from Overview) are unchanged for the same reason. A new generic refresh button (the same "↻" icon `refresh-health` already used) now appears on every page except Logs (which keeps its own dedicated "Refresh logs" button) so every view has an explicit, page-scoped way to pull fresh data without a full browser reload -- previously several views (Hosted, Proxy Hosts, Streaming, Redirects, Access Lists) had no refresh control of their own at all and only ever picked up new data from the page's initial load or the next full-page reload. One deliberate trade-off: sidebar badge counts for sections other than the one currently being viewed are not part of a scoped refresh and can go briefly stale until the next full refresh (a fresh page load, or a visit to Overview) -- intentional, since fetching data a page doesn't display was the entire problem being fixed here.
`v0.16.44` is a temporary, diagnostic-only release -- no behavior changes, just logging -- added after v0.16.43 (which fixed the app from over-fetching per page) didn't resolve the user's reported 6-14 second page loads. A Network-tab Timing capture the user sent for a single `GET /api/sites` request showed DNS and TCP connection at 0-7ms but "Waiting" (time to first byte) at 7485ms -- almost the entire delay happened server-side, before the app sent back a single byte of what should be a near-instant, in-memory list. Since this codebase's database and JS execution is single-threaded, that pattern (a trivially cheap request taking seconds) points to something else blocking the whole process at that moment, not a cost specific to any one endpoint. The leading suspect: `importAccessLogsToSqlite()`, a job that runs every 30 seconds, reads Caddy's access-log files, JSON-parses and hashes up to 5000 lines, and batch-inserts them -- all synchronous work with nothing to yield the event loop partway through. Rather than ship a fourth guess-based fix, this release adds two pieces of logging visible in the container's own logs: a warning whenever that import job takes over 500ms (broken down into read/hash/insert time), and a warning whenever any request takes over 1 second to answer. The next slow page load should show, in the logs, either the import job's duration lining up with the slow request's timestamp (confirming the suspect) or a different pattern entirely (pointing somewhere else). Both log lines are marked as temporary instrumentation, intended to be removed once the real cause is confirmed and fixed.