diff --git a/README.md b/README.md index 9fb6dad..77aa500 100644 --- a/README.md +++ b/README.md @@ -104,7 +104,7 @@ Key ones: - **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). +- **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 ~1 minute, a warning is logged; at ~2 minutes an in-process framework restart is attempted; after ~4 minutes without recovery the process exits so Docker's `restart: unless-stopped` policy brings us back with a fresh Mercury socket. Mercury `offline`/`online` events are also wired for faster detection. 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 2b71f84..7e3ff85 100644 --- a/index.js +++ b/index.js @@ -94,9 +94,14 @@ const botHealth = { 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 + exitingBecauseDead: false, // set true when the watchdog is about to exit the process + lastReconnectAttemptAt: null, // ISO timestamp of last in-process framework restart attempt + reconnectAttempts: 0 // total reconnect attempts this process lifetime }; +// Prevents overlapping framework.stop()/start() calls from the watchdog and Mercury events. +let reconnectInProgress = false; + // Graceful shutdown function (used by signals and crash handlers) function shutdown(force = false) { logger.info('🛑 Graceful shutdown initiated...'); @@ -417,6 +422,8 @@ app.get('/health', (req, res) => { consecutiveFailures: botHealth.consecutiveFailures, lastCheckAt: botHealth.lastCheckAt, lastHealthyAt: botHealth.lastHealthyAt, + lastReconnectAttemptAt: botHealth.lastReconnectAttemptAt, + reconnectAttempts: botHealth.reconnectAttempts, exiting: botHealth.exitingBecauseDead } }; @@ -569,8 +576,84 @@ if (process.env.SMOKE_TEST !== 'true') { // Webex-side outage) the rejection would otherwise be swallowed by the global // unhandledRejection handler and the bot would silently stay dead while // Express keeps serving. Surface it explicitly so the failure is obvious. + /** + * Safely send a bot reply. A failed bot.say() (Mercury dead, rate limit, etc.) + * must not become an unhandled rejection — that leaves the framework wedged. + */ + async function safeSay(bot, payload) { + try { + await bot.say(payload); + } catch (err) { + logger.error('bot.say failed — Mercury may be disconnected', err); + } + } + + /** + * Restart the Webex framework in-process (stop → start) to recover a dead + * Mercury WebSocket without waiting for a full container restart. + */ + async function attemptBotReconnect(reason) { + if (reconnectInProgress || botHealth.exitingBecauseDead) return false; + + reconnectInProgress = true; + botHealth.lastReconnectAttemptAt = new Date().toISOString(); + botHealth.reconnectAttempts++; + + logger.warn('Attempting in-process Webex framework restart', { + reason, + attempt: botHealth.reconnectAttempts + }); + + try { + botHealth.frameworkInitialized = false; + await framework.stop(); + await framework.start(); + // 'initialized' handler re-seeds mercury state and re-wires listeners. + logger.info('Webex framework restart completed', { reason }); + botHealth.consecutiveFailures = 0; + return true; + } catch (err) { + logger.error('Webex framework restart failed', { reason, error: err }); + return false; + } finally { + reconnectInProgress = false; + } + } + + /** + * Subscribe to Mercury lifecycle events so disconnects are visible in logs + * and permanent failures trigger an immediate reconnect attempt. + */ + function wireMercuryListeners() { + const mercury = framework?.webex?.internal?.mercury; + if (!mercury || typeof mercury.on !== 'function') return; + + mercury.on('offline', () => { + botHealth.mercuryConnected = false; + logger.warn('Mercury offline event received'); + }); + + mercury.on('online', () => { + botHealth.mercuryConnected = true; + botHealth.consecutiveFailures = 0; + botHealth.lastHealthyAt = new Date().toISOString(); + logger.info('Mercury online event received'); + }); + + mercury.on('offline.transient', () => { + logger.warn('Mercury transient offline — SDK should auto-reconnect'); + }); + + mercury.on('offline.permanent', () => { + logger.error('Mercury permanent offline — triggering framework restart'); + attemptBotReconnect('mercury.offline.permanent'); + }); + } + framework.start().catch((err) => { - logger.error('Webex framework failed to start (bot will be unresponsive; HTTP server continues)', err); + logger.error('Webex framework failed to start — exiting so Docker can restart', err); + // Without this, webhooks keep working but commands never will until manual restart. + setTimeout(() => shutdown(true), 2000).unref(); }); framework.on('initialized', () => { @@ -583,6 +666,7 @@ if (process.env.SMOKE_TEST !== 'true') { botHealth.mercuryConnected = !!mercury.connected; botHealth.lastHealthyAt = new Date().toISOString(); } + wireMercuryListeners(); }); framework.on('spawn', (bot, id, addedBy) => { @@ -619,15 +703,16 @@ if (process.env.SMOKE_TEST !== 'true') { // 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 WATCHDOG_WARN_AFTER = 1; // 1 consecutive miss → warn (~1 min) + const WATCHDOG_RECONNECT_AFTER = 2; // 2 consecutive misses → in-process restart (~2 min) + const WATCHDOG_EXIT_AFTER = 4; // 4 consecutive misses → exit (~4 min if restart failed) 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) { + if (!botHealth.frameworkInitialized || reconnectInProgress) { return; } @@ -653,11 +738,14 @@ if (process.env.SMOKE_TEST !== 'true') { consecutiveFailures: botHealth.consecutiveFailures, lastHealthyAt: botHealth.lastHealthyAt }); + } else if (botHealth.consecutiveFailures === WATCHDOG_RECONNECT_AFTER) { + attemptBotReconnect('watchdog'); } 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 + lastHealthyAt: botHealth.lastHealthyAt, + reconnectAttempts: botHealth.reconnectAttempts }); clearInterval(watchdogTimer); // Give the log line + any in-flight HTTP responses a beat to flush, @@ -698,13 +786,14 @@ if (process.env.SMOKE_TEST !== 'true') { // A regex like /^offline\b/i is tested directly against trigger.text and would // fail on any mentioned message because the display name comes first. framework.hears('offline', async (bot, trigger) => { + try { if (isVerbose) { logger.debug('offline command received', { user: trigger.person?.displayName || 'Unknown' }); } const filterArg = extractFilterArg(trigger, 'offline'); - await bot.say({ markdown: '🔍 Querying current offline / lost devices from Appspace...' }); + await safeSay(bot, { markdown: '🔍 Querying current offline / lost devices from Appspace...' }); // Pre-resolve for diagnostic logging in the catch block. let apiBaseUrl = process.env.APPSPACE_API_BASE_URL || process.env.APPSPACE_INSTANCE_URL || 'https://api.cloud.appspace.com'; @@ -718,7 +807,7 @@ if (process.env.SMOKE_TEST !== 'true') { const msg = filterArg ? `✅ No **${filterArg}** devices are currently offline.` : '✅ All devices are currently online or in sync.'; - return bot.say({ markdown: msg }); + return safeSay(bot, { markdown: msg }); } const consoleBase = process.env.APPSPACE_CONSOLE_BASE_URL || 'https://app3.cloud.appspace.com'; @@ -826,7 +915,7 @@ if (process.env.SMOKE_TEST !== 'true') { logger.debug(`Offline query returned ${offlineDevices.length} matching devices`); } - await bot.say({ markdown: message }); + await safeSay(bot, { markdown: message }); } catch (err) { const attemptedUrl = `${apiBaseUrl}/api/v3/devices`; @@ -835,7 +924,11 @@ if (process.env.SMOKE_TEST !== 'true') { error: err.message, code: err.code }); - bot.say({ markdown: `⚠️ Failed to query offline devices.\n\n${err.message || 'Unknown error'}` }); + await safeSay(bot, { markdown: `⚠️ Failed to query offline devices.\n\n${err.message || 'Unknown error'}` }); + } + } catch (err) { + logger.error('offline command handler failed unexpectedly', err); + await safeSay(bot, { markdown: '⚠️ An unexpected error occurred while processing the offline command.' }); } }); @@ -848,6 +941,7 @@ if (process.env.SMOKE_TEST !== 'true') { // See note on the 'offline' handler above: string phrases handle mentions // correctly (framework wraps them as `(^| )restart-offline($| )/i`). framework.hears('restart-offline', async (bot, trigger) => { + try { const MAX_RESTART_BATCH = 50; const CONCURRENCY = 3; @@ -856,7 +950,7 @@ if (process.env.SMOKE_TEST !== 'true') { const userLabel = trigger.person?.emails?.[0] || trigger.person?.displayName || 'Unknown'; logger.info('restart-offline invoked', { user: userLabel, filter: filterArg || '(none)' }); - await bot.say({ markdown: `🔁 Querying current offline devices${filterArg ? ` matching \`${filterArg}\`` : ''} from Appspace...` }); + await safeSay(bot, { markdown: `🔁 Querying current offline devices${filterArg ? ` matching \`${filterArg}\`` : ''} from Appspace...` }); let offlineDevices; try { @@ -864,17 +958,17 @@ if (process.env.SMOKE_TEST !== 'true') { offlineDevices = fetched.offlineDevices; } catch (err) { logger.error('restart-offline: Appspace query failed', err); - return bot.say({ markdown: `⚠️ Failed to query offline devices from Appspace.\n\n${err.message || 'Unknown error'}` }); + return safeSay(bot, { markdown: `⚠️ Failed to query offline devices from Appspace.\n\n${err.message || 'Unknown error'}` }); } if (offlineDevices.length === 0) { - return bot.say({ markdown: filterArg + return safeSay(bot, { markdown: filterArg ? `✅ No **${filterArg}** devices are currently offline. Nothing to restart.` : '✅ No devices are currently offline. Nothing to restart.' }); } if (offlineDevices.length > MAX_RESTART_BATCH) { - return bot.say({ markdown: + return safeSay(bot, { markdown: `🛑 **${offlineDevices.length}** offline devices match — that exceeds the safety cap of **${MAX_RESTART_BATCH}** per invocation.\n\n` + `Please narrow with a filter (e.g. \`restart-offline ios\`, \`restart-offline windows\`, or part of a device name) and try again.` }); @@ -895,12 +989,12 @@ if (process.env.SMOKE_TEST !== 'true') { const withoutMdm = candidates.filter(c => !c.mdmId); if (withMdm.length === 0) { - return bot.say({ markdown: + return safeSay(bot, { markdown: `⚠️ Found **${offlineDevices.length}** offline device(s), but none have a Workspace ONE record (matched by serial). Nothing to restart.` }); } - await bot.say({ markdown: + await safeSay(bot, { markdown: `🔁 Sending **SoftReset** to **${withMdm.length}** device(s) via Workspace ONE...` + (withoutMdm.length > 0 ? `\n_(${withoutMdm.length} offline device(s) have no WS1 record — skipping those.)_` : '') }); @@ -970,11 +1064,15 @@ if (process.env.SMOKE_TEST !== 'true') { } } - await bot.say({ markdown: msg }); + await safeSay(bot, { markdown: msg }); + } catch (err) { + logger.error('restart-offline command handler failed unexpectedly', err); + await safeSay(bot, { markdown: '⚠️ An unexpected error occurred while processing restart-offline.' }); + } }); -framework.hears('help', (bot) => { - bot.say({ markdown: + framework.hears('help', async (bot) => { + await safeSay(bot, { markdown: '**Commands:**\n' + '• `offline [filter]` — Current offline / Lost / Failed devices from Appspace (optional name/type filter, e.g. `offline ios`)\n' + '• `restart-offline [filter]` — Send a SoftReset (reboot) via Workspace ONE to every currently offline device that has a WS1 record. Optional filter narrows the set. Capped at 50 per invocation.\n' +