Race condition in GattCharacteristic.js / startNotifications()

[nmasse-itix]

Environment

I'm using the following code to connect to a Lego Powered Up Hub using node-ble on a Framework Laptop 13 AMD running Fedora 40.

Code to reproduce the issue

const debug = require('debug')('sample-code');

const {createBluetooth} = require('node-ble');
const {bluetooth, destroy} = createBluetooth();

async function main () {
    const adapter = await bluetooth.defaultAdapter();

    if (! await adapter.isDiscovering()) {
        await adapter.startDiscovery();
    }

    const device = await adapter.waitDevice('9C:9A:C0:02:E8:69');
    await device.connect();
    const gattServer = await device.gatt();

    const service2 = await gattServer.getPrimaryService('00001623-1212-efde-1623-785feabcd123');
    const characteristic2 = await service2.getCharacteristic('00001624-1212-efde-1623-785feabcd123');
    characteristic2.on('valuechanged', buffer => {
        debug("value changed:", buffer);
    });

    // Cleanup function
    var cleanupInProgress = false;
    async function cleanupAndExit () {
        if (cleanupInProgress) {
            return;
        }
        debug("Cleaning up...");
        cleanupInProgress = true;
        await characteristic2.stopNotifications();
        await device.disconnect();
        destroy();
        
        process.exit(0);
    }

    process.on('SIGTERM', cleanupAndExit);
    process.on('SIGINT', cleanupAndExit);

    await characteristic2.startNotifications();
    return "End of main";
}
main()
  .then(debug)
  .catch(debug)

Expected behavior

Upon startNotifications, exactly 5 notifications are received.

Read 15 bytes from characteristic 000016241212efde1623785feabcd123 (notification = true).
<Buffer 0f 00 04 00 01 02 00 00 00 00 00 00 00 00 00>
Read 15 bytes from characteristic 000016241212efde1623785feabcd123 (notification = true).
<Buffer 0f 00 04 01 01 08 00 00 00 00 00 00 00 00 00>
Read 15 bytes from characteristic 000016241212efde1623785feabcd123 (notification = true).
<Buffer 0f 00 04 32 01 17 00 00 00 00 10 00 00 00 10>
Read 15 bytes from characteristic 000016241212efde1623785feabcd123 (notification = true).
<Buffer 0f 00 04 3b 01 15 00 02 00 00 00 02 00 00 00>
Read 15 bytes from characteristic 000016241212efde1623785feabcd123 (notification = true).
<Buffer 0f 00 04 3c 01 14 00 02 00 00 00 02 00 00 00>

Current behavior

Only 3 to 4 notifications are received.

$ DEBUG="sample-code" node index.js
  sample-code End of main +0ms
  sample-code value changed: <Buffer 0f 00 04 01 01 08 00 00 00 00 00 00 00 00 00> +3ms
  sample-code value changed: <Buffer 0f 00 04 32 01 17 00 00 00 00 10 00 00 00 10> +45ms
  sample-code value changed: <Buffer 0f 00 04 3b 01 15 00 02 00 00 00 02 00 00 00> +1ms
  sample-code value changed: <Buffer 0f 00 04 3c 01 14 00 02 00 00 00 02 00 00 00> +0ms
^C  sample-code Cleaning up... +4s

$ DEBUG="sample-code" node index.js
  sample-code End of main +0ms
  sample-code value changed: <Buffer 0f 00 04 01 01 08 00 00 00 00 00 00 00 00 00> +39ms
  sample-code value changed: <Buffer 0f 00 04 32 01 17 00 00 00 00 10 00 00 00 10> +1ms
  sample-code value changed: <Buffer 0f 00 04 3b 01 15 00 02 00 00 00 02 00 00 00> +1ms
  sample-code value changed: <Buffer 0f 00 04 3c 01 14 00 02 00 00 00 02 00 00 00> +47ms
^C  sample-code Cleaning up... +3s

$ DEBUG="sample-code" node index.js
  sample-code End of main +0ms
  sample-code value changed: <Buffer 0f 00 04 32 01 17 00 00 00 00 10 00 00 00 10> +1ms
  sample-code value changed: <Buffer 0f 00 04 3b 01 15 00 02 00 00 00 02 00 00 00> +1ms
  sample-code value changed: <Buffer 0f 00 04 3c 01 14 00 02 00 00 00 02 00 00 00> +46ms
^C  sample-code Cleaning up... +2s

Possible explanation

In GattCharacteristic.js, in the startNotifications method :

  async startNotifications () {
    await this.helper.callMethod('StartNotify')

    const cb = (propertiesChanged) => {
      if ('Value' in propertiesChanged) {
        const { value } = propertiesChanged.Value
        this.emit('valuechanged', Buffer.from(value))
      }
    }

    this.helper.on('PropertiesChanged', cb)
  }

The startNotify method is called before attaching the callback / event handler. Depending on how your system is busy / scheduled, you might loose 0, 1 or more event notifications.

Possible fix

  async startNotifications () {
-   await this.helper.callMethod('StartNotify')

    const cb = (propertiesChanged) => {
      if ('Value' in propertiesChanged) {
        const { value } = propertiesChanged.Value
        this.emit('valuechanged', Buffer.from(value))
      }
    }

    this.helper.on('PropertiesChanged', cb)
+   await this.helper.callMethod('StartNotify')
  }

Warning

The sample code in the README might also require a fix.

 const service2 = await gattServer.getPrimaryService('uuid')
 const characteristic2 = await service2.getCharacteristic('uuid')
-await characteristic2.startNotifications()
 characteristic2.on('valuechanged', buffer => {
   console.log(buffer)
 })
+await characteristic2.startNotifications()
 await characteristic2.stopNotifications()

Applying this fix on the supplied sample code produces the expected behavior :

$ DEBUG="sample-code" node index.js
  sample-code value changed: <Buffer 0f 00 04 00 01 02 00 00 00 00 00 00 00 00 00> +0ms
  sample-code value changed: <Buffer 0f 00 04 01 01 08 00 00 00 00 00 00 00 00 00> +1ms
  sample-code End of main +0ms
  sample-code value changed: <Buffer 0f 00 04 32 01 17 00 00 00 00 10 00 00 00 10> +50ms
  sample-code value changed: <Buffer 0f 00 04 3b 01 15 00 02 00 00 00 02 00 00 00> +0ms
  sample-code value changed: <Buffer 0f 00 04 3c 01 14 00 02 00 00 00 02 00 00 00> +0ms
^C  sample-code Cleaning up... +5s

[chrvadala]

Hi @nmasse-itix,
thanks for the deep analysis that you did. Looking at the code, I think that you're right, there could be some timings when the notification loose some events.
Your suggested solution should work. Can you submit a PR and some unit test around this fix?
Thanks a lot