From a1e7cc8f7fe6745e64b547ac438082aa5f62f47a Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Sat, 4 Jul 2026 18:35:20 -0700 Subject: [PATCH] fix(selfhost): stop logging routine maintenance-admission backpressure as a warning The maintenance-admission-deferred event fires whenever the queue defers a background job under normal pressure -- expected steady-state behavior, not an operational problem, so it should not sit at warn level next to real failures. Downgrade both the SQLite and Postgres queue drivers to log it at info, matching how other routine/expected events are leveled elsewhere. Also adds a "Maintenance Admission Deferrals (total)" panel next to the existing by-reason breakdown in the Runtime Pressure & Maintenance section, using the two counters already recorded alongside this log line. --- grafana/dashboards/gittensory.json | 67 ++++++++++++++------ src/selfhost/pg-queue.ts | 4 +- src/selfhost/sqlite-queue.ts | 4 +- test/unit/selfhost-grafana-dashboard.test.ts | 16 +++++ test/unit/selfhost-pg-queue.test.ts | 21 ++++++ test/unit/selfhost-sqlite-queue.test.ts | 20 ++++++ 6 files changed, 108 insertions(+), 24 deletions(-) diff --git a/grafana/dashboards/gittensory.json b/grafana/dashboards/gittensory.json index e1a9dcba93..5a86f4e4f7 100644 --- a/grafana/dashboards/gittensory.json +++ b/grafana/dashboards/gittensory.json @@ -2432,9 +2432,36 @@ } ] }, + { + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { "lineWidth": 2, "fillOpacity": 10 }, + "unit": "ops" + } + }, + "gridPos": { "h": 8, "w": 24, "x": 0, "y": 157 }, + "id": 158, + "options": { + "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, + "tooltip": { "mode": "multi", "sort": "desc" } + }, + "title": "Maintenance Admission Deferrals (total)", + "description": "Aggregate rate of maintenance jobs deferred by admission gating, regardless of reason -- routine backpressure behavior logged at info level, not an error. Break down by reason in 'Maintenance Admission Deferrals by Reason' above.", + "type": "timeseries", + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "expr": "sum(rate(gittensory_jobs_maintenance_admission_deferred_total[5m])) or vector(0)", + "legendFormat": "deferred", + "refId": "A" + } + ] + }, { "collapsed": false, - "gridPos": { "h": 1, "w": 24, "x": 0, "y": 157 }, + "gridPos": { "h": 1, "w": 24, "x": 0, "y": 165 }, "id": 138, "title": "Self-Host Runtime Drift Signals", "type": "row" @@ -2454,7 +2481,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 6, "x": 0, "y": 158 }, + "gridPos": { "h": 4, "w": 6, "x": 0, "y": 166 }, "id": 139, "options": { "colorMode": "background", @@ -2489,7 +2516,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 6, "x": 6, "y": 158 }, + "gridPos": { "h": 4, "w": 6, "x": 6, "y": 166 }, "id": 140, "options": { "colorMode": "background", @@ -2524,7 +2551,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 6, "x": 12, "y": 158 }, + "gridPos": { "h": 4, "w": 6, "x": 12, "y": 166 }, "id": 141, "options": { "colorMode": "background", @@ -2559,7 +2586,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 6, "x": 18, "y": 158 }, + "gridPos": { "h": 4, "w": 6, "x": 18, "y": 166 }, "id": 142, "options": { "colorMode": "background", @@ -2588,7 +2615,7 @@ "unit": "ops" } }, - "gridPos": { "h": 8, "w": 12, "x": 0, "y": 162 }, + "gridPos": { "h": 8, "w": 12, "x": 0, "y": 170 }, "id": 143, "options": { "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, @@ -2620,7 +2647,7 @@ "unit": "ops" } }, - "gridPos": { "h": 8, "w": 12, "x": 12, "y": 162 }, + "gridPos": { "h": 8, "w": 12, "x": 12, "y": 170 }, "id": 144, "options": { "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, @@ -2639,7 +2666,7 @@ }, { "collapsed": false, - "gridPos": { "h": 1, "w": 24, "x": 0, "y": 171 }, + "gridPos": { "h": 1, "w": 24, "x": 0, "y": 179 }, "id": 145, "panels": [], "title": "Foreground Liveness (#selfhost-queue-liveness)", @@ -2648,7 +2675,7 @@ { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 0, "y": 172 }, + "gridPos": { "h": 4, "w": 4, "x": 0, "y": 180 }, "id": 146, "options": { "colorMode": "background", @@ -2671,7 +2698,7 @@ { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 4, "y": 172 }, + "gridPos": { "h": 4, "w": 4, "x": 4, "y": 180 }, "id": 147, "options": { "colorMode": "background", @@ -2694,7 +2721,7 @@ { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 8, "y": 172 }, + "gridPos": { "h": 4, "w": 4, "x": 8, "y": 180 }, "id": 148, "options": { "colorMode": "background", @@ -2730,7 +2757,7 @@ "unit": "s" } }, - "gridPos": { "h": 4, "w": 4, "x": 12, "y": 172 }, + "gridPos": { "h": 4, "w": 4, "x": 12, "y": 180 }, "id": 149, "options": { "colorMode": "background", @@ -2753,7 +2780,7 @@ { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 16, "y": 172 }, + "gridPos": { "h": 4, "w": 4, "x": 16, "y": 180 }, "id": 150, "options": { "colorMode": "background", @@ -2778,7 +2805,7 @@ "fieldConfig": { "defaults": { "color": { "mode": "palette-classic" }, "custom": { "lineWidth": 2, "fillOpacity": 10 }, "unit": "short" } }, - "gridPos": { "h": 6, "w": 12, "x": 0, "y": 176 }, + "gridPos": { "h": 6, "w": 12, "x": 0, "y": 184 }, "id": 151, "options": { "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, @@ -2797,7 +2824,7 @@ }, { "collapsed": false, - "gridPos": { "h": 1, "w": 24, "x": 0, "y": 182 }, + "gridPos": { "h": 1, "w": 24, "x": 0, "y": 190 }, "id": 152, "title": "Backlog-vs-Fresh-Intake Lane Fairness (#selfhost-lane-observability)", "type": "row" @@ -2818,7 +2845,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 0, "y": 183 }, + "gridPos": { "h": 4, "w": 4, "x": 0, "y": 191 }, "id": 153, "options": { "colorMode": "background", @@ -2854,7 +2881,7 @@ "unit": "short" } }, - "gridPos": { "h": 4, "w": 4, "x": 4, "y": 183 }, + "gridPos": { "h": 4, "w": 4, "x": 4, "y": 191 }, "id": 154, "options": { "colorMode": "background", @@ -2879,7 +2906,7 @@ "fieldConfig": { "defaults": { "color": { "mode": "palette-classic" }, "custom": { "lineWidth": 2, "fillOpacity": 10 }, "unit": "short" } }, - "gridPos": { "h": 6, "w": 16, "x": 8, "y": 183 }, + "gridPos": { "h": 6, "w": 16, "x": 8, "y": 191 }, "id": 155, "options": { "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, @@ -2902,7 +2929,7 @@ "fieldConfig": { "defaults": { "color": { "mode": "palette-classic" }, "custom": { "lineWidth": 2, "fillOpacity": 10 }, "unit": "ops" } }, - "gridPos": { "h": 6, "w": 12, "x": 0, "y": 189 }, + "gridPos": { "h": 6, "w": 12, "x": 0, "y": 197 }, "id": 156, "options": { "legend": { "calcs": ["lastNotNull"], "displayMode": "table", "placement": "bottom" }, @@ -2922,7 +2949,7 @@ { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, "fieldConfig": { "defaults": { "unit": "short" } }, - "gridPos": { "h": 6, "w": 12, "x": 12, "y": 189 }, + "gridPos": { "h": 6, "w": 12, "x": 12, "y": 197 }, "id": 157, "options": { "showHeader": true, diff --git a/src/selfhost/pg-queue.ts b/src/selfhost/pg-queue.ts index 23a3de4902..f2461bb725 100644 --- a/src/selfhost/pg-queue.ts +++ b/src/selfhost/pg-queue.ts @@ -1195,9 +1195,9 @@ export function createPgQueue( reason: decision.reason, job_type: message.type, }); - console.warn( + console.log( JSON.stringify({ - level: "warn", + level: "info", event: "selfhost_queue_maintenance_admission_deferred", jobType: message.type, reason: decision.reason, diff --git a/src/selfhost/sqlite-queue.ts b/src/selfhost/sqlite-queue.ts index b935bbef79..9409bd6f1f 100644 --- a/src/selfhost/sqlite-queue.ts +++ b/src/selfhost/sqlite-queue.ts @@ -924,9 +924,9 @@ export function createSqliteQueue( reason: decision.reason, job_type: message.type, }); - console.warn( + console.log( JSON.stringify({ - level: "warn", + level: "info", event: "selfhost_queue_maintenance_admission_deferred", jobType: message.type, reason: decision.reason, diff --git a/test/unit/selfhost-grafana-dashboard.test.ts b/test/unit/selfhost-grafana-dashboard.test.ts index 2fde90d002..c4f1b75357 100644 --- a/test/unit/selfhost-grafana-dashboard.test.ts +++ b/test/unit/selfhost-grafana-dashboard.test.ts @@ -151,6 +151,22 @@ describe("Gittensory Self-Host Grafana dashboard", () => { expect(alerts).toContain('time() - gittensory_backup_latest_timestamp_seconds{target=~"postgres|sqlite"} > 93600'); }); + it("surfaces a Maintenance Admission Deferrals (total) panel alongside the by-reason breakdown", () => { + const dashboard = readDashboard(selfhostDashboardPath); + const targets = dashboard.panels.flatMap((panel) => panel.targets ?? []); + const titles = dashboard.panels.map((panel) => panel.title); + + expect(titles).toEqual( + expect.arrayContaining([ + "Runtime Pressure & Maintenance", + "Maintenance Admission Deferrals by Reason", + "Maintenance Admission Deferrals (total)", + ]), + ); + expect(targets.some((target) => target.expr === "sum by (reason, job_type) (rate(gittensory_jobs_maintenance_admission_deferred_by_reason_total[5m])) or vector(0)")).toBe(true); + expect(targets.some((target) => target.expr === "sum(rate(gittensory_jobs_maintenance_admission_deferred_total[5m])) or vector(0)")).toBe(true); + }); + it("surfaces self-host runtime-drift signal panels, every counter query fleet-aggregated", () => { const dashboard = readDashboard(selfhostDashboardPath); const targets = dashboard.panels.flatMap((panel) => panel.targets ?? []); diff --git a/test/unit/selfhost-pg-queue.test.ts b/test/unit/selfhost-pg-queue.test.ts index be2efa7ec4..12f9753bca 100644 --- a/test/unit/selfhost-pg-queue.test.ts +++ b/test/unit/selfhost-pg-queue.test.ts @@ -3209,6 +3209,27 @@ describe("createPgQueue (durable #977)", () => { ); }); + it("logs a deferred maintenance admission at info level, not warn (#selfhost-backpressure-noise)", async () => { + const m = makePool(); + m.setPressureSignals({ live: { cnt: 6, oldest: now } }); // default threshold is 5 + m.enqueueResult({ rows: [], rowCount: 0 }); // empty foreground claim + m.enqueueResult({ rows: [maintenanceRow], rowCount: 1 }); // background claim + const logged = vi.spyOn(console, "log").mockImplementation(() => undefined); + const warned = vi.spyOn(console, "warn").mockImplementation(() => undefined); + const q = createPgQueue(m.pool, async () => undefined); + await q.drain(); + + expect(warned).not.toHaveBeenCalled(); + expect(logged).toHaveBeenCalledWith( + expect.stringContaining('"event":"selfhost_queue_maintenance_admission_deferred"'), + ); + expect(JSON.parse(logged.mock.calls.at(-1)?.[0] as string)).toMatchObject({ + level: "info", + event: "selfhost_queue_maintenance_admission_deferred", + reason: "live_pending_high", + }); + }); + it("admits a maintenance job immediately when pressure is clear", async () => { const m = makePool(); m.enqueueResult({ rows: [], rowCount: 0 }); // empty foreground claim diff --git a/test/unit/selfhost-sqlite-queue.test.ts b/test/unit/selfhost-sqlite-queue.test.ts index 716e6714b3..46f9884c03 100644 --- a/test/unit/selfhost-sqlite-queue.test.ts +++ b/test/unit/selfhost-sqlite-queue.test.ts @@ -3326,6 +3326,26 @@ describe("createSqliteQueue (durable #980)", () => { ); }); + it("logs a deferred maintenance admission at info level, not warn (#selfhost-backpressure-noise)", async () => { + const driver = makeDriver(); + const logged = vi.spyOn(console, "log").mockImplementation(() => undefined); + const warned = vi.spyOn(console, "warn").mockImplementation(() => undefined); + const q = createSqliteQueue(driver, async () => undefined); + seedLiveRows(driver, 6); // default threshold is 5 + await q.binding.send(msg("build-contributor-evidence")); + await q.drain(); + + expect(warned).not.toHaveBeenCalled(); + expect(logged).toHaveBeenCalledWith( + expect.stringContaining('"event":"selfhost_queue_maintenance_admission_deferred"'), + ); + expect(JSON.parse(logged.mock.calls.at(-1)?.[0] as string)).toMatchObject({ + level: "info", + event: "selfhost_queue_maintenance_admission_deferred", + reason: "live_pending_high", + }); + }); + it("admits a maintenance job immediately when pressure is clear", async () => { const driver = makeDriver(); const started: string[] = [];