Compare commits

..

7 Commits

Author SHA1 Message Date
Renato Alcara 5737ba590c fix: preserve full Error for unknown decrypt failures + improve dedup comment
Addresses 3 distinct PR #391 review findings (Copilot Major + Codex P2 + Copilot
nitpick — all valid):

#2 Copilot Major + #4 Codex P2 (same root, MAJOR):
   The previous slim of `errorContext.err` to `{name, message, type}` was applied
   uniformly to all three decrypt-failure branches. The unknown-error branch
   (lines 481-491 — "Unknown/unexpected errors (protobuf, parsing, etc.)") is
   exactly where stack traces matter MOST: there's no recovery path for those,
   so production root-cause analysis depends on having the stack.

   FIX: condition `errorContext.err` on category. Only slim for known-recoverable
   categories (corrupted-session / session-record). Unknown errors keep the full
   originalError so logger.error pino still emits the stack. Adds the
   `isRecoverableCategory` flag to make the intent obvious to future readers.

#3 Copilot (related to #2):
   The previous comment claimed "Full stack is still available via originalError
   if needed in custom handlers" — but originalError wasn't actually exposed
   anywhere downstream and the error wasn't re-thrown. Updated the comment to
   reflect the new conditional behavior (slim only for recoverable cases) so
   future maintainers don't misread the intent.

#1 Copilot (dedup window comment, MINOR):
   The 5000ms dedup window in src/index.ts can suppress genuinely-different
   errors for the same JID within the window. Kept the 5s value (it's the right
   trade-off for noisy production streams) but expanded the comment to spell
   out the trade-off and how to bypass it (BAILEYS_LOG_LEVEL=debug).

Skipped: nothing — all reviewer points addressed.

Tests: 35/35 suites, 824/824 still passing.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-26 11:32:03 -03:00
Renato Alcara 4a4766f52d chore(logs): reduce decrypt-error noise (~75% fewer lines per recoverable Bad MAC)
USER REPORT: Production logs flooded with verbose error blocks for every Bad MAC
recovery cycle. Each recoverable Bad MAC was producing ~40 log lines (transaction
failures, double-printed Bad MAC headers, full err.stack from libsignal). After
this change: ~10 lines, no functional change.

Changes:

1. src/Utils/auth-utils.ts (transaction failed handler):
   Downgrade SessionError to logger.debug — these are part of the normal Bad MAC
   recovery flow (retry receipt → sender resends as pkmsg → new session in ~1.3s).
   Other error names continue to log as ERROR. Error is still re-thrown — recovery
   behavior unchanged. Each Bad MAC recovery cycle saves 2 ERROR lines + the
   verbose error dump that pino attaches to logger.error.

2. src/Utils/decode-wa-message.ts (errorContext + sessionRecordErrors):
   - Added 'No matching sessions found' to sessionRecordErrors so the libsignal
     "decryptWithSessions exhausted all sessions" error categorises into the
     session-record branch (DEBUG on retry, ERROR only when retries exhausted)
     instead of falling through to the unknown-error branch (always ERROR + full
     stack).
   - Slim `errorContext.err` from full originalError to {name, message, type}.
     The 4-5 lines of node_modules/libsignal stack trace per log are noise for
     these recoverable error types. Full stack still available to custom handlers
     that may chain off originalError.

3. src/index.ts (DEDUP_WINDOW_MS):
   Increase from 150ms → 5000ms. Retry attempts of the same message are typically
   300-1000ms apart, so the second attempt fell outside the 150ms window and
   double-printed the masked Bad MAC line. 5s comfortably covers a full retry
   pair without suppressing genuinely new errors for the same JID.

INVARIANTS PRESERVED:
- Bad MAC recovery flow unchanged (sender resends pkmsg → new session)
- Retry receipt continues to be sent
- Errors are still thrown — only log verbosity changes
- ERROR-level still fires for genuinely unknown errors and retry-exhausted cases
- Customizations untouched: zero diff in carousel/buttons/lists/proto/LID-PN

If you need to debug a specific Bad MAC issue, set BAILEYS_LOG_LEVEL=debug in
the environment to surface the SessionError transaction logs again.

Tests: 35/35 suites, 824/824 passing.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-26 11:15:55 -03:00
Renato Alcara 1dffe3b311 perf(inbound-latency): restore async LID mapping + fire-and-forget tc… (#390)
* perf(inbound-latency): restore async LID mapping + fire-and-forget tctoken history sync

PRODUCTION ISSUE: Inbound messages from smartphone to ZPRO frontend were
arriving with seconds of delay. Outbound (ZPRO → smartphone) was instant.
Started after PR #386 (tctoken lifecycle) deploy.

ROOT CAUSE: Three compounding factors:

1. The historical fix d73cd28d39 (2026-02-03, "fix inbound latency by making
   LID mapping async") was partially reverted the same day by c3fc792351
   ("hybrid approach") due to a valid race-condition concern with decrypt().
   The reversion was over-protective: storeLIDPNMappings does NOT need to be
   sync — only migrateSession does. The hybrid kept all 3 awaits sync.

2. PR #386 added `await storeTcTokensFromHistorySync(...)` BEFORE the
   `messaging-history.set` emit. Per chunk this drains the event buffer with
   2-4 store ops, which compounds when many chunks arrive at once (restart,
   QR scan, multi-device login).

3. Each pre-check `await getPNForLID(alt)` / `getLIDForPN(alt)` before
   storeLIDPNMappings was redundant — the store has its own LRU cache + dedup.

Combined under production load (multi-instance store contention, post-PR #386
extra ops per send) the per-message hot-path penalty became user-visible delay.

THIS FIX:

#1+#3: messages-recv.ts ~line 2332 — `storeLIDPNMappings` becomes
fire-and-forget, pre-check `getPNForLID/getLIDForPN` removed. `migrateSession`
stays SYNC (REQUIRED for decrypt — see Codex/Copilot review on PR #72 / commit
c3fc792351). normalizeMessageJids has a fast-path that uses key.*Alt directly
without hitting the store, so the just-arrived message normalizes correctly
even before the background store completes.

#2: process-message.ts ~line 451 — `storeTcTokensFromHistorySync` becomes
fire-and-forget. Trade-off: a listener firing an outbound send IMMEDIATELY
after the emit may race the background persistence and hit error 463 on that
specific send. Existing 463 handler in messages-recv.ts triggers
getPrivacyTokens() refetch that auto-recovers in seconds. Net UX is much
better than per-chunk stalls.

INVARIANTS PRESERVED:
- migrateSession remains SYNC — decrypt() depends on it (race condition guard)
- normalizeMessageJids remains SYNC — events need correct JIDs before emit
- messageMutex remains SYNC — per-chat ordering preserved
- All 824 tests still pass
2026-04-26 10:30:09 -03:00
Renato Alcara 4fe708445a chore: update WhatsApp Web version to v2.3000.1038167900 (#389)
Co-authored-by: github-actions[bot] <github-actions[bot]@users.noreply.github.com>
2026-04-26 06:18:52 -03:00
github-actions[bot] 336ed64a44 chore: update proto/version to v2.3000.1038164556 (#388)
Co-authored-by: rsalcara <rsalcara@users.noreply.github.com>
2026-04-26 01:07:43 -03:00
Renato Alcara 65cb09e4df perf(history-sync): parallelise tcToken JID resolution per chunk (#387)
perf(history-sync): parallelise tcToken JID resolution per chunk (#387)
2026-04-25 23:52:37 -03:00
Renato Alcara 9ff21db749 feat(tctoken): complete lifecycle (TIER 1 + 2 + 3 of upstream PR)
feat(tctoken): complete lifecycle (TIER 1 + 2 + 3 of upstream PR)
2026-04-25 18:52:45 -03:00
7 changed files with 200 additions and 58 deletions
+1 -1
View File
@@ -1,7 +1,7 @@
syntax = "proto3";
package proto;
/// WhatsApp Version: 2.3000.1038024963
/// WhatsApp Version: 2.3000.1038164556
message ADVDeviceIdentity {
optional uint32 rawId = 1;
+1 -1
View File
@@ -1 +1 @@
{"version":[2,3000,1038147544]}
{"version":[2,3000,1038167900]}
+39 -29
View File
@@ -2330,44 +2330,54 @@ export const makeMessagesRecvSocket = (config: SocketConfig) => {
)
const alt = msg.key.participantAlt || msg.key.remoteJidAlt
// Handle LID/PN mappings with hybrid approach:
// - Store mapping operation runs in background (non-critical for decrypt)
// - Session migration MUST complete before decrypt() to avoid "No session record" errors
// This addresses Codex/Copilot review concerns about race conditions with decrypt()
// Handle LID/PN mappings with optimized hot-path:
// - storeLIDPNMappings is fire-and-forget (background) — does NOT block decrypt
// - migrateSession is SYNC (await) — REQUIRED for decrypt to find session
//
// SAFETY: normalizeMessageJids has a fast-path that uses key.*Alt directly without
// hitting the store, so the just-arrived message normalizes correctly even before
// the background store completes. Subsequent messages in the same chat hit the
// store after the background write is done (ms later).
//
// Pre-check (getPNForLID/getLIDForPN) was removed — storeLIDPNMappings has internal
// LRU cache + dedup, the pre-check was a redundant store round-trip per inbound
// message that added latency under load.
//
// HISTORICAL: this restores the intent of d73cd28d39 (2026-02-03) which was
// partially reverted by c3fc792351 the same day due to a race-condition concern
// with migrateSession (kept sync here). storeLIDPNMappings was over-protected:
// it persists a mapping that downstream consumers can re-derive from key.*Alt,
// while migrateSession actually moves the Signal session record that decrypt()
// will load microseconds later — those two have very different criticality.
//
// DO NOT make migrateSession async — decrypt() depends on the session being at
// the correct identifier (LID vs PN) when it runs. Other code paths (USync
// device lookup in messages-send.ts) create LID/PN mappings without migrating
// the session, so we cannot skip migration even when the mapping already exists.
if (!!alt) {
const altServer = jidDecode(alt)?.server
const primaryJid = msg.key.participant || msg.key.remoteJid!
if (altServer === 'lid') {
// Check if mapping already exists to avoid unnecessary storage operations
const existingMapping = await signalRepository.lidMapping.getPNForLID(alt)
if (!existingMapping) {
// MUST await: normalizeMessageJids() runs after this and needs the mapping
// in the LIDMappingStore to resolve LID→PN for events delivered to consumers
await signalRepository.lidMapping
.storeLIDPNMappings([{ lid: alt, pn: primaryJid }])
.catch(error => logger.warn({ error, alt, primaryJid }, 'LID mapping storage failed'))
}
// Fire-and-forget: storeLIDPNMappings has internal cache+dedup,
// pre-check (getPNForLID) was redundant.
signalRepository.lidMapping
.storeLIDPNMappings([{ lid: alt, pn: primaryJid }])
.catch(error => logger.warn({ error, alt, primaryJid }, 'background LID mapping store failed'))
// CRITICAL: ALWAYS migrate session, even if mapping exists
// Other code paths (e.g., USync device lookup in messages-send.ts:310-319)
// may create mappings via storeLIDPNMappings() without calling migrateSession()
// This leaves sessions under PN format while decrypt() expects LID format
// Skipping migration based on mapping existence causes "No session record" errors
// CRITICAL: ALWAYS migrate session SYNC, even if mapping exists.
// Other code paths (e.g., USync device lookup in messages-send.ts) may create
// mappings via storeLIDPNMappings() without calling migrateSession(). This
// leaves sessions under PN format while decrypt() expects LID format.
// Skipping migration based on mapping existence causes "No session record" errors.
await signalRepository.migrateSession(primaryJid, alt)
} else {
// Check if reverse mapping exists
const existingMapping = await signalRepository.lidMapping.getLIDForPN(alt)
if (!existingMapping) {
// MUST await: normalizeMessageJids() runs after this and needs the mapping
// in the LIDMappingStore to resolve LID→PN for events delivered to consumers
await signalRepository.lidMapping
.storeLIDPNMappings([{ lid: primaryJid, pn: alt }])
.catch(error => logger.warn({ error, alt, primaryJid }, 'LID mapping storage failed'))
}
// Fire-and-forget: same rationale as above.
signalRepository.lidMapping
.storeLIDPNMappings([{ lid: primaryJid, pn: alt }])
.catch(error => logger.warn({ error, alt, primaryJid }, 'background LID mapping store failed'))
// CRITICAL: ALWAYS migrate session, even if mapping exists
// Same reasoning as above - mapping existence doesn't guarantee session migration
// CRITICAL: ALWAYS migrate session SYNC.
await signalRepository.migrateSession(alt, primaryJid)
}
}
+12 -1
View File
@@ -341,7 +341,18 @@ export const addTransactionCapability = (
return result
} catch (error) {
logger.error({ error }, 'transaction failed, rolling back')
// 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.
const errName = (error as { name?: string })?.name
if (errName === 'SessionError') {
logger.debug({ error }, 'transaction failed (SessionError — recoverable via retry receipt)')
} else {
logger.error({ error }, 'transaction failed, rolling back')
}
throw error
}
})
+23 -2
View File
@@ -58,7 +58,11 @@ export const BAD_MAC_ERROR_TEXT = 'Bad MAC'
export const DECRYPTION_RETRY_CONFIG = {
maxRetries: 3,
baseDelayMs: 100,
sessionRecordErrors: ['No session record', 'SessionError: No session record'],
// 'No matching sessions found' is the libsignal error when decryptWithSessions exhausts
// all stored sessions for a JID. Same recovery flow (retry receipt → pkmsg → new session)
// — categorise it as session-record so the caller logs DEBUG on retry, ERROR only when
// retries are exhausted (instead of dumping the full stack as an unknown error).
sessionRecordErrors: ['No session record', 'SessionError: No session record', 'No matching sessions found'],
corruptedSessionErrors: ['Bad MAC', 'MessageCounterError', MISSING_KEYS_ERROR_TEXT]
}
@@ -421,9 +425,26 @@ export const decryptMessageNode = (
const isCorrupted = isCorruptedSessionError(originalError)
const isSessionRecord = isSessionRecordError(originalError)
// Slim error projection — keep name/message/type for diagnosis,
// drop `stack` which adds 4-5 lines of node_modules paths per log
// for known-recoverable libsignal errors.
//
// CRITICAL: only slim for KNOWN-RECOVERABLE categories (corrupted /
// session-record). The unknown-error branch keeps the full Error so
// protobuf/parsing/runtime bugs still emit a stack trace where it
// matters most. Catches Copilot/Codex P2 review on PR #391.
const slimErr = originalError
? {
name: (originalError as { name?: string }).name,
message: (originalError as { message?: string }).message,
type: (originalError as { type?: string }).type
}
: undefined
const isRecoverableCategory = isCorrupted || isSessionRecord
const errorContext = {
key: fullMessage.key,
err: originalError,
err: isRecoverableCategory ? slimErr : originalError,
messageType: tag === 'plaintext' ? 'plaintext' : attrs.type,
sender,
author,
+113 -22
View File
@@ -40,7 +40,7 @@ import { getKeyAuthor, toNumber } from './generics'
import { downloadAndProcessHistorySyncNotification } from './history'
import type { ILogger } from './logger'
import { metrics, recordHistorySyncMessages } from './prometheus-metrics.js'
import { buildMergedTcTokenIndexWrite, resolveTcTokenJid } from './tc-token-utils'
import { buildMergedTcTokenIndexWrite } from './tc-token-utils'
type ProcessMessageContext = {
shouldProcessHistoryMsg: boolean
@@ -82,32 +82,106 @@ const REAL_MSG_REQ_ME_STUB_TYPES = new Set([WAMessageStubType.GROUP_PARTICIPANT_
* (TC_TOKEN_INDEX_KEY) via buildMergedTcTokenIndexWrite, so the 24h prune sweep in
* messages-recv picks them up across sessions.
*/
/**
* Single-concurrency queue for `storeTcTokensFromHistorySync` calls.
*
* Why: the function does read-then-write merges (`keyStore.get('tctoken', ...)`
* compute `keyStore.set(...)`) which are NOT atomic at the store level. If two
* history-sync chunks invoke this concurrently (common during reconnect / QR
* scan), an older chunk that started first can `keyStore.set` AFTER a newer
* chunk, overwriting the newer entry and worse, the merged `__index` write
* can drop JIDs the other chunk just added. Result: stale tcTokens / repeat 463
* sends until the next opportunistic refetch.
*
* Serialising via a chained Promise keeps the runs ordered while still freeing
* the calling `processMessage` to emit `messaging-history.set` immediately
* (the chain is fire-and-forget at the call site). Errors don't break the chain
* each `catch` resets it to `Promise.resolve()` so a single failure can't
* stall future runs.
*
* The chain is module-scoped (one per Node process). Multiple Baileys instances
* sharing this module will serialise across instances too, but their writes
* target different keyStores so there's no correctness gain only a tiny loss
* of inter-instance parallelism for tcToken syncs, which is acceptable given
* how rarely this runs vs. how rare cross-instance contention is.
*/
let historyTcTokenChain: Promise<void> = Promise.resolve()
function scheduleHistoryTcTokenSync(
chats: Chat[],
signalRepository: SignalRepositoryWithLIDStore,
keyStore: SignalKeyStoreWithTransaction,
logger?: ILogger
): void {
historyTcTokenChain = historyTcTokenChain
.catch(() => {
/* swallow prior error so chain stays alive */
})
.then(() => storeTcTokensFromHistorySync(chats, signalRepository, keyStore, logger))
.catch(err => {
logger?.warn({ err }, 'background tctoken history-sync persistence failed')
})
}
async function storeTcTokensFromHistorySync(
chats: Chat[],
signalRepository: SignalRepositoryWithLIDStore,
keyStore: SignalKeyStoreWithTransaction,
logger?: ILogger
) {
const getLIDForPN = signalRepository.lidMapping.getLIDForPN.bind(signalRepository.lidMapping)
const candidates: { storageJid: string; token: Buffer; ts: number; senderTs?: number }[] = []
for (const chat of chats) {
// Cheap filter first — most chats in a sync chunk don't carry tcToken at all,
// and we want to avoid spinning up promises for them.
const tokenChats = chats.filter(chat => {
const ts = chat.tcTokenTimestamp ? toNumber(chat.tcTokenTimestamp) : 0
if (chat.tcToken?.length && ts > 0) {
const jid = jidNormalizedUser(chat.id!)
const storageJid = await resolveTcTokenJid(jid, getLIDForPN)
candidates.push({
storageJid,
token: Buffer.from(chat.tcToken),
ts,
senderTs: chat.tcTokenSenderTimestamp ? toNumber(chat.tcTokenSenderTimestamp) : undefined
})
return !!chat.tcToken?.length && ts > 0
})
if (!tokenChats.length) {
return
}
// Pre-normalize so the rest of the pipeline is a synchronous join.
const normalized = tokenChats.map(chat => ({
chat,
ts: toNumber(chat.tcTokenTimestamp!),
jid: jidNormalizedUser(chat.id!)
}))
// BATCHED LID resolution. The previous shape called getLIDForPN once per
// chat (sequential await inside a for-of), which became the bottleneck
// during heavy history sync — every cold-cache hit was a DB round-trip,
// stalling messaging-history.set and spilling into the event-buffer.
// `getLIDsForPNs` resolves a deduped list in ONE batched query (and shares
// USync retry across PNs that miss cache), turning O(N) round-trips into 1.
//
// LID inputs (and `@hosted.lid`) skip the lookup entirely — they're already
// the storage form. Failures degrade gracefully: a missing mapping just
// stores under the original jid, matching `resolveTcTokenJid`'s null branch.
const pnsToResolve = [...new Set(normalized.filter(({ jid }) => !isLidUser(jid)).map(({ jid }) => jid))]
const pnToLid = new Map<string, string>()
if (pnsToResolve.length) {
try {
const mappings = await signalRepository.lidMapping.getLIDsForPNs(pnsToResolve)
// Flat loop (continue-on-skip) keeps max nesting depth at 4 for lint.
for (const { pn, lid } of mappings ?? []) {
if (!pn || !lid) continue
pnToLid.set(jidNormalizedUser(pn), lid)
}
} catch (err) {
// Per-chat fallback below (storageJid := jid). Don't abort the chunk —
// CodeRabbit noted that all-or-nothing rejection here would drop every
// tctoken in the batch AND prevent messaging-history.set from firing.
logger?.warn({ err }, 'storeTcTokensFromHistorySync: getLIDsForPNs batch failed; falling back to per-chat jid')
}
}
if (!candidates.length) {
return
}
const candidates = normalized.map(({ chat, ts, jid }) => ({
storageJid: pnToLid.get(jid) ?? jid,
token: Buffer.from(chat.tcToken!),
ts,
senderTs: chat.tcTokenSenderTimestamp ? toNumber(chat.tcTokenSenderTimestamp) : undefined
}))
const jids = candidates.map(c => c.storageJid)
const existing = await keyStore.get('tctoken', jids)
@@ -532,11 +606,28 @@ const processMessage = async (
}
}
// Persist tctokens carried by history-sync chats BEFORE emitting messaging-history.set
// — listeners may immediately fire outbound sends that need the tctoken, and the store
// has to be populated first to avoid an error 463 on the first multi-device send.
// Runs AFTER storeLIDPNMappings (see comment above) so LID resolution works.
await storeTcTokensFromHistorySync(data.chats, signalRepository, keyStore, logger)
// Persist tctokens carried by history-sync chats in BACKGROUND, serialised.
//
// Originally awaited (PR #386) to avoid 463 on first multi-device send, but in
// production this drained the event buffer per-chunk and added visible delivery
// latency (especially after restart / QR scan when many chunks arrived at once).
//
// `scheduleHistoryTcTokenSync` enqueues onto a single-concurrency promise chain
// (see definition above) — chunks persist sequentially in the order they were
// emitted, preserving timestamp monotonicity AND keeping the `__index` write
// safe from concurrent merge clobbers. The call returns immediately so the
// `messaging-history.set` emit is not blocked.
//
// TRADE-OFF: a listener that fires an outbound send IMMEDIATELY after the emit
// may race the still-pending persistence and get a 463 on that specific send.
// The existing 463 handler in messages-recv.ts triggers a getPrivacyTokens()
// refetch that auto-recovers within seconds. Net result is much better UX than
// per-chunk stalls.
//
// DO NOT add `await` back here without re-evaluating production latency, AND
// DO NOT call storeTcTokensFromHistorySync directly — it must go through the
// chain to preserve write ordering across overlapping chunks.
scheduleHistoryTcTokenSync(data.chats, signalRepository, keyStore, logger)
ev.emit('messaging-history.set', {
...data,
+11 -2
View File
@@ -28,7 +28,16 @@ console.info = function (...args: unknown[]) {
// Track errors by type + JID to avoid duplicates (using Map for better performance)
const _errorTimestamps = new Map<string, number>()
const DEDUP_WINDOW_MS = 150
// Dedup window for repeated decrypt-error console lines (Bad MAC / Counter / etc).
// Was 150ms, but retry attempts of the SAME message are typically ~300-1000ms apart,
// so the second attempt fell outside the window and double-printed.
//
// TRADE-OFF: dedup key is `errorType + JID` (no message-id). With 5s, a burst of
// errors for the SAME JID — even of slightly different categories or different
// messages — collapses to one log line every 5s. This is intentional for a noisy
// production stream; if you need per-message visibility, set BAILEYS_LOG_LEVEL=debug
// to bypass this console-side dedup and see the structured pino logs in full.
const DEDUP_WINDOW_MS = 5000
console.error = function (...args: unknown[]) {
if (args.length > 0 && typeof args[0] === 'string') {
@@ -70,7 +79,7 @@ console.error = function (...args: unknown[]) {
const lastTime = _errorTimestamps.get(dedupeKey)
if (lastTime && now - lastTime < DEDUP_WINDOW_MS) {
return // Skip duplicate within 150ms window
return // Skip duplicate within DEDUP_WINDOW_MS window
}
_errorTimestamps.set(dedupeKey, now)