Compare commits
3 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 170097cf56 | |||
| 9d79bbe351 | |||
| 1734d10209 |
@@ -1,7 +1,7 @@
|
||||
syntax = "proto3";
|
||||
package proto;
|
||||
|
||||
/// WhatsApp Version: 2.3000.1038569661
|
||||
/// WhatsApp Version: 2.3000.1038469210
|
||||
|
||||
message ADVDeviceIdentity {
|
||||
optional uint32 rawId = 1;
|
||||
|
||||
@@ -1 +1 @@
|
||||
{"version":[2,3000,1038585534]}
|
||||
{"version":[2,3000,1038487394]}
|
||||
|
||||
@@ -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')
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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')
|
||||
}
|
||||
|
||||
@@ -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')
|
||||
}
|
||||
|
||||
+31
-4
@@ -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).
|
||||
|
||||
Reference in New Issue
Block a user