Compare commits
2 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 50226ae389 | |||
| 56ca70bd75 |
@@ -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')
|
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -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')
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -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
@@ -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).
|
||||||
|
|||||||
Reference in New Issue
Block a user