Compare commits

..

2 Commits

Author SHA1 Message Date
Renato Alcara 50226ae389 fix(decrypt): correct 1-based attempt check for unknown-error retry
Codex P2 review caught: `retry()` in retry-utils.ts iterates with
`for (let attempt = 1; ...)`, so the `attempt` passed to `shouldRetry` on
the first failure is 1, not 0. The previous `attempt < 1` was therefore
always false → no retry on unknown errors, contradicting the inline policy
comment ("one retry in case it was a transient blip").

Use `attempt < 2` so the SECOND pass happens (initial + 1 retry = 2 total
attempts, which matches `maxAttempts: 2`) and the third pass is refused.

The session-record / corrupted-session branches above already return false
unconditionally and are not affected.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-30 10:34:04 -03:00
Renato Alcara 56ca70bd75 perf(decrypt): fail-fast on session-record errors to clear pipeline backpressure
PRODUCTION BUG (still present after PR #396): inbound messages from the
smartphone take ~60s to surface in the consumer (zpro). PR #396 fixed the
PN/LID lock-vs-storage drift but did NOT clear the latency. Diff against the
known-good Pedro snapshot pinpointed the residual cause: this retry wrapper.

ROOT CAUSE:
`DECRYPTION_RETRY_OPTIONS.shouldRetry` retries 3× with exponential backoff
(200 ms → 400 ms → 800 ms ≈ 1.4 s per failed message) on
`'No matching sessions found'` and friends. After WhatsApp's LID/DSM rollout
own DSM messages flood in for sessions stored under the legacy `_1.0` format
that no longer matches the LID-addressed envelope, so EVERY DSM hits this
path. At ~30 DSM/min the accumulated backoff is ~42 s — enough to block
real-contact messages from reaching the buffer flush.

The Pedro snapshot (Feb 6 2026, 484 commits behind, confirmed fast in prod
on the same auth state) has NO retry wrapper at all: try once → fail → send
retry receipt → phone re-sends as `pkmsg` → fresh session → next message
decrypts cleanly. Total recovery ~300 ms, no pipeline backpressure.

WHY THE RETRIES WERE USELESS:
1. libsignal already scanned every stored session for the JID before throwing
   `No matching sessions found`. Re-running the same lookup 200 ms later
   gives the same answer — no new session record materialises in that window.
2. Bad MAC / counter errors mean the keys are simply wrong; retry doesn't
   regenerate keys. (This branch was already correctly returning false.)

THIS PATCH:
- `sessionRecordErrors` now also returns `false` from `shouldRetry` (matches
  the existing `corruptedSessionErrors` policy).
- Unknown errors retry exactly once (was twice) — quick blip recovery only.
- `maxAttempts` lowered to 2 to match.
- Big block comment captures the rationale so the next person doesn't add
  retries back hoping it'll help.

Recovery still happens — just upstream, via the retry-receipt → pkmsg flow,
which is what WhatsApp protocol intends and what Pedro's working snapshot
relies on.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-30 10:30:22 -03:00
4 changed files with 60 additions and 95 deletions
+1 -14
View File
@@ -2695,20 +2695,7 @@ export const makeMessagesRecvSocket = (config: SocketConfig) => {
} }
}) })
} catch (error) { } catch (error) {
// Slim log: identify the message that crashed without dumping the full logger.error({ error, node: binaryNodeToString(node) }, 'error in handling message')
// stanza XML (which contains kilobytes of inline ciphertext). Under heavy
// load — e.g. a downstream consumer that throws on every Bad MAC — the
// full XML dumps overwhelm stdout and stall the event loop. Operators
// can still pivot on msgId / from / type; full payload at debug level.
const slimNode = {
tag: node.tag,
id: node.attrs?.id,
from: node.attrs?.from,
type: node.attrs?.type,
participant: node.attrs?.participant
}
logger.error({ error, node: slimNode }, 'error in handling message')
logger.debug({ node: binaryNodeToString(node) }, 'error in handling message — full stanza')
} }
} }
+7 -9
View File
@@ -341,16 +341,14 @@ export const addTransactionCapability = (
return result return result
} catch (error) { } catch (error) {
// SessionError / MessageCounterError are part of the normal Bad MAC // SessionError is part of the normal Bad MAC recovery flow
// recovery flow (retry receipt → sender resends as pkmsg → new session // (retry receipt → sender resends as pkmsg → new session within ~1.3s).
// within ~1.3s). Logging them as ERROR creates 2 noise lines per // Logging it as ERROR creates 2 noise lines per recoverable Bad MAC cycle.
// recoverable cycle, and under WhatsApp's LID/DSM rollout these fire // Downgrade to debug for SessionError; keep ERROR for everything else.
// in dense bursts that saturate stdout (synchronous pm2 writes block // The error is still re-thrown — recovery behavior is unchanged.
// the event loop). Downgrade to debug for both; keep ERROR for
// everything else. The error is still re-thrown — recovery is unchanged.
const errName = (error as { name?: string })?.name const errName = (error as { name?: string })?.name
if (errName === 'SessionError' || errName === 'MessageCounterError') { if (errName === 'SessionError') {
logger.debug({ error }, `transaction failed (${errName} — recoverable via retry receipt)`) logger.debug({ error }, 'transaction failed (SessionError — recoverable via retry receipt)')
} else { } else {
logger.error({ error }, 'transaction failed, rolling back') logger.error({ error }, 'transaction failed, rolling back')
} }
+48 -41
View File
@@ -67,33 +67,61 @@ export const DECRYPTION_RETRY_CONFIG = {
} }
/** /**
* Retry options for decryption operations * Retry options for decryption operations.
* Uses exponential backoff with jitter to handle transient failures *
* IMPORTANT — fail-fast policy for decryption:
* Both `sessionRecordErrors` ('No matching sessions found', etc.) and
* `corruptedSessionErrors` ('Bad MAC', 'MessageCounterError', missing keys)
* return `false` from `shouldRetry`. Rationale:
*
* 1. libsignal already scanned ALL stored sessions for the JID before
* throwing — retrying immediately gives the SAME result (no new session
* record materialises in the 200-800ms backoff window).
* 2. The real recovery flow is upstream: failed decrypt → retry receipt to
* WA → phone re-sends as `pkmsg` → libsignal builds a fresh session →
* next message decrypts cleanly. That handshake takes ~300ms total.
* 3. Wrapping decrypt in 3 attempts × exponential backoff (200ms→400ms→800ms
* ≈ 1.4 s per failed message) just blocks the inbound buffer pipeline. At
* the rate own DSM messages flood in after a LID/PN mismatch, this
* compounds to tens of seconds of accumulated delay before live messages
* from real contacts can even reach the consumer.
*
* Only truly *unknown* errors get a single retry — those might be transient
* (network blip, unexpected exception) and a quick 200ms retry is cheap.
*
* If we ever need transient-error retries again (e.g. the storage layer adds
* an async race that benefits from re-reading), set `sessionRecordErrors` to
* `attempt < 1` here, NOT `attempt < 3` — one extra read at most.
*/ */
export const DECRYPTION_RETRY_OPTIONS: RetryOptions = { export const DECRYPTION_RETRY_OPTIONS: RetryOptions = {
maxAttempts: 3, maxAttempts: 2,
baseDelay: 200, // 200ms base delay baseDelay: 200, // 200ms base delay (only used for unknown errors below)
maxDelay: 2000, // 2s max delay maxDelay: 2000,
backoffStrategy: 'exponential', backoffStrategy: 'exponential',
backoffMultiplier: 2, backoffMultiplier: 2,
jitter: 0.2, // 20% jitter jitter: 0.2,
collectMetrics: false, // No Prometheus metrics collectMetrics: false,
operationName: 'message_decryption', operationName: 'message_decryption',
shouldRetry: (error: Error, attempt: number) => { shouldRetry: (error: Error, attempt: number) => {
const errorMsg = error?.message || '' const errorMsg = error?.message || ''
// Always retry on session record errors (session might be syncing) // Session record errors: libsignal already exhausted all stored sessions.
// Retrying immediately gives the same result; the real recovery path
// is the upstream retry-receipt → pkmsg flow. Fail fast.
if (DECRYPTION_RETRY_CONFIG.sessionRecordErrors.some(err => errorMsg.includes(err))) { if (DECRYPTION_RETRY_CONFIG.sessionRecordErrors.some(err => errorMsg.includes(err))) {
return attempt < 3 // Retry up to 3 times return false
} }
// Don't retry on corrupted session errors (need cleanup first) // Corrupted session errors: Bad MAC / counter errors. Same reasoning —
// the keys are wrong and won't right themselves on retry.
if (DECRYPTION_RETRY_CONFIG.corruptedSessionErrors.some(err => errorMsg.includes(err))) { if (DECRYPTION_RETRY_CONFIG.corruptedSessionErrors.some(err => errorMsg.includes(err))) {
return false return false
} }
// Retry other transient errors // Unknown errors: one retry in case it was a transient blip.
return attempt < 2 // Retry up to 2 times for unknown errors // `attempt` is 1-based (retry-utils starts the loop at 1), so `attempt < 2`
// allows the second pass and returns false on the third.
return attempt < 2
} }
} }
@@ -454,40 +482,19 @@ export const decryptMessageNode = (
...(isRetryExhausted && { retriesExhausted: true, attempts: err.attempts }) ...(isRetryExhausted && { retriesExhausted: true, attempts: err.attempts })
} }
// Smart logging based on error type and retry status. // Smart logging based on error type and retry status
//
// PERF NOTE: under WhatsApp's LID/DSM rollout, own DSM messages flood
// the inbound pipeline with Bad MAC / "Key used already" / "No session
// record" errors *every* time the auth state has a session in the
// legacy `_1.0` format that no longer matches the LID-addressed
// envelope. Logging the full errorContext (key + jid + err) per failed
// attempt as warn-level produces tens of JSON lines/sec, which
// saturates stdout in pm2 (synchronous writes to a full pipe block the
// event loop). The clean `🔐 Bad MAC Error | JID: …` line emitted by
// the console.error interceptor in src/index.ts already gives an
// operator-visible signal — the duplicated pino line was pure noise.
//
// We now only emit warn-level when retries are exhausted (rare,
// actionable). Per-attempt detail is still available at debug level
// (BAILEYS_LOG_LEVEL=debug) for active troubleshooting.
const slimErrorContext = {
msgId: fullMessage.key?.id,
jid: fullMessage.key?.remoteJid,
err: slimErr,
attempts: isRetryExhausted ? err.attempts : 1
}
if (isCorrupted) { if (isCorrupted) {
// Corrupted session errors are expected — Signal Protocol auto-recovers // Corrupted session errors are expected and auto-recovered
// via retry receipt → pkmsg → new session. // Only log as ERROR if retries exhausted, otherwise WARN on first attempt
// eslint-disable-next-line max-depth // eslint-disable-next-line max-depth
if (isRetryExhausted) { if (isRetryExhausted) {
logger.warn( logger.error(
slimErrorContext, errorContext,
`⚠️ Session corrupted after ${err.attempts} attempts. Retry+pkmsg flow will recover.` `⚠️ Session corrupted after ${err.attempts} attempts. Retry+pkmsg flow will recover.`
) )
} else { } else {
logger.debug(errorContext, '⚠️ Corrupted session detected - attempting auto-recovery') // First occurrence - log as warning since auto-recovery will attempt
logger.warn(errorContext, '⚠️ Corrupted session detected - attempting auto-recovery')
} }
// Session cleanup is deferred to retry exhaustion (safety net). // Session cleanup is deferred to retry exhaustion (safety net).
@@ -500,7 +507,7 @@ export const decryptMessageNode = (
// Session record errors are transient - retry should handle them // Session record errors are transient - retry should handle them
// eslint-disable-next-line max-depth // eslint-disable-next-line max-depth
if (isRetryExhausted) { if (isRetryExhausted) {
logger.warn(slimErrorContext, `Failed to decrypt: No session record found after ${err.attempts} attempts`) logger.error(errorContext, `Failed to decrypt: No session record found after ${err.attempts} attempts`)
} else { } else {
logger.debug(errorContext, 'No session record - will retry') logger.debug(errorContext, 'No session record - will retry')
} }
+4 -31
View File
@@ -5,30 +5,11 @@
const _origConsoleError = console.error const _origConsoleError = console.error
const _origConsoleLog = console.log const _origConsoleLog = console.log
const _origConsoleInfo = console.info const _origConsoleInfo = console.info
const _origConsoleWarn = console.warn
// Suppress libsignal session lifecycle dumps from console.log / console.info / console.warn.
// libsignal's session_record.js / session_builder.js / session_cipher.js use:
// console.info("Removing old closed session:", obj) ← ~500ms I/O dump per call
// console.info("Opening session:", obj) ← ~500ms I/O dump per call
// console.info("Migrating session to:", v) ← per migration
// console.log("Closing session:", obj) ← ~500ms I/O dump per call
// console.warn("Closing open session in favor of incoming prekey bundle") ← per pkmsg
// console.warn("Session already closed", obj) ← per stale close
// console.warn("Decrypted message with closed session.") ← per recovered decrypt
// console.warn("Unhandled bucket type (for naming):", ...) ← queue_job edge case
//
// Under WhatsApp's LID/DSM rollout these fire dozens of times per minute when
// the auth state has legacy `_1.0` sessions that don't match LID-addressed
// envelopes. Each dump is a synchronous stdout.write — pm2 buffers fill and
// the event loop blocks. Symptom: 60s inbound delivery latency, profile
// pictures don't load, queries time out.
//
// The clean operator-facing signal lives in the console.error interceptor
// below (formats Bad MAC / Counter / Decryption Failed as one emoji line).
const _SESSION_LIFECYCLE_RE =
/^(Closing session|Removing old closed session|Opening session|Migrating session|Closing open session|Session already closed|Decrypted message with closed session|Unhandled bucket type)/
// Suppress libsignal session lifecycle dumps from console.log / console.info.
// libsignal's session_record.js uses console.info("Removing old closed session:", obj)
// and console.log("Closing session:", obj) which dump full session objects (~500ms I/O each).
const _SESSION_LIFECYCLE_RE = /^(Closing session|Removing old closed session)/
console.log = function (...args: unknown[]) { console.log = function (...args: unknown[]) {
if (args.length > 0 && typeof args[0] === 'string' && _SESSION_LIFECYCLE_RE.test(args[0])) { if (args.length > 0 && typeof args[0] === 'string' && _SESSION_LIFECYCLE_RE.test(args[0])) {
return return
@@ -45,14 +26,6 @@ console.info = function (...args: unknown[]) {
_origConsoleInfo.apply(console, args) _origConsoleInfo.apply(console, args)
} }
console.warn = function (...args: unknown[]) {
if (args.length > 0 && typeof args[0] === 'string' && _SESSION_LIFECYCLE_RE.test(args[0])) {
return
}
_origConsoleWarn.apply(console, args)
}
// Track errors by type + JID to avoid duplicates (using Map for better performance) // Track errors by type + JID to avoid duplicates (using Map for better performance)
const _errorTimestamps = new Map<string, number>() const _errorTimestamps = new Map<string, number>()
// Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc). // Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc).