From bff9e8dd0b028663ec028f2c5d44f145e8d16fb1 Mon Sep 17 00:00:00 2001 From: jmcqueen Date: Mon, 6 Jul 2026 08:16:41 -0400 Subject: [PATCH] Detect + recover from silent Mercury WebSocket death MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- README.md | 6 ++- index.js | 135 ++++++++++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 136 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index bc2971f..9fb6dad 100644 --- a/README.md +++ b/README.md @@ -100,7 +100,11 @@ Key ones: 1. Stop the Webex WebSocket framework (important to avoid "excessive device registrations"). 2. Close the HTTP server. 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. - **Secrets**: Never bake secrets into the image. Use: - `env_file` for compose (dev/staging only) diff --git a/index.js b/index.js index 1a7e3a7..2b71f84 100644 --- a/index.js +++ b/index.js @@ -81,6 +81,22 @@ function log(level, msg, meta = {}) { let server; 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) function shutdown(force = false) { logger.info('🛑 Graceful shutdown initiated...'); @@ -374,12 +390,38 @@ function isProblemDevice(device) { // ====================== // 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) => { - res.status(200).json({ - status: 'healthy', + const smokeMode = process.env.SMOKE_TEST === 'true'; + 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', - 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') { framework = new Framework({ 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, @@ -526,6 +575,14 @@ if (process.env.SMOKE_TEST !== 'true') { framework.on('initialized', () => { 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) => { @@ -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) { 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 * the message came from a DM (`offline ios`) or a group-space mention