From 4e6eab0a67c2cb53b54e24817bea40b0dec47a31 Mon Sep 17 00:00:00 2001 From: Joey Stanford Date: Sat, 8 Aug 2026 21:51:16 -0600 Subject: [PATCH 1/3] fix(logging): drop low-value noisy logs and false heartbeat errors Reduce log/support-bundle noise from hot paths that fire on timers or on every successful IPC while healthy, and stop a false-positive error: - MeshCore MQTT: log PINGREQ/PINGRESP once per connection (the pingReqLogged/pingRespLogged gates always logged); reset on reconnect. - Meshtastic SDK: skip routine TRACE [iMeshDevice] chatter and periodic DEBUG Ping heartbeats in forwardRendererConsoleMessage; keep INFO/WARN/ERROR and decode-failure TRACE lines (Foreign LoRa). - reticulumPeerStore: log full refresh only when slow (elapsed > 2000ms); drop the peers.size gate that logged every refresh at scale. - Remove routine processWaitingMessages start/done/skipped/empty debug, per-success IPC mqtt:publishMeshcorePacketLog debug, and clearDiagnostics debug; keep timeouts and real failures. - Fix duplicate "[renderer] Unhandled rejection: Packet does not exist" on Meshtastic heartbeat: both unhandledrejection listeners are at_target on window (fire in registration order, not capture-first), so the app-lifetime renderer logger logged before the per-session capture handler could preventDefault. Add a session-swallow ref-count so the renderer logger defers to the session handler. Adds tests for PING once-only (+reconnect reset), the SDK line filter, and the session-swallow deferral. --- src/main/index.ts | 1 - src/main/log-service.test.ts | 62 +++++++++++++++++ src/main/log-service.ts | 22 ++++++ src/main/meshcore-mqtt-adapter.test.ts | 68 +++++++++++++++++++ src/main/meshcore-mqtt-adapter.ts | 20 ++++-- .../hooks/meshcore/meshcoreConnSideEffects.ts | 45 ------------ .../meshtastic/meshtasticConfigureRetry.ts | 26 +++++++ .../meshtasticSdkRoutingErrorConsoleHook.ts | 6 ++ .../lib/rendererUnhandledRejection.test.ts | 37 ++++++++++ .../lib/rendererUnhandledRejection.ts | 16 ++++- src/renderer/stores/diagnosticsStore.ts | 1 - src/renderer/stores/reticulumPeerStore.ts | 2 +- 12 files changed, 251 insertions(+), 55 deletions(-) diff --git a/src/main/index.ts b/src/main/index.ts index f959f8843..23389acac 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -3247,7 +3247,6 @@ ipcMain.handle('mqtt:publishMeshcore', (event, args) => { ipcMain.handle('mqtt:publishMeshcorePacketLog', (event, args) => { assertIpcSender(event, 'mqtt:publishMeshcorePacketLog'); try { - console.debug('[IPC] mqtt:publishMeshcorePacketLog'); validateMqttPublishMeshcorePacketLogArgs(args); const a = args as { origin: string; diff --git a/src/main/log-service.test.ts b/src/main/log-service.test.ts index 5d7f7402b..cee4d6d32 100644 --- a/src/main/log-service.test.ts +++ b/src/main/log-service.test.ts @@ -352,6 +352,68 @@ describe('stripConsoleStyles (via appendLine + getRecentLines)', () => { }); }); +describe('isDroppableMeshtasticSdkLogLine', () => { + it('drops routine SDK TRACE [iMeshDevice] chatter', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect( + isDroppableMeshtasticSdkLogLine( + '03:39:57:239 TRACE [iMeshDevice] HandleMeshPacket Received STORE_FORWARD_APP packet', + ), + ).toBe(true); + expect( + isDroppableMeshtasticSdkLogLine( + '01:25:29:719 TRACE [iMeshDevice] HandleFromRadio Received Queue Status', + ), + ).toBe(true); + }); + + it('drops periodic DEBUG [iMeshDevice] Ping heartbeats', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect( + isDroppableMeshtasticSdkLogLine( + '01:25:29:561 DEBUG [iMeshDevice] Ping Send heartbeat ping to radio', + ), + ).toBe(true); + }); + + it('keeps INFO / WARN / ERROR SDK lines', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect( + isDroppableMeshtasticSdkLogLine( + '00:56:01:200 WARN [iMeshDevice] HandleFromRadio Unhandled payload variant: deviceuiConfig', + ), + ).toBe(false); + expect( + isDroppableMeshtasticSdkLogLine( + '00:56:01:185 INFO [iMeshDevice] HandleFromRadio Received Node info for this device', + ), + ).toBe(false); + }); + + it('keeps non-Ping DEBUG lines', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect( + isDroppableMeshtasticSdkLogLine( + '00:56:01:222 DEBUG [iMeshDevice] GetMetadata Received metadata packet', + ), + ).toBe(false); + }); + + it('keeps TRACE decode-failure lines needed by Foreign LoRa detection', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect( + isDroppableMeshtasticSdkLogLine( + 'TRACE [iMeshDevice] HandleMeshPacket decode failed rssi -120 snr -8 3c 01 02', + ), + ).toBe(false); + }); + + it('keeps unrelated renderer/main lines', async () => { + const { isDroppableMeshtasticSdkLogLine } = await import('./log-service'); + expect(isDroppableMeshtasticSdkLogLine('[main] [MeshCore MQTT] PINGREQ sent')).toBe(false); + }); +}); + describe('formatRuntimeLogTag', () => { it('includes platform, arch, electron, node, packaged, and buildChannel fields', async () => { const { formatRuntimeLogTag } = await import('./log-service'); diff --git a/src/main/log-service.ts b/src/main/log-service.ts index 5f2a2ade8..e7a7b226f 100644 --- a/src/main/log-service.ts +++ b/src/main/log-service.ts @@ -384,6 +384,27 @@ export function patchMainConsole(): void { patchStream(process.stderr, 'warn', 'stderr'); } +/** + * Failure-context markers used by Foreign LoRa detection (see + * `src/renderer/lib/foreignLoraDetection.ts`). A TRACE line containing any of these + * is preserved so overheard decode-failure frames still reach the renderer. + */ +const SDK_FAILURE_CONTEXT_REGEX = + /packet.?dropped|crc.?err|crc.?fail|crc.?bad|bad.?crc|decode.?fail|decode.?error|corrupt.?packet|bad.?packet|invalid.?packet|preamble|rx.?error|lora.?err/i; + +/** + * True for high-volume `@meshtastic/core` console noise with no triage value: + * routine `TRACE [iMeshDevice]` chatter and periodic `DEBUG [iMeshDevice] Ping` + * heartbeats. INFO/WARN/ERROR and decode-failure TRACE lines are kept. + */ +export function isDroppableMeshtasticSdkLogLine(message: string): boolean { + if (/\bDEBUG \[iMeshDevice\] Ping\b/.test(message)) return true; + if (/\bTRACE \[iMeshDevice\]/.test(message) && !SDK_FAILURE_CONTEXT_REGEX.test(message)) { + return true; + } + return false; +} + /** * Renderer console-message (Electron 40+): single event object with message, level, lineNumber, sourceId. * level is 'info' | 'warning' | 'error' | 'debug'. @@ -406,5 +427,6 @@ export function forwardRendererConsoleMessage(details: { ? sanitizeLogMessage(`renderer:${path.basename(details.sourceId)}:${line}`) : 'renderer'; const msg = sanitizeLogMessage(stripConsoleStyles(details.message)); + if (isDroppableMeshtasticSdkLogLine(msg)) return; appendLine(mapped, src, msg); } diff --git a/src/main/meshcore-mqtt-adapter.test.ts b/src/main/meshcore-mqtt-adapter.test.ts index 5c025ffb4..0a53e989f 100644 --- a/src/main/meshcore-mqtt-adapter.test.ts +++ b/src/main/meshcore-mqtt-adapter.test.ts @@ -73,6 +73,74 @@ describe('MeshcoreMqttAdapter — topicPrefix wildcards', () => { ); }); +describe('MeshcoreMqttAdapter — PING logging', () => { + let adapter: MeshcoreMqttAdapter; + + beforeEach(async () => { + const mqtt = await import('mqtt'); + vi.mocked(mqtt.connect).mockClear(); + adapter = new MeshcoreMqttAdapter(); + adapter.on('error', () => {}); + }); + + afterEach(() => { + adapter.disconnect(); + vi.restoreAllMocks(); + }); + + const lastHandler = ( + client: { on: ReturnType }, + name: string, + ): ((packet: { cmd: string }) => void) => { + const hits = client.on.mock.calls.filter((c: unknown[]) => c[0] === name); + return hits[hits.length - 1]?.[1] as (packet: { cmd: string }) => void; + }; + + it('logs PINGREQ and PINGRESP only once per connection', async () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const mqttMod = await import('mqtt'); + adapter.connect({ ...BASE_SETTINGS }); + const client = vi.mocked(mqttMod.connect).mock.results.at(-1)!.value as { + on: ReturnType; + }; + const onSend = lastHandler(client, 'packetsend'); + const onReceive = lastHandler(client, 'packetreceive'); + + onSend({ cmd: 'pingreq' }); + onSend({ cmd: 'pingreq' }); + onSend({ cmd: 'pingreq' }); + onReceive({ cmd: 'pingresp' }); + onReceive({ cmd: 'pingresp' }); + + const reqLogs = debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGREQ')); + const respLogs = debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGRESP')); + expect(reqLogs).toHaveLength(1); + expect(respLogs).toHaveLength(1); + }); + + it('re-logs PINGREQ once after a reconnect (flags reset)', async () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const mqttMod = await import('mqtt'); + + adapter.connect({ ...BASE_SETTINGS }); + let client = vi.mocked(mqttMod.connect).mock.results.at(-1)!.value as { + on: ReturnType; + }; + lastHandler(client, 'packetsend')({ cmd: 'pingreq' }); + lastHandler(client, 'packetsend')({ cmd: 'pingreq' }); + + adapter.disconnect(); + adapter.connect({ ...BASE_SETTINGS }); + client = vi.mocked(mqttMod.connect).mock.results.at(-1)!.value as { + on: ReturnType; + }; + lastHandler(client, 'packetsend')({ cmd: 'pingreq' }); + + const reqLogs = debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGREQ')); + expect(reqLogs).toHaveLength(2); + }); +}); + describe('MeshcoreMqttAdapter — clientId', () => { let adapter: MeshcoreMqttAdapter; diff --git a/src/main/meshcore-mqtt-adapter.ts b/src/main/meshcore-mqtt-adapter.ts index 9c0ab4251..3afa7fa09 100644 --- a/src/main/meshcore-mqtt-adapter.ts +++ b/src/main/meshcore-mqtt-adapter.ts @@ -311,6 +311,8 @@ export class MeshcoreMqttAdapter extends EventEmitter { settings.tlsInsecure === true, ); this.firstMessageLogged = false; + this.pingReqLogged = false; + this.pingRespLogged = false; this.setStatus('connecting'); this.connectAbortByWatchdog = false; this.client = mqtt.connect(connectOpts); @@ -405,16 +407,22 @@ export class MeshcoreMqttAdapter extends EventEmitter { this.scheduleTokenRefresh(); }); this.client.on('packetsend', (packet) => { - if (packet.cmd === 'pingreq') { - this.pingReqLogged = false; - console.debug('[MeshCore MQTT] PINGREQ sent', new Date().toISOString()); + if (packet.cmd === 'pingreq' && !this.pingReqLogged) { + this.pingReqLogged = true; + console.debug( + '[MeshCore MQTT] PINGREQ sent (first this session)', + new Date().toISOString(), + ); } }); this.client.on('packetreceive', (packet) => { this.lastPacketReceivedAt = Date.now(); - if (packet.cmd === 'pingresp') { - this.pingRespLogged = false; - console.debug('[MeshCore MQTT] PINGRESP received', new Date().toISOString()); + if (packet.cmd === 'pingresp' && !this.pingRespLogged) { + this.pingRespLogged = true; + console.debug( + '[MeshCore MQTT] PINGRESP received (first this session)', + new Date().toISOString(), + ); } }); this.client.on('message', (topic, payload) => { diff --git a/src/renderer/hooks/meshcore/meshcoreConnSideEffects.ts b/src/renderer/hooks/meshcore/meshcoreConnSideEffects.ts index 1f828cfde..ba54e39ed 100644 --- a/src/renderer/hooks/meshcore/meshcoreConnSideEffects.ts +++ b/src/renderer/hooks/meshcore/meshcoreConnSideEffects.ts @@ -243,18 +243,8 @@ async function drainWaitingMessagesManual( deps.setWaitingMessagesCount(total); deps.setWaitingMessagesSyncProgress({ processed: 0, total }); } else if (total === 0) { - console.debug('[meshcoreConnSideEffects] processWaitingMessages empty queue (manual sync)'); return; } - console.debug( - '[meshcoreConnSideEffects] processWaitingMessages start ' + - JSON.stringify({ - count: total, - showSyncBanner: true, - connectionType: deps.connectionType, - mode: 'manual', - }), - ); for (const m of arr) { if (!deps.meshcoreHookMountedRef.current) break; await ingestMeshcoreWaitingMessageItem(m, state, deps); @@ -317,14 +307,6 @@ async function drainWaitingMessagesSilent( deps: MeshcoreWaitingMessagesDrainDeps, ): Promise { const attemptId = beginMeshcoreSilentBulkAttempt(); - console.debug( - '[meshcoreConnSideEffects] processWaitingMessages start ' + - JSON.stringify({ - showSyncBanner: false, - connectionType: deps.connectionType, - mode: 'silent-bulk', - }), - ); try { const msgs = await withTimeout( @@ -339,7 +321,6 @@ async function drainWaitingMessagesSilent( if (!deps.meshcoreHookMountedRef.current) return; const arr = normalizeMeshcoreWaitingMessageBatch(msgs); if (arr.length === 0) { - console.debug('[meshcoreConnSideEffects] processWaitingMessages empty queue (silent bulk)'); return; } state.syncTotal = arr.length; @@ -382,14 +363,6 @@ async function drainWaitingMessagesSilent( state.syncTotal = 0; state.progressActive = true; deps.setWaitingMessagesSyncProgress({ processed: 0, total: 0 }); - console.debug( - '[meshcoreConnSideEffects] processWaitingMessages start ' + - JSON.stringify({ - showSyncBanner: false, - connectionType: deps.connectionType, - mode: 'silent-fallback', - }), - ); if (!deps.meshcoreHookMountedRef.current) return; await drainWaitingMessagesIncremental(conn, state, deps); return; @@ -408,7 +381,6 @@ async function runMeshcoreWaitingMessagesDrain( options: { showSyncBanner: boolean }, deps: MeshcoreWaitingMessagesDrainDeps, ): Promise { - const startedAt = Date.now(); const state: MeshcoreWaitingMessagesDrainState = { processed: 0, bannerActive: false, @@ -429,22 +401,6 @@ async function runMeshcoreWaitingMessagesDrain( } else { await drainWaitingMessagesSilent(conn, state, deps); } - console.debug( - '[meshcoreConnSideEffects] processWaitingMessages done ' + - JSON.stringify({ - count: state.processed, - durationMs: Date.now() - startedAt, - showSyncBanner: options.showSyncBanner, - connectionType: deps.connectionType, - mode: options.showSyncBanner - ? 'manual' - : state.syncTotal > 0 - ? 'silent-bulk' - : state.processed > 0 || state.progressActive - ? 'silent-fallback' - : 'silent', - }), - ); } finally { if (silentDrainUiActive) { deps.setWaitingMessagesSilentDrainActive(false); @@ -646,7 +602,6 @@ export function attachMeshcoreConnSideEffects( } else { requestMeshcoreWaitingMessagesFollowUp(); } - console.debug('[meshcoreConnSideEffects] processWaitingMessages skipped (in flight)'); return getMeshcoreProcessWaitingMessagesInFlight()!; } const showSyncBanner = options?.showSyncBanner !== false; diff --git a/src/renderer/lib/meshtastic/meshtasticConfigureRetry.ts b/src/renderer/lib/meshtastic/meshtasticConfigureRetry.ts index 2ed6935e8..fb420bba6 100644 --- a/src/renderer/lib/meshtastic/meshtasticConfigureRetry.ts +++ b/src/renderer/lib/meshtastic/meshtasticConfigureRetry.ts @@ -11,6 +11,32 @@ const CONFIGURE_RETRYABLE_PATTERN = /packet does not exist/i; let lateConfigureRetryableSwallowUntilMs = 0; +/** + * Ref-count of installed Meshtastic session unhandled-rejection swallow handlers. While > 0, the + * capture-phase handler owns `Packet does not exist` teardown-race rejects, so the app-lifetime + * renderer logger must defer instead of logging them as errors (both listeners are at_target on + * `window`, so registration order — not the capture flag — decides who runs first). + */ +let sessionRejectionSwallowDepth = 0; + +export function beginMeshtasticSessionRejectionSwallow(): void { + sessionRejectionSwallowDepth++; +} + +export function endMeshtasticSessionRejectionSwallow(): void { + sessionRejectionSwallowDepth = Math.max(0, sessionRejectionSwallowDepth - 1); +} + +/** True while a Meshtastic session rejection-swallow handler is installed. */ +export function isMeshtasticSessionRejectionSwallowActive(): boolean { + return sessionRejectionSwallowDepth > 0; +} + +/** Test-only: reset the session swallow ref-count. */ +export function resetMeshtasticSessionRejectionSwallowForTests(): void { + sessionRejectionSwallowDepth = 0; +} + export function isMeshtasticConfigureRetryableError(err: unknown): boolean { return CONFIGURE_RETRYABLE_PATTERN.test(errLikeToLogString(err)); } diff --git a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorConsoleHook.ts b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorConsoleHook.ts index 853f4d2d2..0ffeb533d 100644 --- a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorConsoleHook.ts +++ b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorConsoleHook.ts @@ -1,6 +1,8 @@ import { errLikeToLogString } from '../errLikeToLogString'; import { armMeshtasticLateConfigureRetryableSwallow, + beginMeshtasticSessionRejectionSwallow, + endMeshtasticSessionRejectionSwallow, isMeshtasticConfigureRetryableError, } from './meshtasticConfigureRetry'; import { @@ -79,8 +81,12 @@ export function installMeshtasticSdkRoutingErrorUnhandledRejectionHandler( }; // Capture phase so preventDefault runs before the bubble-phase renderer logger. window.addEventListener('unhandledrejection', handler, { capture: true }); + // Mark a session swallow active so the app-lifetime renderer logger defers to this handler + // even though at_target listeners fire in registration order (renderer logger is installed first). + beginMeshtasticSessionRejectionSwallow(); return () => { window.removeEventListener('unhandledrejection', handler, { capture: true }); + endMeshtasticSessionRejectionSwallow(); // Late SDK queue rejects can settle after wire-effects teardown removes this handler. armMeshtasticLateConfigureRetryableSwallow(); }; diff --git a/src/renderer/lib/rendererUnhandledRejection.test.ts b/src/renderer/lib/rendererUnhandledRejection.test.ts index 7ffa518e9..32ac3bb8b 100644 --- a/src/renderer/lib/rendererUnhandledRejection.test.ts +++ b/src/renderer/lib/rendererUnhandledRejection.test.ts @@ -3,7 +3,10 @@ import { afterEach, describe, expect, it, vi } from 'vitest'; import { armMeshtasticLateConfigureRetryableSwallow, + beginMeshtasticSessionRejectionSwallow, + endMeshtasticSessionRejectionSwallow, resetMeshtasticLateConfigureRetryableSwallowForTests, + resetMeshtasticSessionRejectionSwallowForTests, } from './meshtastic/meshtasticConfigureRetry'; import { installRendererUnhandledRejectionLogger, @@ -50,6 +53,7 @@ function dispatchUnhandledRejection( describe('installRendererUnhandledRejectionLogger', () => { afterEach(() => { resetMeshtasticLateConfigureRetryableSwallowForTests(); + resetMeshtasticSessionRejectionSwallowForTests(); vi.restoreAllMocks(); }); @@ -97,6 +101,39 @@ describe('installRendererUnhandledRejectionLogger', () => { ); }); + it('defers Packet does not exist to the active session swallow handler (no error log)', () => { + const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const uninstall = installRendererUnhandledRejectionLogger(); + beginMeshtasticSessionRejectionSwallow(); + + const event = dispatchUnhandledRejection(new Error('Packet does not exist')); + uninstall(); + + expect(event.defaultPrevented).toBe(true); + expect(errorSpy).not.toHaveBeenCalled(); + // The bubble logger defers silently; the capture-phase session handler owns the debug line. + expect(debugSpy).not.toHaveBeenCalled(); + + endMeshtasticSessionRejectionSwallow(); + }); + + it('still logs unrelated rejections while a session swallow handler is active', () => { + const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const uninstall = installRendererUnhandledRejectionLogger(); + beginMeshtasticSessionRejectionSwallow(); + + dispatchUnhandledRejection(new Error('genuine failure')); + uninstall(); + + expect(errorSpy).toHaveBeenCalledWith( + '[renderer] Unhandled rejection:', + expect.stringContaining('genuine failure'), + ); + + endMeshtasticSessionRejectionSwallow(); + }); + it('does not log Packet does not exist during armed late-swallow window', () => { const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); diff --git a/src/renderer/lib/rendererUnhandledRejection.ts b/src/renderer/lib/rendererUnhandledRejection.ts index 7633cf41e..fb058b866 100644 --- a/src/renderer/lib/rendererUnhandledRejection.ts +++ b/src/renderer/lib/rendererUnhandledRejection.ts @@ -1,4 +1,8 @@ -import { shouldSwallowLateMeshtasticConfigureRetryableRejection } from './meshtastic/meshtasticConfigureRetry'; +import { + isMeshtasticConfigureRetryableError, + isMeshtasticSessionRejectionSwallowActive, + shouldSwallowLateMeshtasticConfigureRetryableRejection, +} from './meshtastic/meshtasticConfigureRetry'; /** Log renderer-wide unhandled promise rejections without throwing a second error. */ export function logRendererUnhandledRejection(reason: unknown): void { @@ -13,6 +17,16 @@ export function installRendererUnhandledRejectionLogger(target: Window = window) const handler = (event: PromiseRejectionEvent) => { // Capture-phase Meshtastic handler may have already preventDefault'd queue rejections. if (event.defaultPrevented) return; + // While a Meshtastic session swallow handler is installed, it owns the mid-send + // `Packet does not exist` teardown race. This bubble handler is registered first, so it runs + // before the capture handler at_target — defer (no error log) and let it log + preventDefault. + if ( + isMeshtasticSessionRejectionSwallowActive() && + isMeshtasticConfigureRetryableError(event.reason) + ) { + event.preventDefault(); + return; + } // Only during a short post-teardown window (armed when Meshtastic session handler unsubscribes). if (shouldSwallowLateMeshtasticConfigureRetryableRejection(event.reason)) { console.debug( diff --git a/src/renderer/stores/diagnosticsStore.ts b/src/renderer/stores/diagnosticsStore.ts index 3e70396fb..6c592bc15 100644 --- a/src/renderer/stores/diagnosticsStore.ts +++ b/src/renderer/stores/diagnosticsStore.ts @@ -1584,7 +1584,6 @@ export const useDiagnosticsStore = create((set, get) => ({ clearDiagnostics(options) { const preserveForeignLora = options?.preserveForeignLora === true; - console.debug(`[diagnosticsStore] clearDiagnostics preserveForeignLora=${preserveForeignLora}`); if (diagnosticsDebounce.incrementalAnalysisTimer) clearTimeout(diagnosticsDebounce.incrementalAnalysisTimer); diagnosticsDebounce.incrementalAnalysisTimer = null; diff --git a/src/renderer/stores/reticulumPeerStore.ts b/src/renderer/stores/reticulumPeerStore.ts index 291b6f111..e9c7ef6e2 100644 --- a/src/renderer/stores/reticulumPeerStore.ts +++ b/src/renderer/stores/reticulumPeerStore.ts @@ -1261,7 +1261,7 @@ async function refreshReticulumPeersFromSidecarOnce( } const elapsed = (typeof performance !== 'undefined' ? performance.now() : Date.now()) - started; - if (elapsed > 2000 || peers.size > 2000) { + if (elapsed > 2000) { console.debug( `[reticulumPeerStore] full refresh ${Math.round(elapsed)}ms peers=${peers.size} force=${Boolean(opts.forceRefresh)}`, ); From ee34c903e649437da9371424f939cf10c6b4ee2f Mon Sep 17 00:00:00 2001 From: Joey Stanford Date: Sat, 8 Aug 2026 22:00:09 -0600 Subject: [PATCH 2/3] fix(meshtastic): auto-request recipient key on PKI DM send failure When an outbound DM fails with PKI_SEND_FAIL_PUBLIC_KEY or PKI_UNKNOWN_PUBKEY the recipient's public key is missing from the NodeDB, so a manual retry would fail identically. Trigger the existing rate-limited NODEINFO request for the recipient node so the key lands in the NodeDB and a retry can succeed. - Add isMeshtasticMissingRecipientKeyError() and an optional onMissingRecipientKey(recipientNodeNum) callback to the routing-error apply context; fire it for DM rows (broadcast rows carry no recipient) after the row is marked failed. - Wire maybeRequestNodeInfoForNode (NODEINFO_APP, 120s/node rate limit) into both the console-log and queue-rejection apply paths. - Tests: NODEINFO requested for PKI missing-key DM rows; not requested for non-key errors, broadcast rows, or unmatched packets; predicate unit test. MAX_RETRANSMIT is unchanged (already fails with manual retry available). --- .../meshtasticRuntimeWireEffects.ts | 2 + .../meshtasticSdkRoutingErrorLog.test.ts | 65 ++++++++++++++++++- .../meshtasticSdkRoutingErrorLog.ts | 14 ++++ 3 files changed, 80 insertions(+), 1 deletion(-) diff --git a/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts b/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts index 112e55ab4..0bc1e5147 100644 --- a/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts +++ b/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts @@ -834,6 +834,7 @@ export function attachMeshtasticRuntimeWireEffects( myNodeNum: myNodeNumRef.current, identityId: meshtasticIdentityIdRef.current, tempIdToWirePacketId: ackMeshPacketIdByTempIdRef.current, + onMissingRecipientKey: maybeRequestNodeInfoForNode, }); }; @@ -842,6 +843,7 @@ export function attachMeshtasticRuntimeWireEffects( myNodeNum: myNodeNumRef.current, identityId: meshtasticIdentityIdRef.current, tempIdToWirePacketId: ackMeshPacketIdByTempIdRef.current, + onMissingRecipientKey: maybeRequestNodeInfoForNode, }); if (!uiApplied) { const parsed = reason as { id?: number; packetId?: number; error?: number }; diff --git a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.test.ts b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.test.ts index 9142d478d..ef53b95bd 100644 --- a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.test.ts +++ b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.test.ts @@ -34,6 +34,7 @@ import { applyMeshtasticOutboundRoutingErrorFromRejection, chatRoutingErrorKeyForSdkErrorName, humanizeMeshtasticSdkQueueRejectionError, + isMeshtasticMissingRecipientKeyError, parseMeshtasticSdkQueueRejection, parseMeshtasticSdkRoutingErrorLog, } from './meshtasticSdkRoutingErrorLog'; @@ -48,6 +49,7 @@ interface SeedRow { channelIndex?: number; timestamp?: number; from?: number; + to?: number; } function clearStoreMessages(): void { @@ -66,7 +68,7 @@ function seedOutbound(rows: SeedRow[]): void { id: String(row.packetId), from: row.from ?? 42, senderName: 'Me', - to: 0xffffffff, + to: row.to ?? 0xffffffff, payload: row.payload ?? 'hello', channelIndex: row.channelIndex ?? 0, timestamp: row.timestamp ?? Date.now(), @@ -271,6 +273,67 @@ describe('meshtasticSdkRoutingErrorLog', () => { ).toBeTruthy(); expect(humanizeMeshtasticSdkQueueRejectionError('x')).toBeNull(); }); + + it('requests recipient NODEINFO on PKI_SEND_FAIL_PUBLIC_KEY for a DM row', () => { + seedOutbound([{ packetId: 669520633, to: 0x1234 }]); + const onMissingRecipientKey = vi.fn(); + const applied = applyMeshtasticOutboundRoutingErrorFromLog( + 'Error received for packet 669520633: PKI_SEND_FAIL_PUBLIC_KEY', + { myNodeNum: 42, identityId: IDENTITY, onMissingRecipientKey }, + ); + expect(applied).toBe(true); + expect(onMissingRecipientKey).toHaveBeenCalledWith(0x1234); + }); + + it('requests recipient NODEINFO on PKI_UNKNOWN_PUBKEY for a DM row', () => { + seedOutbound([{ packetId: 669520633, to: 0xabcd }]); + const onMissingRecipientKey = vi.fn(); + applyMeshtasticOutboundRoutingErrorFromLog( + 'Error received for packet 669520633: PKI_UNKNOWN_PUBKEY', + { myNodeNum: 42, identityId: IDENTITY, onMissingRecipientKey }, + ); + expect(onMissingRecipientKey).toHaveBeenCalledWith(0xabcd); + }); + + it('does not request NODEINFO for non-key routing errors', () => { + seedOutbound([{ packetId: 711859058, to: 0x1234 }]); + const onMissingRecipientKey = vi.fn(); + applyMeshtasticOutboundRoutingErrorFromLog('Packet 711859058 of type packet timed out', { + myNodeNum: 42, + identityId: IDENTITY, + onMissingRecipientKey, + }); + expect(onMissingRecipientKey).not.toHaveBeenCalled(); + }); + + it('does not request NODEINFO for a broadcast row (no recipient)', () => { + seedOutbound([{ packetId: 669520633 }]); + const onMissingRecipientKey = vi.fn(); + const applied = applyMeshtasticOutboundRoutingErrorFromLog( + 'Error received for packet 669520633: PKI_SEND_FAIL_PUBLIC_KEY', + { myNodeNum: 42, identityId: IDENTITY, onMissingRecipientKey }, + ); + expect(applied).toBe(true); + expect(onMissingRecipientKey).not.toHaveBeenCalled(); + }); + + it('does not request NODEINFO when no outbound row matches', () => { + seedOutbound([]); + const onMissingRecipientKey = vi.fn(); + const applied = applyMeshtasticOutboundRoutingErrorFromLog( + 'Error received for packet 669520633: PKI_SEND_FAIL_PUBLIC_KEY', + { myNodeNum: 42, identityId: IDENTITY, onMissingRecipientKey }, + ); + expect(applied).toBe(false); + expect(onMissingRecipientKey).not.toHaveBeenCalled(); + }); + + it('classifies missing recipient key errors', () => { + expect(isMeshtasticMissingRecipientKeyError('PKI_SEND_FAIL_PUBLIC_KEY')).toBe(true); + expect(isMeshtasticMissingRecipientKeyError('PKI_UNKNOWN_PUBKEY')).toBe(true); + expect(isMeshtasticMissingRecipientKeyError('MAX_RETRANSMIT')).toBe(false); + expect(isMeshtasticMissingRecipientKeyError('TIMEOUT')).toBe(false); + }); }); describe('installMeshtasticSdkRoutingErrorConsoleHook', () => { diff --git a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts index c916a2e99..4b8f12b70 100644 --- a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts +++ b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts @@ -69,6 +69,14 @@ export function humanizeMeshtasticSdkQueueRejectionError(reason: unknown): strin return i18nKey ? i18n.t(i18nKey) : parsed.errorName; } +/** + * True for routing errors that mean we lack a usable public key for the DM recipient. + * Requesting the recipient's NODEINFO can recover the key so a retry succeeds. + */ +export function isMeshtasticMissingRecipientKeyError(errorName: string): boolean { + return errorName === 'PKI_SEND_FAIL_PUBLIC_KEY' || errorName === 'PKI_UNKNOWN_PUBKEY'; +} + export function chatRoutingErrorKeyForSdkErrorName(errorName: string): string | null { switch (errorName) { case 'PKI_SEND_FAIL_PUBLIC_KEY': @@ -98,6 +106,8 @@ export interface ApplyMeshtasticOutboundRoutingErrorContext { identityId: string | null; /** tempId → wire packet id assigned by the SDK (may differ from optimistic id). */ tempIdToWirePacketId?: ReadonlyMap; + /** Invoked with the recipient node num when a DM fails for lack of that node's public key. */ + onMissingRecipientKey?: (recipientNodeNum: number) => void; } function outboundMatchesWirePacketId( @@ -191,6 +201,10 @@ export function applyMeshtasticOutboundRoutingError( } const storeMessageId = resolveStoreMessageId(target, parsed.packetId); updateMessageStatus(identityId, storeMessageId, 'failed', errorText); + // Missing recipient public key: fetch the recipient's NODEINFO so a retry can succeed. + if (isMeshtasticMissingRecipientKeyError(parsed.errorName) && target.to != null) { + ctx.onMissingRecipientKey?.(target.to); + } // The DB row may still hold the optimistic temp packet id (device never acked, // so updateMessagePacketId never ran) — key the update on the row's own id, // not the wire id from the radio NAK, or the UPDATE matches zero rows. From 4f5b949b915de66caae314b1c2ba53d4c2d90b2c Mon Sep 17 00:00:00 2001 From: Joey Stanford Date: Sat, 8 Aug 2026 22:20:01 -0600 Subject: [PATCH 3/3] fix(review): harden PKI key refresh, MQTT stale-client guard, log threshold Address PR #827 review comments: - meshtasticRuntimeWireEffects: PKI missing-recipient-key recovery now bypasses the display-identity short-circuit so recipients we already know by name but lack a usable public key still trigger a NODEINFO/key refresh, while keeping the existing request rate limit. - meshtasticSdkRoutingErrorLog: never call onMissingRecipientKey for the broadcast address (defensive; adapter already nulls broadcast `to`). - meshcore-mqtt-adapter: packetsend/packetreceive listeners capture their session client and ignore callbacks once this.client has been replaced, so a stale mqtt.js client cannot touch lastPacketReceivedAt or consume the new session's first-ping logs; add coverage. - reticulumPeerStore.test: assert full-refresh debug logs only when elapsed exceeds the 2s threshold. --- src/main/meshcore-mqtt-adapter.test.ts | 71 +++++++++++++++++++ src/main/meshcore-mqtt-adapter.ts | 10 ++- .../meshtasticRuntimeWireEffects.ts | 22 ++++-- .../meshtasticSdkRoutingErrorLog.ts | 9 ++- .../stores/reticulumPeerStore.test.ts | 50 +++++++++++++ 5 files changed, 154 insertions(+), 8 deletions(-) diff --git a/src/main/meshcore-mqtt-adapter.test.ts b/src/main/meshcore-mqtt-adapter.test.ts index 0a53e989f..9b1b41995 100644 --- a/src/main/meshcore-mqtt-adapter.test.ts +++ b/src/main/meshcore-mqtt-adapter.test.ts @@ -141,6 +141,77 @@ describe('MeshcoreMqttAdapter — PING logging', () => { }); }); +describe('MeshcoreMqttAdapter — stale client isolation', () => { + let adapter: MeshcoreMqttAdapter; + + interface AdapterPacketPrivate { + lastPacketReceivedAt: number; + } + + const makeClient = () => ({ + on: vi.fn(), + end: vi.fn(), + removeAllListeners: vi.fn(), + connected: false, + publish: vi.fn(), + subscribe: vi.fn(), + reschedulePing: vi.fn(), + options: {}, + stream: {}, + }); + + const lastHandler = ( + client: { on: ReturnType }, + name: string, + ): ((packet: { cmd: string }) => void) => { + const hits = client.on.mock.calls.filter((c: unknown[]) => c[0] === name); + return hits[hits.length - 1]?.[1] as (packet: { cmd: string }) => void; + }; + + beforeEach(async () => { + const mqtt = await import('mqtt'); + vi.mocked(mqtt.connect).mockClear(); + adapter = new MeshcoreMqttAdapter(); + adapter.on('error', () => {}); + }); + + afterEach(() => { + adapter.disconnect(); + vi.restoreAllMocks(); + }); + + it('ignores packet events from a client that is no longer this.client', async () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const mqttMod = await import('mqtt'); + const first = makeClient(); + const second = makeClient(); + vi.mocked(mqttMod.connect) + .mockImplementationOnce(() => first as never) + .mockImplementationOnce(() => second as never); + + adapter.connect({ ...BASE_SETTINGS }); + // Reconnect: connect() force-ends `first` and installs `second` as this.client. + adapter.connect({ ...BASE_SETTINGS }); + + const priv = adapter as unknown as AdapterPacketPrivate; + priv.lastPacketReceivedAt = 0; + + // Stale `first` client emits after it was replaced — must be ignored entirely. + lastHandler(first, 'packetreceive')({ cmd: 'pingresp' }); + lastHandler(first, 'packetsend')({ cmd: 'pingreq' }); + expect(priv.lastPacketReceivedAt).toBe(0); + expect(debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGRESP'))).toHaveLength(0); + expect(debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGREQ'))).toHaveLength(0); + + // Live `second` client still updates state and consumes the first-ping logs. + lastHandler(second, 'packetreceive')({ cmd: 'pingresp' }); + lastHandler(second, 'packetsend')({ cmd: 'pingreq' }); + expect(priv.lastPacketReceivedAt).toBeGreaterThan(0); + expect(debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGRESP'))).toHaveLength(1); + expect(debugSpy.mock.calls.filter((c) => String(c[0]).includes('PINGREQ'))).toHaveLength(1); + }); +}); + describe('MeshcoreMqttAdapter — clientId', () => { let adapter: MeshcoreMqttAdapter; diff --git a/src/main/meshcore-mqtt-adapter.ts b/src/main/meshcore-mqtt-adapter.ts index 3afa7fa09..93d127609 100644 --- a/src/main/meshcore-mqtt-adapter.ts +++ b/src/main/meshcore-mqtt-adapter.ts @@ -316,6 +316,10 @@ export class MeshcoreMqttAdapter extends EventEmitter { this.setStatus('connecting'); this.connectAbortByWatchdog = false; this.client = mqtt.connect(connectOpts); + // Capture this session's client so listeners from an already-replaced (stale) client + // — mqtt.js can still emit after end() — cannot touch lastPacketReceivedAt or consume + // the new session's first-ping logs. + const sessionClient = this.client; this.client.on('error', (err) => { this.clearConnectTimers(); console.error( @@ -406,7 +410,8 @@ export class MeshcoreMqttAdapter extends EventEmitter { // Schedule proactive token refresh this.scheduleTokenRefresh(); }); - this.client.on('packetsend', (packet) => { + sessionClient.on('packetsend', (packet) => { + if (this.client !== sessionClient) return; if (packet.cmd === 'pingreq' && !this.pingReqLogged) { this.pingReqLogged = true; console.debug( @@ -415,7 +420,8 @@ export class MeshcoreMqttAdapter extends EventEmitter { ); } }); - this.client.on('packetreceive', (packet) => { + sessionClient.on('packetreceive', (packet) => { + if (this.client !== sessionClient) return; this.lastPacketReceivedAt = Date.now(); if (packet.cmd === 'pingresp' && !this.pingRespLogged) { this.pingRespLogged = true; diff --git a/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts b/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts index 0bc1e5147..35e452a15 100644 --- a/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts +++ b/src/renderer/lib/meshtastic/meshtasticRuntimeWireEffects.ts @@ -622,11 +622,19 @@ export function attachMeshtasticRuntimeWireEffects( }); unsubscribesRef.current.push(unsub2); - const maybeRequestNodeInfoForNode = (from: number): void => { + const maybeRequestNodeInfoForNode = ( + from: number, + opts?: { ignoreDisplayIdentity?: boolean }, + ): void => { if (from === 0 || from === myNodeNumRef.current) return; if (isConfiguringRef.current) return; - const existing = getIdentityNode(meshtasticIdentityIdRef.current, from); - if (existing && !meshtasticNodeLacksDisplayIdentity(existing, from)) return; + // Missing-recipient-key recovery must refresh even nodes that already have a + // display name (we know who they are, we just lack a usable public key), so it + // opts out of the display-identity short-circuit while keeping the rate limit. + if (!opts?.ignoreDisplayIdentity) { + const existing = getIdentityNode(meshtasticIdentityIdRef.current, from); + if (existing && !meshtasticNodeLacksDisplayIdentity(existing, from)) return; + } const now = Date.now(); const last = lastNodeInfoRequestAtRef.current.get(from) ?? 0; if (now - last < REQUEST_NODEINFO_MIN_INTERVAL_MS) return; @@ -834,7 +842,9 @@ export function attachMeshtasticRuntimeWireEffects( myNodeNum: myNodeNumRef.current, identityId: meshtasticIdentityIdRef.current, tempIdToWirePacketId: ackMeshPacketIdByTempIdRef.current, - onMissingRecipientKey: maybeRequestNodeInfoForNode, + onMissingRecipientKey: (recipientNodeNum) => { + maybeRequestNodeInfoForNode(recipientNodeNum, { ignoreDisplayIdentity: true }); + }, }); }; @@ -843,7 +853,9 @@ export function attachMeshtasticRuntimeWireEffects( myNodeNum: myNodeNumRef.current, identityId: meshtasticIdentityIdRef.current, tempIdToWirePacketId: ackMeshPacketIdByTempIdRef.current, - onMissingRecipientKey: maybeRequestNodeInfoForNode, + onMissingRecipientKey: (recipientNodeNum) => { + maybeRequestNodeInfoForNode(recipientNodeNum, { ignoreDisplayIdentity: true }); + }, }); if (!uiApplied) { const parsed = reason as { id?: number; packetId?: number; error?: number }; diff --git a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts index 4b8f12b70..17bce8a3c 100644 --- a/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts +++ b/src/renderer/lib/meshtastic/meshtasticSdkRoutingErrorLog.ts @@ -4,6 +4,7 @@ import { resolveMeshtasticOutboundStoreKey } from '@/renderer/lib/sessions/mesht import { messageRecordsToChatMessages } from '@/renderer/lib/storeRecordAdapters'; import type { ChatMessage } from '@/renderer/lib/types'; import { updateMessageStatus, useMessageStore } from '@/renderer/stores/messageStore'; +import { isMeshtasticBroadcastNodeNum } from '@/shared/nodeNameUtils'; import { meshtasticRoutingErrorName } from './meshtasticApplyErrorMessage'; import { @@ -202,7 +203,13 @@ export function applyMeshtasticOutboundRoutingError( const storeMessageId = resolveStoreMessageId(target, parsed.packetId); updateMessageStatus(identityId, storeMessageId, 'failed', errorText); // Missing recipient public key: fetch the recipient's NODEINFO so a retry can succeed. - if (isMeshtasticMissingRecipientKeyError(parsed.errorName) && target.to != null) { + // Only for real DM recipients — never the broadcast address (a PKI NAK there is not + // a per-node key gap, and 0xffffffff has no NODEINFO to fetch). + if ( + isMeshtasticMissingRecipientKeyError(parsed.errorName) && + target.to != null && + !isMeshtasticBroadcastNodeNum(target.to) + ) { ctx.onMissingRecipientKey?.(target.to); } // The DB row may still hold the optimistic temp packet id (device never acked, diff --git a/src/renderer/stores/reticulumPeerStore.test.ts b/src/renderer/stores/reticulumPeerStore.test.ts index 87cb689d3..2e2bc46a8 100644 --- a/src/renderer/stores/reticulumPeerStore.test.ts +++ b/src/renderer/stores/reticulumPeerStore.test.ts @@ -1101,6 +1101,56 @@ describe('reticulumPeerStore', () => { }); }); + const stubRefreshWindow = (): void => { + vi.stubGlobal('window', { + electronAPI: { + reticulum: { + proxyGet: vi.fn((path: string) => { + if (path === '/api/v1/contacts') return Promise.resolve({ contacts: [] }); + if (path === '/api/v1/peers' || path.startsWith('/api/v1/peers?')) { + return Promise.resolve({ peers: [{ destination_hash: 'bb', hops: 3 }] }); + } + if (path === '/api/v1/nomadnetwork/nodes') return Promise.resolve({ nodes: [] }); + return Promise.resolve({}); + }), + }, + db: { getReticulumDestinations: vi.fn().mockResolvedValue([]) }, + }, + }); + }; + + it('does not log a full-refresh debug line when refresh completes under 2s', async () => { + stubRefreshWindow(); + // started and elapsed both read the same clock value → elapsed 0ms. + vi.spyOn(performance, 'now').mockReturnValue(1000); + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + + await refreshReticulumPeersFromSidecar({ forceRefresh: true }); + + expect(useReticulumPeerStore.getState().peers.get('bb')?.hops).toBe(3); + expect(debugSpy.mock.calls.filter((c) => String(c[0]).includes('full refresh'))).toHaveLength( + 0, + ); + debugSpy.mockRestore(); + }); + + it('logs a full-refresh debug line when refresh exceeds the 2s threshold', async () => { + stubRefreshWindow(); + // First now() call seeds `started` at 0; all later calls (incl. elapsed calc) → 5000ms. + vi.spyOn(performance, 'now').mockReturnValueOnce(0).mockReturnValue(5000); + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + + await refreshReticulumPeersFromSidecar({ forceRefresh: true }); + + expect(useReticulumPeerStore.getState().peers.get('bb')?.hops).toBe(3); + const fullRefreshLogs = debugSpy.mock.calls.filter((c) => + String(c[0]).includes('full refresh'), + ); + expect(fullRefreshLogs).toHaveLength(1); + expect(String(fullRefreshLogs[0][0])).toContain('5000ms'); + debugSpy.mockRestore(); + }); + it('applyReticulumAnnounceReceivedOptimistic inserts a peer before path-table refresh', () => { applyReticulumAnnounceReceivedOptimistic({ destination_hash: 'AaBbCcDdEeFf00112233445566778899',