diff --git a/scripts/whatsapp-bridge/bridge.js b/scripts/whatsapp-bridge/bridge.js index 26489896e2..02d0b7215c 100644 --- a/scripts/whatsapp-bridge/bridge.js +++ b/scripts/whatsapp-bridge/bridge.js @@ -50,6 +50,7 @@ import { normalizeWhatsAppId, pollCreationMessageFromPayload, pollUpdateForAggregation, + timestampedLine, } from './bridge_helpers.js'; // Parse CLI args @@ -426,7 +427,7 @@ async function startSocket() { if (reason === DisconnectReason.loggedOut) { emitPairEvent({ event: 'error', error: 'logged_out', reason }); if (!PAIR_JSON) { - console.log('❌ Logged out. Delete session and restart to re-authenticate.'); + console.log(timestampedLine('❌ Logged out. Delete session and restart to re-authenticate.')); } process.exit(1); } else { @@ -434,9 +435,9 @@ async function startSocket() { emitPairEvent({ event: 'disconnected', reason }); if (!PAIR_JSON) { if (reason === 515) { - console.log('↻ WhatsApp requested restart (code 515). Reconnecting...'); + console.log(timestampedLine('↻ WhatsApp requested restart (code 515). Reconnecting...')); } else { - console.log(`⚠️ Connection closed (reason: ${reason}). Reconnecting in 3s...`); + console.log(timestampedLine(`⚠️ Connection closed (reason: ${reason}). Reconnecting in 3s...`)); } } scheduleReconnect(reason === 515 ? 1000 : 3000); @@ -451,11 +452,11 @@ async function startSocket() { : null; emitPairEvent({ event: 'connected', user: connectedUser }); if (!PAIR_JSON) { - console.log('✅ WhatsApp connected!'); + console.log(timestampedLine('✅ WhatsApp connected!')); } if (PAIR_ONLY) { if (!PAIR_JSON) { - console.log('✅ Pairing complete. Credentials saved.'); + console.log(timestampedLine('✅ Pairing complete. Credentials saved.')); } // Give Baileys a moment to flush creds, then exit cleanly setTimeout(() => process.exit(0), 2000); @@ -499,7 +500,7 @@ async function startSocket() { }); } } catch (err) { - console.warn('[bridge] failed to aggregate poll update:', err.message); + console.warn(timestampedLine(`[bridge] failed to aggregate poll update: ${err.message}`)); } const selectedOptions = normalizePollUpdateOptions(aggregation, pollUpdates?.[0]); logPollUpdateDiagnostic({ @@ -700,7 +701,7 @@ async function startSocket() { }); } } catch (err) { - console.warn('[bridge] failed to aggregate poll upsert:', err.message); + console.warn(timestampedLine(`[bridge] failed to aggregate poll upsert: ${err.message}`)); } const selectedOptions = normalizePollUpdateOptions(aggregation, pollUpdates[0]); logPollUpdateDiagnostic({ @@ -948,7 +949,7 @@ app.post('/send-media', async (req, res) => { gifPlayback: true, }; } catch (gifErr) { - console.warn('[bridge] gif conversion failed, sending as image/gif:', gifErr.message); + console.warn(timestampedLine(`[bridge] gif conversion failed, sending as image/gif: ${gifErr.message}`)); msgPayload = mediaPayloadForFile({ buffer, filePath, mediaType: type, caption, fileName }); } finally { try { if (tmpGifMp4 && existsSync(tmpGifMp4)) unlinkSync(tmpGifMp4); } catch (_) {} @@ -980,7 +981,7 @@ app.post('/send-media', async (req, res) => { audioExt = 'ogg'; } catch (convErr) { // ffmpeg not available or conversion failed — fall back to original format - console.warn('[bridge] ffmpeg conversion failed, sending as file attachment:', convErr.message); + console.warn(timestampedLine(`[bridge] ffmpeg conversion failed, sending as file attachment: ${convErr.message}`)); } finally { try { if (tmpPath && existsSync(tmpPath)) unlinkSync(tmpPath); } catch (_) {} } @@ -1088,7 +1089,7 @@ app.post('/read', async (req, res) => { await sock.readMessages(receiptKeys); return res.json({ success: true, marked: true }); } catch (err) { - console.warn('[bridge] failed to send read receipt:', err.message); + console.warn(timestampedLine(`[bridge] failed to send read receipt: ${err.message}`)); return res.status(500).json({ error: 'Failed to send read receipt' }); } }); @@ -1149,8 +1150,8 @@ if (PAIR_ONLY) { }); } else { app.listen(PORT, '127.0.0.1', () => { - console.log(`🌉 WhatsApp bridge listening on port ${PORT} (mode: ${WHATSAPP_MODE})`); - console.log(`📁 Session stored in: ${SESSION_DIR}`); + console.log(timestampedLine(`🌉 WhatsApp bridge listening on port ${PORT} (mode: ${WHATSAPP_MODE})`)); + console.log(timestampedLine(`📁 Session stored in: ${SESSION_DIR}`)); if (ALLOWED_USERS.size > 0) { console.log(`🔒 Allowed users: ${Array.from(ALLOWED_USERS).join(', ')}`); } else if (WHATSAPP_MODE === 'self-chat') { diff --git a/scripts/whatsapp-bridge/bridge_helpers.js b/scripts/whatsapp-bridge/bridge_helpers.js index 6769c734e5..100744c6f2 100644 --- a/scripts/whatsapp-bridge/bridge_helpers.js +++ b/scripts/whatsapp-bridge/bridge_helpers.js @@ -725,3 +725,19 @@ export function createVersionResolver(fetchVersionFn, { return cachedVersion; }; } + +/** + * Prefix a human-facing bridge log line with an ISO-8601 UTC timestamp. + * + * Startup/connection-lifecycle console.log/console.warn lines carried no + * timestamp, and the platform adapter pipes the bridge's stdout/stderr + * verbatim into bridge.log (no timestamps are added downstream either) -- + * only structured JSON events (pair events, allowlist rejections, #92683) + * were timestamped. During incident forensics this made bridge.log + * impossible to sequence on its own (issue #97021). Kept distinct from the + * JSON `ts: Date.now()` convention those structured events use since these + * are plain human-readable lines, not JSON payloads. + */ +export function timestampedLine(message) { + return `[${new Date().toISOString()}] ${message}`; +} diff --git a/scripts/whatsapp-bridge/bridge_helpers.timestamp.test.mjs b/scripts/whatsapp-bridge/bridge_helpers.timestamp.test.mjs new file mode 100644 index 0000000000..2fe7670be0 --- /dev/null +++ b/scripts/whatsapp-bridge/bridge_helpers.timestamp.test.mjs @@ -0,0 +1,65 @@ +/** + * Unit tests for timestampedLine, the ISO-8601-prefix helper for + * bridge.js's human-facing lifecycle log lines. + * + * Regression for issue #97021: startup/connection lifecycle console.log/ + * console.warn lines (bridge listening, connected, logged out, reconnect, + * "[bridge] ..." warnings) carried no timestamp, and the platform adapter + * captures the bridge's stdout/stderr verbatim into bridge.log -- only + * structured JSON events (pair events, allowlist rejections, #92683) were + * timestamped, making bridge.log impossible to sequence on its own during + * incident forensics. + */ + +import { strict as assert } from 'node:assert'; + +import { timestampedLine } from './bridge_helpers.js'; + +const ISO_8601_PREFIX_RE = /^\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z\] /; + +// The prefix is a valid, parseable ISO-8601 UTC timestamp. +{ + const line = timestampedLine('✅ WhatsApp connected!'); + + assert.match(line, ISO_8601_PREFIX_RE); + + const bracketed = line.slice(1, line.indexOf(']')); + assert.ok(!Number.isNaN(new Date(bracketed).getTime())); +} + +// The original message text survives byte-for-byte after the prefix -- +// this is a display shim, not a message-mangling one. +{ + const message = '❌ Logged out. Delete session and restart to re-authenticate.'; + const line = timestampedLine(message); + + assert.ok(line.endsWith(message)); +} + +// A template-literal-interpolated message (matching the actual bridge.js +// call sites, e.g. the reconnect/warn lines) is preserved intact too. +{ + const reason = 'stream error'; + const message = `⚠️ Connection closed (reason: ${reason}). Reconnecting in 3s...`; + const line = timestampedLine(message); + + assert.ok(line.includes('stream error')); + assert.ok(line.endsWith(message)); +} + +// Two calls a moment apart produce increasing (or equal, at ms resolution) +// timestamps -- the prefix reflects the actual call time, not a cached or +// module-load-time value, so a relaunch loop's individual lines remain +// independently sequenceable. +{ + const first = timestampedLine('a'); + await new Promise(resolve => setTimeout(resolve, 5)); + const second = timestampedLine('b'); + + const firstTs = new Date(first.slice(1, first.indexOf(']'))).getTime(); + const secondTs = new Date(second.slice(1, second.indexOf(']'))).getTime(); + + assert.ok(secondTs >= firstTs); +} + +console.log('bridge_helpers.timestamp.test.mjs: all assertions passed');