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