From 170097cf5697c46b49207cd4bf35d86143db3824 Mon Sep 17 00:00:00 2001 From: Renato Alcara Date: Thu, 30 Apr 2026 13:00:41 -0300 Subject: [PATCH] =?UTF-8?q?perf(logs):=20suppress=20libsignal=20console.wa?= =?UTF-8?q?rn=20=E2=80=94=20the=20missing=20piece=20of=20stdout=20flood?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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_cipher.js:182 → "Decrypted message with closed session." queue_job.js:50 → "Unhandled bucket type (for naming):", 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) --- src/index.ts | 35 +++++++++++++++++++++++++++++++---- 1 file changed, 31 insertions(+), 4 deletions(-) diff --git a/src/index.ts b/src/index.ts index fc3a701c..efa84fa5 100644 --- a/src/index.ts +++ b/src/index.ts @@ -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() // Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc).