fix(whatsapp): timestamp bridge.js's lifecycle console.log/warn lines
Fixes #97021. The WhatsApp bridge's human-facing lifecycle lines -- startup ("bridge listening", "session stored"), connection state (connected, logged out, restart/reconnect), and "[bridge] ..." warning lines -- were bare console.log/console.warn output with no timestamp. The platform adapter pipes the bridge's stdout/stderr verbatim into bridge.log, so no timestamp is added downstream either. Only structured JSON events (pair events, allowlist rejections from #92683) carried a timestamp. During incident forensics this made bridge.log impossible to sequence on its own -- the exact durations of a relaunch/re-pair loop, or the ordering of "Logged out" relative to a fatal stream error, couldn't be reconstructed without cross-correlating gateway logs and the sparser pino output. Added timestampedLine() to bridge_helpers.js (the existing pure, testable helper module bridge.js already draws from for reconnect scheduling and version resolution) -- a small function that prefixes a message with an ISO-8601 UTC timestamp in brackets, matching the issue's own suggested fix direction and kept deliberately distinct from the `ts: Date.now()` epoch-ms convention #92683 already established for the JSON event stream (these are plain human-readable lines, not JSON payloads). Applied it at the exact lifecycle line sites the issue's own line inventory cites: the core startup lines ("bridge listening on port", "session stored in"), the connection lifecycle lines (connected, logged out, restart-code-515, reconnect-in-3s, pairing complete), and the five "[bridge] ..." warning lines (poll update/upsert aggregation failures, gif/ffmpeg conversion fallback, failed read receipt). Scoped narrowly to what the issue asked for -- did not touch the already-structured JSON event lines, or the separate config-summary startup block (allowed users / DM policy lines) the issue didn't cite. Added a new test file (bridge_helpers.timestamp.test.mjs), following the established plain-assert, no-framework pattern from the existing bridge.reconnect.test.mjs: verifies the prefix is a valid, parseable ISO-8601 timestamp; the original message text (including template-literal-interpolated content, matching the actual call sites) survives byte-for-byte after the prefix; and two calls a moment apart produce non-decreasing timestamps, confirming the prefix reflects actual call time rather than a cached value -- so a relaunch loop's individual lines stay independently sequenceable, the issue's core ask. All assertions pass in the new test file. Ran the existing bridge.reconnect.test.mjs, bridge.sendqueue.test.mjs, and allowlist.test.mjs directly -- all pass unchanged (no regression to bridge_helpers.js's other exports or to bridge.js's own logic, since this only wraps pre-existing message strings passed to console.log/ console.warn without changing any control flow).
This commit is contained in:
@@ -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') {
|
||||
|
||||
@@ -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}`;
|
||||
}
|
||||
|
||||
65
scripts/whatsapp-bridge/bridge_helpers.timestamp.test.mjs
Normal file
65
scripts/whatsapp-bridge/bridge_helpers.timestamp.test.mjs
Normal file
@@ -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');
|
||||
Reference in New Issue
Block a user