search

nathankellenicki / node-poweredup

A Javascript module to interface with LEGO Powered Up components.
https://nathankellenicki.github.io/node-poweredup/
MIT License
483 stars 61 forks source link

Scan interrupt when a tentative to connect to a device #59

Closed phantase closed 4 years ago

phantase commented 4 years ago

Hi, I am making some test with this library, my goal is to connect on a Raspberry Pi multiple train and multiple remote.

When I try and adapt the examples, I have the following problem: the scan for new hubs/remotes stop once a device is discovered and the connection is initiated.

I have this following test : 

const PoweredUP = require("node-poweredup");
const poweredUP = new PoweredUP.PoweredUP();

poweredUP.on("discover", async (hub) => { // Wait to discover a Hub

  console.log(`##############################`)
  console.log(`Discovered ${hub.name}!`);

  if( hub instanceof PoweredUP.PUPRemote ){
    console.log("~~ Powered UP Remote ~~")
    await hub.connect(); // Connect to the Hub
    console.log("Connected");
    await hub.sleep(3000);

    if(hub.name.indexOf("Remote Grey") > -1){
      await hub.setLEDColor(PoweredUP.Consts.Color.WHITE);
    } else if(hub.name.indexOf("Remote Blue") > -1){
      await hub.setLEDColor(PoweredUP.Consts.Color.BLUE);
    } else if(hub.name.indexOf("Remote Red") > -1){
      await hub.setLEDColor(PoweredUP.Consts.Color.RED);
    } else if(hub.name.indexOf("Remote Green") > -1){
      await hub.setLEDColor(PoweredUP.Consts.Color.GREEN);
    }
  }

});
poweredUP.scan(); // Start scanning for Hubs
console.log("Scanning for Hubs...");

Which will just color the LED of the remote depending of the name of the remote.

When I just turn on one remote, this one is connected and the LED changes color. If I turn on another remote, this remote is never discoverer.

