Insert failures after the 204 are invisible: silent event loss on DB outage

Sub-tickets

Activity

• wi-cli-venus created · 6w ago
• wi-cli-venus audit-finding · 6w ago
  Cluster restart 2026-09-02 07:35:19.765-07:36:18 UTC (59s, real postgres-down, two attempts one window) did NOT exercise the failed-insert branch. Measured: rows 15068 -> 15068, max(ts)/max(receivedAt) unchanged at 03:32Z, zero rows with receivedAt >= 07:30Z, zero journal entries on the unit since 07:30Z. Nothing arrived, so nothing failed - INCONCLUSIVE, not a pass. Cause: traffic is not uniform. Events by UTC hour over 14d peak at 18:00 (582) and bottom at 06:00 (8) / 07:00 (13), about 0.9/hour at the restart hour vs ~42/hour at peak. The window was chosen as quiet for the cluster, which is the same property that made it useless as a test. Exercising this needs deliberate fault injection, not another restart. SECOND FINDING, real: server.mjs has no pool.on('error') handler (pg 8.22.0, default 10s idleTimeoutMillis). node-postgres Pool emits 'error' for idle clients killed server-side and an unlistened EventEmitter 'error' throws, so a postgres restart with a client inside that 10s idle window would take the process down as an uncaught exception rather than log the handled path. Survived this time only because the pool had been empty ~4h. Restart=always would mask it as a crash-recover.
• wi-cli-venus commit · 4w ago
  7c23f86 ElazarPimentel/telemetry-ingest. Detection, not a contract change - the 204 stays. Four axes: (1) /healthz is now a real query path (select 1 -> dbOk) returning 503 when not ok, replacing dbConfigured which answers only was-a-DSN-set-at-boot and reads true against a Postgres down for a week; (2) insert accounting exposed - insertBatchesOk/Failed, eventsInserted/Lost, poolErrors, lastFailureAt/Error, lastSuccessAt, pending, plus since=process-start so a zero is readable; (3) hourly telemetry-ingest-health.timer polls /healthz and DMs the hub - a counter nobody reads is the same green line as a log line nobody greps, and NOTHING on venus polled this port before; (4) pool.on(error) handler plus connectionTimeoutMillis 10s / query_timeout 30s - pg-pool ships no default for either (verified in the installed node_modules), so a HUNG database parked every 204-accepted batch in memory forever, an unbounded retry queue with no retry, and an idle-client backend error was an unhandled error event that killed the process with its in-flight batches. Also SIGTERM drain: every systemctl restart, including the one deploying this fix, dropped accepted-but-unwritten batches.
• wi-cli-venus verified · 4w ago
  FORCED-RED CONTROL, not a green line. Scratch instance on a verified-free port with DATABASE_URL=127.0.0.1:1 (ECONNREFUSED, throwaway token, no real credential, nothing written to disk): POST /v1/usage returned 204 (contract v1 intact) and GET /healthz returned HTTP 503 with insertBatchesFailed=1, eventsLost=1, dbOk=false, lastFailureError=connect ECONNREFUSED. Paired same-run green: production /healthz 200, dbOk=true. SIGTERM drain exercised - drained; ok=0 failed=1 lost=1, clean exit. First attempt at this control measured the WRONG SERVICE: port 9721 was already held by something that answers /healthz with a different payload, so the run reported ok:true from a process that was not mine (assert-presence-before-measuring-absence, again). Re-run after ss -ltn confirmed the port free. Hub alarm path exercised end to end: rollup-failnotify.sh hand-run delivered its DM, arriving tagged [hand-run, NOT systemd-invoked] as designed. COVERAGE LIMIT, stated: the SUCCESS accounting (insertBatchesOk/eventsInserted/lastSuccessAt) is still 0 - no real event has arrived since the 01:41 restart. That is the arrival pattern, not a regression: the table shows a 36-minute gap at 00:57->01:33 the same night, max(ts) predates the restart, and the scratch control already proved POST reaches insertBatch on this code. Unexercised, not verified.
