feat: improve decryption error logging with smart suppression
feat: improve decryption error logging with smart suppression
This commit is contained in:
+24
-5
@@ -22,14 +22,33 @@ import { SenderKeyRecord } from './Group/sender-key-record'
|
|||||||
import { GroupCipher, GroupSessionBuilder, SenderKeyDistributionMessage } from './Group'
|
import { GroupCipher, GroupSessionBuilder, SenderKeyDistributionMessage } from './Group'
|
||||||
import { LIDMappingStore } from './lid-mapping'
|
import { LIDMappingStore } from './lid-mapping'
|
||||||
|
|
||||||
// Suppress verbose "Closing session: SessionEntry {...}" logs from libsignal
|
// Suppress verbose logs from libsignal native library
|
||||||
// These are raw console.log calls from the native Signal library that dump
|
// These are raw console.log calls that dump internal state and transient errors
|
||||||
// cryptographic session details (keys, ratchets, etc.) on every encrypt/decrypt
|
// that are already handled by our retry logic and session recovery system
|
||||||
const _origConsoleLog = console.log
|
const _origConsoleLog = console.log
|
||||||
console.log = function(...args: unknown[]) {
|
console.log = function(...args: unknown[]) {
|
||||||
if (args.length > 0 && typeof args[0] === 'string' && args[0].startsWith('Closing session')) {
|
if (args.length > 0 && typeof args[0] === 'string') {
|
||||||
return // suppress libsignal session dump
|
const msg = args[0]
|
||||||
|
|
||||||
|
// Suppress session lifecycle dumps (cryptographic details on every encrypt/decrypt)
|
||||||
|
if (msg.startsWith('Closing session')) {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
|
||||||
|
// Suppress transient decryption errors that are auto-recovered by retry logic
|
||||||
|
// These flood logs during normal operation when sessions are being re-established
|
||||||
|
// Final failures are still logged via our structured logger (see decode-wa-message.ts)
|
||||||
|
if (
|
||||||
|
msg.includes('Session error') ||
|
||||||
|
msg.includes('Bad MAC') ||
|
||||||
|
msg.includes('MessageCounterError') ||
|
||||||
|
msg.includes('Key used already or never filled') ||
|
||||||
|
msg.includes('Failed to decrypt message with any known session')
|
||||||
|
) {
|
||||||
|
return // suppress - our retry system handles these gracefully
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
_origConsoleLog.apply(console, args)
|
_origConsoleLog.apply(console, args)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -19,7 +19,7 @@ import {
|
|||||||
} from '../WABinary'
|
} from '../WABinary'
|
||||||
import { unpadRandomMax16 } from './generics'
|
import { unpadRandomMax16 } from './generics'
|
||||||
import type { ILogger } from './logger'
|
import type { ILogger } from './logger'
|
||||||
import { retry, type RetryOptions } from './retry-utils'
|
import { retry, type RetryOptions, RetryExhaustedError } from './retry-utils'
|
||||||
|
|
||||||
export const getDecryptionJid = async (sender: string, repository: SignalRepositoryWithLIDStore): Promise<string> => {
|
export const getDecryptionJid = async (sender: string, repository: SignalRepositoryWithLIDStore): Promise<string> => {
|
||||||
if (isLidUser(sender) || isHostedLidUser(sender)) {
|
if (isLidUser(sender) || isHostedLidUser(sender)) {
|
||||||
@@ -386,25 +386,43 @@ export const decryptMessageNode = (
|
|||||||
fullMessage.message = msg
|
fullMessage.message = msg
|
||||||
}
|
}
|
||||||
} catch (err: any) {
|
} catch (err: any) {
|
||||||
const isCorrupted = isCorruptedSessionError(err)
|
// Check if this is a final failure after all retries exhausted
|
||||||
const isSessionRecord = isSessionRecordError(err)
|
const isRetryExhausted = err instanceof RetryExhaustedError
|
||||||
|
const originalError = isRetryExhausted ? err.originalError : err
|
||||||
|
|
||||||
|
const isCorrupted = isCorruptedSessionError(originalError)
|
||||||
|
const isSessionRecord = isSessionRecordError(originalError)
|
||||||
|
|
||||||
const errorContext = {
|
const errorContext = {
|
||||||
key: fullMessage.key,
|
key: fullMessage.key,
|
||||||
err,
|
err: originalError,
|
||||||
messageType: tag === 'plaintext' ? 'plaintext' : attrs.type,
|
messageType: tag === 'plaintext' ? 'plaintext' : attrs.type,
|
||||||
sender,
|
sender,
|
||||||
author,
|
author,
|
||||||
decryptionJid,
|
decryptionJid,
|
||||||
isSessionRecordError: isSessionRecord,
|
isSessionRecordError: isSessionRecord,
|
||||||
isCorruptedSession: isCorrupted
|
isCorruptedSession: isCorrupted,
|
||||||
|
...(isRetryExhausted && { retriesExhausted: true, attempts: err.attempts })
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// Smart logging: Only show ERROR on final failure
|
||||||
|
// During retries, libsignal may log internally - we can't suppress those
|
||||||
|
// But we can avoid adding our own duplicate error logs for each retry
|
||||||
if (isCorrupted) {
|
if (isCorrupted) {
|
||||||
logger.error(
|
// Corrupted session errors are expected and auto-recovered
|
||||||
errorContext,
|
// Only log as ERROR if this is the final failure after all retries
|
||||||
'⚠️ Corrupted session detected - Bad MAC or MessageCounter error.'
|
if (isRetryExhausted) {
|
||||||
)
|
logger.error(
|
||||||
|
errorContext,
|
||||||
|
`⚠️ Session corrupted and recovery failed after ${err.attempts} attempts. Auto-cleanup will attempt to recover.`
|
||||||
|
)
|
||||||
|
} else {
|
||||||
|
// First occurrence - log as warning since auto-recovery will attempt
|
||||||
|
logger.warn(
|
||||||
|
errorContext,
|
||||||
|
'⚠️ Corrupted session detected - attempting auto-recovery'
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
// Automatic cleanup of corrupted session (if enabled)
|
// Automatic cleanup of corrupted session (if enabled)
|
||||||
if (autoCleanCorrupted) {
|
if (autoCleanCorrupted) {
|
||||||
@@ -412,21 +430,38 @@ export const decryptMessageNode = (
|
|||||||
await cleanupCorruptedSession(decryptionJid, repository, logger)
|
await cleanupCorruptedSession(decryptionJid, repository, logger)
|
||||||
logger.info(
|
logger.info(
|
||||||
{ decryptionJid, author },
|
{ decryptionJid, author },
|
||||||
'✅ Corrupted session cleaned up automatically. New session will be created on next message.'
|
'✅ Corrupted session cleaned up. New session will be created on next message.'
|
||||||
)
|
)
|
||||||
} catch (cleanupErr) {
|
} catch (cleanupErr) {
|
||||||
logger.error(
|
logger.error(
|
||||||
{ decryptionJid, err: cleanupErr },
|
{ decryptionJid, err: cleanupErr },
|
||||||
'Failed to cleanup corrupted session'
|
'❌ Failed to cleanup corrupted session'
|
||||||
)
|
)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
} else if (isSessionRecord) {
|
||||||
|
// Session record errors are transient - retry should handle them
|
||||||
|
if (isRetryExhausted) {
|
||||||
|
logger.error(
|
||||||
|
errorContext,
|
||||||
|
`Failed to decrypt: No session record found after ${err.attempts} attempts`
|
||||||
|
)
|
||||||
|
} else {
|
||||||
|
logger.debug(errorContext, 'No session record - will retry')
|
||||||
|
}
|
||||||
} else {
|
} else {
|
||||||
logger.error(errorContext, 'failed to decrypt message')
|
// Unknown/unexpected error - always log as error
|
||||||
|
const logLevel = isRetryExhausted ? 'error' : 'warn'
|
||||||
|
logger[logLevel](
|
||||||
|
errorContext,
|
||||||
|
isRetryExhausted
|
||||||
|
? `Failed to decrypt message after ${err.attempts} attempts`
|
||||||
|
: 'Failed to decrypt message'
|
||||||
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
fullMessage.messageStubType = proto.WebMessageInfo.StubType.CIPHERTEXT
|
fullMessage.messageStubType = proto.WebMessageInfo.StubType.CIPHERTEXT
|
||||||
fullMessage.messageStubParameters = [err.message.toString()]
|
fullMessage.messageStubParameters = [originalError.message.toString()]
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user