What I've done
1) Set up ot-br on an Rpi4 by following this guide.
2) Set up a 52840Dongle (plugged into the RPi4) as RCP by following this guide.
3) Installed the light_bulb example on a 52840DK using the nrf connect vscode extenrion.
What I've tried next
1) Hold "IF BOOT RESET" on the DK to reset to a clean state
2) Commission the device on to the network by running
~/connectedhomeip/out/host$ sudo ./chip-tool pairing code 1 MT:6FCJ142C00KA0648G00` 3 times. Note that the runs give different results.
Logs from the chip-tool commands:
ubuntu@ubuntu:~/connectedhomeip/out/host$ sudo ./chip-tool pairing code 1 MT:6FCJ142C00KA0648G00
[1657752376.872877][1970:1970] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657752376.873088][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_kvs-DWgaQ8)
[1657752376.873223][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1657752376.873565][1970:1970] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657752376.873684][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-wrZbmc)
[1657752376.873799][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657752376.873864][1970:1970] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657752376.873949][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_config.ini-d4Jxq9)
[1657752376.874029][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657752376.874086][1970:1970] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657752376.874153][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-XW8F57)
[1657752376.874231][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752376.874413][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-8kIW2b)
[1657752376.874770][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657752376.874804][1970:1970] CHIP:DL: NVS set: chip-factory/unique-id = "C652FD5861393522"
[1657752376.874900][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-Ni6EH9)
[1657752376.877865][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657752376.877913][1970:1970] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1)
[1657752376.878043][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-u3OlZa)
[1657752376.878598][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657752376.878639][1970:1970] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001)
[1657752376.878747][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-A0fIda)
[1657752376.879317][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752376.879381][1970:1970] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1)
[1657752376.879538][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YOSyV9)
[1657752376.880083][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752376.880127][1970:1970] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657752376.880282][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-x1b0Rb)
[1657752376.883532][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752376.883598][1970:1970] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0)
[1657752376.883774][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_config.ini-ZZfYg9)
[1657752376.884263][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657752376.884317][1970:1970] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0)
[1657752376.884460][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_config.ini-2lvcJb)
[1657752376.884999][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657752376.885055][1970:1970] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2)
[1657752376.886042][1970:1970] CHIP:DL: Got Ethernet interface: eth0
[1657752376.887042][1970:1970] CHIP:DL: Found the primary Ethernet interface:eth0
[1657752376.887542][1970:1970] CHIP:DL: Got WiFi interface: wlan0
[1657752376.890024][1970:1970] CHIP:DL: Found the primary WiFi interface:wlan0
[1657752376.890097][1970:1970] CHIP:IN: UDP::Init bind&listen port=0
[1657752376.890444][1970:1970] CHIP:IN: UDP::Init bound to port=43463
[1657752376.890479][1970:1970] CHIP:IN: UDP::Init bind&listen port=0
[1657752376.890579][1970:1970] CHIP:IN: UDP::Init bound to port=50465
[1657752376.890608][1970:1970] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657752376.890656][1970:1970] CHIP:IN: TransportMgr initialized
[1657752376.890726][1970:1970] CHIP:FP: Initializing FabricTable from persistent storage
[1657752376.890841][1970:1970] CHIP:TS: Last Known Good Time: [unknown]
[1657752376.890886][1970:1970] CHIP:TS: Setting Last Known Good Time to firmware build time 2022-07-13T18:42:46
[1657752376.893380][1970:1970] CHIP:ZCL: Using ZAP configuration...
[1657752376.894841][1970:1970] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752376.897134][1970:1970] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752376.898032][1970:1970] CHIP:CTL: System State Initialized...
[1657752376.899133][1970:1970] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752376.899190][1970:1970] CHIP:CTL: Setting attestation nonce to random value
[1657752376.899255][1970:1970] CHIP:CTL: Setting CSR nonce to random value
[1657752376.899372][1970:1970] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752376.899401][1970:1970] CHIP:CTL: Setting attestation nonce to random value
[1657752376.899447][1970:1970] CHIP:CTL: Setting CSR nonce to random value
[1657752376.899880][1970:1970] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1657752376.902620][1970:1970] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1657752376.903838][1970:1970] CHIP:CTL: Generating RCAC
[1657752376.907228][1970:1970] CHIP:CTL: Generating ICAC
[1657752376.910410][1970:1970] CHIP:CTL: Generating NOC
[1657752376.913826][1970:1970] CHIP:FP: Validating NOC chain
[1657752376.915908][1970:1970] CHIP:FP: NOC chain validation successful
[1657752376.918116][1970:1970] CHIP:FP: Added new fabric at index: 0x1
[1657752376.918152][1970:1970] CHIP:FP: Assigned compressed fabric ID: 0x0D0D872986F5DBB4, node ID: 0x000000000001B669
[1657752376.918185][1970:1970] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752376.918213][1970:1970] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752376.918237][1970:1970] CHIP:TS: Retaining current Last Known Good Time
[1657752376.919893][1970:1970] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657752376.922141][1970:1970] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752376.924454][1970:1970] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657752376.924570][1970:1970] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752376.924613][1970:1970] CHIP:CTL: Setting attestation nonce to random value
[1657752376.924686][1970:1970] CHIP:CTL: Setting CSR nonce to random value
[1657752376.926024][1970:1970] CHIP:CTL: Generating NOC
[1657752376.926955][1970:1970] CHIP:FP: Validating NOC chain
[1657752376.929072][1970:1970] CHIP:FP: NOC chain validation successful
[1657752376.929264][1970:1970] CHIP:FP: Added new fabric at index: 0x2
[1657752376.929295][1970:1970] CHIP:FP: Assigned compressed fabric ID: 0x371042A6B8C55FE8, node ID: 0x000000000001B669
[1657752376.929326][1970:1970] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752376.929350][1970:1970] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752376.929372][1970:1970] CHIP:TS: Retaining current Last Known Good Time
[1657752376.930982][1970:1970] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657752376.933252][1970:1970] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752376.938283][1970:1970] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657752376.938396][1970:1970] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752376.938430][1970:1970] CHIP:CTL: Setting attestation nonce to random value
[1657752376.938488][1970:1970] CHIP:CTL: Setting CSR nonce to random value
[1657752376.939555][1970:1970] CHIP:CTL: Generating NOC
[1657752376.940418][1970:1970] CHIP:FP: Validating NOC chain
[1657752376.942116][1970:1970] CHIP:FP: NOC chain validation successful
[1657752376.942269][1970:1970] CHIP:FP: Added new fabric at index: 0x3
[1657752376.942291][1970:1970] CHIP:FP: Assigned compressed fabric ID: 0x3D3201B65A89FB29, node ID: 0x000000000001B669
[1657752376.942316][1970:1970] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752376.942335][1970:1970] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752376.942352][1970:1970] CHIP:TS: Retaining current Last Known Good Time
[1657752376.943946][1970:1970] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657752376.954317][1970:1970] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752376.957199][1970:1970] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657752377.033210][1970:1976] CHIP:DL: CHIP task running
[1657752377.033351][1970:1976] CHIP:CTL: Setting attestation nonce to random value
[1657752377.033504][1970:1976] CHIP:CTL: Setting CSR nonce to random value
[1657752377.036695][1970:1976] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752377.036728][1970:1976] CHIP:CTL: Starting commissioning discovery over BLE
[1657752377.036760][1970:1976] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1657752377.037069][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752377.037702][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752377.037735][1970:1976] CHIP:DIS: mDNS broadcast had only partial success: 8 successes and 2 failures.
[1657752377.038011][1970:1977] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657752377.038431][1970:1973] CHIP:DL: TRACE: Bus acquired for name C-07b2
[1657752377.049881][1970:1976] CHIP:DL: PlatformBlueZInit init success
[1657752377.055880][1970:1973] CHIP:BLE: BLE removing known devices.
[1657752377.057376][1970:1973] CHIP:BLE: BLE initiating scan.
[1657752377.812119][1970:1976] CHIP:DL: Long dispatch time: 774 ms, for event type 2
[1657752377.850872][1970:1973] CHIP:BLE: Device 66:DB:45:2B:A1:BA does not look like a CHIP device.
[1657752377.856569][1970:1973] CHIP:BLE: Device FC:58:FA:8B:4D:4B does not look like a CHIP device.
[1657752377.879525][1970:1973] CHIP:BLE: Device 50:01:00:00:01:2E does not look like a CHIP device.
[1657752377.881215][1970:1973] CHIP:BLE: Device 66:B5:C2:5B:4A:5F does not look like a CHIP device.
[1657752377.882733][1970:1973] CHIP:BLE: Device 7C:0A:3F:99:31:F9 does not look like a CHIP device.
[1657752378.025532][1970:1973] CHIP:BLE: Device 71:3D:2F:2A:AC:F0 does not look like a CHIP device.
[1657752378.027943][1970:1973] CHIP:BLE: Device 7B:D3:38:94:29:5A does not look like a CHIP device.
[1657752378.037893][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752378.038741][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752378.038787][1970:1976] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752378.039852][1970:1973] CHIP:BLE: Device F8:9A:FA:3C:7B:E4 does not look like a CHIP device.
[1657752378.277114][1970:1973] CHIP:BLE: Device 5A:4B:3A:A2:83:8F does not look like a CHIP device.
[1657752378.386483][1970:1973] CHIP:BLE: Device 54:96:94:3A:78:70 does not look like a CHIP device.
[1657752378.431936][1970:1973] CHIP:BLE: Device 5C:56:CA:2B:F8:30 does not look like a CHIP device.
[1657752378.483268][1970:1973] CHIP:BLE: Device 53:EE:CB:63:79:6D does not look like a CHIP device.
[1657752378.548415][1970:1973] CHIP:BLE: Device 42:E7:91:48:90:9B does not look like a CHIP device.
[1657752378.679448][1970:1973] CHIP:BLE: Device 57:E4:C4:C9:EC:08 does not look like a CHIP device.
[1657752378.681175][1970:1973] CHIP:BLE: Device 34:E0:1A:FC:91:D4 does not look like a CHIP device.
[1657752378.876036][1970:1973] CHIP:BLE: Device 77:37:77:08:E4:12 does not look like a CHIP device.
[1657752379.111460][1970:1973] CHIP:BLE: New device scanned: DF:84:4E:3B:47:6F
[1657752379.111543][1970:1973] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657752379.116259][1970:1973] CHIP:BLE: Scan complete notification without an active scan.
[1657752379.552347][1970:1973] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752380.040417][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752380.041726][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752380.041804][1970:1976] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752380.736130][1970:1973] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752381.633532][1970:1973] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752382.347258][1970:1973] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752383.399842][1970:1973] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752383.400117][1970:1976] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657752383.400201][1970:1976] CHIP:CTL: Commissioning discovery over BLE failed: ../../src/platform/Linux/bluez/Helper.cpp:1775: CHIP Error 0x000000AC: Internal error
[1657752383.400261][1970:1976] CHIP:-: ../../src/platform/Linux/bluez/Helper.cpp:1775: CHIP Error 0x000000AC: Internal error at ../../src/controller/SetUpCodePairer.cpp:270
[1657752384.041587][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752384.042884][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752384.043019][1970:1976] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752392.044202][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752392.046348][1970:1976] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752392.046426][1970:1976] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752407.053852][1970:1976] CHIP:CTL: Discovery timed out
[1657752407.053939][1970:1976] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752407.053995][1970:1976] CHIP:TOO: Secure Pairing Failed
[1657752407.054614][1970:1970] CHIP:CTL: Shutting down the commissioner
[1657752407.054688][1970:1970] CHIP:CTL: Shutting down the controller
[1657752407.054746][1970:1970] CHIP:CTL: Shutting down the commissioner
[1657752407.054793][1970:1970] CHIP:CTL: Shutting down the controller
[1657752407.054841][1970:1970] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1657752407.054887][1970:1970] CHIP:FP: Forgetting fabric 0x1
[1657752407.054949][1970:1970] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752407.055339][1970:1970] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752407.055394][1970:1970] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752407.055475][1970:1970] CHIP:CTL: Shutting down the commissioner
[1657752407.055522][1970:1970] CHIP:CTL: Shutting down the controller
[1657752407.055565][1970:1970] CHIP:IN: Expiring all sessions for fabric 0x2!!
[1657752407.055607][1970:1970] CHIP:FP: Forgetting fabric 0x2
[1657752407.055657][1970:1970] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752407.055982][1970:1970] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752407.056037][1970:1970] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752407.056105][1970:1970] CHIP:CTL: Shutting down the commissioner
[1657752407.056152][1970:1970] CHIP:CTL: Shutting down the controller
[1657752407.056194][1970:1970] CHIP:IN: Expiring all sessions for fabric 0x3!!
[1657752407.056236][1970:1970] CHIP:FP: Forgetting fabric 0x3
[1657752407.056285][1970:1970] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752407.056543][1970:1970] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752407.056594][1970:1970] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752407.056652][1970:1970] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657752407.057742][1970:1970] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752407.057800][1970:1970] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752407.057843][1970:1970] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752407.057885][1970:1970] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752407.057929][1970:1970] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657752407.058086][1970:1970] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657752407.058513][1970:1970] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-o2a0kc)
[1657752407.059508][1970:1970] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752407.059608][1970:1970] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657752407.059660][1970:1970] CHIP:DL: Inet Layer shutdown
[1657752407.059747][1970:1970] CHIP:DL: BLE shutdown
[1657752407.062040][1970:1970] CHIP:DL: System Layer shutdown
[1657752407.062292][1970:1970] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/pairing/PairingCommand.cpp:151: CHIP Error 0x00000003: Incorrect state
ubuntu@ubuntu:~/connectedhomeip/out/host$ sudo ./chip-tool pairing code 1 MT:6FCJ142C00KA0648G00
[1657752409.785223][1983:1983] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657752409.785700][1983:1983] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657752409.785849][1983:1983] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657752409.785947][1983:1983] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657752409.786231][1983:1983] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-H6SeR8)
[1657752409.786706][1983:1983] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752409.786742][1983:1983] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1657752409.787443][1983:1983] CHIP:DL: Got Ethernet interface: eth0
[1657752409.788017][1983:1983] CHIP:DL: Found the primary Ethernet interface:eth0
[1657752409.788515][1983:1983] CHIP:DL: Got WiFi interface: wlan0
[1657752409.790625][1983:1983] CHIP:DL: Found the primary WiFi interface:wlan0
[1657752409.790684][1983:1983] CHIP:IN: UDP::Init bind&listen port=0
[1657752409.790795][1983:1983] CHIP:IN: UDP::Init bound to port=44091
[1657752409.790815][1983:1983] CHIP:IN: UDP::Init bind&listen port=0
[1657752409.790893][1983:1983] CHIP:IN: UDP::Init bound to port=54164
[1657752409.790920][1983:1983] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657752409.790942][1983:1983] CHIP:IN: TransportMgr initialized
[1657752409.790972][1983:1983] CHIP:FP: Initializing FabricTable from persistent storage
[1657752409.791239][1983:1983] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752409.792072][1983:1983] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x0D0D872986F5DBB4, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752409.792676][1983:1983] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x371042A6B8C55FE8, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752409.793034][1983:1983] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3201B65A89FB29, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752409.795917][1983:1983] CHIP:ZCL: Using ZAP configuration...
[1657752409.797104][1983:1983] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752409.799084][1983:1983] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752409.799913][1983:1983] CHIP:CTL: System State Initialized...
[1657752409.799985][1983:1983] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752409.800018][1983:1983] CHIP:CTL: Setting attestation nonce to random value
[1657752409.800075][1983:1983] CHIP:CTL: Setting CSR nonce to random value
[1657752409.800160][1983:1983] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752409.800185][1983:1983] CHIP:CTL: Setting attestation nonce to random value
[1657752409.800223][1983:1983] CHIP:CTL: Setting CSR nonce to random value
[1657752409.802693][1983:1983] CHIP:CTL: Generating NOC
[1657752409.803921][1983:1983] CHIP:FP: Validating NOC chain
[1657752409.805551][1983:1983] CHIP:FP: NOC chain validation successful
[1657752409.805704][1983:1983] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1657752409.805735][1983:1983] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752409.805755][1983:1983] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752409.805772][1983:1983] CHIP:TS: Retaining current Last Known Good Time
[1657752409.810021][1983:1983] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657752409.812186][1983:1983] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752409.814032][1983:1983] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657752409.814149][1983:1983] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752409.814185][1983:1983] CHIP:CTL: Setting attestation nonce to random value
[1657752409.814246][1983:1983] CHIP:CTL: Setting CSR nonce to random value
[1657752409.815124][1983:1983] CHIP:CTL: Generating NOC
[1657752409.816553][1983:1983] CHIP:FP: Validating NOC chain
[1657752409.818673][1983:1983] CHIP:FP: NOC chain validation successful
[1657752409.818864][1983:1983] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669
[1657752409.818904][1983:1983] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752409.818929][1983:1983] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752409.818951][1983:1983] CHIP:TS: Retaining current Last Known Good Time
[1657752409.824428][1983:1983] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657752409.826622][1983:1983] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752409.828487][1983:1983] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657752409.828599][1983:1983] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752409.828635][1983:1983] CHIP:CTL: Setting attestation nonce to random value
[1657752409.828693][1983:1983] CHIP:CTL: Setting CSR nonce to random value
[1657752409.829556][1983:1983] CHIP:CTL: Generating NOC
[1657752409.830666][1983:1983] CHIP:FP: Validating NOC chain
[1657752409.832408][1983:1983] CHIP:FP: NOC chain validation successful
[1657752409.832574][1983:1983] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669
[1657752409.832606][1983:1983] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752409.832629][1983:1983] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752409.832647][1983:1983] CHIP:TS: Retaining current Last Known Good Time
[1657752409.836669][1983:1983] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657752409.838575][1983:1983] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752409.840526][1983:1983] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657752409.879575][1983:1988] CHIP:DL: CHIP task running
[1657752409.879800][1983:1988] CHIP:CTL: Setting attestation nonce to random value
[1657752409.879977][1983:1988] CHIP:CTL: Setting CSR nonce to random value
[1657752409.880105][1983:1988] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752409.880128][1983:1988] CHIP:CTL: Starting commissioning discovery over BLE
[1657752409.880157][1983:1988] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1657752409.880461][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752409.881327][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752409.881362][1983:1988] CHIP:DIS: mDNS broadcast had only partial success: 8 successes and 2 failures.
[1657752409.881617][1983:1989] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657752409.881883][1983:1986] CHIP:DL: TRACE: Bus acquired for name C-07bf
[1657752409.895010][1983:1988] CHIP:DL: PlatformBlueZInit init success
[1657752409.905480][1983:1986] CHIP:BLE: BLE removing known devices.
[1657752409.908700][1983:1986] CHIP:BLE: BLE initiating scan.
[1657752409.938500][1983:1986] CHIP:BLE: Device 66:B5:C2:5B:4A:5F does not look like a CHIP device.
[1657752409.953570][1983:1986] CHIP:BLE: Device 4C:8E:52:D4:BE:A3 does not look like a CHIP device.
[1657752409.961800][1983:1986] CHIP:BLE: Device FC:58:FA:8B:4D:4B does not look like a CHIP device.
[1657752409.970896][1983:1986] CHIP:BLE: Device 7B:B7:68:40:C0:8C does not look like a CHIP device.
[1657752410.029005][1983:1986] CHIP:BLE: Device 50:01:00:00:01:2E does not look like a CHIP device.
[1657752410.032800][1983:1986] CHIP:BLE: Device 5C:56:CA:2B:F8:30 does not look like a CHIP device.
[1657752410.072013][1983:1986] CHIP:BLE: Device 53:EE:CB:63:79:6D does not look like a CHIP device.
[1657752410.081062][1983:1986] CHIP:BLE: Device 54:96:94:3A:78:70 does not look like a CHIP device.
[1657752410.107036][1983:1986] CHIP:BLE: Device 5C:05:92:56:43:66 does not look like a CHIP device.
[1657752410.138800][1983:1986] CHIP:BLE: Device 42:E7:91:48:90:9B does not look like a CHIP device.
[1657752410.141156][1983:1986] CHIP:BLE: Device F8:9A:FA:3C:7B:E4 does not look like a CHIP device.
[1657752410.236911][1983:1986] CHIP:BLE: Device 7B:D3:38:94:29:5A does not look like a CHIP device.
[1657752410.409508][1983:1986] CHIP:BLE: Device 6B:C0:21:04:FB:01 does not look like a CHIP device.
[1657752410.429226][1983:1986] CHIP:BLE: Device 66:DB:45:2B:A1:BA does not look like a CHIP device.
[1657752410.473471][1983:1986] CHIP:BLE: Device 57:E4:C4:C9:EC:08 does not look like a CHIP device.
[1657752410.476147][1983:1986] CHIP:BLE: Device 34:E0:1A:FC:91:D4 does not look like a CHIP device.
[1657752410.555955][1983:1986] CHIP:BLE: Device E4:79:38:33:55:EB does not look like a CHIP device.
[1657752410.557485][1983:1986] CHIP:BLE: Device 1A:40:BD:C5:11:6B does not look like a CHIP device.
[1657752410.809194][1983:1986] CHIP:BLE: Device 51:6E:FC:D2:F2:31 does not look like a CHIP device.
[1657752410.876226][1983:1986] CHIP:BLE: Device 76:75:34:3F:F6:4E does not look like a CHIP device.
[1657752410.881695][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752410.882685][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752410.882734][1983:1988] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752411.185409][1983:1986] CHIP:BLE: Device 69:A6:EA:56:02:E4 does not look like a CHIP device.
[1657752411.276895][1983:1986] CHIP:BLE: Device 7C:0A:3F:99:31:F9 does not look like a CHIP device.
[1657752411.415264][1983:1986] CHIP:BLE: Device 77:37:77:08:E4:12 does not look like a CHIP device.
[1657752411.718630][1983:1986] CHIP:BLE: New device scanned: DF:84:4E:3B:47:6F
[1657752411.718710][1983:1986] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657752411.722673][1983:1986] CHIP:BLE: Scan complete notification without an active scan.
[1657752412.883988][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752412.885319][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752412.885399][1983:1988] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752414.347505][1983:1986] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752416.227441][1983:1986] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752416.888142][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752416.889501][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752416.889653][1983:1988] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752419.018729][1983:1986] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752421.721300][1983:1988] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657752421.721406][1983:1988] CHIP:CTL: Commissioning discovery over BLE failed: ../../src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout
[1657752421.721464][1983:1988] CHIP:-: ../../src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout at ../../src/controller/SetUpCodePairer.cpp:270
[1657752421.721539][1983:1986] CHIP:DL: FAIL: ConnectDevice : Operation was cancelled (19)
[1657752421.721774][1983:1988] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657752424.891601][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752424.893855][1983:1988] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752424.894005][1983:1988] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752426.947609][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947791][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947829][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947854][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947893][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947918][1983:1986] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752426.947956][1983:1986] CHIP:DL: New BLE connection 0xffff94031890, device DF:84:4E:3B:47:6F, path /org/bluez/hci0/dev_DF_84_4E_3B_47_6F
[1657752426.948217][1983:1988] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1657752439.894425][1983:1988] CHIP:CTL: Discovery timed out
[1657752439.894513][1983:1988] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752439.894563][1983:1988] CHIP:TOO: Secure Pairing Failed
[1657752439.895386][1983:1983] CHIP:CTL: Shutting down the commissioner
[1657752439.895457][1983:1983] CHIP:CTL: Shutting down the controller
[1657752439.895520][1983:1983] CHIP:CTL: Shutting down the commissioner
[1657752439.895560][1983:1983] CHIP:CTL: Shutting down the controller
[1657752439.895596][1983:1983] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1657752439.895633][1983:1983] CHIP:FP: Forgetting fabric 0x1
[1657752439.895725][1983:1983] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752439.896126][1983:1983] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752439.896185][1983:1983] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752439.896301][1983:1983] CHIP:CTL: Shutting down the commissioner
[1657752439.896353][1983:1983] CHIP:CTL: Shutting down the controller
[1657752439.896399][1983:1983] CHIP:IN: Expiring all sessions for fabric 0x2!!
[1657752439.896441][1983:1983] CHIP:FP: Forgetting fabric 0x2
[1657752439.896492][1983:1983] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752439.896770][1983:1983] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752439.896822][1983:1983] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752439.896903][1983:1983] CHIP:CTL: Shutting down the commissioner
[1657752439.896952][1983:1983] CHIP:CTL: Shutting down the controller
[1657752439.896995][1983:1983] CHIP:IN: Expiring all sessions for fabric 0x3!!
[1657752439.897037][1983:1983] CHIP:FP: Forgetting fabric 0x3
[1657752439.897089][1983:1983] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752439.897355][1983:1983] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752439.897408][1983:1983] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752439.897466][1983:1983] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657752439.898570][1983:1983] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752439.898624][1983:1983] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752439.898669][1983:1983] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752439.898710][1983:1983] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752439.898747][1983:1983] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657752439.898901][1983:1983] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657752439.899323][1983:1983] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-PuBAO7)
[1657752439.900382][1983:1983] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752439.900485][1983:1983] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657752439.900539][1983:1983] CHIP:DL: Inet Layer shutdown
[1657752439.900584][1983:1983] CHIP:DL: BLE shutdown
[1657752439.905635][1983:1983] CHIP:DL: System Layer shutdown
[1657752439.905883][1983:1983] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/pairing/PairingCommand.cpp:151: CHIP Error 0x00000003: Incorrect state
ubuntu@ubuntu:~/connectedhomeip/out/host$ sudo ./chip-tool pairing code 1 MT:6FCJ142C00KA0648G00
[1657752442.354863][1995:1995] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657752442.355326][1995:1995] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657752442.355466][1995:1995] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657752442.355556][1995:1995] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657752442.355881][1995:1995] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-kzpJx1)
[1657752442.356358][1995:1995] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752442.356395][1995:1995] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3)
[1657752442.357304][1995:1995] CHIP:DL: Got Ethernet interface: eth0
[1657752442.357662][1995:1995] CHIP:DL: Found the primary Ethernet interface:eth0
[1657752442.357970][1995:1995] CHIP:DL: Got WiFi interface: wlan0
[1657752442.360009][1995:1995] CHIP:DL: Found the primary WiFi interface:wlan0
[1657752442.360067][1995:1995] CHIP:IN: UDP::Init bind&listen port=0
[1657752442.360148][1995:1995] CHIP:IN: UDP::Init bound to port=38520
[1657752442.360180][1995:1995] CHIP:IN: UDP::Init bind&listen port=0
[1657752442.360259][1995:1995] CHIP:IN: UDP::Init bound to port=56285
[1657752442.360284][1995:1995] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657752442.360299][1995:1995] CHIP:IN: TransportMgr initialized
[1657752442.360347][1995:1995] CHIP:FP: Initializing FabricTable from persistent storage
[1657752442.360589][1995:1995] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752442.361095][1995:1995] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x0D0D872986F5DBB4, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752442.361570][1995:1995] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x371042A6B8C55FE8, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752442.361992][1995:1995] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3201B65A89FB29, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752442.364354][1995:1995] CHIP:ZCL: Using ZAP configuration...
[1657752442.365611][1995:1995] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752442.368364][1995:1995] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752442.369294][1995:1995] CHIP:CTL: System State Initialized...
[1657752442.369372][1995:1995] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752442.369406][1995:1995] CHIP:CTL: Setting attestation nonce to random value
[1657752442.369481][1995:1995] CHIP:CTL: Setting CSR nonce to random value
[1657752442.369609][1995:1995] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752442.369645][1995:1995] CHIP:CTL: Setting attestation nonce to random value
[1657752442.369700][1995:1995] CHIP:CTL: Setting CSR nonce to random value
[1657752442.372641][1995:1995] CHIP:CTL: Generating NOC
[1657752442.374372][1995:1995] CHIP:FP: Validating NOC chain
[1657752442.376152][1995:1995] CHIP:FP: NOC chain validation successful
[1657752442.376294][1995:1995] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1657752442.376344][1995:1995] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752442.376361][1995:1995] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752442.376375][1995:1995] CHIP:TS: Retaining current Last Known Good Time
[1657752442.385070][1995:1995] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657752442.387886][1995:1995] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752442.389915][1995:1995] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657752442.390034][1995:1995] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752442.390071][1995:1995] CHIP:CTL: Setting attestation nonce to random value
[1657752442.390134][1995:1995] CHIP:CTL: Setting CSR nonce to random value
[1657752442.391041][1995:1995] CHIP:CTL: Generating NOC
[1657752442.392247][1995:1995] CHIP:FP: Validating NOC chain
[1657752442.394067][1995:1995] CHIP:FP: NOC chain validation successful
[1657752442.394332][1995:1995] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669
[1657752442.394368][1995:1995] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752442.394390][1995:1995] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752442.394409][1995:1995] CHIP:TS: Retaining current Last Known Good Time
[1657752442.397006][1995:1995] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657752442.399041][1995:1995] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752442.408765][1995:1995] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657752442.408922][1995:1995] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752442.408976][1995:1995] CHIP:CTL: Setting attestation nonce to random value
[1657752442.409063][1995:1995] CHIP:CTL: Setting CSR nonce to random value
[1657752442.410380][1995:1995] CHIP:CTL: Generating NOC
[1657752442.412119][1995:1995] CHIP:FP: Validating NOC chain
[1657752442.414935][1995:1995] CHIP:FP: NOC chain validation successful
[1657752442.415191][1995:1995] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669
[1657752442.415243][1995:1995] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752442.415278][1995:1995] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752442.415307][1995:1995] CHIP:TS: Retaining current Last Known Good Time
[1657752442.418796][1995:1995] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657752442.420992][1995:1995] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752442.422929][1995:1995] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657752442.458313][1995:2000] CHIP:DL: CHIP task running
[1657752442.458446][1995:2000] CHIP:CTL: Setting attestation nonce to random value
[1657752442.458591][1995:2000] CHIP:CTL: Setting CSR nonce to random value
[1657752442.458705][1995:2000] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752442.458727][1995:2000] CHIP:CTL: Starting commissioning discovery over BLE
[1657752442.458758][1995:2000] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1657752442.459039][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752442.460001][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752442.460048][1995:2000] CHIP:DIS: mDNS broadcast had only partial success: 8 successes and 2 failures.
[1657752442.460380][1995:2001] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657752442.460637][1995:1998] CHIP:DL: TRACE: Bus acquired for name C-07cb
[1657752442.483779][1995:2000] CHIP:DL: PlatformBlueZInit init success
[1657752442.498197][1995:1998] CHIP:BLE: BLE removing known devices.
[1657752444.855848][1995:1998] CHIP:BLE: BLE initiating scan.
[1657752444.878813][1995:2000] CHIP:DL: Long dispatch time: 2419 ms, for event type 2
[1657752444.879435][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752444.880207][1995:1998] CHIP:BLE: New device scanned: DF:84:4E:3B:47:6F
[1657752444.880290][1995:1998] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657752444.881420][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752444.881502][1995:2000] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752444.886102][1995:1998] CHIP:BLE: Scan complete notification without an active scan.
[1657752444.888657][1995:1998] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.freedesktop.DBus.Error.UnknownObject: Method "Connect" with signature "" on interface "org.bluez.Device1" doesn't exist
(41)
[1657752444.888844][1995:2000] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657752444.888886][1995:2000] CHIP:CTL: Commissioning discovery over BLE failed: ../../src/platform/Linux/bluez/Helper.cpp:1775: CHIP Error 0x000000AC: Internal error
[1657752444.888937][1995:2000] CHIP:-: ../../src/platform/Linux/bluez/Helper.cpp:1775: CHIP Error 0x000000AC: Internal error at ../../src/controller/SetUpCodePairer.cpp:270
[1657752446.880158][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752446.881568][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752446.881644][1995:2000] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752450.884473][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752450.886000][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752450.886078][1995:2000] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752458.889103][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752458.890380][1995:2000] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752458.890452][1995:2000] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752472.473497][1995:2000] CHIP:CTL: Discovery timed out
[1657752472.473586][1995:2000] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752472.473640][1995:2000] CHIP:TOO: Secure Pairing Failed
[1657752472.474292][1995:1995] CHIP:CTL: Shutting down the commissioner
[1657752472.474364][1995:1995] CHIP:CTL: Shutting down the controller
[1657752472.474423][1995:1995] CHIP:CTL: Shutting down the commissioner
[1657752472.474469][1995:1995] CHIP:CTL: Shutting down the controller
[1657752472.474513][1995:1995] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1657752472.474557][1995:1995] CHIP:FP: Forgetting fabric 0x1
[1657752472.474620][1995:1995] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752472.475021][1995:1995] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752472.475077][1995:1995] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752472.475151][1995:1995] CHIP:CTL: Shutting down the commissioner
[1657752472.475197][1995:1995] CHIP:CTL: Shutting down the controller
[1657752472.475238][1995:1995] CHIP:IN: Expiring all sessions for fabric 0x2!!
[1657752472.475280][1995:1995] CHIP:FP: Forgetting fabric 0x2
[1657752472.475332][1995:1995] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752472.475597][1995:1995] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752472.475645][1995:1995] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752472.475753][1995:1995] CHIP:CTL: Shutting down the commissioner
[1657752472.475803][1995:1995] CHIP:CTL: Shutting down the controller
[1657752472.475843][1995:1995] CHIP:IN: Expiring all sessions for fabric 0x3!!
[1657752472.475885][1995:1995] CHIP:FP: Forgetting fabric 0x3
[1657752472.475933][1995:1995] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752472.476201][1995:1995] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752472.476250][1995:1995] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752472.476307][1995:1995] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657752472.477405][1995:1995] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752472.477462][1995:1995] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752472.477503][1995:1995] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752472.477545][1995:1995] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752472.477588][1995:1995] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657752472.477747][1995:1995] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657752472.478146][1995:1995] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Ebu9m2)
[1657752472.479141][1995:1995] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752472.479244][1995:1995] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657752472.479296][1995:1995] CHIP:DL: Inet Layer shutdown
[1657752472.479340][1995:1995] CHIP:DL: BLE shutdown
[1657752472.482467][1995:1995] CHIP:DL: System Layer shutdown
[1657752472.482743][1995:1995] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/pairing/PairingCommand.cpp:151: CHIP Error 0x00000003: Incorrect state
ubuntu@ubuntu:~/connectedhomeip/out/host$ sudo ./chip-tool pairing code 1 MT:6FCJ142C00KA0648G00
[1657752492.953606][2004:2004] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657752492.954075][2004:2004] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657752492.954215][2004:2004] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657752492.954307][2004:2004] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657752492.954613][2004:2004] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8naLEI)
[1657752492.955086][2004:2004] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752492.955124][2004:2004] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1657752492.955643][2004:2004] CHIP:DL: Got Ethernet interface: eth0
[1657752492.955976][2004:2004] CHIP:DL: Found the primary Ethernet interface:eth0
[1657752492.956724][2004:2004] CHIP:DL: Got WiFi interface: wlan0
[1657752492.958763][2004:2004] CHIP:DL: Found the primary WiFi interface:wlan0
[1657752492.958827][2004:2004] CHIP:IN: UDP::Init bind&listen port=0
[1657752492.958928][2004:2004] CHIP:IN: UDP::Init bound to port=40468
[1657752492.958951][2004:2004] CHIP:IN: UDP::Init bind&listen port=0
[1657752492.959021][2004:2004] CHIP:IN: UDP::Init bound to port=52091
[1657752492.959039][2004:2004] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657752492.959055][2004:2004] CHIP:IN: TransportMgr initialized
[1657752492.959086][2004:2004] CHIP:FP: Initializing FabricTable from persistent storage
[1657752492.959292][2004:2004] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752492.959848][2004:2004] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x0D0D872986F5DBB4, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752492.960199][2004:2004] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x371042A6B8C55FE8, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752492.960533][2004:2004] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x3D3201B65A89FB29, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657752492.962752][2004:2004] CHIP:ZCL: Using ZAP configuration...
[1657752492.964071][2004:2004] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752492.966471][2004:2004] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1657752492.967437][2004:2004] CHIP:CTL: System State Initialized...
[1657752492.967524][2004:2004] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752492.967562][2004:2004] CHIP:CTL: Setting attestation nonce to random value
[1657752492.967630][2004:2004] CHIP:CTL: Setting CSR nonce to random value
[1657752492.967765][2004:2004] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752492.967797][2004:2004] CHIP:CTL: Setting attestation nonce to random value
[1657752492.967846][2004:2004] CHIP:CTL: Setting CSR nonce to random value
[1657752492.970740][2004:2004] CHIP:CTL: Generating NOC
[1657752492.972175][2004:2004] CHIP:FP: Validating NOC chain
[1657752492.974115][2004:2004] CHIP:FP: NOC chain validation successful
[1657752492.974253][2004:2004] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1657752492.974282][2004:2004] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752492.974300][2004:2004] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752492.974316][2004:2004] CHIP:TS: Retaining current Last Known Good Time
[1657752492.978386][2004:2004] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657752492.980613][2004:2004] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752492.982570][2004:2004] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657752492.982673][2004:2004] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752492.982704][2004:2004] CHIP:CTL: Setting attestation nonce to random value
[1657752492.982770][2004:2004] CHIP:CTL: Setting CSR nonce to random value
[1657752492.984321][2004:2004] CHIP:CTL: Generating NOC
[1657752492.985793][2004:2004] CHIP:FP: Validating NOC chain
[1657752492.987956][2004:2004] CHIP:FP: NOC chain validation successful
[1657752492.988149][2004:2004] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669
[1657752492.988195][2004:2004] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752492.988219][2004:2004] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752492.988239][2004:2004] CHIP:TS: Retaining current Last Known Good Time
[1657752492.998141][2004:2004] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657752493.003991][2004:2004] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752493.005968][2004:2004] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657752493.006085][2004:2004] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752493.006122][2004:2004] CHIP:CTL: Setting attestation nonce to random value
[1657752493.006183][2004:2004] CHIP:CTL: Setting CSR nonce to random value
[1657752493.007089][2004:2004] CHIP:CTL: Generating NOC
[1657752493.008644][2004:2004] CHIP:FP: Validating NOC chain
[1657752493.011171][2004:2004] CHIP:FP: NOC chain validation successful
[1657752493.011399][2004:2004] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669
[1657752493.011444][2004:2004] CHIP:TS: Last Known Good Time: 2022-07-13T18:42:46
[1657752493.011475][2004:2004] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657752493.011502][2004:2004] CHIP:TS: Retaining current Last Known Good Time
[1657752493.014508][2004:2004] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657752493.017368][2004:2004] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-13T18:42:46
[1657752493.019432][2004:2004] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657752493.054004][2004:2009] CHIP:DL: CHIP task running
[1657752493.054166][2004:2009] CHIP:CTL: Setting attestation nonce to random value
[1657752493.054351][2004:2009] CHIP:CTL: Setting CSR nonce to random value
[1657752493.054486][2004:2009] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752493.054514][2004:2009] CHIP:CTL: Starting commissioning discovery over BLE
[1657752493.054550][2004:2009] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1657752493.054885][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752493.055651][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752493.055731][2004:2009] CHIP:DIS: mDNS broadcast had only partial success: 8 successes and 2 failures.
[1657752493.056311][2004:2010] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657752493.056432][2004:2007] CHIP:DL: TRACE: Bus acquired for name C-07d4
[1657752493.071967][2004:2009] CHIP:DL: PlatformBlueZInit init success
[1657752493.085603][2004:2007] CHIP:BLE: BLE removing known devices.
[1657752493.087340][2004:2007] CHIP:BLE: BLE initiating scan.
[1657752493.811908][2004:2009] CHIP:DL: Long dispatch time: 756 ms, for event type 2
[1657752493.837921][2004:2007] CHIP:BLE: Device 53:EE:CB:63:79:6D does not look like a CHIP device.
[1657752493.861374][2004:2007] CHIP:BLE: Device 5D:CB:48:F9:3B:1F does not look like a CHIP device.
[1657752493.893548][2004:2007] CHIP:BLE: Device 50:01:00:00:01:2E does not look like a CHIP device.
[1657752493.893945][2004:2007] CHIP:BLE: Device FC:58:FA:8B:4D:4B does not look like a CHIP device.
[1657752493.902524][2004:2007] CHIP:BLE: Device 66:B5:C2:5B:4A:5F does not look like a CHIP device.
[1657752493.911154][2004:2007] CHIP:BLE: Device 61:43:32:A4:B1:18 does not look like a CHIP device.
[1657752493.912676][2004:2007] CHIP:BLE: Device 7B:D3:38:94:29:5A does not look like a CHIP device.
[1657752493.937573][2004:2007] CHIP:BLE: Device 54:96:94:3A:78:70 does not look like a CHIP device.
[1657752493.978726][2004:2007] CHIP:BLE: Device 7B:B7:68:40:C0:8C does not look like a CHIP device.
[1657752493.979093][2004:2007] CHIP:BLE: Device 1A:40:BD:C5:11:6B does not look like a CHIP device.
[1657752494.054920][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752494.056396][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752494.056463][2004:2009] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752494.161644][2004:2007] CHIP:BLE: Device 5C:05:92:56:43:66 does not look like a CHIP device.
[1657752494.172595][2004:2007] CHIP:BLE: Device 5C:56:CA:2B:F8:30 does not look like a CHIP device.
[1657752494.276034][2004:2007] CHIP:BLE: Device 7C:0A:3F:99:31:F9 does not look like a CHIP device.
[1657752494.345511][2004:2007] CHIP:BLE: Device 42:E7:91:48:90:9B does not look like a CHIP device.
[1657752494.348386][2004:2007] CHIP:BLE: Device F8:9A:FA:3C:7B:E4 does not look like a CHIP device.
[1657752494.436317][2004:2007] CHIP:BLE: Device 34:E0:1A:FC:91:D4 does not look like a CHIP device.
[1657752494.519657][2004:2007] CHIP:BLE: Device 69:A6:EA:56:02:E4 does not look like a CHIP device.
[1657752494.685478][2004:2007] CHIP:BLE: Device 57:E4:C4:C9:EC:08 does not look like a CHIP device.
[1657752494.848274][2004:2007] CHIP:BLE: Device 4C:8E:52:D4:BE:A3 does not look like a CHIP device.
[1657752494.945641][2004:2007] CHIP:BLE: Device 66:DB:45:2B:A1:BA does not look like a CHIP device.
[1657752494.948038][2004:2007] CHIP:BLE: Device CB:EB:C4:74:02:65 does not look like a CHIP device.
[1657752495.427106][2004:2007] CHIP:BLE: Device 76:75:34:3F:F6:4E does not look like a CHIP device.
[1657752495.429572][2004:2007] CHIP:BLE: Device F8:E1:7F:E0:82:06 does not look like a CHIP device.
[1657752495.665894][2004:2007] CHIP:BLE: Device 7C:0A:3F:49:DF:27 does not look like a CHIP device.
[1657752496.021631][2004:2007] CHIP:BLE: Device 6B:C0:21:04:FB:01 does not look like a CHIP device.
[1657752496.056172][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752496.057590][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752496.057669][2004:2009] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752496.192121][2004:2007] CHIP:BLE: New device scanned: DF:84:4E:3B:47:6F
[1657752496.192204][2004:2007] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657752496.196975][2004:2007] CHIP:BLE: Scan complete notification without an active scan.
[1657752498.840603][2004:2007] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657752500.060521][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752500.061835][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752500.061910][2004:2009] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752502.379191][2004:2007] CHIP:DL: ConnectDevice complete
[1657752503.041706][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.041888][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.041934][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.041964][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042016][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0001
[1657752503.042046][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042108][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0001
[1657752503.042155][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042223][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0001
[1657752503.042253][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042355][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042404][2004:2007] CHIP:DL: Char1 /org/bluez/hci0/dev_DF_84_4E_3B_47_6F/service0010
[1657752503.042467][2004:2007] CHIP:DL: New BLE connection 0xffffa0038300, device DF:84:4E:3B:47:6F, path /org/bluez/hci0/dev_DF_84_4E_3B_47_6F
[1657752503.042690][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1657752503.042740][2004:2009] CHIP:CTL: Discovered device to be commissioned over BLE
[1657752503.042784][2004:2009] CHIP:CTL: Attempting PASE connection to BLE
[1657752503.042839][2004:2009] CHIP:IN: BleConnectionComplete: endPoint 0xaaaac67da288
[1657752503.043152][2004:2009] CHIP:IN: SecureSession[0xffff94005f00]: Allocated Type:1 LSID:35411
[1657752503.043202][2004:2009] CHIP:SC: Assigned local session key ID 35411
[1657752503.043300][2004:2009] CHIP:SC: Including MRP parameters in PBKDF param request
[1657752503.043401][2004:2009] CHIP:IN: Prepared unauthenticated message 0xffffa98d7f28 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 54529i with MessageCounter:258070661.
[1657752503.043461][2004:2009] CHIP:IN: Sending unauthenticated msg 0xffffa98d7f28 with MessageCounter:258070661 to 0x0000000000000000 at monotonic time: 0000000000191AB3 msec
[1657752503.043503][2004:2009] CHIP:IN: Message appended to BLE send queue
[1657752503.043534][2004:2009] CHIP:SC: Sent PBKDF param request
[1657752503.043564][2004:2009] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1657752504.182173][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752504.328648][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1657752504.328731][2004:2009] CHIP:BLE: subscribe complete, ep = 0xaaaac67da288
[1657752504.328995][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752504.329320][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752504.329383][2004:2009] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1657752504.329437][2004:2009] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1657752504.329497][2004:2009] CHIP:BLE: local and remote recv window size = 5
[1657752504.329756][2004:2009] CHIP:IN: BLE EndPoint 0xaaaac67da288 Connection Complete
[1657752504.474124][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752504.574278][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752504.574532][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752504.574807][2004:2009] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:227647507 on exchange 54529i
[1657752504.574912][2004:2009] CHIP:EM: Found matching exchange: 54529i, Delegate: 0xffff9401d9f0
[1657752504.575016][2004:2009] CHIP:SC: Received PBKDF param response
[1657752504.575141][2004:2009] CHIP:SC: Peer assigned session ID 32888
[1657752504.575252][2004:2009] CHIP:SC: Found MRP parameters in the message
[1657752504.587566][2004:2009] CHIP:IN: Prepared unauthenticated message 0xffffa98d79f8 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 54529i with MessageCounter:258070662.
[1657752504.587624][2004:2009] CHIP:IN: Sending unauthenticated msg 0xffffa98d79f8 with MessageCounter:258070662 to 0x0000000000000000 at monotonic time: 00000000001920BB msec
[1657752504.587985][2004:2009] CHIP:SC: Sent spake2p msg1
[1657752504.669075][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752506.621922][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752506.622201][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752506.622404][2004:2009] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:227647508 on exchange 54529i
[1657752506.622534][2004:2009] CHIP:EM: Found matching exchange: 54529i, Delegate: 0xffff9401d9f0
[1657752506.622654][2004:2009] CHIP:SC: Received spake2p msg2
[1657752506.626501][2004:2009] CHIP:IN: Prepared unauthenticated message 0xffffa98d7b38 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 54529i with MessageCounter:258070663.
[1657752506.626603][2004:2009] CHIP:IN: Sending unauthenticated msg 0xffffa98d7b38 with MessageCounter:258070663 to 0x0000000000000000 at monotonic time: 00000000001928B2 msec
[1657752506.626784][2004:2009] CHIP:SC: Sent spake2p msg3
[1657752506.716655][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752506.815727][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752506.815978][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752506.816233][2004:2009] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:227647509 on exchange 54529i
[1657752506.816346][2004:2009] CHIP:EM: Found matching exchange: 54529i, Delegate: 0xffff9401d9f0
[1657752506.816572][2004:2009] CHIP:SC: SecureSession[0xffff94005f00]: Moving from state 'kEstablishing' --> 'kActive'
[1657752506.816668][2004:2009] CHIP:IN: SecureSession[0xffff94005f00]: Activated - Type:1 LSID:35411
[1657752506.816712][2004:2009] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:35411 PSID:32888!
[1657752506.816785][2004:2009] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1657752506.816868][2004:2009] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657752506.816913][2004:2009] CHIP:TOO: Pairing Success
[1657752506.816953][2004:2009] CHIP:TOO: PASE establishment successful
[1657752506.817052][2004:2009] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1657752506.817104][2004:2009] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1657752506.817142][2004:2009] CHIP:CTL: Sending request for commissioning information
[1657752506.817256][2004:2009] CHIP:DMG: SendReadRequest ReadClient[0xffffa0035b10]: Sending Read Request
[1657752506.817544][2004:2009] CHIP:IN: Prepared secure message 0xffffa98d7348 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 54530i with MessageCounter:137041521.
[1657752506.817626][2004:2009] CHIP:IN: Sending encrypted msg 0xffffa98d7348 with MessageCounter:137041521 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000192971 msec
[1657752506.817799][2004:2009] CHIP:DMG: MoveToState ReadClient[0xffffa0035b10]: Moving to [AwaitingIn]
[1657752507.009073][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752507.110281][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752507.110531][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752507.253363][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752507.253621][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752507.253907][2004:2009] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:4752760 on exchange 54530i
[1657752507.253970][2004:2009] CHIP:EM: Found matching exchange: 54530i, Delegate: 0xffffa0035b10
[1657752507.254199][2004:2009] CHIP:DMG: ReportDataMessage =
[1657752507.254308][2004:2009] CHIP:DMG: {
[1657752507.254354][2004:2009] CHIP:DMG: AttributeReportIBs =
[1657752507.254421][2004:2009] CHIP:DMG: [
[1657752507.254471][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.254588][2004:2009] CHIP:DMG: {
[1657752507.254668][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.254761][2004:2009] CHIP:DMG: {
[1657752507.254830][2004:2009] CHIP:DMG: DataVersion = 0x7afebd43,
[1657752507.254937][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.255049][2004:2009] CHIP:DMG: {
[1657752507.255129][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.255246][2004:2009] CHIP:DMG: Cluster = 0x31,
[1657752507.255329][2004:2009] CHIP:DMG: Attribute = 0x0000_0003,
[1657752507.255405][2004:2009] CHIP:DMG: }
[1657752507.255486][2004:2009] CHIP:DMG:
[1657752507.255564][2004:2009] CHIP:DMG: Data = 20,
[1657752507.255635][2004:2009] CHIP:DMG: },
[1657752507.255760][2004:2009] CHIP:DMG:
[1657752507.255819][2004:2009] CHIP:DMG: },
[1657752507.255902][2004:2009] CHIP:DMG:
[1657752507.255953][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.256023][2004:2009] CHIP:DMG: {
[1657752507.256079][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.256150][2004:2009] CHIP:DMG: {
[1657752507.256223][2004:2009] CHIP:DMG: DataVersion = 0x4b25a87b,
[1657752507.256295][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.256370][2004:2009] CHIP:DMG: {
[1657752507.256448][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.256527][2004:2009] CHIP:DMG: Cluster = 0x28,
[1657752507.256608][2004:2009] CHIP:DMG: Attribute = 0x0000_0004,
[1657752507.256684][2004:2009] CHIP:DMG: }
[1657752507.256764][2004:2009] CHIP:DMG:
[1657752507.256841][2004:2009] CHIP:DMG: Data = 32773,
[1657752507.256912][2004:2009] CHIP:DMG: },
[1657752507.256988][2004:2009] CHIP:DMG:
[1657752507.257044][2004:2009] CHIP:DMG: },
[1657752507.257129][2004:2009] CHIP:DMG:
[1657752507.257179][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.257249][2004:2009] CHIP:DMG: {
[1657752507.257306][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.257377][2004:2009] CHIP:DMG: {
[1657752507.257450][2004:2009] CHIP:DMG: DataVersion = 0x4b25a87b,
[1657752507.257521][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.257595][2004:2009] CHIP:DMG: {
[1657752507.257672][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.257752][2004:2009] CHIP:DMG: Cluster = 0x28,
[1657752507.257966][2004:2009] CHIP:DMG: Attribute = 0x0000_0002,
[1657752507.258045][2004:2009] CHIP:DMG: }
[1657752507.258125][2004:2009] CHIP:DMG:
[1657752507.258203][2004:2009] CHIP:DMG: Data = 65521,
[1657752507.258274][2004:2009] CHIP:DMG: },
[1657752507.258350][2004:2009] CHIP:DMG:
[1657752507.258408][2004:2009] CHIP:DMG: },
[1657752507.258488][2004:2009] CHIP:DMG:
[1657752507.258537][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.258607][2004:2009] CHIP:DMG: {
[1657752507.258664][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.258734][2004:2009] CHIP:DMG: {
[1657752507.258807][2004:2009] CHIP:DMG: DataVersion = 0xfa8c2bf4,
[1657752507.258874][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.258949][2004:2009] CHIP:DMG: {
[1657752507.259025][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.259104][2004:2009] CHIP:DMG: Cluster = 0x30,
[1657752507.259184][2004:2009] CHIP:DMG: Attribute = 0x0000_0003,
[1657752507.259259][2004:2009] CHIP:DMG: }
[1657752507.259338][2004:2009] CHIP:DMG:
[1657752507.259416][2004:2009] CHIP:DMG: Data = 0,
[1657752507.259487][2004:2009] CHIP:DMG: },
[1657752507.259564][2004:2009] CHIP:DMG:
[1657752507.259608][2004:2009] CHIP:DMG: },
[1657752507.259647][2004:2009] CHIP:DMG:
[1657752507.259686][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.259766][2004:2009] CHIP:DMG: {
[1657752507.259796][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.259831][2004:2009] CHIP:DMG: {
[1657752507.259868][2004:2009] CHIP:DMG: DataVersion = 0xfa8c2bf4,
[1657752507.259904][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.260069][2004:2009] CHIP:DMG: {
[1657752507.260126][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.260164][2004:2009] CHIP:DMG: Cluster = 0x30,
[1657752507.260202][2004:2009] CHIP:DMG: Attribute = 0x0000_0002,
[1657752507.260265][2004:2009] CHIP:DMG: }
[1657752507.260321][2004:2009] CHIP:DMG:
[1657752507.260367][2004:2009] CHIP:DMG: Data = 0,
[1657752507.260405][2004:2009] CHIP:DMG: },
[1657752507.260444][2004:2009] CHIP:DMG:
[1657752507.260472][2004:2009] CHIP:DMG: },
[1657752507.260515][2004:2009] CHIP:DMG:
[1657752507.260557][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.260725][2004:2009] CHIP:DMG: {
[1657752507.260762][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.260826][2004:2009] CHIP:DMG: {
[1657752507.260865][2004:2009] CHIP:DMG: DataVersion = 0xfa8c2bf4,
[1657752507.260900][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.260933][2004:2009] CHIP:DMG: {
[1657752507.260990][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.261035][2004:2009] CHIP:DMG: Cluster = 0x30,
[1657752507.261078][2004:2009] CHIP:DMG: Attribute = 0x0000_0001,
[1657752507.261116][2004:2009] CHIP:DMG: }
[1657752507.261155][2004:2009] CHIP:DMG:
[1657752507.261203][2004:2009] CHIP:DMG: Data =
[1657752507.261248][2004:2009] CHIP:DMG: {
[1657752507.261314][2004:2009] CHIP:DMG: 0x0 = 60,
[1657752507.261362][2004:2009] CHIP:DMG: },
[1657752507.261399][2004:2009] CHIP:DMG: },
[1657752507.261440][2004:2009] CHIP:DMG:
[1657752507.261479][2004:2009] CHIP:DMG: },
[1657752507.261531][2004:2009] CHIP:DMG:
[1657752507.261556][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.261593][2004:2009] CHIP:DMG: {
[1657752507.261652][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.261702][2004:2009] CHIP:DMG: {
[1657752507.261739][2004:2009] CHIP:DMG: DataVersion = 0xfa8c2bf4,
[1657752507.261775][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.261812][2004:2009] CHIP:DMG: {
[1657752507.261850][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.261889][2004:2009] CHIP:DMG: Cluster = 0x30,
[1657752507.261930][2004:2009] CHIP:DMG: Attribute = 0x0000_0000,
[1657752507.261968][2004:2009] CHIP:DMG: }
[1657752507.262008][2004:2009] CHIP:DMG:
[1657752507.262043][2004:2009] CHIP:DMG: Data = 0,
[1657752507.262079][2004:2009] CHIP:DMG: },
[1657752507.262117][2004:2009] CHIP:DMG:
[1657752507.262145][2004:2009] CHIP:DMG: },
[1657752507.262185][2004:2009] CHIP:DMG:
[1657752507.262209][2004:2009] CHIP:DMG: AttributeReportIB =
[1657752507.262245][2004:2009] CHIP:DMG: {
[1657752507.262274][2004:2009] CHIP:DMG: AttributeDataIB =
[1657752507.262306][2004:2009] CHIP:DMG: {
[1657752507.262342][2004:2009] CHIP:DMG: DataVersion = 0x7afebd43,
[1657752507.262378][2004:2009] CHIP:DMG: AttributePathIB =
[1657752507.262415][2004:2009] CHIP:DMG: {
[1657752507.262453][2004:2009] CHIP:DMG: Endpoint = 0x0,
[1657752507.262493][2004:2009] CHIP:DMG: Cluster = 0x31,
[1657752507.262533][2004:2009] CHIP:DMG: Attribute = 0x0000_FFFC,
[1657752507.262570][2004:2009] CHIP:DMG: }
[1657752507.262610][2004:2009] CHIP:DMG:
[1657752507.262644][2004:2009] CHIP:DMG: Data = 2,
[1657752507.262680][2004:2009] CHIP:DMG: },
[1657752507.262718][2004:2009] CHIP:DMG:
[1657752507.262746][2004:2009] CHIP:DMG: },
[1657752507.262780][2004:2009] CHIP:DMG:
[1657752507.262804][2004:2009] CHIP:DMG: ],
[1657752507.262868][2004:2009] CHIP:DMG:
[1657752507.262895][2004:2009] CHIP:DMG: SuppressResponse = true,
[1657752507.262921][2004:2009] CHIP:DMG: InteractionModelRevision = 1
[1657752507.262944][2004:2009] CHIP:DMG: }
[1657752507.264329][2004:2009] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1657752507.264370][2004:2009] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1657752507.264402][2004:2009] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1657752507.264425][2004:2009] CHIP:CTL: Arming failsafe (60 seconds)
[1657752507.264538][2004:2009] CHIP:DMG: ICR moving to [AddingComm]
[1657752507.264584][2004:2009] CHIP:DMG: ICR moving to [AddedComma]
[1657752507.264981][2004:2009] CHIP:IN: Prepared secure message 0xffffa98d7128 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54531i with MessageCounter:137041522.
[1657752507.265039][2004:2009] CHIP:IN: Sending encrypted msg 0xffffa98d7128 with MessageCounter:137041522 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000192B31 msec
[1657752507.265217][2004:2009] CHIP:DMG: ICR moving to [CommandSen]
[1657752507.594314][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752507.595880][2004:2007] CHIP:DL: Indication received, conn = 0xffffa0038300
[1657752507.596139][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657752507.596394][2004:2009] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4752761 on exchange 54531i
[1657752507.596462][2004:2009] CHIP:EM: Found matching exchange: 54531i, Delegate: 0xffff94019400
[1657752507.596542][2004:2009] CHIP:DMG: ICR moving to [ResponseRe]
[1657752507.596642][2004:2009] CHIP:DMG: InvokeResponseMessage =
[1657752507.596695][2004:2009] CHIP:DMG: {
[1657752507.596745][2004:2009] CHIP:DMG: suppressResponse = false,
[1657752507.596797][2004:2009] CHIP:DMG: InvokeResponseIBs =
[1657752507.596867][2004:2009] CHIP:DMG: [
[1657752507.596928][2004:2009] CHIP:DMG: InvokeResponseIB =
[1657752507.597009][2004:2009] CHIP:DMG: {
[1657752507.597070][2004:2009] CHIP:DMG: CommandDataIB =
[1657752507.597140][2004:2009] CHIP:DMG: {
[1657752507.597206][2004:2009] CHIP:DMG: CommandPathIB =
[1657752507.597278][2004:2009] CHIP:DMG: {
[1657752507.597352][2004:2009] CHIP:DMG: EndpointId = 0x0,
[1657752507.597427][2004:2009] CHIP:DMG: ClusterId = 0x30,
[1657752507.597512][2004:2009] CHIP:DMG: CommandId = 0x1,
[1657752507.597590][2004:2009] CHIP:DMG: },
[1657752507.597671][2004:2009] CHIP:DMG:
[1657752507.597742][2004:2009] CHIP:DMG: CommandFields =
[1657752507.597819][2004:2009] CHIP:DMG: {
[1657752507.597894][2004:2009] CHIP:DMG: 0x0 = 0,
[1657752507.597979][2004:2009] CHIP:DMG: 0x1 = "",
[1657752507.598060][2004:2009] CHIP:DMG: },
[1657752507.598124][2004:2009] CHIP:DMG: },
[1657752507.598206][2004:2009] CHIP:DMG:
[1657752507.598264][2004:2009] CHIP:DMG: },
[1657752507.598336][2004:2009] CHIP:DMG:
[1657752507.598387][2004:2009] CHIP:DMG: ],
[1657752507.598451][2004:2009] CHIP:DMG:
[1657752507.598502][2004:2009] CHIP:DMG: InteractionModelRevision = 1
[1657752507.598552][2004:2009] CHIP:DMG: },
[1657752507.598687][2004:2009] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1657752507.604315][2004:2009] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1657752507.604394][2004:2009] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1657752507.604443][2004:2009] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1657752507.604500][2004:2009] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1657752507.604545][2004:2009] CHIP:CTL: Setting Regulatory Config
[1657752507.604588][2004:2009] CHIP:CTL: Device does not support configurable regulatory location
[1657752507.604704][2004:2009] CHIP:DMG: ICR moving to [AddingComm]
[1657752507.604772][2004:2009] CHIP:DMG: ICR moving to [AddedComma]
[1657752507.604948][2004:2009] CHIP:IN: Prepared secure message 0xffffa98d6cb8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54532i with MessageCounter:137041523.
[1657752507.605036][2004:2009] CHIP:IN: Sending encrypted msg 0xffffa98d6cb8 with MessageCounter:137041523 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000192C85 msec
[1657752507.605238][2004:2009] CHIP:DMG: ICR moving to [CommandSen]
[1657752507.605361][2004:2009] CHIP:DMG: ICR moving to [AwaitingDe]
[1657752508.061533][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752508.062824][2004:2009] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1657752508.062887][2004:2009] CHIP:DIS: mDNS broadcast had only partial success: 6 successes and 2 failures.
[1657752508.110513][2004:2007] CHIP:DL: Bluez disconnected
[1657752508.110596][2004:2007] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1657752508.110915][2004:2009] CHIP:IN: Clearing BLE pending packets.
[1657752508.111318][2004:2009] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657752508.111384][2004:2009] CHIP:BLE: no endpoint for BLE sent data ack
[1657752524.077581][2004:2009] CHIP:DIS: Timeout waiting for mDNS resolution.
[1657752537.618410][2004:2009] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 54532i
[1657752537.618524][2004:2009] CHIP:CTL: Received failure response ../../src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout
[1657752537.618624][2004:2009] CHIP:CTL: Error on commissioning step 'ConfigRegulatory': '../../src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'
[1657752537.618674][2004:2009] CHIP:CTL: Failed to perform commissioning step 4
[1657752537.618728][2004:2009] CHIP:CTL: Going from commissioning step 'ConfigRegulatory' with lastErr = '../../src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1657752537.618800][2004:2009] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'
[1657752537.618851][2004:2009] CHIP:CTL: Expiring failsafe on proxy 0xffff9401d9a0
[1657752537.618984][2004:2009] CHIP:DMG: ICR moving to [AddingComm]
[1657752537.619048][2004:2009] CHIP:DMG: ICR moving to [AddedComma]
[1657752537.619241][2004:2009] CHIP:IN: Prepared secure message 0xffffa98d7878 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54533i with MessageCounter:137041524.
[1657752537.619331][2004:2009] CHIP:IN: Sending encrypted msg 0xffffa98d7878 with MessageCounter:137041524 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000019A1C3 msec
[1657752537.619402][2004:2009] CHIP:IN: Message appended to BLE send queue
[1657752537.619454][2004:2009] CHIP:DMG: ICR moving to [CommandSen]
[1657752537.619517][2004:2009] CHIP:DMG: ICR moving to [AwaitingDe]
[1657752543.049198][2004:2009] CHIP:DIS: Closing all BLE connections
[1657752543.049364][2004:2009] CHIP:TOO: Pairing Failure: ../../src/controller/CHIPDeviceController.cpp:1406: CHIP Error 0x00000032: Timeout
[1657752543.049995][2004:2004] CHIP:CTL: Shutting down the commissioner
[1657752543.050065][2004:2004] CHIP:CTL: Shutting down the controller
[1657752543.050125][2004:2004] CHIP:CTL: Shutting down the commissioner
[1657752543.050171][2004:2004] CHIP:CTL: Shutting down the controller
[1657752543.050215][2004:2004] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1657752543.050261][2004:2004] CHIP:FP: Forgetting fabric 0x1
[1657752543.050323][2004:2004] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752543.050717][2004:2004] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752543.050773][2004:2004] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752543.050851][2004:2004] CHIP:CTL: Shutting down the commissioner
[1657752543.050900][2004:2004] CHIP:CTL: Shutting down the controller
[1657752543.050944][2004:2004] CHIP:IN: Expiring all sessions for fabric 0x2!!
[1657752543.050988][2004:2004] CHIP:FP: Forgetting fabric 0x2
[1657752543.051038][2004:2004] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752543.051306][2004:2004] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752543.051356][2004:2004] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752543.051421][2004:2004] CHIP:CTL: Shutting down the commissioner
[1657752543.051468][2004:2004] CHIP:CTL: Shutting down the controller
[1657752543.051510][2004:2004] CHIP:IN: Expiring all sessions for fabric 0x3!!
[1657752543.051554][2004:2004] CHIP:FP: Forgetting fabric 0x3
[1657752543.051604][2004:2004] CHIP:TS: Pending Last Known Good Time: 2022-07-13T18:42:46
[1657752543.051919][2004:2004] CHIP:TS: Previous Last Known Good Time: 2022-07-13T18:42:46
[1657752543.051970][2004:2004] CHIP:TS: Reverted Last Known Good Time to previous value
[1657752543.052030][2004:2004] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657752543.053023][2004:2004] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752543.053072][2004:2004] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752543.053111][2004:2004] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752543.053146][2004:2004] CHIP:DMG: IM WH moving to [Uninitialized]
[1657752543.053184][2004:2004] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657752543.053322][2004:2004] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657752543.053680][2004:2004] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CKzcVH)
[1657752543.054579][2004:2004] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657752543.054672][2004:2004] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657752543.054719][2004:2004] CHIP:DL: Inet Layer shutdown
[1657752543.054759][2004:2004] CHIP:DL: BLE shutdown
[1657752543.057415][2004:2004] CHIP:DL: System Layer shutdown
[1657752543.057581][2004:2004] CHIP:IN: SecureSession[0xffff94005f00]: MarkForEviction Type:1 LSID:35411
[1657752543.057632][2004:2004] CHIP:SC: SecureSession[0xffff94005f00]: Moving from state 'kActive' --> 'kPendingEviction'
Segmentation fault
Logs from the 52840DK:
uart:~$ I: 227 [DL]BLE address: DF:84:4E:3B:47:6F I: SoftDevice Controller build revision: I: 33 78 2a 18 20 f5 61 61 |3x*. .aa I: a6 8b 77 60 62 83 39 2a |..w`b.9* I: 7c f1 14 e4 ||... I: 253 [DL]OpenThread started: OK I: 256 [DL]Setting OpenThread device type to ROUTER I: 263 [SVR]Server initializing... D: 266 [DIS]Init fabric pairing table with server storage I: 272 [DMG]AccessControl: initializing I: 275 [DMG]Examples::AccessControlDelegate::Init I: 280 [DMG]AccessControl: setting I: 283 [DMG]DefaultAclStorage: initializing I: 287 [DMG]DefaultAclStorage: 0 entries loaded I: 291 [ZCL]Using ZAP configuration... I: 296 [DMG]AccessControlCluster: initializing I: 300 [ZCL]Initiating Admin Commissioning cluster. D: 305 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fa8c2bf4 I: 311 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. D: 319 [DIS]Add fabric pairing table delegate D: 324 [DMG]Endpoint 0, Cluster 0x0000_0004 update version to 68b850e8 E: 330 [ZCL]DeviceInfoProvider is not registered E: 334 [ZCL]Trying to write invalid Calendar Type E: 339 [ZCL]Failed to write calendar type with error: 0x87 D: 344 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 2df8198d D: 350 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to a15f8c4f I: 357 [ZCL]Cluster OnOff: attribute OnOff set to 0 D: 361 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to ea42a106 I: 368 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 374 [IN]UDP::Init bind&listen port=5540 E: 378 [IN]SO_REUSEPORT failed: 109 D: 381 [IN]UDP::Init bound to port=5540 D: 385 [IN]BLEBase::Init - setting/overriding transport D: 390 [IN]TransportMgr initialized D: 397 [DIS]Add fabric pairing table delegate D: 402 [DL]Using Thread extended MAC for hostname. D: 411 [SC]Assigned local session key ID 32888 D: 415 [SC]Waiting for PBKDF param request D: 419 [DL]CHIPoBLE advertising set to on I: 422 [DIS]Updating services using commissioning mode 1 D: 428 [DL]Using Thread extended MAC for hostname. D: 432 [DL]Using Thread extended MAC for hostname. I: 438 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 446 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 453 [DIS]Scheduling discovery timeout in 900s E: 457 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 464 [DIS]Updating services using commissioning mode 1 D: 469 [DL]Using Thread extended MAC for hostname. D: 474 [DL]Using Thread extended MAC for hostname. I: 479 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 487 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 494 [DIS]Scheduling discovery timeout in 900s E: 499 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 505 [DIS]Delaying proxy of operational discovery: missing delegate I: 511 [IN]CASE Server enabling CASE session setups I: 516 [SVR]Joining Multicast groups D: 519 [ZCL]Emitting StartUp event D: 522 [EVL]LogEvent event number: 0x00000000000A0000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000000020A D: 536 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted D: 541 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to f40b7e3b D: 548 [EVL]LogEvent event number: 0x00000000000A0001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000224 I: 562 [SVR]Server Listening... I: 565 [DL]Device Configuration: I: 568 [DL] Serial Number: TEST_SN I: 571 [DL] Vendor Id: 65521 (0xFFF1) I: 575 [DL] Product Id: 32773 (0x8005) I: 579 [DL] Hardware Version: 0 I: 582 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 588 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 595 [DL] Manufacturing Date: (not set) I: 599 [DL] Device Type: 65535 (0xFFFF) I: 604 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 608 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 615 [SVR]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00 I: 623 [SVR]Manual pairing code: [34970112332] I: 628 [DL]CHIP task running I: 634 [DL]CHIPoBLE advertising started I: 639 [DL]NFC Tag emulation started I: 30639 [DL]CHIPoBLE advertising mode changed to slow I: 55201 [DL]BLE connection established (ConnId: 0x00) I: 55206 [DL]Current number of connections: 1/1 I: 55211 [DL]CHIPoBLE advertising stopped I: 55215 [DL]NFC Tag emulation stopped I: 75263 [DL]BLE GAP connection terminated (reason 0x13) I: 75268 [DL]Current number of connections: 0/1 I: 75275 [DL]CHIPoBLE advertising started I: 75279 [DL]NFC Tag emulation started I: 105278 [DL]CHIPoBLE advertising mode changed to slow I: 132658 [DL]BLE connection established (ConnId: 0x00) I: 132663 [DL]Current number of connections: 1/1 I: 132667 [DL]CHIPoBLE advertising stopped I: 132671 [DL]NFC Tag emulation stopped D: 134507 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 134513 [BLE]local and remote recv window sizes = 5 I: 134518 [BLE]selected BTP version 4 I: 134521 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 134653 [DL]ConnId: 0x00, New CCCD value: 0x0001 D: 134658 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6) D: 134664 [IN]BLE EndPoint 0x20009ac8 Connection Complete I: 134670 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 134849 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 134855 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 134861 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:258070661 on exchange 54529r D: 134871 [EM]Handling via exchange: 54529r, Delegate: 0x20005940 D: 134877 [SC]Received PBKDF param request D: 134881 [SC]Peer assigned session ID 35411 D: 134885 [SC]Found MRP parameters in the message D: 134890 [SC]Including MRP parameters in PBKDF param response I: 134896 [IN]Prepared unauthenticated message 0x2002d878 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 54529r with MessageCounter:227647507. I: 134911 [IN]Sending unauthenticated msg 0x2002d878 with MessageCounter:227647507 to 0x0000000000000000 at monotonic time: 0000000000020EFF msec D: 134924 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 140) D: 134931 [SC]Sent PBKDF param response D: 135044 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 135050 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 135056 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:258070662 on exchange 54529r D: 135066 [EM]Found matching exchange: 54529r, Delegate: 0x20005940 D: 135072 [SC]Received spake2p msg1 I: 136986 [IN]Prepared unauthenticated message 0x2002d808 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 54529r with MessageCounter:227647508. I: 137001 [IN]Sending unauthenticated msg 0x2002d808 with MessageCounter:227647508 to 0x0000000000000000 at monotonic time: 0000000000021729 msec D: 137014 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 132) D: 137020 [SC]Sent spake2p msg2 E: 137023 [DL]Long dispatch time: 1973 ms, for event type 16388 D: 137091 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 137097 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 137103 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:258070663 on exchange 54529r D: 137113 [EM]Found matching exchange: 54529r, Delegate: 0x20005940 D: 137119 [SC]Received spake2p msg3 D: 137123 [SC]Sending status report. Protocol code 0, exchange 54529 I: 137129 [IN]Prepared unauthenticated message 0x2002d898 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 54529r with MessageCounter:227647509. I: 137145 [IN]Sending unauthenticated msg 0x2002d898 with MessageCounter:227647509 to 0x0000000000000000 at monotonic time: 00000000000217B8 msec D: 137157 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 35) D: 137165 [IN]New secure session created for device <FFFFFFFB00000000, 0>, LSID:32888 PSID:35411! I: 137174 [SVR]Commissioning completed session establishment step I: 137180 [DIS]Updating services using commissioning mode 0 D: 137185 [DL]Using Thread extended MAC for hostname. D: 137191 [DL]Using Thread extended MAC for hostname. I: 137196 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 137205 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003 D: 137213 [DIS]Scheduling extended discovery timeout in 900s E: 137218 [DIS]Failed to finalize service update: Error CHIP:0x0000001C D: 137225 [DL]CHIPoBLE advertising set to off I: 137242 [SVR]Device completed Rendezvous process E: 137247 [DL]Long dispatch time: 150 ms, for event type 16388 D: 137287 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 137292 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 137299 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:137041521 on exchange 54530r D: 137310 [EM]Handling via exchange: 54530r, Delegate: 0x200078bc D: 137315 [IM]Received Read request D: 137321 [DMG]IM RH moving to [GeneratingReports] D: 137326 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 137334 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty D: 137340 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) D: 137349 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty D: 137354 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 137363 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty D: 137368 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 137377 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty D: 137383 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 137392 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty D: 137397 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 137406 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty D: 137411 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 137420 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty D: 137425 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D: 137435 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty D: 137440 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) D: 137449 [DMG]<RE> Sending report (payload has 224 bytes)... I: 137457 [IN]Prepared secure message 0x2002da40 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 54530r with MessageCounter:4752760. I: 137471 [IN]Sending encrypted msg 0x2002da40 with MessageCounter:4752760 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000218FE msec D: 137484 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 137490 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 137495 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 137502 [DMG]IM RH moving to [AwaitingDestruction] D: 137507 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 137578 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 137583 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17) D: 137676 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 137871 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 137878 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:137041522 on exchange 54531r D: 137888 [EM]Handling via exchange: 54531r, Delegate: 0x200078bc D: 137895 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 D: 137903 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fa8c2bf5 D: 137910 [DMG]ICR moving to [ Preparing] D: 137913 [DMG]ICR moving to [AddingComm] D: 137917 [DMG]ICR moving to [AddedComma] D: 137921 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 137928 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54531r with MessageCounter:4752761. I: 137943 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:4752761 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000021AD6 msec D: 137955 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 137962 [DMG]ICR moving to [CommandSen] D: 137965 [DMG]ICR moving to [AwaitingDe] D: 138081 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 138087 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 138094 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:137041523 on exchange 54532r D: 138104 [EM]Handling via exchange: 54532r, Delegate: 0x200078bc D: 138110 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 138121 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fa8c2bf6 D: 138127 [DMG]ICR moving to [ Preparing] D: 138131 [DMG]ICR moving to [AddingComm] D: 138135 [DMG]ICR moving to [AddedComma] D: 138139 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 138146 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54532r with MessageCounter:4752762. I: 138160 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:4752762 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000021BB0 msec D: 138173 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 138179 [DMG]ICR moving to [CommandSen] D: 138183 [DMG]ICR moving to [AwaitingDe] I: 138531 [DL]BLE GAP connection terminated (reason 0x08) D: 138536 [IN]Clearing BLE pending packets. I: 138540 [BLE]Releasing end point's BLE connection back to application. I: 138546 [DL]Closing BLE GATT connection (ConnId 00) I: 138551 [DL]Current number of connections: 0/1 E: 197902 [SVR]Failsafe timer expired E: 197906 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032 D: 197914 [SC]Assigned local session key ID 32889 D: 197918 [SC]Waiting for PBKDF param request D: 197922 [DL]CHIPoBLE advertising set to on I: 197926 [DIS]Updating services using commissioning mode 1 D: 197932 [DL]Using Thread extended MAC for hostname. D: 197937 [DL]Using Thread extended MAC for hostname. I: 197942 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 197951 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 197958 [DIS]Scheduling discovery timeout in 900s E: 197963 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 197970 [ZCL]OpCreds: Call to FailSafeCleanup D: 197974 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fa8c2bf7 D: 197980 [ZCL]Failsafe timeout, tell platform driver to revert network credentials. I: 197994 [DL]CHIPoBLE advertising started I: 197999 [DL]NFC Tag emulation started I: 227997 [DL]CHIPoBLE advertising mode changed to slow I: 900409 [SVR]Closing pairing window I: 900413 [DIS]Updating services using commissioning mode 0 D: 900418 [DL]Using Thread extended MAC for hostname. D: 900423 [DL]Using Thread extended MAC for hostname. I: 900429 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 900438 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003 D: 900446 [DIS]Scheduling extended discovery timeout in 900s E: 900451 [DIS]Failed to finalize service update: Error CHIP:0x0000001C D: 900457 [DL]CHIPoBLE advertising set to off I: 900462 [DL]CHIPoBLE advertising stopped I: 900466 [DL]NFC Tag emulation stopped
Versions
Everything was downloaded today
matter commit b682834e
ot-br-posix commit d839abf5
ot-nrf528xx commit 24f53468
nrfSDK v2.0.0
OS: Ubuntu 20.04 LTS (desktop for PC, server for Raspberry Pi 4)
Additional
About a month ago I successfully joined these two devices. I wiped them and ttried to do it again now and it doen't seem to work.
Also, the dongle is not recognised by vscode.
Also, I cannot use the NRF Programmer tool for the dongle, since it only gives me `Error when fetching device versions: readFwInfo error (Origin: "Error when starting nrfdl_fw_read_info")`
