CLI sometimes fails to find/connect to BLE devices on Mac OS

[dandelany]

Hi and thanks for Espruino!

I'm seeing some "flaky" behavior connecting to my MDBT42Q breakout board over BLE using the CLI - sometimes it works, sometimes it doesn't. Retrying usually works after a few times. It almost always works in the Web IDE, but I'd prefer to use the CLI. The board was purchased recently & I just updated to the latest firmware 2v04. I am running Mac OS Mojave 10.14.6.

Here's a test script I wrote, with the relevant bit snipped from the CLI code. I noticed the CLI already tries two attempts to list the ports - I kept this in the test to see if it helps, but it doesn't seem to. I realize this is more likely a problem in the underlying (noble?) library, but figured I'd post here in case it's helpful.

const { init } = require("espruino");

//override default console.log
var log = console.log;
console.log = function() {};

function Queue(concurrency = 1) {
  let running = 0;
  const taskQueue = [];

  const runTask = task => {
    running++;
    task(_ => {
      running--;
      if (taskQueue.length > 0) {
        runTask(taskQueue.shift());
      }
    });
  };

  const enqueueTask = task => taskQueue.push(task);

  return {
    push: task => (running < concurrency ? runTask(task) : enqueueTask(task))
  };
}

init(() => {
  function checkPorts(done) {
    Espruino.Core.Serial.getPorts(function(ports) {
      if (ports.length >= 2) {
        log("OK ON 1ST TRY");
        done();
      } else { /* Try again */
        Espruino.Core.Serial.getPorts(function(ports) {
          if (ports.length >= 2) log("OK ON 2ND TRY");
          else log("NOT FOUND :(");
          done();
        });
      }
    });
  }

  const queue = Queue(1);

  for (i = 0; i < 10; i++) {
    queue.push(checkPorts);
    queue.push(done => {
      setTimeout(() => done(), 2000);
    });
  }
  queue.push(done => {
    process.exit(0);
    done();
  });
});

Here are the outputs from a few runs of the test - I tend to get long strings of "OK" or "not OK" in a row for some reason, but not always. I also don't appear to be getting any "OK on 2nd try," so I'm not sure the retry in the existing code is helping.

delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
NOT FOUND :(
OK ON 1ST TRY
OK ON 1ST TRY
NOT FOUND :(
OK ON 1ST TRY
OK ON 1ST TRY
delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
NOT FOUND :(
NOT FOUND :(
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
OK ON 1ST TRY
NOT FOUND :(

Finally, here's a verbose output from a "not working" run. Thanks in advance for any help!

delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
Acorn library not found - you'll need it for compiled code
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/libs/targz.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/libs/utf8.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/espruino.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/codeWriter.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/config.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/env.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/flasher.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/modules.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/notifications.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_chrome_serial.js
No chrome.serial - Chrome Serial disabled
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_chrome_socket.js
No chrome.sockets - Chrome Socket disabled
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_frame.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_noble.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_node_serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_node_socket.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_audio.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_bluetooth.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_websocket_local.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_websocket_relay.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_winnus.js
Not on Windows, Winnus not needed
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/terminal.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/utils.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/assembler.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/boardJSON.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/compiler.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/getGitHub.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/localModules.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/minify.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/pretokenise.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/saveOnSend.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/setTime.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/unicode.js
Loading UTF8 with require
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/versionChecker.js
espruinoRollup library not found - you'll need it to minify code
Initialising CodeWriter
Initialising Config
Initialising Env
Initialising Flasher
Initialising Modules
Initialising Notifications
Initialising Serial
  - Initialising Serial Noble Bluetooth LE
  - Initialising Serial Node Serial
  - Initialising Serial Node Socket
  - Initialising Serial Web Bluetooth
  - Initialising Serial Web Serial
Initialising Utils
Initialising Status
Initialising Assembler
Initialising BoardJSON
Initialising Compiler
Initialising GetGitHub
Initialising LocalModules
Initialising Minify
Initialising Pretokenise
Initialising SaveOnSend
Initialising SetTime
Initialising Unicode
Initialising VersionChecker
Initialising CoreModules
Noble: getPorts - not initialised
No navigator.bluetooth - Web Bluetooth not enabled
No navigator.serial - Web Serial not enabled
Noble: stateChange -> poweredOn
Noble: Disable Web Bluetooth as we have Noble instead
Noble: Starting scan
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
NOT FOUND :(
Noble: Found device:  
Noble: Found UART device: MDBT42Q db64 e8-04-f5-d8-db-64
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
delany@MT-110099:~/Documents/repos/rubble-alpha-espruino []$ node scripts/ble_test.js 
Acorn library not found - you'll need it for compiled code
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/libs/targz.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/libs/utf8.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/espruino.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/codeWriter.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/config.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/env.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/flasher.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/modules.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/notifications.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_chrome_serial.js
No chrome.serial - Chrome Serial disabled
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_chrome_socket.js
No chrome.sockets - Chrome Socket disabled
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_frame.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_noble.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_node_serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_node_socket.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_audio.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_bluetooth.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_web_serial.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_websocket_local.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_websocket_relay.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/serial_winnus.js
Not on Windows, Winnus not needed
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/terminal.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/core/utils.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/assembler.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/boardJSON.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/compiler.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/getGitHub.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/localModules.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/minify.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/pretokenise.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/saveOnSend.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/setTime.js
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/unicode.js
Loading UTF8 with require
Found /Users/delany/Documents/repos/rubble-alpha-espruino/node_modules/espruino/plugins/versionChecker.js
espruinoRollup library not found - you'll need it to minify code
Initialising CodeWriter
Initialising Config
Initialising Env
Initialising Flasher
Initialising Modules
Initialising Notifications
Initialising Serial
  - Initialising Serial Noble Bluetooth LE
  - Initialising Serial Node Serial
  - Initialising Serial Node Socket
  - Initialising Serial Web Bluetooth
  - Initialising Serial Web Serial
Initialising Utils
Initialising Status
Initialising Assembler
Initialising BoardJSON
Initialising Compiler
Initialising GetGitHub
Initialising LocalModules
Initialising Minify
Initialising Pretokenise
Initialising SaveOnSend
Initialising SetTime
Initialising Unicode
Initialising VersionChecker
Initialising CoreModules
Noble: getPorts - not initialised
No navigator.bluetooth - Web Bluetooth not enabled
No navigator.serial - Web Serial not enabled
Noble: stateChange -> poweredOn
Noble: Disable Web Bluetooth as we have Noble instead
Noble: Starting scan
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
NOT FOUND :(
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  

[dandelany]

BTW - the "found device" 94-b0-1f-68-5a-99 in the log above is not my MDBT42Q - I'm not sure what it is.

However, running the verbose test a few more times, I did notice that occasionally there are failed runs of the test where getPorts does not return the Espruino board, but then it does subsequently show up as "found" in the log! eg.:

...
Noble: stateChange -> poweredOn
Noble: Disable Web Bluetooth as we have Noble instead
Noble: Starting scan
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device:  
Noble: Found device:  
Noble: Found device:  
Noble: Found device: ALAM (24:64:46) 
NOT FOUND :( // getPorts callback called here
Noble: Found device:  
Noble: Found UART device: MDBT42Q db64 e8-04-f5-d8-db-64 // here is my espruino
Noble: Found device:  
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99
Noble: Found device: 94-b0-1f-68-5a-99 94-b0-1f-68-5a-99

(most of the time, though, it's missing from the logs entirely)

Also BTW - this is not a super high priority problem for me, since I can still upload code if I try enough times :) Hopefully it's helpful though.

[gfwilliams]

Hi Dan, thanks - I'm a bit bust at the moment but I'll try and look at this when things calm down.

Because the same code gets used for the IDE itself, the scan is done in the background and for each getPorts call, the devices found up to that point are returned. The scan doesn't immediately stop as soon as the getPorts stops being called (in case getPorts is called >1 time), which might be why you see other devices?

getPorts should be called more than once though, and if it's being called after the UART device is found and isn't returning the device, that's definitely a big bug we should look at.

Also if the CLI is reasonably reliably finding your device after scanning is stopped, we could try calling getPorts one more time to extend the scanning window?

[jameshowe]

I've got a similar issue using --list on the Mac (Catalina 10.15.1 / Node v12.18.1), the results are sporadic - however, not unexpected from my experience of working with BLE devices on the Mac, can pick it up pretty consistently with the Nordic app on my phone.

@gfwilliams whats your thoughts on perhaps just adding a timeout option to --list to allow for longer scan period? e.g. --list 10000, at a glance it looks like it would be a case of making this timeout configurable? Could be trivialising, but would be happy to take a proper look and create a PR for it.

[jameshowe]

Ok, as expected definitely trivialised this - wasn't thinking about the fact it would need supported across all the various target platforms 🤦

[gfwilliams]

:) I think it'd be a good idea. Actually it's almost that easy I think:

https://github.com/espruino/EspruinoTools/blob/gh-pages/bin/espruino-cli.js#L683

Although looking at it, Espruino.Core.Serial.getPorts is called in two places with two different types of timeout, and that should really be merged into one function.

I think probably it needs to call Espruino.Core.Serial.getPorts a few times and actually merge the results it gets

[gfwilliams]

Think this is fixed now - getPorts is called multiple times until a device is found