Detect + recover from silent Mercury WebSocket death
Some checks failed
CI / Syntax check (push) Has been cancelled
CI / Docker build + healthcheck smoke test (push) Has been cancelled

The Cisco Webex SDK's Mercury WebSocket (used by the bot in WebSocket
mode) can die silently — network blip, WDM device TTL expiring, Cisco-
side hiccup — without any error the framework surfaces. When this
happens, the HTTP paths (webhook → Webex message API) keep working but
the bot silently stops receiving commands. This is the classic
"webhook alerts still arrive but the bot ignores me" failure mode.

Detect it by polling the SDK's live `webex.internal.mercury.connected`
boolean every 60s. Track consecutive misses:
  - After ~2 min disconnected: log a warning
  - After ~5 min disconnected: log an error and trigger graceful
    shutdown, so Docker's `restart: unless-stopped` policy brings us
    back with a fresh Mercury socket

Complementary changes:
- /health now returns 503 when the watchdog considers the bot dead,
  with `bot.mercuryConnected`, `consecutiveFailures`, `lastHealthyAt`
  in the JSON body. Docker HEALTHCHECK will start failing too, which
  helps external autoheal / K8s liveness probes catch it before the
  in-process exit fires. During SMOKE_TEST=true the bot state is
  reported as "skipped-smoke-test" so smoke tests still pass.
- Framework 'log' events are forwarded into our structured logger so
  framework-internal diagnostics (device registration issues,
  membership rule denials, etc.) are actually visible in logs.
- `removeDeviceRegistrationsOnStart: true` cleans up WDM device
  registrations left behind by previous silently-dead instances so
  they don't accumulate over time. Safe for single-instance
  deployments; comment flags the multi-instance caveat.

README updated to document the new health semantics and watchdog.

Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
jmcqueen 2026-07-06 08:16:41 -04:00
parent f7cda8f0c1
commit bff9e8dd0b
2 changed files with 136 additions and 5 deletions

View file

@ -100,7 +100,11 @@ Key ones:
1. Stop the Webex WebSocket framework (important to avoid "excessive device registrations"). 1. Stop the Webex WebSocket framework (important to avoid "excessive device registrations").
2. Close the HTTP server. 2. Close the HTTP server.
3. Exit cleanly. A hard safety timeout forces exit after ~8s (or ~3s from a crash handler). 3. Exit cleanly. A hard safety timeout forces exit after ~8s (or ~3s from a crash handler).
- **Healthcheck**: `/health` returns 200 with basic status. Used by Docker and orchestrators. - **Healthcheck**: `/health` returns:
- **200** when the HTTP server is up AND the Webex bot's Mercury WebSocket appears healthy (or the framework is still initializing during the startup grace window).
- **503** when a background watchdog has detected the bot's Mercury WebSocket is dead (bot commands would be silently failing even though webhooks still work). Response body includes `bot.mercuryConnected`, `bot.consecutiveFailures`, `bot.lastHealthyAt`, etc. for debugging.
- `bot` is reported as `"skipped-smoke-test"` when `SMOKE_TEST=true`.
- **Bot watchdog**: The Cisco Webex SDK's Mercury WebSocket (used for the bot in WebSocket mode) can die silently — a network blip, WDM device TTL expiring, or a Cisco-side hiccup — while the HTTP paths (webhook → Webex message API) keep working. This creates the classic "webhook alerts still fire but the bot doesn't respond to commands" symptom. A watchdog polls `webex.internal.mercury.connected` every 60s. If it stays disconnected for ~2 minutes, a warning is logged; after ~5 minutes, the process exits so Docker's `restart: unless-stopped` policy brings us back with a fresh Mercury socket. On startup, `removeDeviceRegistrationsOnStart` cleans up any WDM device registrations left behind by previous instances (safe for single-instance deployments; revisit if you ever run multiple instances against the same bot token).
- **Logging**: Logs go to stdout/stderr (12-factor / Docker friendly). Use `LOG_FORMAT=json` or `NODE_ENV=production` for structured JSON. Use `DEBUG=true` in non-prod for detail. Pipe to a collector (Loki, CloudWatch, etc.) as needed. Errors (including axios failures) are serialized with `message`, `stack`, `code`, `responseStatus`, and `responseData` so failures are actually visible in logs. - **Logging**: Logs go to stdout/stderr (12-factor / Docker friendly). Use `LOG_FORMAT=json` or `NODE_ENV=production` for structured JSON. Use `DEBUG=true` in non-prod for detail. Pipe to a collector (Loki, CloudWatch, etc.) as needed. Errors (including axios failures) are serialized with `message`, `stack`, `code`, `responseStatus`, and `responseData` so failures are actually visible in logs.
- **Secrets**: Never bake secrets into the image. Use: - **Secrets**: Never bake secrets into the image. Use:
- `env_file` for compose (dev/staging only) - `env_file` for compose (dev/staging only)

