Improve Mercury WebSocket recovery so bot commands stay responsive.

Add in-process framework restart, Mercury event listeners, and safer command reply handling to recover from silent WebSocket death without waiting for a manual container restart.

Co-authored-by: Cursor <cursoragent@cursor.com>

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)

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' +