perf(logs): suppress libsignal console.warn — the missing piece of stdout flood

Following commits 1734d10209 + 9d79bbe351 the user reported pm2 logs were
STILL flooding and inbound latency persisted. Inspecting libsignal source
reveals 4 console.warn calls that bypass our existing log/info/error
interceptors:

  session_builder.js:74 → "Closing open session in favor of incoming prekey bundle"
  session_record.js:270 → "Session already closed", <session object>
  session_cipher.js:182 → "Decrypted message with closed session."
  queue_job.js:50      → "Unhandled bucket type (for naming):", <bucket>

Plus we were missing 2 console.info paths from session_record.js:
  - "Opening session:" (dumps the full session object)
  - "Migrating session to:" (per migration)

Under WhatsApp's LID/DSM rollout the pkmsg flow fires "Closing open session"
on EVERY incoming pkmsg (which is every recovery message from the user's own
phone after a Bad MAC). The user's log shows hundreds of these per session.
Each is a synchronous stdout.write. pm2's pipe buffer fills, write() blocks
the Node event loop, inbound delivery freezes for tens of seconds. Profile
pictures and IQ queries time out for the same reason — they need the loop
to dispatch them.

This is the same root cause as the historical Feb-27 fix (d233a7856f, "fix:
eliminate 40s message delivery delay caused by libsignal console dumps")
but the warn channel was overlooked.

THIS PATCH:
- Add console.warn interceptor with the same suppression regex.
- Extend the regex to cover the missing patterns (Opening session,
  Migrating session, Closing open session, Session already closed,
  Decrypted message with closed session, Unhandled bucket type).
- Operator-facing signal is unchanged — the console.error path still
  formats Bad MAC / Counter / Decryption Failed as the clean emoji line.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Renato Alcara
2026-04-30 13:00:41 -03:00
parent 9d79bbe351
commit 170097cf56
+31 -4
View File
@@ -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).