feat(logger): add [BAILEYS] console-friendly logging functions
feat(logger): add [BAILEYS] console-friendly logging functions
This commit is contained in:
@@ -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')
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -509,4 +509,447 @@ 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'
|
||||
}
|
||||
|
||||
/**
|
||||
* Safely stringify a value, handling circular references, Errors, and special types
|
||||
*/
|
||||
function safeStringify(value: unknown, seen: WeakSet<object> = 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<string, unknown>)
|
||||
if (keys.length === 0) return '{}'
|
||||
if (keys.length <= 5) {
|
||||
const pairs = keys.map(k => {
|
||||
const v = (value as Record<string, unknown>)[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<string, unknown>, singleLine: boolean = true): string {
|
||||
if (!data || Object.keys(data).length === 0) return ''
|
||||
|
||||
const seen = new WeakSet<object>()
|
||||
|
||||
if (singleLine) {
|
||||
// Single line format: { key1: value1, key2: value2 }
|
||||
const pairs = Object.entries(data).map(([k, v]) => {
|
||||
return `${k}: ${safeStringify(v, seen)}`
|
||||
})
|
||||
return `{ ${pairs.join(', ')} }`
|
||||
}
|
||||
|
||||
// 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)
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* 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<string, unknown>,
|
||||
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<string, unknown>,
|
||||
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<string, unknown>,
|
||||
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<string, unknown>,
|
||||
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<string, unknown>, sessionName?: string): void {
|
||||
if (!isBaileysLogEnabled()) return
|
||||
|
||||
const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]'
|
||||
const formatted = data ? formatLogData(data) : ''
|
||||
const dataStr = formatted ? ' ' + formatted : ''
|
||||
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<string, unknown>, sessionName?: string): void {
|
||||
if (!isBaileysLogEnabled()) return
|
||||
|
||||
const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]'
|
||||
const formatted = data ? formatLogData(data) : ''
|
||||
const dataStr = formatted ? ' ' + formatted : ''
|
||||
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<string, unknown>, sessionName?: string): void {
|
||||
if (!isBaileysLogEnabled()) return
|
||||
|
||||
const prefix = sessionName ? `[BAILEYS] [${sessionName}]` : '[BAILEYS]'
|
||||
const formatted = data ? formatLogData(data) : ''
|
||||
const dataStr = formatted ? ' ' + formatted : ''
|
||||
console.error(`${prefix} ❌ ${message}${dataStr}`)
|
||||
}
|
||||
|
||||
/**
|
||||
* Log LID mapping store event
|
||||
*/
|
||||
export function logLidMapping(
|
||||
event: 'initialized' | 'lookup' | 'store' | 'batch_resolved',
|
||||
data?: Record<string, unknown>,
|
||||
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
|
||||
|
||||
@@ -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 } from './baileys-logger'
|
||||
|
||||
// ============================================================================
|
||||
// BUFFER CONFIGURATION - Environment Variable Support
|
||||
@@ -315,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'
|
||||
}
|
||||
}
|
||||
|
||||
// ============================================================================
|
||||
@@ -431,6 +445,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 +478,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 +493,7 @@ export const makeEventBuffer = (
|
||||
|
||||
if (!isBuffering) {
|
||||
logger.debug('Event buffer activated')
|
||||
logEventBuffer('buffer_start')
|
||||
isBuffering = true
|
||||
bufferCount = 0
|
||||
currentEventCount = 0
|
||||
@@ -486,6 +509,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 +531,7 @@ export const makeEventBuffer = (
|
||||
}
|
||||
|
||||
const eventCount = currentEventCount
|
||||
const flushStartTime = Date.now()
|
||||
logger.debug({ bufferCount, eventCount, force }, 'Flushing event buffer')
|
||||
|
||||
isBuffering = false
|
||||
@@ -530,6 +555,15 @@ export const makeEventBuffer = (
|
||||
// Record metrics
|
||||
recordFlushMetrics(eventCount, force)
|
||||
|
||||
// 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: config.enableAdaptiveTimeout ? adaptiveTimeout.getMode() : 'fixed',
|
||||
...(flushDuration > 5 ? { duration: `${flushDuration}ms` } : {})
|
||||
})
|
||||
|
||||
const newData = makeBufferData()
|
||||
const chatUpdates = Object.values(data.chatUpdates)
|
||||
let conditionalChatUpdatesLeft = 0
|
||||
|
||||
@@ -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<typeof console.log>
|
||||
let consoleErrorSpy: jest.SpiedFunction<typeof console.error>
|
||||
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<string, unknown> = { 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:'))
|
||||
})
|
||||
})
|
||||
})
|
||||
Reference in New Issue
Block a user