• wi-cli-venus audit-finding · 4w ago
  FOUND WHILE WIRING THE READER: telemetry-webusage-rollup.service had NO OnFailure=. WEBUSAGE-4 gave rollup.sh a real alarm - exit 1 on zero events ingested in 24h, plus set -euo pipefail and ON_ERROR_STOP=1 on any SQL error - and every one of those exits would have marked the unit failed and told nobody. The same defect shape this WI is about (a signal produced and not routed), inside the fix for the previous WI, shipped four hours earlier. Closed in the same commit: OnFailure=telemetry-webusage-rollup-failnotify.service, body in rollup-failnotify.sh, sharing no code with rollup.sh (plain curl, no psql, no DSN) so a failure in the rollup's own dependencies cannot silence its own alarm. The health unit itself carries no OnFailure and that is stated in the unit file rather than implied away: its whole job is to send the alert, so watching it would be the same regress one level down - the independent backstop is rollup.sh's 24h fresh-arrival check on a different schedule and a different mechanism (SQL, not HTTP).
• wi-cli-venus completed · 4w ago
  Shipped 7c23f86, live on venus (telemetry-ingest.service restarted 01:41 UTC, telemetry-ingest-health.timer enabled, next 02:00:54 UTC). Answering the WI's three options explicitly: (a) surface failures beyond stderr - YES, done, counters on /healthz plus an hourly poller that DMs the hub, because a counter with no reader is the same invisible green line as the console.error it replaces and nothing on this host polled port 9720; (b) move the 204 after the write - NO, and deliberately: README contract v1 documents no retry and no client in the fleet implements one, so a synchronous 5xx trades silent loss for loud loss the caller has nowhere to put. The WI's own framing (detection first) is correct; (c) bounded in-memory retry - NOT ADDED, but the unbounded one that already existed is now closed. pg-pool ships no connectionTimeoutMillis or query_timeout default, so a hung database held every 204-accepted batch in memory indefinitely. Detection latency is now layered and each layer's blind spot is in the README table: /healthz counters see partial loss instantly but only when read; the hourly poller bounds a total outage at 1h and cannot see whether events are still ARRIVING; rollup.sh's 24h fresh-arrival check sees exactly that and nothing sub-24h. Two adjacent defects closed in the same commit: rollup.service had no OnFailure= (its WEBUSAGE-4 alarm reached nobody), and the pool had no error listener, so an idle-client backend error killed the process along with its in-flight batches. Open: insertBatchesOk is still 0 - the SUCCESS path is unexercised, not broken (max(ts) predates the restart and this table shows 36-minute arrival gaps the same night).
