From 3f2ced450190a30abce3a576a5af2270a0713be0 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 20 Jan 2026 20:48:26 +0000 Subject: [PATCH 1/2] feat(logger): add [BAILEYS] console-friendly logging functions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add formatted logging functions with [BAILEYS] prefix and emojis: - logEventBuffer: buffer events (๐Ÿ“ฆ, ๐Ÿ”„, โš ๏ธ, โฐ, ๐Ÿงน, ๐Ÿง ) - logBufferMetrics: metrics display (๐Ÿ“Š) - logMessageSent/Received: message events (๐Ÿ“ค, ๐Ÿ“ฅ) - logConnection: connection events (๐Ÿ”Œ, โœ…, ๐Ÿ”ด, ๐Ÿ”„, โŒ) - logAuth: authentication events (๐Ÿ“ฑ, ๐Ÿ”‘, ๐Ÿšช, ๐Ÿ”) - logCircuitBreaker: circuit breaker state (โšก, โœ…, ๐Ÿ”ถ) - logRetry: retry attempts (๐Ÿ”) - logInfo/Warn/Error: generic messages (โ„น๏ธ, โš ๏ธ, โŒ) - logLidMapping: LID store events (๐Ÿ—‚๏ธ, ๐Ÿ”, ๐Ÿ’พ, ๐Ÿ“ฆ) All functions respect BAILEYS_LOG=false environment variable. Integrated into event-buffer.ts and messages-send/recv.ts. --- src/Socket/messages-recv.ts | 6 + src/Socket/messages-send.ts | 4 + src/Utils/baileys-logger.ts | 368 ++++++++++++++++++++++++++++++++++++ src/Utils/event-buffer.ts | 30 +++ 4 files changed, 408 insertions(+) diff --git a/src/Socket/messages-recv.ts b/src/Socket/messages-recv.ts index 95957134..0ed3da54 100644 --- a/src/Socket/messages-recv.ts +++ b/src/Socket/messages-recv.ts @@ -16,6 +16,7 @@ import type { WAPatchName } from '../Types' import { WAMessageStatus, WAMessageStubType } from '../Types' +import { logMessageReceived } from '../Utils/baileys-logger' import { aesDecryptCTR, aesEncryptGCM, @@ -1318,6 +1319,11 @@ export const makeMessagesRecvSocket = (config: SocketConfig) => { cleanMessage(msg, authState.creds.me!.id, authState.creds.me!.lid!) await upsertMessage(msg, node.attrs.offline ? 'append' : 'notify') + + // Log with [BAILEYS] prefix + if (msg.key.id && msg.key.remoteJid) { + logMessageReceived(msg.key.id, msg.key.remoteJid) + } }) } catch (error) { logger.error({ error, node: binaryNodeToString(node) }, 'error in handling message') diff --git a/src/Socket/messages-send.ts b/src/Socket/messages-send.ts index b6177ede..d95102c5 100644 --- a/src/Socket/messages-send.ts +++ b/src/Socket/messages-send.ts @@ -12,6 +12,7 @@ import type { WAMessage, WAMessageKey } from '../Types' +import { logMessageSent } from '../Utils/baileys-logger' import { aggregateMessageKeysNotFromMe, assertMediaContent, @@ -1034,6 +1035,9 @@ export const makeMessagesSocket = (config: SocketConfig) => { await sendNode(stanza) + // Log with [BAILEYS] prefix + logMessageSent(msgId, destinationJid) + // Add message to retry cache if enabled if (messageRetryManager && !participant) { messageRetryManager.addRecentMessage(destinationJid, msgId, message) diff --git a/src/Utils/baileys-logger.ts b/src/Utils/baileys-logger.ts index b713296c..efadcbf8 100644 --- a/src/Utils/baileys-logger.ts +++ b/src/Utils/baileys-logger.ts @@ -509,4 +509,372 @@ export function setDefaultBaileysLogger(logger: BaileysLogger): void { defaultBaileysLogger = logger } +// ============================================================================ +// CONSOLE-FRIENDLY LOGGING FUNCTIONS WITH [BAILEYS] PREFIX +// ============================================================================ + +/** + * Check if Baileys logging is enabled via environment variable + * BAILEYS_LOG=false disables all [BAILEYS] console logs + */ +function isBaileysLogEnabled(): boolean { + return process.env.BAILEYS_LOG !== 'false' +} + +/** + * Format data object for single-line or multi-line output + */ +function formatLogData(data: Record, singleLine: boolean = true): string { + if (Object.keys(data).length === 0) return '' + + if (singleLine) { + // Single line format: { key1: value1, key2: value2 } + const pairs = Object.entries(data).map(([k, v]) => { + if (typeof v === 'object' && v !== null) { + return `${k}: ${JSON.stringify(v)}` + } + return `${k}: ${v}` + }) + return `{ ${pairs.join(', ')} }` + } + + // Multi-line format for complex objects + return JSON.stringify(data, null, 2) +} + +/** + * Event buffer logging types + */ +export type EventBufferLogType = + | 'buffer_start' + | 'buffer_flush' + | 'buffer_overflow' + | 'buffer_timeout' + | 'cache_cleanup' + | 'adaptive_mode' + +/** + * Log event buffer operations with emoji and [BAILEYS] prefix + * + * @example + * logEventBuffer('buffer_start') + * // Output: [BAILEYS] ๐Ÿ“ฆ Event buffering started + * + * logEventBuffer('buffer_flush', { flushCount: 10, historyCacheSize: 5, mode: 'aggressive' }) + * // Output: [BAILEYS] ๐Ÿ”„ Event buffer flushed { flushCount: 10, historyCacheSize: 5, mode: 'aggressive' } + */ +export function logEventBuffer( + type: EventBufferLogType, + data?: Record, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = data ? ' ' + formatLogData(data) : '' + + switch (type) { + case 'buffer_start': + console.log(`${prefix} ๐Ÿ“ฆ Event buffering started${dataStr}`) + break + case 'buffer_flush': + console.log(`${prefix} ๐Ÿ”„ Event buffer flushed${dataStr}`) + break + case 'buffer_overflow': + console.log(`${prefix} โš ๏ธ Buffer overflow detected${dataStr}`) + break + case 'buffer_timeout': + console.log(`${prefix} โฐ Buffer timeout reached${dataStr}`) + break + case 'cache_cleanup': + console.log(`${prefix} ๐Ÿงน History cache cleanup${dataStr}`) + break + case 'adaptive_mode': + console.log(`${prefix} ๐Ÿง  Adaptive mode updated${dataStr}`) + break + } +} + +/** + * Log buffer metrics in a formatted way + * + * @example + * logBufferMetrics({ + * itemsBuffered: 0, + * flushCount: 120, + * historyCacheSize: 0, + * buffersInProgress: 0, + * adaptive: { mode: 'aggressive', timeout: 1000, eventRate: 1.34, isHealthy: true } + * }) + */ +export function logBufferMetrics( + metrics: { + itemsBuffered: number + flushCount: number + historyCacheSize: number + buffersInProgress: number + adaptive?: { + mode: string + timeout: number + eventRate: number + isHealthy: boolean + } + }, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + + console.log(`${prefix} ๐Ÿ“Š Buffer Metrics {`) + console.log(`${prefix} itemsBuffered: ${metrics.itemsBuffered},`) + console.log(`${prefix} flushCount: ${metrics.flushCount},`) + console.log(`${prefix} historyCacheSize: ${metrics.historyCacheSize},`) + console.log(`${prefix} buffersInProgress: ${metrics.buffersInProgress}${metrics.adaptive ? ',' : ''}`) + if (metrics.adaptive) { + console.log(`${prefix} adaptive: {`) + console.log(`${prefix} mode: '${metrics.adaptive.mode}',`) + console.log(`${prefix} timeout: ${metrics.adaptive.timeout},`) + console.log(`${prefix} eventRate: ${metrics.adaptive.eventRate.toFixed(2)},`) + console.log(`${prefix} isHealthy: ${metrics.adaptive.isHealthy}`) + console.log(`${prefix} }`) + } + console.log(`${prefix} }`) +} + +/** + * Log message sent event + * + * @example + * logMessageSent('3EB02FA562D6CCC0876CDE', '5511999999999@s.whatsapp.net') + * // Output: [BAILEYS] ๐Ÿ“ค Message sent: 3EB02FA562D6CCC0876CDE โ†’ 5511999999999@s.whatsapp.net + */ +export function logMessageSent( + messageId: string, + recipientJid: string, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + console.log(`${prefix} ๐Ÿ“ค Message sent: ${messageId} โ†’ ${recipientJid}`) +} + +/** + * Log message received event + * + * @example + * logMessageReceived('A5E0349897A3F16F3F2778EEF94A065F', '238315571802285@lid') + * // Output: [BAILEYS] ๐Ÿ“ฅ Message received: A5E0349897A3F16F3F2778EEF94A065F โ† 238315571802285@lid + */ +export function logMessageReceived( + messageId: string, + senderJid: string, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + console.log(`${prefix} ๐Ÿ“ฅ Message received: ${messageId} โ† ${senderJid}`) +} + +/** + * Log connection event + * + * @example + * logConnection('connecting') + * // Output: [BAILEYS] ๐Ÿ”Œ Connecting to WhatsApp... + * + * logConnection('open') + * // Output: [BAILEYS] โœ… Connected to WhatsApp + */ +export function logConnection( + event: 'connecting' | 'open' | 'close' | 'reconnecting' | 'error', + details?: Record, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = details ? ' ' + formatLogData(details) : '' + + switch (event) { + case 'connecting': + console.log(`${prefix} ๐Ÿ”Œ Connecting to WhatsApp...${dataStr}`) + break + case 'open': + console.log(`${prefix} โœ… Connected to WhatsApp${dataStr}`) + break + case 'close': + console.log(`${prefix} ๐Ÿ”ด Disconnected from WhatsApp${dataStr}`) + break + case 'reconnecting': + console.log(`${prefix} ๐Ÿ”„ Reconnecting to WhatsApp...${dataStr}`) + break + case 'error': + console.log(`${prefix} โŒ Connection error${dataStr}`) + break + } +} + +/** + * Log authentication event + * + * @example + * logAuth('qr_generated') + * // Output: [BAILEYS] ๐Ÿ“ฑ QR Code generated - scan with WhatsApp + */ +export function logAuth( + event: 'qr_generated' | 'pairing_code' | 'authenticated' | 'logout' | 'creds_updated', + details?: Record, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = details ? ' ' + formatLogData(details) : '' + + switch (event) { + case 'qr_generated': + console.log(`${prefix} ๐Ÿ“ฑ QR Code generated - scan with WhatsApp${dataStr}`) + break + case 'pairing_code': + console.log(`${prefix} ๐Ÿ”‘ Pairing code generated${dataStr}`) + break + case 'authenticated': + console.log(`${prefix} โœ… Authentication successful${dataStr}`) + break + case 'logout': + console.log(`${prefix} ๐Ÿšช Logged out${dataStr}`) + break + case 'creds_updated': + console.log(`${prefix} ๐Ÿ” Credentials updated${dataStr}`) + break + } +} + +/** + * Log circuit breaker event + * + * @example + * logCircuitBreaker('open', { failures: 5 }) + * // Output: [BAILEYS] โšก Circuit breaker OPEN { failures: 5 } + */ +export function logCircuitBreaker( + state: 'open' | 'closed' | 'half_open', + details?: Record, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = details ? ' ' + formatLogData(details) : '' + + switch (state) { + case 'open': + console.log(`${prefix} โšก Circuit breaker OPEN${dataStr}`) + break + case 'closed': + console.log(`${prefix} โœ… Circuit breaker CLOSED${dataStr}`) + break + case 'half_open': + console.log(`${prefix} ๐Ÿ”ถ Circuit breaker HALF-OPEN${dataStr}`) + break + } +} + +/** + * Log retry event + * + * @example + * logRetry(2, 3, 5000, 'connection') + * // Output: [BAILEYS] ๐Ÿ” Retry attempt 2/3 for connection (delay: 5000ms) + */ +export function logRetry( + attempt: number, + maxAttempts: number, + delayMs: number, + operation: string, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + console.log(`${prefix} ๐Ÿ” Retry attempt ${attempt}/${maxAttempts} for ${operation} (delay: ${delayMs}ms)`) +} + +/** + * Log generic Baileys info message + * + * @example + * logInfo('PreKey validation passed') + * // Output: [BAILEYS] โ„น๏ธ PreKey validation passed + */ +export function logInfo(message: string, data?: Record, sessionName?: string): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = data ? ' ' + formatLogData(data) : '' + console.log(`${prefix} โ„น๏ธ ${message}${dataStr}`) +} + +/** + * Log generic Baileys warning message + * + * @example + * logWarn('Rate limit approaching') + * // Output: [BAILEYS] โš ๏ธ Rate limit approaching + */ +export function logWarn(message: string, data?: Record, sessionName?: string): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = data ? ' ' + formatLogData(data) : '' + console.log(`${prefix} โš ๏ธ ${message}${dataStr}`) +} + +/** + * Log generic Baileys error message + * + * @example + * logError('Failed to send message', { error: 'timeout' }) + * // Output: [BAILEYS] โŒ Failed to send message { error: 'timeout' } + */ +export function logError(message: string, data?: Record, sessionName?: string): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = data ? ' ' + formatLogData(data) : '' + console.error(`${prefix} โŒ ${message}${dataStr}`) +} + +/** + * Log LID mapping store event + */ +export function logLidMapping( + event: 'initialized' | 'lookup' | 'store' | 'batch_resolved', + data?: Record, + sessionName?: string +): void { + if (!isBaileysLogEnabled()) return + + const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' + const dataStr = data ? ' ' + formatLogData(data) : '' + + switch (event) { + case 'initialized': + console.log(`${prefix} ๐Ÿ—‚๏ธ LID Mapping Store initialized${dataStr}`) + break + case 'lookup': + console.log(`${prefix} ๐Ÿ” LID lookup${dataStr}`) + break + case 'store': + console.log(`${prefix} ๐Ÿ’พ LID stored${dataStr}`) + break + case 'batch_resolved': + console.log(`${prefix} ๐Ÿ“ฆ LID batch resolved${dataStr}`) + break + } +} + export default BaileysLogger diff --git a/src/Utils/event-buffer.ts b/src/Utils/event-buffer.ts index 247f0022..9f6a9afe 100644 --- a/src/Utils/event-buffer.ts +++ b/src/Utils/event-buffer.ts @@ -15,6 +15,7 @@ import { trimUndefined } from './generics' import type { ILogger } from './logger' import { updateMessageWithReaction, updateMessageWithReceipt } from './messages' import { isRealMessage, shouldIncrementChatUnread } from './process-message' +import { logEventBuffer, logBufferMetrics } from './baileys-logger' // ============================================================================ // BUFFER CONFIGURATION - Environment Variable Support @@ -431,6 +432,10 @@ export const makeEventBuffer = ( currentSize: currentEventCount, maxSize: config.maxBufferSize }, 'Buffer overflow detected, forcing flush') + logEventBuffer('buffer_overflow', { + currentSize: currentEventCount, + maxSize: config.maxBufferSize + }) flush(true) return true } @@ -460,6 +465,10 @@ export const makeEventBuffer = ( remaining: historyCache.size, maxSize: config.maxHistoryCacheSize }, 'LRU cleanup performed on history cache') + logEventBuffer('cache_cleanup', { + removed: removed.length, + remaining: historyCache.size + }) } } @@ -471,6 +480,7 @@ export const makeEventBuffer = ( if (!isBuffering) { logger.debug('Event buffer activated') + logEventBuffer('buffer_start') isBuffering = true bufferCount = 0 currentEventCount = 0 @@ -486,6 +496,7 @@ export const makeEventBuffer = ( bufferTimeout = setTimeout(() => { if (isBuffering) { logger.warn({ timeout }, 'Buffer timeout reached, auto-flushing') + logEventBuffer('buffer_timeout', { timeout }) stats.forcedFlushes++ flush(true) } @@ -507,6 +518,7 @@ export const makeEventBuffer = ( } const eventCount = currentEventCount + const flushStartTime = Date.now() logger.debug({ bufferCount, eventCount, force }, 'Flushing event buffer') isBuffering = false @@ -530,6 +542,24 @@ export const makeEventBuffer = ( // Record metrics recordFlushMetrics(eventCount, force) + // Determine adaptive mode label + const currentTimeoutMs = config.enableAdaptiveTimeout ? adaptiveTimeout.getTimeout() : config.bufferTimeoutMs + let adaptiveMode = 'balanced' + if (currentTimeoutMs <= config.minBufferTimeoutMs * 1.5) { + adaptiveMode = 'aggressive' + } else if (currentTimeoutMs >= config.maxBufferTimeoutMs * 0.8) { + adaptiveMode = 'conservative' + } + + // Log with [BAILEYS] prefix + const flushDuration = Date.now() - flushStartTime + logEventBuffer('buffer_flush', { + flushCount: stats.totalFlushes, + historyCacheSize: stats.historyCacheSize, + mode: adaptiveMode, + ...(flushDuration > 5 ? { duration: `${flushDuration}ms` } : {}) + }) + const newData = makeBufferData() const chatUpdates = Object.values(data.chatUpdates) let conditionalChatUpdatesLeft = 0 From bb73662e8fea25ad9c41f3116dc3ae508607c1d6 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 20 Jan 2026 21:44:08 +0000 Subject: [PATCH 2/2] fix(logger): address PR #19 code review feedback Fixes: - Remove unused import logBufferMetrics from event-buffer.ts - Add safeStringify() for robust data formatting: - Handles circular references gracefully - Formats Error objects properly - Truncates large arrays [Array(n)] - Handles undefined/null/Date/BigInt values - Add getMode() method to AdaptiveTimeoutCalculator to avoid duplicating mode calculation logic in flush() - Fix empty data object handling (no trailing space) Tests: - Add comprehensive test suite (39 tests) covering: - Environment variable check (BAILEYS_LOG=false) - All logging functions with emoji verification - Session name handling - formatLogData edge cases (circular, Error, arrays, etc.) --- src/Utils/baileys-logger.ts | 95 +++++- src/Utils/event-buffer.ts | 28 +- .../Utils/baileys-logger-console.test.ts | 297 ++++++++++++++++++ 3 files changed, 398 insertions(+), 22 deletions(-) create mode 100644 src/__tests__/Utils/baileys-logger-console.test.ts diff --git a/src/Utils/baileys-logger.ts b/src/Utils/baileys-logger.ts index efadcbf8..c99bcb46 100644 --- a/src/Utils/baileys-logger.ts +++ b/src/Utils/baileys-logger.ts @@ -521,25 +521,97 @@ function isBaileysLogEnabled(): boolean { return process.env.BAILEYS_LOG !== 'false' } +/** + * Safely stringify a value, handling circular references, Errors, and special types + */ +function safeStringify(value: unknown, seen: WeakSet = new WeakSet()): string { + // Handle primitives + if (value === null) return 'null' + if (value === undefined) return 'undefined' + if (typeof value === 'string') return value + if (typeof value === 'number' || typeof value === 'boolean') return String(value) + if (typeof value === 'function') return '[Function]' + if (typeof value === 'symbol') return value.toString() + if (typeof value === 'bigint') return `${value}n` + + // Handle objects + if (typeof value === 'object') { + // Check for circular reference + if (seen.has(value)) return '[Circular]' + seen.add(value) + + // Handle Error objects + if (value instanceof Error) { + return `${value.name}: ${value.message}` + } + + // Handle Date objects + if (value instanceof Date) { + return value.toISOString() + } + + // Handle Arrays + if (Array.isArray(value)) { + if (value.length === 0) return '[]' + if (value.length <= 3) { + const items = value.map(v => safeStringify(v, seen)) + return `[${items.join(', ')}]` + } + return `[Array(${value.length})]` + } + + // Handle plain objects + try { + const keys = Object.keys(value as Record) + if (keys.length === 0) return '{}' + if (keys.length <= 5) { + const pairs = keys.map(k => { + const v = (value as Record)[k] + return `${k}: ${safeStringify(v, seen)}` + }) + return `{${pairs.join(', ')}}` + } + return `{Object(${keys.length} keys)}` + } catch { + return '[Object]' + } + } + + return String(value) +} + /** * Format data object for single-line or multi-line output + * Handles circular references, Error objects, arrays, and undefined values */ function formatLogData(data: Record, singleLine: boolean = true): string { - if (Object.keys(data).length === 0) return '' + if (!data || Object.keys(data).length === 0) return '' + + const seen = new WeakSet() if (singleLine) { // Single line format: { key1: value1, key2: value2 } const pairs = Object.entries(data).map(([k, v]) => { - if (typeof v === 'object' && v !== null) { - return `${k}: ${JSON.stringify(v)}` - } - return `${k}: ${v}` + return `${k}: ${safeStringify(v, seen)}` }) return `{ ${pairs.join(', ')} }` } - // Multi-line format for complex objects - return JSON.stringify(data, null, 2) + // Multi-line format - use safe replacer for JSON.stringify + try { + return JSON.stringify(data, (key, value) => { + if (value instanceof Error) { + return { name: value.name, message: value.message, stack: value.stack } + } + if (typeof value === 'bigint') { + return `${value}n` + } + return value + }, 2) + } catch { + // Fallback for circular references or other issues + return safeStringify(data, seen) + } } /** @@ -814,7 +886,8 @@ export function logInfo(message: string, data?: Record, session if (!isBaileysLogEnabled()) return const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' - const dataStr = data ? ' ' + formatLogData(data) : '' + const formatted = data ? formatLogData(data) : '' + const dataStr = formatted ? ' ' + formatted : '' console.log(`${prefix} โ„น๏ธ ${message}${dataStr}`) } @@ -829,7 +902,8 @@ export function logWarn(message: string, data?: Record, session if (!isBaileysLogEnabled()) return const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' - const dataStr = data ? ' ' + formatLogData(data) : '' + const formatted = data ? formatLogData(data) : '' + const dataStr = formatted ? ' ' + formatted : '' console.log(`${prefix} โš ๏ธ ${message}${dataStr}`) } @@ -844,7 +918,8 @@ export function logError(message: string, data?: Record, sessio if (!isBaileysLogEnabled()) return const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]' - const dataStr = data ? ' ' + formatLogData(data) : '' + const formatted = data ? formatLogData(data) : '' + const dataStr = formatted ? ' ' + formatted : '' console.error(`${prefix} โŒ ${message}${dataStr}`) } diff --git a/src/Utils/event-buffer.ts b/src/Utils/event-buffer.ts index 9f6a9afe..15a0f47c 100644 --- a/src/Utils/event-buffer.ts +++ b/src/Utils/event-buffer.ts @@ -15,7 +15,7 @@ import { trimUndefined } from './generics' import type { ILogger } from './logger' import { updateMessageWithReaction, updateMessageWithReceipt } from './messages' import { isRealMessage, shouldIncrementChatUnread } from './process-message' -import { logEventBuffer, logBufferMetrics } from './baileys-logger' +import { logEventBuffer } from './baileys-logger' // ============================================================================ // BUFFER CONFIGURATION - Environment Variable Support @@ -316,6 +316,19 @@ class AdaptiveTimeoutCalculator { this.eventTimestamps = [] this.currentTimeout = (this.minTimeout + this.maxTimeout) / 2 } + + /** + * Get current adaptive mode based on timeout + * Returns 'aggressive', 'balanced', or 'conservative' + */ + getMode(): 'aggressive' | 'balanced' | 'conservative' { + if (this.currentTimeout <= this.minTimeout * 1.5) { + return 'aggressive' + } else if (this.currentTimeout >= this.maxTimeout * 0.8) { + return 'conservative' + } + return 'balanced' + } } // ============================================================================ @@ -542,21 +555,12 @@ export const makeEventBuffer = ( // Record metrics recordFlushMetrics(eventCount, force) - // Determine adaptive mode label - const currentTimeoutMs = config.enableAdaptiveTimeout ? adaptiveTimeout.getTimeout() : config.bufferTimeoutMs - let adaptiveMode = 'balanced' - if (currentTimeoutMs <= config.minBufferTimeoutMs * 1.5) { - adaptiveMode = 'aggressive' - } else if (currentTimeoutMs >= config.maxBufferTimeoutMs * 0.8) { - adaptiveMode = 'conservative' - } - - // Log with [BAILEYS] prefix + // Log with [BAILEYS] prefix - use getMode() to avoid duplicating mode calculation logic const flushDuration = Date.now() - flushStartTime logEventBuffer('buffer_flush', { flushCount: stats.totalFlushes, historyCacheSize: stats.historyCacheSize, - mode: adaptiveMode, + mode: config.enableAdaptiveTimeout ? adaptiveTimeout.getMode() : 'fixed', ...(flushDuration > 5 ? { duration: `${flushDuration}ms` } : {}) }) diff --git a/src/__tests__/Utils/baileys-logger-console.test.ts b/src/__tests__/Utils/baileys-logger-console.test.ts new file mode 100644 index 00000000..91ecfa91 --- /dev/null +++ b/src/__tests__/Utils/baileys-logger-console.test.ts @@ -0,0 +1,297 @@ +/** + * Unit tests for baileys-logger.ts console-friendly logging functions + */ + +import { describe, it, expect, beforeEach, afterEach, jest } from '@jest/globals' +import { + logEventBuffer, + logBufferMetrics, + logMessageSent, + logMessageReceived, + logConnection, + logAuth, + logCircuitBreaker, + logRetry, + logInfo, + logWarn, + logError, + logLidMapping, +} from '../../Utils/baileys-logger.js' + +describe('Baileys Console Logging Functions', () => { + let consoleSpy: jest.SpiedFunction + let consoleErrorSpy: jest.SpiedFunction + const originalEnv = process.env.BAILEYS_LOG + + beforeEach(() => { + consoleSpy = jest.spyOn(console, 'log').mockImplementation(() => {}) + consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}) + // Reset env var + delete process.env.BAILEYS_LOG + }) + + afterEach(() => { + jest.restoreAllMocks() + if (originalEnv !== undefined) { + process.env.BAILEYS_LOG = originalEnv + } else { + delete process.env.BAILEYS_LOG + } + }) + + describe('environment variable check', () => { + it('should log when BAILEYS_LOG is not set', () => { + delete process.env.BAILEYS_LOG + logEventBuffer('buffer_start') + expect(consoleSpy).toHaveBeenCalled() + }) + + it('should log when BAILEYS_LOG=true', () => { + process.env.BAILEYS_LOG = 'true' + logEventBuffer('buffer_start') + expect(consoleSpy).toHaveBeenCalled() + }) + + it('should NOT log when BAILEYS_LOG=false', () => { + process.env.BAILEYS_LOG = 'false' + logEventBuffer('buffer_start') + expect(consoleSpy).not.toHaveBeenCalled() + }) + }) + + describe('logEventBuffer', () => { + it('should log buffer_start with ๐Ÿ“ฆ emoji', () => { + logEventBuffer('buffer_start') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ“ฆ Event buffering started') + }) + + it('should log buffer_flush with ๐Ÿ”„ emoji and data', () => { + logEventBuffer('buffer_flush', { flushCount: 10, mode: 'aggressive' }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ”„ Event buffer flushed')) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('flushCount: 10')) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('mode: aggressive')) + }) + + it('should log buffer_overflow with โš ๏ธ emoji', () => { + logEventBuffer('buffer_overflow', { currentSize: 5000 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โš ๏ธ Buffer overflow detected')) + }) + + it('should log buffer_timeout with โฐ emoji', () => { + logEventBuffer('buffer_timeout', { timeout: 30000 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โฐ Buffer timeout reached')) + }) + + it('should log cache_cleanup with ๐Ÿงน emoji', () => { + logEventBuffer('cache_cleanup', { removed: 100 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿงน History cache cleanup')) + }) + + it('should include session name when provided', () => { + logEventBuffer('buffer_start', undefined, 'session-123') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] [session-123] ๐Ÿ“ฆ Event buffering started') + }) + }) + + describe('logBufferMetrics', () => { + it('should log metrics in multi-line format', () => { + logBufferMetrics({ + itemsBuffered: 50, + flushCount: 100, + historyCacheSize: 200, + buffersInProgress: 1, + }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('๐Ÿ“Š Buffer Metrics')) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('itemsBuffered: 50')) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('flushCount: 100')) + }) + + it('should include adaptive info when provided', () => { + logBufferMetrics({ + itemsBuffered: 0, + flushCount: 120, + historyCacheSize: 0, + buffersInProgress: 0, + adaptive: { + mode: 'aggressive', + timeout: 1000, + eventRate: 1.34, + isHealthy: true, + }, + }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining("mode: 'aggressive'")) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('timeout: 1000')) + }) + }) + + describe('logMessageSent and logMessageReceived', () => { + it('should log message sent with ๐Ÿ“ค emoji and arrow', () => { + logMessageSent('MSG123', '5511999999999@s.whatsapp.net') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ“ค Message sent: MSG123 โ†’ 5511999999999@s.whatsapp.net') + }) + + it('should log message received with ๐Ÿ“ฅ emoji and arrow', () => { + logMessageReceived('MSG456', '5511888888888@s.whatsapp.net') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ“ฅ Message received: MSG456 โ† 5511888888888@s.whatsapp.net') + }) + + it('should include session name for messages', () => { + logMessageSent('MSG789', 'user@lid', 'session-abc') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] [session-abc] ๐Ÿ“ค Message sent: MSG789 โ†’ user@lid') + }) + }) + + describe('logConnection', () => { + it('should log connecting with ๐Ÿ”Œ emoji', () => { + logConnection('connecting') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ”Œ Connecting to WhatsApp...') + }) + + it('should log open with โœ… emoji', () => { + logConnection('open') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] โœ… Connected to WhatsApp') + }) + + it('should log close with ๐Ÿ”ด emoji', () => { + logConnection('close', { reason: 'logout' }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ”ด Disconnected from WhatsApp')) + }) + + it('should log reconnecting with ๐Ÿ”„ emoji', () => { + logConnection('reconnecting', { attempt: 2 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ”„ Reconnecting to WhatsApp')) + }) + + it('should log error with โŒ emoji', () => { + logConnection('error', { code: 'ECONNREFUSED' }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โŒ Connection error')) + }) + }) + + describe('logAuth', () => { + it('should log qr_generated with ๐Ÿ“ฑ emoji', () => { + logAuth('qr_generated') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ“ฑ QR Code generated - scan with WhatsApp') + }) + + it('should log authenticated with โœ… emoji', () => { + logAuth('authenticated') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] โœ… Authentication successful') + }) + + it('should log logout with ๐Ÿšช emoji', () => { + logAuth('logout') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿšช Logged out') + }) + }) + + describe('logCircuitBreaker', () => { + it('should log open state with โšก emoji', () => { + logCircuitBreaker('open', { failures: 5 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โšก Circuit breaker OPEN')) + }) + + it('should log closed state with โœ… emoji', () => { + logCircuitBreaker('closed') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] โœ… Circuit breaker CLOSED') + }) + + it('should log half_open state with ๐Ÿ”ถ emoji', () => { + logCircuitBreaker('half_open') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ”ถ Circuit breaker HALF-OPEN') + }) + }) + + describe('logRetry', () => { + it('should log retry attempt with ๐Ÿ” emoji', () => { + logRetry(2, 5, 5000, 'connection') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ” Retry attempt 2/5 for connection (delay: 5000ms)') + }) + }) + + describe('logInfo, logWarn, logError', () => { + it('should log info with โ„น๏ธ emoji', () => { + logInfo('PreKey validation passed') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] โ„น๏ธ PreKey validation passed') + }) + + it('should log warning with โš ๏ธ emoji', () => { + logWarn('Rate limit approaching', { remaining: 10 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โš ๏ธ Rate limit approaching')) + }) + + it('should log error with โŒ emoji to console.error', () => { + logError('Failed to send', { error: 'timeout' }) + expect(consoleErrorSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] โŒ Failed to send')) + }) + }) + + describe('logLidMapping', () => { + it('should log LID events with appropriate emojis', () => { + logLidMapping('initialized') + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] ๐Ÿ—‚๏ธ LID Mapping Store initialized') + + logLidMapping('lookup', { jid: 'user@lid' }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ” LID lookup')) + + logLidMapping('store', { count: 5 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ’พ LID stored')) + + logLidMapping('batch_resolved', { resolved: 10 }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[BAILEYS] ๐Ÿ“ฆ LID batch resolved')) + }) + }) + + describe('formatLogData edge cases', () => { + it('should handle undefined values in data', () => { + logInfo('Test', { key: undefined }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('key: undefined')) + }) + + it('should handle null values in data', () => { + logInfo('Test', { key: null }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('key: null')) + }) + + it('should handle Error objects in data', () => { + const error = new Error('Test error') + logInfo('Test', { error }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('Error: Test error')) + }) + + it('should handle arrays in data', () => { + logInfo('Test', { items: [1, 2, 3] }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[1, 2, 3]')) + }) + + it('should handle large arrays with truncation', () => { + logInfo('Test', { items: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('[Array(10)]')) + }) + + it('should handle circular references gracefully', () => { + const obj: Record = { name: 'test' } + obj.self = obj // Create circular reference + // Should not throw + expect(() => logInfo('Test', { obj })).not.toThrow() + expect(consoleSpy).toHaveBeenCalled() + }) + + it('should handle Date objects', () => { + const date = new Date('2026-01-20T12:00:00.000Z') + logInfo('Test', { date }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('2026-01-20T12:00:00.000Z')) + }) + + it('should handle empty data object', () => { + logInfo('Test', {}) + // Empty data object should not add trailing space + expect(consoleSpy).toHaveBeenCalledWith('[BAILEYS] โ„น๏ธ Test') + }) + + it('should handle nested objects', () => { + logInfo('Test', { outer: { inner: { value: 42 } } }) + expect(consoleSpy).toHaveBeenCalledWith(expect.stringContaining('outer:')) + }) + }) +})