perf(logs): silence MessageCounterError + slim stanza dump on handler errors

Following PR #402 / fix/silence-decrypt-error-spam, prod logs still showed
two heavy stdout-saturation sources that survived the previous pass:

1) auth-utils.ts:353 — `transaction failed, rolling back` fired at ERROR
   level for every `MessageCounterError` ("Key used already or never filled").
   Only `SessionError` was downgraded. Under WhatsApp's LID/DSM rollout,
   own DSM messages flood with MessageCounterError when the auth state has
   a legacy `_1.0` session that no longer matches the LID-addressed
   envelope. ~30+ JSON ERROR lines per minute hit stdout.

2) messages-recv.ts:2698 — `error in handling message` logged the FULL
   stanza XML via `binaryNodeToString(node)`. Each stanza contains the
   inline encrypted ciphertext — kilobytes per log entry. Under load (e.g.
   downstream consumer throws on every Bad MAC), this is THE biggest
   single source of stdout pressure.

Pedro's snapshot doesn't have these specifically — its libsignal failures
fall through to upstream's leaner logging path.

THIS PATCH:
- auth-utils: extend the recoverable-error downgrade to MessageCounterError
  too (same recovery path: retry receipt → pkmsg → new session). Both now
  log at debug; everything else still ERRORs.
- messages-recv: log a SLIM node projection (tag + id + from + type +
  participant) at error level. Full stanza XML moved to debug. Operators
  retain enough to pivot to the offending message; investigations via
  BAILEYS_LOG_LEVEL=debug still get the full payload.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Renato Alcara
2026-04-30 12:40:02 -03:00
parent 1734d10209
commit 9d79bbe351
2 changed files with 23 additions and 8 deletions
+14 -1
View File
@@ -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')
}
}
+9 -7
View File
@@ -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')
}