If I turn all my remote at the same time when no other device is connected, all the remote are discovered and the connection to all the remote is made (and the LEDs' color will change).

Of course, same with standard trains hub. When one hub is connected, scan is interrupted and no more hub nor remote can be discovered.

When I disconnect the attached device, the scan restart and new devices can be discovered.

I had a look to the log (DEBUG=* node scanners.js) and it seems that the Noble library decide to stop scanning after the connection is enabled. After a look to the code, I don't see why it decide to stop scanning without the stop command.

Here is the (long) log: 

root@rpi-indoor:~/nfslocal/dev/puptest# DEBUG=* node scanners.js
Scanning for Hubs...
  hci setting filter to: 1600000020c10000000000400000 +0ms
  hci set event mask - writing: 01010c08fffffbff07f8bf3d +4ms
  hci set le event mask - writing: 010120081f00000000000000 +1ms
  hci read local version - writing: 01011000 +2ms
  hci write LE host supported - writing: 016d0c020100 +1ms
  hci read LE host supported - writing: 016c0c00 +1ms
  hci read bd addr - writing: 01091000 +1ms
  hci onSocketData: 040e0401010c00 +6ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 3073 +1ms
  hci           status = 0 +1ms
  hci           result =  +0ms
  hci onSocketData: 040e0401012000 +2ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8193 +1ms
  hci           status = 0 +0ms
  hci           result =  +0ms
  hci onSocketData: 040e0c010110000922010931011961 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 4097 +1ms
  hci           status = 0 +0ms
  hci           result = 0922010931011961 +0ms
  hci set scan enabled - writing: 010c20020001 +1ms
  hci set scan parameters - writing: 010b200701100010000000 +2ms
  hci onSocketData: 040e04016d0c00 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci           cmd = 3181 +1ms
  hci           status = 0 +0ms
  hci           result =  +0ms
  hci onSocketData: 040e06016c0c000100 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci           cmd = 3180 +1ms
  hci           status = 0 +0ms
  hci           result = 0100 +0ms
  hci                   le = 1 +1ms
  hci                   simul = 0 +0ms
  hci onSocketData: 040e0a01091000be65feeb27b8 +0ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 4105 +0ms
  hci           status = 0 +1ms
  hci           result = be65feeb27b8 +0ms
  hci address = b8:27:eb:fe:65:be +0ms
  noble addressChange b8:27:eb:fe:65:be +0ms
  hci onSocketData: 040e04010c200c +2ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8204 +1ms
  hci           status = 12 +0ms
  hci           result =  +0ms
  hci onSocketData: 040e04010b2000 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8203 +0ms
  hci           status = 0 +0ms
  hci           result =  +1ms
  noble stateChange poweredOn +5ms
  poweredup Scanning started +0ms
  hci set scan enabled - writing: 010c20020001 +3ms
  hci set scan parameters - writing: 010b200701100010000000 +1ms
  hci set scan enabled - writing: 010c20020101 +0ms
  hci onSocketData: 040e04010c200c +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8204 +0ms
  hci           status = 12 +0ms
  hci           result =  +1ms
  hci onSocketData: 040e04010b2000 +0ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci           cmd = 8203 +0ms
  hci           status = 0 +0ms
  hci           result =  +0ms
  hci onSocketData: 040e04010c2000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci           cmd = 8204 +0ms
  hci           status = 0 +0ms
  hci           result =  +0ms
  noble scanStart +11ms
  hci onSocketData: 043e2b02010000a4aa6732daa41f020106110723d1bcea5f782316deef12122316000009ff970300420a006100b8 +2s
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci           LE meta event type = 2 +0ms
  hci           LE meta event status = 1 +0ms
  hci           LE meta event data = 0000a4aa6732daa41f020106110723d1bcea5f782316deef12122316000009ff970300420a006100b8 +1ms
  hci                   type = 0 +2ms
  hci                   address = a4:da:32:67:aa:a4 +0ms
  hci                   address type = public +0ms
  hci                   eir = 020106110723d1bcea5f782316deef12122316000009ff970300420a006100 +1ms
  hci                   rssi = -72 +1ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[151,3,0,66,10,0,97,0]},"serviceData":[],"serviceUuids":["000016231212efde1623785feabcd123"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +0ms
  hci onSocketData: 043e2a02010400a4aa6732daa41e140952656d6f746520426c75650000000000000000051210002000020a00b7 +6ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +1ms
  hci           LE meta event type = 2 +0ms
  hci           LE meta event status = 1 +1ms
  hci           LE meta event data = 0400a4aa6732daa41e140952656d6f746520426c75650000000000000000051210002000020a00b7 +0ms
  hci                   type = 4 +2ms
  hci                   address = a4:da:32:67:aa:a4 +0ms
  hci                   address type = public +1ms
  hci                   eir = 140952656d6f746520426c75650000000000000000051210002000020a00 +0ms
  hci                   rssi = -73 +1ms
  gap advertisement = {"localName":"Remote Blue\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000","txPowerLevel":0,"manufacturerData":{"type":"Buffer","data":[151,3,0,66,10,0,97,0]},"serviceData":[],"serviceUuids":["000016231212efde1623785feabcd123"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +10ms
  pupremote Discovered Powered UP Remote +0ms
  poweredup Hub a4da3267aaa4 discovered +3s
##############################
Discovered Remote Blue!
~~ Powered UP Remote ~~
  pupremote Connecting to Powered UP Remote +1s
  hci create le conn - writing: 010d2019600030000000a4aa6732daa40006000c000000c80004000600 +1s
  hci onSocketData: 040f0400010d20 +4ms
  hci   event type = 4 +1ms
  hci   sub event type = 15 +0ms
  hci           status = 0 +1ms
  hci           cmd = 8205 +0ms
  hci onSocketData: 043e13010040000000a4aa6732daa40c000000c80000 +42ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +1ms
  hci           LE meta event type = 1 +0ms
  hci           LE meta event status = 0 +1ms
  hci           LE meta event data = 40000000a4aa6732daa40c000000c80000 +0ms
  hci                   handle = 64 +2ms
  hci                   role = 0 +1ms
  hci                   address type = public +0ms
  hci                   address = a4:da:32:67:aa:a4 +1ms
  hci                   interval = 15 +0ms
  hci                   latency = 0 +1ms
  hci                   supervision timeout = 2000 +0ms
  hci                   master clock accuracy = 0 +1ms
  att a4:da:32:67:aa:a4: write: 020001 +0ms
  hci write acl data pkt - writing: 024000070003000400020001 +19ms
  hci onSocketData: 011620024000 +6ms
  hci   event type = 1 +1ms
  hci           cmd = 8214 +0ms
  hci           data len = 2 +1ms
  hci onSocketData: 040f0400011620 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 15 +1ms
  hci           status = 0 +0ms
  hci           cmd = 8214 +1ms
  hci onSocketData: 010c20020000 +1ms
  hci   event type = 1 +0ms
  hci           cmd = 8204 +1ms
  hci           data len = 2 +0ms
  hci                   LE enable scan command +1ms
  hci                   enable scanning = false +0ms
  hci                   filter duplicates = false +1ms
  noble scanStop +4s
  hci onSocketData: 040e0e0116200000000000000000000000 +4ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8214 +1ms
  hci           status = 0 +0ms
  hci           result = 00000000000000000000 +1ms
  hci onSocketData: 040e04010c2000 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci           cmd = 8204 +1ms
  hci           status = 0 +0ms
  hci           result =  +1ms
  hci onSocketData: 043e0c040040000100000000000000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 62 +1ms
  hci           LE meta event type = 4 +0ms
  hci           LE meta event status = 0 +1ms
  hci           LE meta event data = 40000100000000000000 +0ms
  hci onSocketData: 024020070003000400031700 +2ms
  hci   event type = 2 +1ms
  hci           cid = 4 +0ms
  hci           handle = 64 +1ms
  hci           data = 031700 +0ms
  att a4:da:32:67:aa:a4: read: 031700 +39ms
  att a4:da:32:67:aa:a4: new MTU is 23 +1ms
  att a4:da:32:67:aa:a4: write: 100100ffff0028 +1ms
  hci write acl data pkt - writing: 0240000b0007000400100100ffff0028 +7ms
  hci onSocketData: 02402012000e0004001106010007000018080008000118 +21ms
  hci   event type = 2 +0ms
  hci           cid = 4 +1ms
  hci           handle = 64 +0ms
  hci           data = 1106010007000018080008000118 +0ms
  att a4:da:32:67:aa:a4: read: 1106010007000018080008000118 +25ms
  att a4:da:32:67:aa:a4: write: 100900ffff0028 +1ms
  hci write acl data pkt - writing: 0240000b0007000400100900ffff0028 +3ms
  hci onSocketData: 0240201a001600040011140900ffff23d1bcea5f782316deef121223160000 +27ms
  hci   event type = 2 +0ms
  hci           cid = 4 +0ms
  hci           handle = 64 +1ms
  hci           data = 11140900ffff23d1bcea5f782316deef121223160000 +0ms
  att a4:da:32:67:aa:a4: read: 11140900ffff23d1bcea5f782316deef121223160000 +29ms
  bledevice Service/characteristic discovery started +0ms
  att a4:da:32:67:aa:a4: write: 080900ffff0328 +4ms
  hci write acl data pkt - writing: 0240000b0007000400080900ffff0328 +5ms
  hci onSocketData: 0240201b001700040009150a001c0b0023d1bcea5f782316deef121224160000 +24ms
  hci   event type = 2 +0ms
  hci           cid = 4 +0ms
  hci           handle = 64 +0ms
  hci           data = 09150a001c0b0023d1bcea5f782316deef121224160000 +1ms
  att a4:da:32:67:aa:a4: read: 09150a001c0b0023d1bcea5f782316deef121224160000 +26ms
  att a4:da:32:67:aa:a4: write: 080c00ffff0328 +2ms
  hci write acl data pkt - writing: 0240000b0007000400080c00ffff0328 +4ms
  hci onSocketData: 02402009000500040001080c000a +24ms
  hci   event type = 2 +1ms
  hci           cid = 4 +0ms
  hci           handle = 64 +0ms
  hci           data = 01080c000a +0ms
  att a4:da:32:67:aa:a4: read: 01080c000a +27ms
  bledevice Service/characteristic discovery finished +59ms
  att a4:da:32:67:aa:a4: write: 080a00ffff0229 +3ms
  hci write acl data pkt - writing: 0240000b0007000400080a00ffff0229 +4ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 0a 00 41 3b 00 01 00 00 00 01> +0ms
  hci onSocketData: 0240200a000600040009040c000000 +25ms
  hci   event type = 2 +0ms
  hci           cid = 4 +1ms
  hci           handle = 64 +0ms
  hci           data = 09040c000000 +0ms
  att a4:da:32:67:aa:a4: read: 09040c000000 +27ms
  att a4:da:32:67:aa:a4: write: 120b000a00413b000100000001 +1ms
  hci write acl data pkt - writing: 02400011000d000400120b000a00413b000100000001 +2ms
  hci onSocketData: 02402005000100040013 +27ms
  hci   event type = 2 +0ms
  hci           cid = 4 +0ms
  hci           handle = 64 +1ms
  hci           data = 13 +0ms
  att a4:da:32:67:aa:a4: read: 13 +29ms
  att a4:da:32:67:aa:a4: write: 120c000100 +1ms
  hci write acl data pkt - writing: 024000090005000400120c000100 +2ms
  hci onSocketData: 02402005000100040013 +27ms
  hci   event type = 2 +0ms
  hci           cid = 4 +0ms
  hci           handle = 64 +0ms
  hci           data = 13 +1ms
  att a4:da:32:67:aa:a4: read: 13 +29ms
  hci onSocketData: 02402011000d0004001b0b000a00473b000100000001 +14ms
  hci   event type = 2 +0ms
  hci           cid = 4 +1ms
  hci           handle = 64 +0ms
  hci           data = 1b0b000a00473b000100000001 +0ms
  lpf2hub Received Message (LPF2_ALL) <Buffer 0a 00 47 3b 00 01 00 00 00 01> +102ms
  hci onSocketData: 0240201600120004001b0b000f0004000137000000001000000010 +3ms
  hci   event type = 2 +0ms
  hci           cid = 4 +0ms
  hci           handle = 64 +1ms
  hci           data = 1b0b000f0004000137000000001000000010 +0ms
  lpf2hub Received Message (LPF2_ALL) <Buffer 0f 00 04 00 01 37 00 00 00 00 10 00 00 00 10> +3ms
  lpf2hubmodeinfo Port 00, type 0037 (POWERED_UP_REMOTE_BUTTON) +0ms
  lpf2hubmodeinfo Port 00, hardware version 1.0.00.0000, software version 1.0.00.0000 +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 21 00 01> +3ms
  att a4:da:32:67:aa:a4: write: 120b000500210001 +24ms
  hci write acl data pkt - writing: 0240000c0008000400120b000500210001 +6ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 21 00 02> +2ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 0a 00 41 00 00 01 00 00 00 01> +2ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 02 02> +3ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 03 05> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 04 05> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 05 02> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 06 02> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 01 0d 05> +0ms
  poweredup Hub a4da3267aaa4 connected +367ms
  pupremote Connect completed +362ms
Connected
  hci onSocketData: 0240201600120004001b0b000f0004010137000000001000000010 +12ms
  hci   event type = 2 +0ms
  hci           cid = 4 +1ms
  hci           handle = 64 +0ms
  hci           data = 1b0b000f0004010137000000001000000010 +0ms
  lpf2hub Received Message (LPF2_ALL) <Buffer 0f 00 04 01 01 37 00 00 00 00 10 00 00 00 10> +5ms
  lpf2hubmodeinfo Port 01, type 0037 (POWERED_UP_REMOTE_BUTTON) +17ms
  lpf2hubmodeinfo Port 01, hardware version 1.0.00.0000, software version 1.0.00.0000 +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 21 01 01> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 05 00 21 01 02> +1ms
  lpf2hub Sent Message (LPF2_ALL) <Buffer 0a 00 41 01 00 01 00 00 00 01> +1ms

I am doing my test on a Raspberry Pi 3 and a Raspberry Pi 0 with the integrated Bluetooth. Latest Raspbian (Raspbian GNU/Linux 10 (buster)) Node: v12.13.1 for the RPi3, v11.15.0 for the RPi0 "node-poweredup": "^4.3.0" I can give the full node dependencies if required.

I hope you will be able to give me a hint.

Thanks

nathankellenicki commented 4 years ago

I've experienced this myself with Raspbian on the Raspberry Pi, but not on macOS. There's an open issue for it against the Noble project: https://github.com/noble/noble/issues/223. The workaround is here: https://github.com/noble/noble/issues/223#issuecomment-241924168

With this library you can call poweredUP.scan() again after connecting to the hub. I added this to the library at once point but it had adverse side effects, so I removed it. Hopefully it works for your scenario.

phantase commented 4 years ago

OK, just tested and restarted the scan after the connect.

I will try to find a RPi4 to see if the problem is the same with this model.

In any case it solve my case, thanks, I will continue working/playing/testing on that.

nutki commented 4 years ago

@phantase I had the same issue on RPi3 and fixed this in my fork: https://github.com/nutki/node-poweredup/commit/6cb5c0d621e488adc3e3dbda48abe5454c2f1424 I did not have any further problems with this.

nathankellenicki commented 4 years ago

@nutki That exact fix was implemented in this library, but I removed it as it caused a few issues in certain edge cases.

Namely:

  1. Start scanning
  2. Turn on two hubs at the same time
  3. Library discovers one
  4. Library discovers second
  5. Library starts connecting to one
  6. Library starts connecting to second
  7. Library succeeds connecting to one, starts scanning again
  8. Library discovers second again, as it is still advertising as it has not finished connecting
  9. Library starts connecting to second for a second time
  10. Now, the handle to the second hub from the first connect is invalid as the Noble peripheral is no longer valid as it has discovered it again and Noble has given it a different peripheral id and constructed a new peripheral object
  11. Get errors while trying to send/receive data with old hub and old Noble peripheral

I wanted to implement some kind of filtering so it wouldn't try connecting to the same device again if a connection is already in progress, which worked, but the trouble is that Noble gives each device a different peripheral id on every discover. So the original reference was no longer valid.

So, this solution can work well as long as you're willing sequentially connect hubs, waiting for the first to fully connect before turning on the second. But it won't handle disconnects/reconnects very well.

phantase commented 4 years ago

Thanks for this feedback @nutki and this explanation @nathankellenicki I will probably only reactivate scan after a connect.