perf(decrypt): silence per-attempt warn logs that saturate stdout

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) <noreply@anthropic.com>
This commit is contained in:
Renato Alcara
2026-04-30 12:04:06 -03:00
parent bb78f61c6a
commit 1734d10209
+29 -8
View File
@@ -454,19 +454,40 @@ 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 and auto-recovered // Corrupted session errors are expected — Signal Protocol auto-recovers
// Only log as ERROR if retries exhausted, otherwise WARN on first attempt // via retry receipt → pkmsg → new session.
// eslint-disable-next-line max-depth // eslint-disable-next-line max-depth
if (isRetryExhausted) { if (isRetryExhausted) {
logger.error( logger.warn(
errorContext, slimErrorContext,
`⚠️ Session corrupted after ${err.attempts} attempts. Retry+pkmsg flow will recover.` `⚠️ Session corrupted after ${err.attempts} attempts. Retry+pkmsg flow will recover.`
) )
} else { } else {
// First occurrence - log as warning since auto-recovery will attempt logger.debug(errorContext, '⚠️ Corrupted session detected - attempting auto-recovery')
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).
@@ -479,7 +500,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.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 { } else {
logger.debug(errorContext, 'No session record - will retry') logger.debug(errorContext, 'No session record - will retry')
} }