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
+23 -149
View File
@@ -54,7 +54,7 @@ import {
resolveLidToPn
} from '../Utils'
import { makeKeyedMutex, makeMutex } from '../Utils/make-mutex'
import processMessage, { getChatId } from '../Utils/process-message'
import processMessage from '../Utils/process-message'
import { buildTcTokenFromJid } from '../Utils/tc-token-utils'
import {
type BinaryNode,
@@ -130,18 +130,6 @@ export const makeChatsSocket = (config: SocketConfig) => {
/** this mutex ensures that notifications from the same chat are processed in order, while allowing parallel processing across chats */
const notificationMutex = makeKeyedMutex()
/**
* Per-chat mutex dedicated to post-upsert work (history app-state sync +
* processMessage side effects). Kept separate from `messageMutex` because
* the inbound caller already holds `messageMutex(chatId)` while running
* decrypt + upsertMessage; sharing the same mutex would let a concurrently-
* arrived message N+1 enqueue *between* msg N's outer callback and msg N's
* post-upsert task, so msg N+1's processMessage could run before msg N's
* (breaking per-chat ordering of side effects). With a separate mutex,
* post-upsert tasks enqueue strictly in upsertMessage call order.
*/
const postUpsertMutex = makeKeyedMutex()
// Timeout for AwaitingInitialSync state
let awaitingSyncTimeout: NodeJS.Timeout | undefined
@@ -1411,19 +1399,7 @@ export const makeChatsSocket = (config: SocketConfig) => {
blockedCollections.clear()
logger.info('Doing app state sync')
try {
await resyncAppState(ALL_WA_PATCH_NAMES, true)
} catch (err) {
// Failure recovery: without this, syncState would stay at Syncing
// and ev.flush() would never run, leaving the event buffer pinned
// until the buffer's own safety timeout expires. Force the state
// machine forward so live inbound events can flow even if the
// app-state resync failed (collections are already cleared, so
// blocked patches will be retried on the next creds.update tick).
syncState = SyncState.Online
ev.flush()
throw err
}
await resyncAppState(ALL_WA_PATCH_NAMES, true)
// Sync is complete, go online and flush everything
syncState = SyncState.Online
@@ -1435,131 +1411,29 @@ export const makeChatsSocket = (config: SocketConfig) => {
}
}
// Post-upsert work: history app-state sync + processMessage side effects.
// Awaiting here keeps `messages.upsert` pinned in the event buffer
// (createBufferedFunction only schedules flush after work() resolves), so
// the hot path detaches this work to release the emit on the next debounce
// tick.
//
// Use Promise.allSettled so the combined promise only settles after BOTH
// tasks finish. With a plain Promise.all, an early rejection from one task
// would release the keyed mutex while the other task is still mutating
// chat state — letting the next message of the same chat overtake it and
// break per-chat ordering.
//
// Returns the per-task settle status so the keyShare branch can know
// whether processMessage actually persisted the new app-state-sync key
// before triggering doAppStateSync (otherwise the sync would hit
// isMissingKeyError and park collections in blockedCollections).
const postUpsertTasks = async (): Promise<{ processMessageOk: boolean }> => {
const [historyResult, processResult] = await Promise.allSettled([
shouldProcessHistoryMsg ? doAppStateSync() : Promise.resolve(),
processMessage(msg, {
signalRepository,
shouldProcessHistoryMsg,
placeholderResendCache,
ev,
creds: authState.creds,
keyStore: authState.keys,
logger,
options: config.options,
getMessage
})
])
if (historyResult.status === 'rejected') {
logger?.warn(
{ err: historyResult.reason, messageId: msg.key?.id, remoteJid: msg.key?.remoteJid },
'history doAppStateSync failed'
)
}
if (processResult.status === 'rejected') {
logger?.warn(
{ err: processResult.reason, messageId: msg.key?.id, remoteJid: msg.key?.remoteJid },
'processMessage failed'
)
}
return { processMessageOk: processResult.status === 'fulfilled' }
}
// Use getChatId + jidNormalizedUser so the mutex key matches the chat-id
// scheme processMessage uses for chat updates (broadcasts target the
// participant). When getChatId/jidNormalizedUser yields nothing usable
// (missing or malformed JID), prefer a message-derived fallback over a
// single global 'unknown' bucket — that bucket would head-of-line block
// every malformed message behind a shared queue. msg.key.id is unique
// per message so unrelated malformed inputs no longer serialize together;
// for valid messages we still hit the normalized chat-id path, so the
// per-chat ordering guarantee is unchanged where it matters.
const rawChatId = getChatId(msg.key)
const normalizedChatId = rawChatId ? jidNormalizedUser(rawChatId) : ''
const postUpsertChatId = normalizedChatId || msg.key?.id || 'unknown'
// Wrap in `postUpsertMutex(chatId)` (a SEPARATE keyed mutex from the outer
// `messageMutex` held by the inbound caller) so per-chat ordering of
// processMessage side effects (chat.unreadCount, LID/PN mapping,
// messages.update, history downloads) is preserved across messages of the
// same chat.
//
// Why a separate mutex: if we re-used messageMutex, a concurrently-arrived
// message N+1 could enqueue on the outer mutex BEFORE msg N's post-upsert
// task gets enqueued (because N's outer callback yields on `await decrypt()`
// before reaching the inner enqueue site). The queue would then be
// [OuterN+1, InnerN, ...], so InnerN+1 would beat InnerN to processMessage.
// With its own mutex, post-upsert tasks enqueue strictly in upsertMessage
// call order (which IS message arrival order because the outer
// messageMutex serializes the upserts per-chat).
const postUpsertWork = postUpsertMutex.mutex(postUpsertChatId, postUpsertTasks)
const isKeyShareDuringSync =
!!msg.message?.protocolMessage?.appStateSyncKeyShare && syncState === SyncState.Syncing
if (isKeyShareDuringSync) {
// appStateSyncKeyShare path: processMessage persists the new app-state-sync
// key in its APP_STATE_SYNC_KEY_SHARE handler (via keyStore.transaction).
// The follow-up doAppStateSync() needs that key to decrypt patches, so
// we MUST wait for processMessage to actually succeed before kicking off
// the sync — otherwise it would hit isMissingKeyError and park
// collections in blockedCollections, regressing the very issue this
// branch was added to fix.
//
// No deadlock with the inbound caller's messageMutex because
// postUpsertMutex is a different mutex instance.
logger.info('App state sync key arrived, awaiting persistence before triggering sync')
const { processMessageOk } = await postUpsertWork
if (!processMessageOk) {
logger?.warn(
{ messageId: msg.key?.id, remoteJid: msg.key?.remoteJid },
'processMessage failed during key-share — skipping doAppStateSync to avoid isMissingKeyError'
)
} else {
try {
await Promise.all([
(async () => {
if (shouldProcessHistoryMsg) {
await doAppStateSync()
} catch (err) {
logger?.warn(
{ err, messageId: msg.key?.id, remoteJid: msg.key?.remoteJid },
'doAppStateSync failed after key-share persistence'
)
}
}
} else {
// `postUpsertWork` is not expected to reject — `Promise.allSettled`
// inside `postUpsertTasks` never rejects, and per-task failures are
// already logged inline. The defensive catch routes any truly
// unexpected rejection (e.g. `postUpsertMutex` internal corruption,
// future synchronous throws inside processMessage) through
// `onUnexpectedError` instead of letting it surface as an
// UnhandledPromiseRejection — which on Node ≥15 can terminate the
// long-running socket process.
postUpsertWork.catch(err =>
onUnexpectedError(
err,
`processing post-upsert work for message ${msg.key?.id || 'unknown'} on ${msg.key?.remoteJid || 'unknown chat'}`
)
)
})(),
processMessage(msg, {
signalRepository,
shouldProcessHistoryMsg,
placeholderResendCache,
ev,
creds: authState.creds,
keyStore: authState.keys,
logger,
options: config.options,
getMessage
})
])
// If the app state key arrives and we are waiting to sync, trigger the sync now.
if (msg.message?.protocolMessage?.appStateSyncKeyShare && syncState === SyncState.Syncing) {
logger.info('App state sync key arrived, triggering app state sync')
await doAppStateSync()
}
})