From 4a4766f52d73347123d15f4d0898b8a2da0082d9 Mon Sep 17 00:00:00 2001 From: Renato Alcara Date: Sun, 26 Apr 2026 11:15:55 -0300 Subject: [PATCH] chore(logs): reduce decrypt-error noise (~75% fewer lines per recoverable Bad MAC) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit USER REPORT: Production logs flooded with verbose error blocks for every Bad MAC recovery cycle. Each recoverable Bad MAC was producing ~40 log lines (transaction failures, double-printed Bad MAC headers, full err.stack from libsignal). After this change: ~10 lines, no functional change. Changes: 1. src/Utils/auth-utils.ts (transaction failed handler): Downgrade SessionError to logger.debug — these are part of the normal Bad MAC recovery flow (retry receipt → sender resends as pkmsg → new session in ~1.3s). Other error names continue to log as ERROR. Error is still re-thrown — recovery behavior unchanged. Each Bad MAC recovery cycle saves 2 ERROR lines + the verbose error dump that pino attaches to logger.error. 2. src/Utils/decode-wa-message.ts (errorContext + sessionRecordErrors): - Added 'No matching sessions found' to sessionRecordErrors so the libsignal "decryptWithSessions exhausted all sessions" error categorises into the session-record branch (DEBUG on retry, ERROR only when retries exhausted) instead of falling through to the unknown-error branch (always ERROR + full stack). - Slim `errorContext.err` from full originalError to {name, message, type}. The 4-5 lines of node_modules/libsignal stack trace per log are noise for these recoverable error types. Full stack still available to custom handlers that may chain off originalError. 3. src/index.ts (DEDUP_WINDOW_MS): Increase from 150ms → 5000ms. Retry attempts of the same message are typically 300-1000ms apart, so the second attempt fell outside the 150ms window and double-printed the masked Bad MAC line. 5s comfortably covers a full retry pair without suppressing genuinely new errors for the same JID. INVARIANTS PRESERVED: - Bad MAC recovery flow unchanged (sender resends pkmsg → new session) - Retry receipt continues to be sent - Errors are still thrown — only log verbosity changes - ERROR-level still fires for genuinely unknown errors and retry-exhausted cases - Customizations untouched: zero diff in carousel/buttons/lists/proto/LID-PN If you need to debug a specific Bad MAC issue, set BAILEYS_LOG_LEVEL=debug in the environment to surface the SessionError transaction logs again. Tests: 35/35 suites, 824/824 passing. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/Utils/auth-utils.ts | 13 ++++++++++++- src/Utils/decode-wa-message.ts | 20 ++++++++++++++++++-- src/index.ts | 8 ++++++-- 3 files changed, 36 insertions(+), 5 deletions(-) diff --git a/src/Utils/auth-utils.ts b/src/Utils/auth-utils.ts index 204e16be..adabf548 100644 --- a/src/Utils/auth-utils.ts +++ b/src/Utils/auth-utils.ts @@ -341,7 +341,18 @@ export const addTransactionCapability = ( return result } catch (error) { - logger.error({ error }, 'transaction failed, rolling back') + // SessionError is part of the normal Bad MAC recovery flow + // (retry receipt → sender resends as pkmsg → new session within ~1.3s). + // Logging it as ERROR creates 2 noise lines per recoverable Bad MAC cycle. + // Downgrade to debug for SessionError; keep ERROR for everything else. + // The error is still re-thrown — recovery behavior is unchanged. + const errName = (error as { name?: string })?.name + if (errName === 'SessionError') { + logger.debug({ error }, 'transaction failed (SessionError — recoverable via retry receipt)') + } else { + logger.error({ error }, 'transaction failed, rolling back') + } + throw error } }) diff --git a/src/Utils/decode-wa-message.ts b/src/Utils/decode-wa-message.ts index a88e06be..171338f7 100644 --- a/src/Utils/decode-wa-message.ts +++ b/src/Utils/decode-wa-message.ts @@ -58,7 +58,11 @@ export const BAD_MAC_ERROR_TEXT = 'Bad MAC' export const DECRYPTION_RETRY_CONFIG = { maxRetries: 3, baseDelayMs: 100, - sessionRecordErrors: ['No session record', 'SessionError: No session record'], + // 'No matching sessions found' is the libsignal error when decryptWithSessions exhausts + // all stored sessions for a JID. Same recovery flow (retry receipt → pkmsg → new session) + // — categorise it as session-record so the caller logs DEBUG on retry, ERROR only when + // retries are exhausted (instead of dumping the full stack as an unknown error). + sessionRecordErrors: ['No session record', 'SessionError: No session record', 'No matching sessions found'], corruptedSessionErrors: ['Bad MAC', 'MessageCounterError', MISSING_KEYS_ERROR_TEXT] } @@ -421,9 +425,21 @@ export const decryptMessageNode = ( const isCorrupted = isCorruptedSessionError(originalError) const isSessionRecord = isSessionRecordError(originalError) + // Slim error projection — keep name/message/type for diagnosis, + // drop `stack` which adds 4-5 lines of node_modules paths per log + // for known-recoverable libsignal errors. Full stack is still + // available via originalError if needed in custom handlers. + const slimErr = originalError + ? { + name: (originalError as { name?: string }).name, + message: (originalError as { message?: string }).message, + type: (originalError as { type?: string }).type + } + : undefined + const errorContext = { key: fullMessage.key, - err: originalError, + err: slimErr, messageType: tag === 'plaintext' ? 'plaintext' : attrs.type, sender, author, diff --git a/src/index.ts b/src/index.ts index e997ddfd..745af59f 100644 --- a/src/index.ts +++ b/src/index.ts @@ -28,7 +28,11 @@ console.info = function (...args: unknown[]) { // Track errors by type + JID to avoid duplicates (using Map for better performance) const _errorTimestamps = new Map() -const DEDUP_WINDOW_MS = 150 +// Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc). +// Was 150ms, but retry attempts of the SAME message are typically ~300-1000ms apart, +// so the second attempt fell outside the window and double-printed. 5s comfortably +// covers a retry pair without suppressing genuinely new errors for the same JID. +const DEDUP_WINDOW_MS = 5000 console.error = function (...args: unknown[]) { if (args.length > 0 && typeof args[0] === 'string') { @@ -70,7 +74,7 @@ console.error = function (...args: unknown[]) { const lastTime = _errorTimestamps.get(dedupeKey) if (lastTime && now - lastTime < DEDUP_WINDOW_MS) { - return // Skip duplicate within 150ms window + return // Skip duplicate within DEDUP_WINDOW_MS window } _errorTimestamps.set(dedupeKey, now)