135
index.js
View file

@ -81,6 +81,22 @@ function log(level, msg, meta = {}) {
let server; let server;
let framework; let framework;
// ======================
// BOT LIVENESS STATE (populated by the Mercury watchdog below)
// ======================
// Represents whether the Webex bot's WebSocket (Mercury) transport is currently
// healthy. Read by /health so container orchestrators can observe the state.
// Set to `true` initially so we don't fail the healthcheck during the startup
// window before the framework has finished initializing.
const botHealth = {
mercuryConnected: null, // last-observed value of webex.internal.mercury.connected (null = not-yet-checked)
consecutiveFailures: 0, // consecutive watchdog checks that saw a dead socket
lastCheckAt: null, // ISO timestamp of last watchdog check
lastHealthyAt: null, // ISO timestamp of last healthy check (for staleness reporting)
frameworkInitialized: false, // set true on framework 'initialized' event
exitingBecauseDead: false // set true when the watchdog is about to exit the process
};
// Graceful shutdown function (used by signals and crash handlers) // Graceful shutdown function (used by signals and crash handlers)
function shutdown(force = false) { function shutdown(force = false) {
logger.info('🛑 Graceful shutdown initiated...'); logger.info('🛑 Graceful shutdown initiated...');
@ -374,12 +390,38 @@ function isProblemDevice(device) {
// ====================== // ======================
// HEALTHCHECK // HEALTHCHECK
// ====================== // ======================
// Reports both HTTP server health AND Webex bot (Mercury WebSocket) health.
// Returns 503 when the bot has been detected as dead — this is what triggers
// Docker's HEALTHCHECK to mark the container unhealthy so an autoheal sidecar
// or orchestrator can restart. (For plain `docker compose` with
// `restart: unless-stopped`, the container isn't restarted on unhealthy; the
// watchdog also calls process.exit(1) after sustained failure so the compose
// restart policy will kick in.)
//
// During smoke tests (SMOKE_TEST=true), the bot is intentionally not started —
// treat the bot state as N/A rather than unhealthy so the smoke test can pass.
app.get('/health', (req, res) => { app.get('/health', (req, res) => {
res.status(200).json({ const smokeMode = process.env.SMOKE_TEST === 'true';
status: 'healthy', const botConsideredHealthy =
smokeMode ||
!botHealth.frameworkInitialized || // startup grace: don't fail before framework is even up
botHealth.mercuryConnected !== false; // treat null (not-yet-checked) as OK
const payload = {
status: botConsideredHealthy ? 'healthy' : 'degraded',
environment: process.env.NODE_ENV || 'production', environment: process.env.NODE_ENV || 'production',
timestamp: new Date().toISOString() timestamp: new Date().toISOString(),
}); bot: smokeMode ? 'skipped-smoke-test' : {
frameworkInitialized: botHealth.frameworkInitialized,
mercuryConnected: botHealth.mercuryConnected,
consecutiveFailures: botHealth.consecutiveFailures,
lastCheckAt: botHealth.lastCheckAt,
lastHealthyAt: botHealth.lastHealthyAt,
exiting: botHealth.exitingBecauseDead
}
};
res.status(botConsideredHealthy ? 200 : 503).json(payload);
}); });
// ====================== // ======================
@ -514,6 +556,13 @@ app.post('/webhook', async (req, res) => {
if (process.env.SMOKE_TEST !== 'true') { if (process.env.SMOKE_TEST !== 'true') {
framework = new Framework({ framework = new Framework({
token: process.env.WEBEX_BOT_TOKEN, token: process.env.WEBEX_BOT_TOKEN,
// On startup, delete any stale WDM device registrations left behind by
// previously-dead-and-restarted instances. Prevents "excessive device
// registrations" errors that accumulate over the lifetime of the bot
// account when the process silently loses its Mercury socket and gets
// restarted. Safe for single-instance deployments; if you ever run
// multiple instances against the same bot token, revisit this.
removeDeviceRegistrationsOnStart: true
}); });
// If the framework fails to start (bad token, WebSocket handshake failure, // If the framework fails to start (bad token, WebSocket handshake failure,
@ -526,6 +575,14 @@ if (process.env.SMOKE_TEST !== 'true') {
framework.on('initialized', () => { framework.on('initialized', () => {
logger.info('Webex Bot Framework initialized (WebSocket mode)'); logger.info('Webex Bot Framework initialized (WebSocket mode)');
botHealth.frameworkInitialized = true;
// Seed the watchdog state so /health has something meaningful to report
// before the first watchdog tick fires.
const mercury = framework.webex?.internal?.mercury;
if (mercury) {
botHealth.mercuryConnected = !!mercury.connected;
botHealth.lastHealthyAt = new Date().toISOString();
}
}); });
framework.on('spawn', (bot, id, addedBy) => { framework.on('spawn', (bot, id, addedBy) => {
@ -538,10 +595,80 @@ if (process.env.SMOKE_TEST !== 'true') {
} }
}); });
// Forward the framework's internal 'log' events into our structured logger.
// Without this, framework-internal diagnostics (device registration issues,
// membership rule denials, etc.) are lost — which is a big part of why the
// Mercury silent-death is hard to diagnose from our logs alone.
framework.on('log', (msg) => {
logger.info('[framework]', { message: msg });
});
if (isVerbose) { if (isVerbose) {
logger.debug('Webex Bot Framework starting in WebSocket mode...'); logger.debug('Webex Bot Framework starting in WebSocket mode...');
} }
// ======================
// MERCURY WATCHDOG
// ======================
// The Webex SDK's Mercury WebSocket (server-push event stream) can die
// silently — network blip, WDM device TTL expiry, or a Cisco-side hiccup —
// without ever emitting an error the framework surfaces. When that happens
// the HTTP paths (webhooks, message-send API) keep working but the bot
// stops receiving commands. This watchdog polls the SDK's live
// `mercury.connected` boolean; if it stays false for enough consecutive
// checks, we log an error, mark ourselves unhealthy, and eventually exit
// so Docker's restart policy brings us back with a fresh connection.
const WATCHDOG_INTERVAL_MS = 60 * 1000; // check every minute
const WATCHDOG_WARN_AFTER = 2; // 2 consecutive misses → warn (~2 min)
const WATCHDOG_EXIT_AFTER = 5; // 5 consecutive misses → exit (~5 min)
const watchdogTimer = setInterval(() => {
botHealth.lastCheckAt = new Date().toISOString();
// If the framework hasn't finished initializing yet, don't count misses
// — we're still in the startup window.
if (!botHealth.frameworkInitialized) {
return;
}
const mercury = framework.webex?.internal?.mercury;
const connected = !!(mercury && mercury.connected);
botHealth.mercuryConnected = connected;
if (connected) {
if (botHealth.consecutiveFailures > 0) {
logger.info('Mercury WebSocket recovered', {
afterFailures: botHealth.consecutiveFailures
});
}
botHealth.consecutiveFailures = 0;
botHealth.lastHealthyAt = botHealth.lastCheckAt;
return;
}
botHealth.consecutiveFailures++;
if (botHealth.consecutiveFailures === WATCHDOG_WARN_AFTER) {
logger.warn('Mercury WebSocket appears disconnected — bot may be silent', {
consecutiveFailures: botHealth.consecutiveFailures,
lastHealthyAt: botHealth.lastHealthyAt
});
} else if (botHealth.consecutiveFailures >= WATCHDOG_EXIT_AFTER && !botHealth.exitingBecauseDead) {
botHealth.exitingBecauseDead = true;
logger.error('Mercury WebSocket dead for sustained period — exiting so Docker restart policy can reconnect', {
consecutiveFailures: botHealth.consecutiveFailures,
lastHealthyAt: botHealth.lastHealthyAt
});
clearInterval(watchdogTimer);
// Give the log line + any in-flight HTTP responses a beat to flush,
// then trigger the same graceful shutdown path as SIGTERM. If that
// hangs, shutdown()'s own safety timeout forces exit.
setTimeout(() => shutdown(), 500).unref();
}
}, WATCHDOG_INTERVAL_MS);
// .unref() so this timer doesn't hold the process open by itself.
watchdogTimer.unref();
/** /**
* Extract the trailing filter portion of a command message, regardless of whether * Extract the trailing filter portion of a command message, regardless of whether
* the message came from a DM (`offline ios`) or a group-space mention * the message came from a DM (`offline ios`) or a group-space mention