fix(ble): only report disconnects the device starts as unexpected

src/ble.ts

@@ -497,7 +497,8 @@ export class BLEConnection {
   // Expected disconnect tracking
   private expectedDisconnects: Set<string> = new Set()
   /**
-   * Mark the next disconnect for this MAC as expected
+   * Mark the next disconnect started by the device as expected (for example after a command that
+   * restarts it), so it is not logged as unexpected
    */
   markExpectedDisconnect(mac: string): void {
     this.expectedDisconnects.add(normalizeMAC(mac))
@@ -925,20 +926,16 @@ export class BLEConnection {
 
     this.connections.set(normalizedMac, peripheral)
     this.clearDisconnectTimer(normalizedMac)
+    this.expectedDisconnects.delete(normalizedMac)
+    this.watchForDisconnect(normalizedMac, mac, peripheral)
     this.logger.info(`Connected to ${mac}`)
 
     // Discover characteristics (may throw)
     try {
       await this.discoverCharacteristics(normalizedMac, peripheral)
     } catch (error) {
-      // Clean up partial connection if characteristic discovery fails
-      this.connections.delete(normalizedMac)
-      this.characteristics.delete(normalizedMac)
-
-      // Best effort disconnect to avoid leaked active BLE links
-      await new Promise<void>((resolve) => {
-        peripheral.disconnect(() => resolve())
-      })
+      // Clean up the partial connection, and disconnect to avoid leaking an active BLE link
+      await this.disconnect(normalizedMac)
 
       throw error
     }
@@ -986,44 +983,76 @@ export class BLEConnection {
   }
 
   /**
-   * Disconnect from a device
+   * Forget the connection state for a device: characteristics, encryption session, notification
+   * handlers and any pending reply.
    */
-  async disconnect(mac: string): Promise<void> {
-    const normalizedMac = normalizeMAC(mac)
-    const peripheral = this.connections.get(normalizedMac)
+  private dropConnectionState(normalizedMac: string, reason: string): void {
+    this.connections.delete(normalizedMac)
+    this.characteristics.delete(normalizedMac)
     this.clearDisconnectTimer(normalizedMac)
     // Reset encryption state (IV, cipher, mode) for this device
     this.clearEncryption(normalizedMac)
     this.notificationHandlers.delete(normalizedMac)
-
-    const wasExpected = this.expectedDisconnects.has(normalizedMac)
-    if (wasExpected) {
-      this.expectedDisconnects.delete(normalizedMac)
+    const pending = this.notificationFutures.get(normalizedMac)
+    if (pending) {
+      clearTimeout(pending.timer)
+      this.notificationFutures.delete(normalizedMac)
+      pending.reject(new Error(reason))
     }
+  }
 
-    if (!peripheral) {
-      if (!wasExpected) {
-        this.logger.warn(`Unexpected disconnect: peripheral not found for ${mac}`)
+  /**
+   * Watch for the device dropping the link (out of range, powered off, rebooted). Without this the
+   * stale peripheral stays in `connections` and the next command is sent over a dead link.
+   */
+  private watchForDisconnect(normalizedMac: string, mac: string, peripheral: any): void {
+    if (typeof peripheral?.once !== 'function') {
+      return
+    }
+    peripheral.once('disconnect', () => {
+      const expected = this.expectedDisconnects.delete(normalizedMac)
+      if (this.connections.get(normalizedMac) !== peripheral) {
+        return
+      }
+      if (expected) {
+        this.logger.debug(`${mac} disconnected`)
       } else {
-        this.logger.info(`Expected disconnect: peripheral not found for ${mac}`)
+        this.logger.warn(`Unexpected disconnect from ${mac}`)
       }
+      this.dropConnectionState(normalizedMac, `${mac} disconnected while waiting for a reply`)
+    })
+  }
+
+  /**
+   * Disconnect from a device. Disconnects started here (idle timeout, disconnectAll, a failed
+   * connection) are expected and logged at debug level; only a disconnect the device starts is
+   * reported as unexpected.
+   */
+  async disconnect(mac: string): Promise<void> {
+    const normalizedMac = normalizeMAC(mac)
+    const peripheral = this.connections.get(normalizedMac)
+    this.dropConnectionState(normalizedMac, `Disconnected from ${mac} while waiting for a reply`)
+
+    if (!peripheral) {
+      this.expectedDisconnects.delete(normalizedMac)
+      this.logger.debug(`Not connected to ${mac}`)
       return
     }
 
+    // Consumed by the 'disconnect' listener from watchForDisconnect
+    this.expectedDisconnects.add(normalizedMac)
     await new Promise<void>((resolve) => {
       peripheral.disconnect(() => {
-        this.connections.delete(normalizedMac)
-        this.characteristics.delete(normalizedMac)
-        if (wasExpected) {
-          this.logger.info(`Expected disconnect from ${mac}`)
-        } else {
-          this.logger.warn(`Unexpected disconnect from ${mac}`)
-        }
+        this.logger.debug(`Disconnected from ${mac}`)
         resolve()
       })
     })
+    if (typeof peripheral.once !== 'function') {
+      this.expectedDisconnects.delete(normalizedMac)
+    }
   }
 
+
   /**
    * Write data to device
    */

test/apis/ble-disconnect.test.ts

@@ -0,0 +1,92 @@
+import { EventEmitter } from 'node:events'
+
+import { describe, expect, it, vi } from 'vitest'
+
+import { BLEConnection } from '../../src/ble.js'
+import { BLE_NOTIFY_CHARACTERISTIC_UUID, BLE_WRITE_CHARACTERISTIC_UUID } from '../../src/settings.js'
+
+// Every disconnect BLEConnection started itself (the idle timer, disconnectAll) was logged as
+// "Unexpected disconnect", while a disconnect started by the device left a stale connection behind.
+// https://github.com/OpenWonderLabs/node-switchbot/pull/348
+
+function createPeripheral() {
+  const peripheral: any = new EventEmitter()
+  Object.assign(peripheral, {
+    id: 'mock-id',
+    address: 'aa:bb:cc:dd:ee:ff',
+    connect: (callback: (error?: Error) => void) => callback(),
+    disconnect: vi.fn((callback: () => void) => {
+      setImmediate(() => {
+        peripheral.emit('disconnect')
+        callback()
+      })
+    }),
+    discoverSomeServicesAndCharacteristics: (_s: string[], _c: string[], callback: (error: Error | null, services: any[], chars: any[]) => void) => {
+      callback(null, [], [
+        { uuid: BLE_WRITE_CHARACTERISTIC_UUID, write: vi.fn() },
+        { uuid: BLE_NOTIFY_CHARACTERISTIC_UUID, subscribe: (cb: any) => cb(), on: vi.fn() },
+      ])
+    },
+  })
+  return peripheral
+}
+
+function setup() {
+  const peripheral = createPeripheral()
+  const logger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }
+  const connection = new BLEConnection({ noble: { peripherals: [peripheral] }, logger: logger as any })
+  return { peripheral, logger, connection, internal: connection as any }
+}
+
+describe('bLEConnection disconnects', () => {
+  it('does not warn for a disconnect it starts', async () => {
+    const { connection, logger, internal } = setup()
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    await connection.disconnect('AA:BB:CC:DD:EE:FF')
+    await new Promise(resolve => setImmediate(resolve))
+    expect(logger.warn).not.toHaveBeenCalled()
+    expect(internal.connections.size).toBe(0)
+    expect(internal.expectedDisconnects.size).toBe(0)
+  })
+
+  it('does not warn for disconnectAll', async () => {
+    const { connection, logger } = setup()
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    await connection.disconnectAll()
+    expect(logger.warn).not.toHaveBeenCalled()
+  })
+
+  it('does not warn when asked to disconnect a device that is not connected', async () => {
+    const { connection, logger } = setup()
+    await connection.disconnect('AA:BB:CC:DD:EE:FF')
+    expect(logger.warn).not.toHaveBeenCalled()
+  })
+
+  it('warns and drops the connection when the device disconnects', async () => {
+    const { connection, logger, peripheral, internal } = setup()
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    peripheral.emit('disconnect')
+    expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('Unexpected disconnect'))
+    expect(internal.connections.size).toBe(0)
+    expect(internal.characteristics.size).toBe(0)
+  })
+
+  it('reconnects after the device disconnects instead of reusing the dead link', async () => {
+    const { connection, peripheral } = setup()
+    const connect = vi.spyOn(peripheral, 'connect')
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    peripheral.emit('disconnect')
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    expect(connect).toHaveBeenCalledTimes(2)
+  })
+
+  it('does not warn for a device disconnect marked as expected', async () => {
+    const { connection, logger, peripheral, internal } = setup()
+    await connection.connect('AA:BB:CC:DD:EE:FF')
+    connection.markExpectedDisconnect('AA:BB:CC:DD:EE:FF')
+    peripheral.emit('disconnect')
+    expect(logger.warn).not.toHaveBeenCalled()
+    expect(internal.expectedDisconnects.size).toBe(0)
+    expect(internal.connections.size).toBe(0)
+  })
+})