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>
This commit is contained in:
+12
-1
@@ -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
|
||||
}
|
||||
})
|
||||
|
||||
@@ -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,
|
||||
|
||||
+6
-2
@@ -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<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. 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)
|
||||
|
||||
Reference in New Issue
Block a user