search

project-chip / matter.js

A complete typescript implementation of the Matter protocol specification (https://buildwithmatter.com). Includes full support for controller, device, commissioning, secure communications, device types, and cluster definitions.
Apache License 2.0
350 stars 60 forks source link

matter-controller example: Peripheral is not connectable #1345

Open leonardocavagnis opened 1 day ago

leonardocavagnis commented 1 day ago

I'm testing the matter-controller example, and I'm encountering an issue during the Bluetooth commissioning phase.

My setup:

To reproduce:

sudo npm run matter-controller --
--ble 
--ble-thread-networkname=<my-ble-threadnetworkname> 
--ble-thread-operationaldataset=<my-ble-thread-operationalset>
--pairingcode=<my-pairing-code>

Output (truncated):

...
Storage location: /Users/leonardocavagnis/.matter (Directory)
2024-10-31 18:36:24.836 INFO   Controller           Use the parameter "--storage-path=NAME-OR-PATH" to specify a different storage location in this directory, use --storage-clear to start with an empty storage.
2024-10-31 18:36:24.837 INFO   Controller           node-matter Controller started
2024-10-31 18:36:24.843 DEBUG  Controller           Data extracted from pairing code: {"shortDiscriminator":15,"passcode":20202021,"vendorId":"undefined","productId":"undefined"}
2024-10-31 18:36:24.843 INFO   Controller           Registering Commissioning over BLE with Thread: OpenThread-ESP
2024-10-31 18:36:24.844 INFO   ControllerStore      Opened 1730384820050 storage at /Users/leonardocavagnis/.matter/1730384820050
2024-10-31 18:36:24.848 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.851 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.852 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.854 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.855 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:undefined localAddress: :::59526
2024-10-31 18:36:24.855 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:59526 localAddress: 0.0.0.0:59526
2024-10-31 18:36:24.926 DEBUG  CertificateAuthority Loaded stored credentials with ID 0
2024-10-31 18:36:24.927 INFO   MatterController     Creating new fabric
2024-10-31 18:36:24.929 DEBUG  Fabric               FabricBuilder setOperationalCert: nodeId=6290779623816817677, fabricId=1, caseAuthenticatedTags=undefined
2024-10-31 18:36:24.932 DEBUG  DeviceAdvertiser     Announcing fabric: 1
2024-10-31 18:36:24.933 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: ap1
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: en0
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: awdl0
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: llw0
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: utun0
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: utun1
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: utun2
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: utun3
2024-10-31 18:36:24.934 DEBUG  MdnsBroadcaster      Announcement Generator: Fabric id: 5b37aa2d63c5a0b5/6290779623816817677 qname: 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local port: 59526 interface: bridge100
2024-10-31 18:36:24.935 INFO   Controller           Commissioning ... {"commissioning":{"regulatoryLocation":2,"regulatoryCountryCode":"XX","threadNetwork":{"networkName":"OpenThread-ESP","operationalDataset":"0e080000000000010000000300000f35060004001fffe00208dead00beef00cafe0708fd000db800a00000051000112233445566778899aabbccddeeff030e4f70656e5468726561642d455350010212340410104810e2315100afd6bc9215a6bfac530c0402a0f7f8"}},"discovery":{"knownAddress":"undefined","identifierData":{"shortDiscriminator":15},"discoveryCapabilities":{"ble":true}},"passcode":20202021}
2024-10-31 18:36:24.935 INFO   PeerCommissioner     Commissioning device with identifier {"shortDiscriminator":15} and 2 scanners and knownAddress "undefined"
2024-10-31 18:36:24.935 INFO   ControllerDiscovery  Start Discovering devices using identifier {"shortDiscriminator":15} ...
2024-10-31 18:36:24.935 DEBUG  MdnsScanner          Registered waiter for query _S15._sub._matterc._udp.local with timeout 30 seconds
2024-10-31 18:36:24.935 DEBUG  MdnsScanner          Set 2 query records for query _S15._sub._matterc._udp.local: [{"name":"_matterc._udp.local","recordClass":1,"recordType":12},{"name":"_S15._sub._matterc._udp.local","recordClass":1,"recordType":12}]
2024-10-31 18:36:24.935 DEBUG  NobleBleClient       noble state is not poweredOn ... delay scanning till poweredOn
2024-10-31 18:36:24.938 DEBUG  BleScanner           Registered waiter for query SD:15 with timeout 30 seconds
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.938 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: ::%ap1:5353 interface: ap1 type: udp6
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: 192.168.1.6:5353 interface: en0 type: udp4
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: ::%en0:5353 interface: en0 type: udp6
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: ::%awdl0:5353 interface: awdl0 type: udp6
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: ::%llw0:5353 interface: llw0 type: udp6
2024-10-31 18:36:24.939 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun0:5353 interface: utun0 type: udp6
2024-10-31 18:36:24.940 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun1:5353 interface: utun1 type: udp6
2024-10-31 18:36:24.940 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun2:5353 interface: utun2 type: udp6
2024-10-31 18:36:24.940 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun3:5353 interface: utun3 type: udp6
2024-10-31 18:36:24.940 DEBUG  UdpChannelNode       Initialize multicast address: 192.168.2.1:5353 interface: bridge100 type: udp4
2024-10-31 18:36:24.940 DEBUG  UdpChannelNode       Initialize multicast address: ::%bridge100:5353 interface: bridge100 type: udp6
2024-10-31 18:36:24.942 DEBUG  MdnsScanner          Sending 2 query records for 1 queries with 0 known answers. Re-Announce in 1.5 seconds
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: 0.0.0.0:5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Socket created and bound remoteAddress: undefined:5353 localAddress: :::5353
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Initialize multicast address: ::%ap1:5353 interface: ap1 type: udp6
2024-10-31 18:36:24.943 DEBUG  UdpChannelNode       Initialize multicast address: 192.168.1.6:5353 interface: en0 type: udp4
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%en0:5353 interface: en0 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%awdl0:5353 interface: awdl0 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%llw0:5353 interface: llw0 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun0:5353 interface: utun0 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun1:5353 interface: utun1 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun2:5353 interface: utun2 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%utun3:5353 interface: utun3 type: udp6
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: 192.168.2.1:5353 interface: bridge100 type: udp4
2024-10-31 18:36:24.944 DEBUG  UdpChannelNode       Initialize multicast address: ::%bridge100:5353 interface: bridge100 type: udp6
2024-10-31 18:36:24.950 DEBUG  NobleBleClient       Noble state changed to poweredOn
2024-10-31 18:36:24.950 DEBUG  NobleBleClient       Start BLE scanning for Matter Services ...
2024-10-31 18:36:24.997 DEBUG  NobleBleClient       Found peripheral  (Arduino Matter device): {"localName":"Arduino Matter device","serviceData":[{"uuid":"fff6","data":{"type":"Buffer","data":[0,0,15,241,255,5,128,0]}}],"serviceUuids":["fff6"]}
2024-10-31 18:36:24.997 DEBUG  BleScanner           Discovered device  00000ff1ff058000
2024-10-31 18:36:24.997 DEBUG  BleScanner           Discovered device  data: {"deviceIdentifier":"","D":3840,"SD":15,"VP":"65521+32773","CM":1,"addresses":[{"type":"ble","peripheralAddress":""}]}
2024-10-31 18:36:24.997 DEBUG  BleScanner           Finishing waiter for query SD:15, resolving: true
2024-10-31 18:36:24.997 DEBUG  NobleBleClient       Stop BLE scanning for Matter Services ...
2024-10-31 18:36:24.997 INFO   ControllerDiscovery  Found 1 devices using identifier {"shortDiscriminator":15}
2024-10-31 18:36:24.997 DEBUG  ControllerDiscovery  Server addresses to try: undefined: ble://
2024-10-31 18:36:24.998 DEBUG  ControllerDiscovery  Try to communicate with ble:// ...
2024-10-31 18:36:24.998 INFO   PeerCommissioner     Commissioning device SII: undefined SAI: undefined SAT: undefined T: undefined DT: undefined PH: undefined ICD: undefined VP: 65521+32773 DN: undefined RI: undefined PI: undefined
2024-10-31 18:36:24.998 DEBUG  BleScanner           Discovered device  00000ff1ff058000
2024-10-31 18:36:24.998 DEBUG  BleScanner           Discovered device  data: {"deviceIdentifier":"","D":3840,"SD":15,"VP":"65521+32773","CM":1,"addresses":[{"type":"ble","peripheralAddress":""}]}
2024-10-31 18:36:24.998 DEBUG  BleChannel           BLE peripheral state disconnected
2024-10-31 18:36:24.998 DEBUG  BleChannel           Connect to Peripheral now (try 1)
2024-10-31 18:36:25.426 DEBUG  NobleBleClient       Found peripheral  (Empty Example): {"localName":"Empty Example","serviceData":[{"uuid":"fff6","data":{"type":"Buffer","data":[0,0,15,241,255,5,128,0]}}],"serviceUuids":["fff6"]}
2024-10-31 18:36:25.427 INFO   NobleBleClient       Peripheral  is not connectable ... ignoring
2024-10-31 18:36:25.659 DEBUG  BleChannel           Found services: fff6
2024-10-31 18:36:25.660 DEBUG  BleChannel           found service: fff6
2024-10-31 18:36:25.809 DEBUG  BleChannel           found characteristic: 18ee2ef5263d4559959f4f9c429f9d11 read write
2024-10-31 18:36:25.810 DEBUG  BleChannel           found C1 characteristic
2024-10-31 18:36:25.810 DEBUG  BleChannel           found characteristic: 18ee2ef5263d4559959f4f9c429f9d12 read writeWithoutResponse write indicate
2024-10-31 18:36:25.810 DEBUG  BleChannel           found C2 characteristic
2024-10-31 18:36:25.810 DEBUG  BleChannel           found characteristic: 64630238877245f2b87d748a83218f04 read
2024-10-31 18:36:25.810 DEBUG  BleChannel           found C3 characteristic
2024-10-31 18:36:25.810 DEBUG  BleChannel           Using MTU=0 (Peripheral MTU=null)
2024-10-31 18:36:25.810 DEBUG  BleChannel           sending BTP handshake request: "656c040000000000ff"
2024-10-31 18:36:25.817 DEBUG  BleChannel           subscribing to C2 characteristic
2024-10-31 18:36:26.443 DEBUG  MdnsScanner          Sending 2 query records for 1 queries with 0 known answers. Re-Announce in 3 seconds
2024-10-31 18:36:27.382 DEBUG  MdnsScanner          Adding operational device 5B37AA2D63C5A0B5-574D56BCE5DDEC0D._matter._tcp.local in cache (interface en0, ttl=120) with TXT data: SII: 500 SAI: 300 SAT: 4000 T: 0 DT: undefined PH: undefined ICD: 0 VP: undefined DN: undefined RI: undefined PI: undefined
2024-10-31 18:36:29.445 DEBUG  MdnsScanner          Sending 2 query records for 1 queries with 0 known answers. Re-Announce in 6 seconds
2024-10-31 18:36:30.819 DEBUG  BleChannel           Handshake Response not received. Disconnected from peripheral
2024-10-31 18:36:35.446 DEBUG  MdnsScanner          Sending 2 query records for 1 queries with 0 known answers. Re-Announce in 12 seconds
2024-10-31 18:36:47.447 DEBUG  MdnsScanner          Sending 2 query records for 1 queries with 0 known answers. Re-Announce in 24 seconds
2024-10-31 18:36:54.937 DEBUG  MdnsScanner          Finishing waiter for query _S15._sub._matterc._udp.local, resolving: true
2024-10-31 18:36:54.939 DEBUG  MdnsScanner          Removing last query _S15._sub._matterc._udp.local and stopping announce timer
2024-10-31 18:36:54.939 INFO   ControllerDiscovery  Found 0 devices using identifier {"shortDiscriminator":15}

I have noticed the following message: 2024-10-31 18:36:25.427 INFO NobleBleClient Peripheral is not connectable ... ignoring

Operating System: macOS Sonoma 14.6.1 (MacBook Pro 2023 - Apple M2 Pro)

Apollon77 commented 23 hours ago

In this case the device reports that it is not connectable .. at least noble thinks this

https://github.com/project-chip/matter.js/blob/80ced3c2f61b8e5f1cf222640fc199fbc6244037/packages/nodejs-ble/src/NobleBleClient.ts#L101

Why it is that way would be a question to check with the "device" ... so do you maybe need anything to configure on the Arduino device with BLE to report as conectable?

Apollon77 commented 12 hours ago

@leonardocavagnis After a short check with @stoprocent it really seems that our device needs to adjust the way it advertises:

Bluetooth Low Energy (BLE) advertising, the "Flags" field within the Advertising Data (AD) packet provides information about the connectability of the device. Specifically:

This is the primary indicator for connectability in BLE advertising packets.