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:
@@ -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')
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user