From c460bb87a87cb4a39db11c6cec2ca9f1ffbb956f Mon Sep 17 00:00:00 2001 From: Anso Date: Mon, 18 May 2026 16:48:09 -0400 Subject: [PATCH] fix(mesh): probe upstream synchronously in route diagnostic (F-11) (#1100) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GET /api/mesh/aliases/:alias/diagnostic returned a cached state derived from the last latency/error maps. Those maps only mutated when someone called POST .../test or when a cross-node connect logged an event, so once an upstream stopped the diagnostic kept reporting "healthy" until the 60 s alias-cache refresh pruned the alias entirely. The GET now calls testUpstream synchronously after the alias-resolved, opted-in, tunnel-up short-circuits. Probe failures land in routeErrorMap via logActivity (cross-node already did this; same-node timeout/error paths now log probe.fail in the same shape), so the state computation flips to "unreachable" on the same request that exposed the stopped upstream. A new routeProbeAtMap stamps freshness and surfaces in the response as lastProbeAt; the route detail sheet renders "Last probe · " using the existing formatTimeAgo helper. --- .../mesh-diagnostic-freshness.test.ts | 177 ++++++++++++++++++ .../__tests__/mesh-diagnostic-local.test.ts | 10 + backend/src/services/MeshService.ts | 50 ++++- .../components/fleet/MeshRouteDetailSheet.tsx | 7 +- frontend/src/types/mesh.ts | 2 + 5 files changed, 241 insertions(+), 5 deletions(-) create mode 100644 backend/src/__tests__/mesh-diagnostic-freshness.test.ts diff --git a/backend/src/__tests__/mesh-diagnostic-freshness.test.ts b/backend/src/__tests__/mesh-diagnostic-freshness.test.ts new file mode 100644 index 00000000..1b2550fd --- /dev/null +++ b/backend/src/__tests__/mesh-diagnostic-freshness.test.ts @@ -0,0 +1,177 @@ +/** + * Regression guard for F-11: `MeshService.getRouteDiagnostic` must reflect + * current upstream reachability, not the last cached probe outcome. + * + * Pre-fix behavior: after a stop of the upstream container, the alias + * remained in `aliasCache` for up to 60 s (the refresh interval), and + * `routeLatencyMap` still carried the last successful probe value. + * `getRouteDiagnostic` returned `state: 'healthy'` from the stale data + * until someone manually hit `POST /aliases/:alias/test`. + * + * Post-fix behavior: `getRouteDiagnostic` calls `testUpstream` synchronously + * before computing state, so a failed probe lands in `routeErrorMap` and + * the state computation resolves to `'unreachable'` on the same GET. + */ +import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from 'vitest'; +import { setupTestDb, cleanupTestDb } from './helpers/setupTestDb'; + +let tmpDir: string; +let MeshService: typeof import('../services/MeshService').MeshService; +let DatabaseService: typeof import('../services/DatabaseService').DatabaseService; +let PilotTunnelManager: typeof import('../services/PilotTunnelManager').PilotTunnelManager; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ MeshService } = await import('../services/MeshService')); + ({ DatabaseService } = await import('../services/DatabaseService')); + ({ PilotTunnelManager } = await import('../services/PilotTunnelManager')); +}); + +afterAll(() => { + vi.restoreAllMocks(); + cleanupTestDb(tmpDir); +}); + +afterEach(() => { + vi.restoreAllMocks(); + const svc = MeshService.getInstance() as unknown as { + aliasCache: Map; + aliasByPort: Map; + routeLatencyMap: Map; + routeErrorMap: Map; + routeProbeAtMap: Map; + }; + svc.aliasCache = new Map(); + svc.aliasByPort = new Map(); + svc.routeLatencyMap = new Map(); + svc.routeErrorMap = new Map(); + svc.routeProbeAtMap = new Map(); +}); + +describe('MeshService.getRouteDiagnostic — freshness (F-11)', () => { + const ALIAS = 'echo.audit-mesh-fresh.local.sencho'; + + function seedHealthyLocalAlias(): number { + const svc = MeshService.getInstance(); + const db = DatabaseService.getInstance(); + const localNodeId = db.getNodes()[0].id; + db.insertMeshStack(localNodeId, 'audit-mesh-fresh', 'tester'); + + // Local node has no pilot tunnel; the helper short-circuits to + // routable=true. + vi.spyOn(PilotTunnelManager.getInstance(), 'hasActiveTunnel').mockReturnValue(false); + + (svc as unknown as { aliasCache: Map }).aliasCache = new Map([ + [ALIAS, { + host: ALIAS, + nodeId: localNodeId, + nodeName: 'local', + stackName: 'audit-mesh-fresh', + serviceName: 'echo', + port: 9100, + }], + ]); + // Seed the maps with stale "healthy" data — the pre-fix sequence the + // bug report described (last probe was fast and recent, no errors). + (svc as unknown as { routeLatencyMap: Map }).routeLatencyMap.set(ALIAS, 19); + (svc as unknown as { routeProbeAtMap: Map }).routeProbeAtMap.set( + ALIAS, Date.now() - 30_000, + ); + return localNodeId; + } + + it('flips state from cached "healthy" to "unreachable" when the live probe fails', async () => { + const svc = MeshService.getInstance(); + const localNodeId = seedHealthyLocalAlias(); + + // Mock testUpstream the same way the real same-node failure path + // would: write a fresh routeErrorMap entry (which the real probe + // achieves via logActivity → error event → routeErrorMap.set), bump + // routeProbeAtMap, and resolve a failing MeshProbeResult. + vi.spyOn(svc, 'testUpstream').mockImplementation(async (alias: string) => { + (svc as unknown as { routeErrorMap: Map }) + .routeErrorMap.set(alias, { ts: Date.now(), message: 'ECONNREFUSED' }); + (svc as unknown as { routeProbeAtMap: Map }) + .routeProbeAtMap.set(alias, Date.now()); + return { ok: false, where: 'target_port', code: 'unreachable', message: 'ECONNREFUSED' }; + }); + + const diag = await svc.getRouteDiagnostic(ALIAS); + expect(diag.state).toBe('unreachable'); + expect(diag.lastError?.message).toBe('ECONNREFUSED'); + expect(diag.lastProbeAt).not.toBeNull(); + // Probe should have been invoked exactly once during the GET. + expect(svc.testUpstream).toHaveBeenCalledTimes(1); + + DatabaseService.getInstance().deleteMeshStack(localNodeId, 'audit-mesh-fresh'); + }); + + it('keeps state healthy and stamps a fresh lastProbeAt when the live probe succeeds', async () => { + const svc = MeshService.getInstance(); + const localNodeId = seedHealthyLocalAlias(); + const beforeMs = Date.now(); + + vi.spyOn(svc, 'testUpstream').mockImplementation(async (alias: string) => { + (svc as unknown as { routeLatencyMap: Map }).routeLatencyMap.set(alias, 4); + (svc as unknown as { routeProbeAtMap: Map }) + .routeProbeAtMap.set(alias, Date.now()); + return { ok: true, latencyMs: 4 }; + }); + + const diag = await svc.getRouteDiagnostic(ALIAS); + expect(diag.state).toBe('healthy'); + expect(diag.lastProbeMs).toBe(4); + expect(diag.lastProbeAt).not.toBeNull(); + expect(diag.lastProbeAt!).toBeGreaterThanOrEqual(beforeMs); + expect(svc.testUpstream).toHaveBeenCalledTimes(1); + + DatabaseService.getInstance().deleteMeshStack(localNodeId, 'audit-mesh-fresh'); + }); + + it('does not probe when the target is unresolved (alias not in cache)', async () => { + const svc = MeshService.getInstance(); + // No aliasCache seed; lookup returns null. + const probeSpy = vi.spyOn(svc, 'testUpstream'); + + const diag = await svc.getRouteDiagnostic('ghost.notthere.local.sencho'); + expect(diag.state).toBe('not authorized'); + expect(diag.target).toBeNull(); + expect(probeSpy).not.toHaveBeenCalled(); + }); + + it('does not probe when the tunnel is down (avoids holding the GET for the probe timeout)', async () => { + const svc = MeshService.getInstance(); + const db = DatabaseService.getInstance(); + const remoteNodeId = db.addNode({ + name: 'f11-remote', + type: 'remote', + mode: 'pilot_agent', + compose_dir: '/tmp', + is_default: false, + api_url: '', + api_token: '', + }); + db.insertMeshStack(remoteNodeId, 'audit-mesh-down', 'tester'); + vi.spyOn(PilotTunnelManager.getInstance(), 'hasActiveTunnel').mockReturnValue(false); + + const alias = 'echo.audit-mesh-down.f11-remote.sencho'; + (svc as unknown as { aliasCache: Map }).aliasCache = new Map([ + [alias, { + host: alias, + nodeId: remoteNodeId, + nodeName: 'f11-remote', + stackName: 'audit-mesh-down', + serviceName: 'echo', + port: 9101, + }], + ]); + const probeSpy = vi.spyOn(svc, 'testUpstream'); + + const diag = await svc.getRouteDiagnostic(alias); + expect(diag.state).toBe('tunnel down'); + expect(probeSpy).not.toHaveBeenCalled(); + + db.deleteMeshStack(remoteNodeId, 'audit-mesh-down'); + db.deleteNode(remoteNodeId); + }); +}); diff --git a/backend/src/__tests__/mesh-diagnostic-local.test.ts b/backend/src/__tests__/mesh-diagnostic-local.test.ts index f7aefa53..9f74e824 100644 --- a/backend/src/__tests__/mesh-diagnostic-local.test.ts +++ b/backend/src/__tests__/mesh-diagnostic-local.test.ts @@ -49,6 +49,16 @@ describe('MeshService diagnostic — local-node pilot state (M-12)', () => { // 'tunnel down'. vi.spyOn(PilotTunnelManager.getInstance(), 'hasActiveTunnel').mockReturnValue(false); + // F-11: getRouteDiagnostic now probes synchronously. Stub testUpstream + // so the unit test does not depend on a live TCP socket on port 9000. + // The stub writes routeLatencyMap in lockstep with the real probe + // success path so the state computation below resolves to 'healthy'. + vi.spyOn(svc, 'testUpstream').mockImplementation(async (alias: string) => { + (svc as unknown as { routeLatencyMap: Map }).routeLatencyMap.set(alias, 5); + (svc as unknown as { routeProbeAtMap: Map }).routeProbeAtMap.set(alias, Date.now()); + return { ok: true, latencyMs: 5 }; + }); + (svc as unknown as { aliasCache: Map }).aliasCache = new Map([ ['echo.audit-mesh-prod.local.sencho', { host: 'echo.audit-mesh-prod.local.sencho', diff --git a/backend/src/services/MeshService.ts b/backend/src/services/MeshService.ts index 14f65266..a47abdbe 100644 --- a/backend/src/services/MeshService.ts +++ b/backend/src/services/MeshService.ts @@ -219,6 +219,8 @@ export interface MeshRouteDiagnostic { pilot: { connected: boolean; lastSeen: number | null }; lastError: { ts: number; message: string } | null; lastProbeMs: number | null; + /** Wall-clock ms epoch of the last probe for this alias; null when no probe has ever run. */ + lastProbeAt: number | null; state: 'healthy' | 'degraded' | 'unreachable' | 'tunnel down' | 'not authorized'; } @@ -275,6 +277,10 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { private bridgeReconcileTimer?: NodeJS.Timeout; private routeErrorMap = new Map(); private routeLatencyMap = new Map(); + // Lets the route diagnostic distinguish a fresh "healthy" verdict from a + // stale one carried over from a past probe; written in lockstep with the + // latency/error maps by every probe outcome. + private routeProbeAtMap = new Map(); private activityListeners = new Set<(e: MeshActivityEvent) => void>(); private readonly forwarder: MeshForwarder; private senchoIp: string | null = null; @@ -1964,12 +1970,14 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { return new Promise((resolve) => { const timer = setTimeout(() => { stream.destroy(); + this.routeProbeAtMap.set(target.host, Date.now()); resolve({ ok: false, where: 'agent_dial', code: 'timeout', message: 'probe timeout' }); }, PROBE_TIMEOUT_MS); stream.once('open', () => { clearTimeout(timer); const latency = Date.now() - t0; this.routeLatencyMap.set(target.host, latency); + this.routeProbeAtMap.set(target.host, Date.now()); stream.destroy(); this.logActivity({ source: 'mesh', level: 'info', type: 'probe.ok', @@ -1979,6 +1987,7 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { }); stream.once('error', (err: Error) => { clearTimeout(timer); + this.routeProbeAtMap.set(target.host, Date.now()); const sanitized = sanitizeForLog(err.message); this.logActivity({ source: 'mesh', level: 'error', type: 'probe.fail', @@ -1996,15 +2005,27 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { sock.once('connect', () => { const latency = Date.now() - t0; this.routeLatencyMap.set(target.host, latency); + this.routeProbeAtMap.set(target.host, Date.now()); sock.destroy(); resolve({ ok: true, latencyMs: latency }); }); sock.once('timeout', () => { sock.destroy(); + this.routeProbeAtMap.set(target.host, Date.now()); + this.logActivity({ + source: 'mesh', level: 'error', type: 'probe.fail', + alias: target.host, message: 'connect timeout', + }); resolve({ ok: false, where: 'target_port', code: 'timeout', message: 'connect timeout' }); }); sock.once('error', (err) => { - resolve({ ok: false, where: 'target_port', code: 'unreachable', message: sanitizeForLog(err.message) }); + this.routeProbeAtMap.set(target.host, Date.now()); + const sanitized = sanitizeForLog(err.message); + this.logActivity({ + source: 'mesh', level: 'error', type: 'probe.fail', + alias: target.host, message: sanitized, + }); + resolve({ ok: false, where: 'target_port', code: 'unreachable', message: sanitized }); }); }); } @@ -2059,11 +2080,12 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { public async getRouteDiagnostic(alias: string): Promise { const target = this.lookupAliasGlobal(alias); - const lastError = this.routeErrorMap.get(alias) || null; - const lastProbeMs = this.routeLatencyMap.get(alias) ?? null; if (!target) { - return { alias, target: null, pilot: { connected: false, lastSeen: null }, lastError, lastProbeMs, state: 'not authorized' }; + const lastError = this.routeErrorMap.get(alias) || null; + const lastProbeMs = this.routeLatencyMap.get(alias) ?? null; + const lastProbeAt = this.routeProbeAtMap.get(alias) ?? null; + return { alias, target: null, pilot: { connected: false, lastSeen: null }, lastError, lastProbeMs, lastProbeAt, state: 'not authorized' }; } const node = DatabaseService.getInstance().getNode(target.nodeId); @@ -2077,6 +2099,25 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { const lastSeen = node?.pilot_last_seen ?? null; const optedIn = DatabaseService.getInstance().isMeshStackEnabled(target.nodeId, target.stackName); + // F-11: cached state was stale until someone manually hit POST .../test. + // Probe synchronously here so the GET reflects current upstream state. + // Skip when the probe would be wasted (no target, opt-out, tunnel down) — + // those short-circuits keep a downed peer from holding the GET for + // PROBE_TIMEOUT_MS. Probe failures are swallowed because we only use the + // call for its side effects on routeLatencyMap / routeErrorMap / + // routeProbeAtMap; the activity log already records probe.fail. + if (optedIn && routable && pilotLive) { + try { + await this.testUpstream(alias, NodeRegistry.getInstance().getDefaultNodeId()); + } catch { + // ignore — diagnostic must not error out on probe failure + } + } + + const lastError = this.routeErrorMap.get(alias) || null; + const lastProbeMs = this.routeLatencyMap.get(alias) ?? null; + const lastProbeAt = this.routeProbeAtMap.get(alias) ?? null; + let state: MeshRouteDiagnostic['state']; if (!optedIn) state = 'not authorized'; else if (!routable || !pilotLive) state = 'tunnel down'; @@ -2096,6 +2137,7 @@ export class MeshService extends EventEmitter implements MeshForwarderHost { pilot: { connected: pilotLive, lastSeen }, lastError, lastProbeMs, + lastProbeAt, state, }; } diff --git a/frontend/src/components/fleet/MeshRouteDetailSheet.tsx b/frontend/src/components/fleet/MeshRouteDetailSheet.tsx index bfe8e38e..55f4e283 100644 --- a/frontend/src/components/fleet/MeshRouteDetailSheet.tsx +++ b/frontend/src/components/fleet/MeshRouteDetailSheet.tsx @@ -1,5 +1,6 @@ import { useEffect, useState } from 'react'; import { apiFetch } from '@/lib/api'; +import { formatTimeAgo } from '@/lib/relativeTime'; import { SystemSheet, SheetSection } from '@/components/ui/system-sheet'; import { Badge } from '@/components/ui/badge'; import { Loader2, Activity, Hash } from 'lucide-react'; @@ -71,7 +72,11 @@ export function MeshRouteDetailSheet({ open, onOpenChange, alias }: Props) { const footerContext = probe ? (probe.ok ? `Last probe ok · ${probe.latencyMs}ms` : `Last probe failed · ${probe.where ?? 'unknown'}`) - : (diag?.lastProbeMs != null ? `Last probe ${diag.lastProbeMs}ms` : 'No probe run yet'); + : diag?.lastProbeMs != null + ? (diag.lastProbeAt != null + ? `Last probe ${formatTimeAgo(diag.lastProbeAt)} · ${diag.lastProbeMs}ms` + : `Last probe ${diag.lastProbeMs}ms`) + : 'No probe run yet'; return (