perf(logs): suppress libsignal console.warn — the missing piece of stdout flood

Following commits 1734d10209 + 9d79bbe351 the user reported pm2 logs were
STILL flooding and inbound latency persisted. Inspecting libsignal source
reveals 4 console.warn calls that bypass our existing log/info/error
interceptors:

  session_builder.js:74 → "Closing open session in favor of incoming prekey bundle"
  session_record.js:270 → "Session already closed", <session object>
  session_cipher.js:182 → "Decrypted message with closed session."
  queue_job.js:50      → "Unhandled bucket type (for naming):", <bucket>

Plus we were missing 2 console.info paths from session_record.js:
  - "Opening session:" (dumps the full session object)
  - "Migrating session to:" (per migration)

Under WhatsApp's LID/DSM rollout the pkmsg flow fires "Closing open session"
on EVERY incoming pkmsg (which is every recovery message from the user's own
phone after a Bad MAC). The user's log shows hundreds of these per session.
Each is a synchronous stdout.write. pm2's pipe buffer fills, write() blocks
the Node event loop, inbound delivery freezes for tens of seconds. Profile
pictures and IQ queries time out for the same reason — they need the loop
to dispatch them.

This is the same root cause as the historical Feb-27 fix (d233a7856f, "fix:
eliminate 40s message delivery delay caused by libsignal console dumps")
but the warn channel was overlooked.

THIS PATCH:
- Add console.warn interceptor with the same suppression regex.
- Extend the regex to cover the missing patterns (Opening session,
  Migrating session, Closing open session, Session already closed,
  Decrypted message with closed session, Unhandled bucket type).
- Operator-facing signal is unchanged — the console.error path still
  formats Bad MAC / Counter / Decryption Failed as the clean emoji line.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

src/Socket/messages-recv.ts

@@ -2695,7 +2695,20 @@ export const makeMessagesRecvSocket = (config: SocketConfig) => {
 				}
 			})
 		} catch (error) {
-			logger.error({ error, node: binaryNodeToString(node) }, 'error in handling message')
+			// Slim log: identify the message that crashed without dumping the full
+			// 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')
 		}
 	}
 

src/Utils/auth-utils.ts

@@ -341,14 +341,16 @@ export const addTransactionCapability = (
 
 						return result
 					} catch (error) {
-						// 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.
+						// SessionError / MessageCounterError are part of the normal Bad MAC
+						// recovery flow (retry receipt → sender resends as pkmsg → new session
+						// within ~1.3s). Logging them as ERROR creates 2 noise lines per
+						// recoverable cycle, and under WhatsApp's LID/DSM rollout these fire
+						// in dense bursts that saturate stdout (synchronous pm2 writes block
+						// 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
-						if (errName === 'SessionError') {
-							logger.debug({ error }, 'transaction failed (SessionError — recoverable via retry receipt)')
+						if (errName === 'SessionError' || errName === 'MessageCounterError') {
+							logger.debug({ error }, `transaction failed (${errName} — recoverable via retry receipt)`)
 						} else {
 							logger.error({ error }, 'transaction failed, rolling back')
 						}

src/Utils/decode-wa-message.ts

@@ -67,61 +67,33 @@ export const DECRYPTION_RETRY_CONFIG = {
 }
 
 /**
- * Retry options for decryption operations.
- *
- * 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.
+ * Retry options for decryption operations
+ * Uses exponential backoff with jitter to handle transient failures
  */
 export const DECRYPTION_RETRY_OPTIONS: RetryOptions = {
-	maxAttempts: 2,
-	baseDelay: 200, // 200ms base delay (only used for unknown errors below)
-	maxDelay: 2000,
+	maxAttempts: 3,
+	baseDelay: 200, // 200ms base delay
+	maxDelay: 2000, // 2s max delay
 	backoffStrategy: 'exponential',
 	backoffMultiplier: 2,
-	jitter: 0.2,
-	collectMetrics: false,
+	jitter: 0.2, // 20% jitter
+	collectMetrics: false, // No Prometheus metrics
 	operationName: 'message_decryption',
 	shouldRetry: (error: Error, attempt: number) => {
 		const errorMsg = error?.message || ''
 
-		// 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.
+		// Always retry on session record errors (session might be syncing)
 		if (DECRYPTION_RETRY_CONFIG.sessionRecordErrors.some(err => errorMsg.includes(err))) {
-			return false
+			return attempt < 3 // Retry up to 3 times
 		}
 
-		// Corrupted session errors: Bad MAC / counter errors. Same reasoning —
-		// the keys are wrong and won't right themselves on retry.
+		// Don't retry on corrupted session errors (need cleanup first)
 		if (DECRYPTION_RETRY_CONFIG.corruptedSessionErrors.some(err => errorMsg.includes(err))) {
 			return false
 		}
 
-		// Unknown errors: one retry in case it was a transient blip.
-		// `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
+		// Retry other transient errors
+		return attempt < 2 // Retry up to 2 times for unknown errors
 	}
 }
 
@@ -482,19 +454,40 @@ export const decryptMessageNode = (
 							...(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) {
-							// Corrupted session errors are expected and auto-recovered
-							// Only log as ERROR if retries exhausted, otherwise WARN on first attempt
+							// Corrupted session errors are expected — Signal Protocol auto-recovers
+							// via retry receipt → pkmsg → new session.
 							// eslint-disable-next-line max-depth
 							if (isRetryExhausted) {
-								logger.error(
-									errorContext,
+								logger.warn(
+									slimErrorContext,
 									`⚠️ Session corrupted after ${err.attempts} attempts. Retry+pkmsg flow will recover.`
 								)
 							} else {
-								// First occurrence - log as warning since auto-recovery will attempt
-								logger.warn(errorContext, '⚠️ Corrupted session detected - attempting auto-recovery')
+								logger.debug(errorContext, '⚠️ Corrupted session detected - attempting auto-recovery')
 							}
 
 							// Session cleanup is deferred to retry exhaustion (safety net).
@@ -507,7 +500,7 @@ export const decryptMessageNode = (
 							// Session record errors are transient - retry should handle them
 							// eslint-disable-next-line max-depth
 							if (isRetryExhausted) {
-								logger.error(errorContext, `Failed to decrypt: No session record found after ${err.attempts} attempts`)
+								logger.warn(slimErrorContext, `Failed to decrypt: No session record found after ${err.attempts} attempts`)
 							} else {
 								logger.debug(errorContext, 'No session record - will retry')
 							}

src/index.ts

@@ -5,11 +5,30 @@
 const _origConsoleError = console.error
 const _origConsoleLog = console.log
 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[]) {
 	if (args.length > 0 && typeof args[0] === 'string' && _SESSION_LIFECYCLE_RE.test(args[0])) {
 		return
@@ -26,6 +45,14 @@ console.info = function (...args: unknown[]) {
 	_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)
 const _errorTimestamps = new Map<string, number>()
 // Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc).