Compare commits

...

2 Commits

Author SHA1 Message Date
Renato Alcara 5737ba590c fix: preserve full Error for unknown decrypt failures + improve dedup comment
Addresses 3 distinct PR #391 review findings (Copilot Major + Codex P2 + Copilot
nitpick — all valid):

#2 Copilot Major + #4 Codex P2 (same root, MAJOR):
   The previous slim of `errorContext.err` to `{name, message, type}` was applied
   uniformly to all three decrypt-failure branches. The unknown-error branch
   (lines 481-491 — "Unknown/unexpected errors (protobuf, parsing, etc.)") is
   exactly where stack traces matter MOST: there's no recovery path for those,
   so production root-cause analysis depends on having the stack.

   FIX: condition `errorContext.err` on category. Only slim for known-recoverable
   categories (corrupted-session / session-record). Unknown errors keep the full
   originalError so logger.error pino still emits the stack. Adds the
   `isRecoverableCategory` flag to make the intent obvious to future readers.

#3 Copilot (related to #2):
   The previous comment claimed "Full stack is still available via originalError
   if needed in custom handlers" — but originalError wasn't actually exposed
   anywhere downstream and the error wasn't re-thrown. Updated the comment to
   reflect the new conditional behavior (slim only for recoverable cases) so
   future maintainers don't misread the intent.

#1 Copilot (dedup window comment, MINOR):
   The 5000ms dedup window in src/index.ts can suppress genuinely-different
   errors for the same JID within the window. Kept the 5s value (it's the right
   trade-off for noisy production streams) but expanded the comment to spell
   out the trade-off and how to bypass it (BAILEYS_LOG_LEVEL=debug).

Skipped: nothing — all reviewer points addressed.

Tests: 35/35 suites, 824/824 still passing.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-26 11:32:03 -03:00
Renato Alcara 4a4766f52d chore(logs): reduce decrypt-error noise (~75% fewer lines per recoverable Bad MAC)
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) <noreply@anthropic.com>
2026-04-26 11:15:55 -03:00
3 changed files with 46 additions and 5 deletions
+12 -1
View File
@@ -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
}
})
+23 -2
View File
@@ -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,26 @@ 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.
//
// CRITICAL: only slim for KNOWN-RECOVERABLE categories (corrupted /
// session-record). The unknown-error branch keeps the full Error so
// protobuf/parsing/runtime bugs still emit a stack trace where it
// matters most. Catches Copilot/Codex P2 review on PR #391.
const slimErr = originalError
? {
name: (originalError as { name?: string }).name,
message: (originalError as { message?: string }).message,
type: (originalError as { type?: string }).type
}
: undefined
const isRecoverableCategory = isCorrupted || isSessionRecord
const errorContext = {
key: fullMessage.key,
err: originalError,
err: isRecoverableCategory ? slimErr : originalError,
messageType: tag === 'plaintext' ? 'plaintext' : attrs.type,
sender,
author,
+11 -2
View File
@@ -28,7 +28,16 @@ console.info = function (...args: unknown[]) {
// Track errors by type + JID to avoid duplicates (using Map for better performance)
const _errorTimestamps = new Map<string, number>()
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.
//
// TRADE-OFF: dedup key is `errorType + JID` (no message-id). With 5s, a burst of
// errors for the SAME JID — even of slightly different categories or different
// messages — collapses to one log line every 5s. This is intentional for a noisy
// production stream; if you need per-message visibility, set BAILEYS_LOG_LEVEL=debug
// to bypass this console-side dedup and see the structured pino logs in full.
const DEDUP_WINDOW_MS = 5000
console.error = function (...args: unknown[]) {
if (args.length > 0 && typeof args[0] === 'string') {
@@ -70,7 +79,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)