From 1734d10209013f3c8718bdc055eac247964c3b14 Mon Sep 17 00:00:00 2001 From: Renato Alcara Date: Thu, 30 Apr 2026 12:04:06 -0300 Subject: [PATCH] perf(decrypt): silence per-attempt warn logs that saturate stdout MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit PRODUCTION BUG (still present after PR #396, #402): inbound 60s latency. Diff vs Pedro snapshot pinpointed the residual cause: pino warn-level logs of `errorContext` (key + jid + err + sender + author + decryptionJid + flags) on EVERY decrypt failure attempt. Under WA's LID/DSM rollout the user's own DSM floods the inbound pipeline with Bad MAC / "Key used already" / "No session record" errors when the auth state has a legacy `_1.0` session that no longer matches the LID-addressed envelope. At ~30 failed attempts/min this is ~30 JSON lines/sec of full key+context dumps. pm2 writes stdout synchronously; once the pipe buffer fills, `process.stdout.write` BLOCKS the event loop. Inbound delivery, query responses, profile-pic loads — everything stalls. Pedro doesn't have this rich logging; libsignal's own console.error is already intercepted in src/index.ts and reformatted as a single emoji line ("🔐 Bad MAC Error | JID: 1940****_1.0"). The duplicated pino warn was pure noise. THIS PATCH: - Per-attempt warn → debug. With BAILEYS_LOG_LEVEL=warn (production) these drop entirely. With LEVEL=debug they still surface for active troubleshooting. - Retry-exhausted warn (rare) keeps a SLIM context: msgId + jid + slimErr + attempts. No more full key/sender/author/decryptionJid dump. - error → warn for retry-exhausted (level 50 is reserved for unknown errors that fall through to the else branch — those are real bugs). Co-Authored-By: Claude Opus 4.7 (1M context) --- src/Utils/decode-wa-message.ts | 37 ++++++++++++++++++++++++++-------- 1 file changed, 29 insertions(+), 8 deletions(-) diff --git a/src/Utils/decode-wa-message.ts b/src/Utils/decode-wa-message.ts index 5ebf5520..24328675 100644 --- a/src/Utils/decode-wa-message.ts +++ b/src/Utils/decode-wa-message.ts @@ -454,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). @@ -479,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') }