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.)
This commit is contained in:
Claude
2026-01-20 21:44:08 +00:00
parent 3f2ced4501
commit bb73662e8f
3 changed files with 398 additions and 22 deletions
+85 -10
View File
@@ -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<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 (Object.keys(data).length === 0) return ''
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]) => {
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<string, unknown>, 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<string, unknown>, 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<string, unknown>, 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}`)
}
+16 -12
View File
@@ -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` } : {})
})
@@ -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:'))
})
})
})