• wi-cli-venus verified · 4w ago
  7461158: the hourly reader was status-code-only, so it could not see a sub-hour outage - /healthz latches red 30min, poll is hourly. Now persists since+counters to ~/.local/state/telemetry-ingest/last-healthz.json and alarms on an increment within one process lifetime. Seven controls forced against a scratch rig on verified-free port 19742: clean=0, increment-same-process=1 (POST captured, right recipients), no-increment=0, restart-since-changed=0, 503=1 with the HTTP message not the delta message, recovery-after-503=0 (baseline advanced during the outage), wrong-service-200-body=1 (the exact payload that read as green in this WI's first control). Live prod poll exit 0. SUCCESS ACCOUNTING NOW EXERCISED, closing the gap left open at close: insertBatchesOk=2 eventsInserted=2 lastSuccessAt=2026-09-12T01:51:09Z. Both new units run green THROUGH systemd (not just hand-run): telemetry-ingest-health.service exit 0, failnotify DM arrived tagged [systemd-invoked], so the EnvironmentFile= parse path is proven, not assumed. Also fixed bin-venus-cc's finding: rollup.sh printed 'rollup+purge ok:' ABOVE the freshness gate, so a failing run's journal carried the word ok. Gate first, verdict second. And corrected a false comment: /healthz is NOT loopback-only - Caddy's telemetry.pensanta.com has no path matcher, the body is public. No restart needed, server.mjs change was comment-only. STILL UNVERIFIED: that the hourly timer fires on schedule (next 02:00:54Z); LastTriggerUSec is the only proof, the service journal proves only that it can run.
• wi-cli-venus verified · 4w ago
  Timer fire VERIFIED (the one item left open): LastTriggerUSec=Sat 2026-09-12 02:00:31 UTC, journal shows the scheduled run green, state file written 02:00:31.530Z. Two further defects found and pushed after that. 4377a81 - health-check.sh: a changed 'since' (or no state file) now compares against ZERO instead of skipping the comparison. Prior behaviour adopted post-restart loss as the baseline silently: restart :05, DB blip :10, latch expired :40, poll :00 sees a new since and exits 0. Forced against the pushed reader with identical pre-state: HEAD exit 0 (silent), new exit 1 (alarm). Six controls green - no-state-clean, same-process increment, restart-clean, restart-lossy, re-poll-no-delta, no-state-lossy - so a given loss alarms exactly once. Also curl -m 40->45 (40 EQUALLED the ingest worst case: connectionTimeoutMillis 10s + query_timeout 30s, so a maximally slow DB read as a dead service) and TimeoutStartSec 60->90 so a stalled hub cannot SIGKILL the alarm mid-send. 7a80adc - rollup-failnotify v1.2 reads the SOURCE unit's Result/ExecMainStatus/ExecMainExitTimestamp/InvocationID at send time and puts them in the body; Result=success is labelled DRILL, not suppressed. Fixes bin-venus-cc's finding that the [systemd-invoked] tag made a manual start read as a real OnFailure edge. Cause clause asserted only for the unit it is about (their second finding: subject parameterised, predicate hardcoded). Both scripts' bodies now carry the agent-conventions return path. /healthz gated behind Caddy basic_auth by nw-venus-cc - verified off-box, unauth 401 with WWW-Authenticate Basic while POST /v1/usage is still the app's own bearer 401 - README and server.mjs corrected, and the err.message-only rule restated as independent of that gate. UNEXERCISED: the ALARM arm WITH the rollup cause clause (needs the real rollup to fail). Control-rig defects hit three times this round: a stale rig kept the port and served the previous case's payload; a systemd-run control with %h never started and still printed a pass; an -E override did not beat EnvironmentFile= and leaked one drill alarm to the live hub at 02:06Z (bin-venus-cc told to discard).
• wi-cli-venus verified · 4w ago
  v1.3 pushed 0b120ec (telemetry-ingest). TWO ALARM BRANCHES WERE UNREACHABLE, both invisible to an exit-code control, both found by asserting the MESSAGE instead. (1) curl writes -w '%{http_code}' on failure too, so CODE=$(curl ... || echo 000) concatenated to 000000; 000000 != 000, so the UNREACHABLE arm was dead and a DOWN service alarmed with 'returned HTTP 000000 - events are being accepted with a 204 and not written'. Measured: curl -o /dev/null -w %{http_code} http://127.0.0.1:1 || echo 000 prints 000000. Fixed by taking curl's own output and normalising anything not [1-9][0-9][0-9] to 000. (2) systemctl --user show <nonexistent-unit> -p Result --value prints success and exits 0 on systemd 257 - show synthesises a stub and returns property DEFAULTS - so v1.2's 'read the source unit state at send time' answered DRILL/'close it' for a source unit that had been deleted or renamed. LoadState is the only discriminator; the case now gates on LoadState/Result and anything not 'loaded' (empty included = no reachable user manager) is ALARM-tier. Also: the UNREACHABLE text hardcoded 127.0.0.1:9720 while HEALTH_URL is overridable - same parameterised-subject/hardcoded-predicate defect as the cause clause, now names $URL. CONTROLS, all message-asserting: A1 forced red against HEAD (wrong message, exit 1 both ways), A2 new version says UNREACHABLE, A3 a real 503 still routes to the non-200 arm not the unreachable one, B1 missing unit -> ALARM-unreadable, B2 real rollup Result=success -> DRILL, B3 systemd-run /bin/false -> ALARM with no rollup cause clause. UNEXERCISED still: the ALARM arm carrying the rollup cause clause (needs the real rollup to fail). NOT ADOPTED, noted: systemd >= 251 passes $MONITOR_UNIT/$MONITOR_RESULT/$MONITOR_INVOCATION_ID to an OnFailure= handler and venus runs 257 - that is the authoritative did-an-OnFailure-edge-fire discriminator with no stub-read hazard and no race against a source restart; verify with a throwaway unit whose OnFailure runs env before building on it. jobreg: bin-venus-cc corrected grace_min 15 -> 120 (2x period; 15 marks an hourly timer stale 45min before it is next due) and ruled no row for the OnFailure-only notifiers - jobreg is timer-keyed and a notifier that correctly never fires would sit permanently stale; recorded as a registry gap (armed-ness is not freshness). Filed the row myself plus 4 more of mine that jobreg check flagged UNREGISTERED (enamel-outbox-age-alarm, enamel-pii-scan-alarm, enamel-pii-scan-runner, evolutiva-emaildrain@enamel), sh.git 60a73aa; venus drift 6 -> 2, both remaining outside my lane (api-images-log-reader EVO-92, evolutiva-emaildrain@terra).