Regarding commissioning a matter device

I'm getting the following error when I'm trying to commission my matter device using chip-tool downloaded from https://snapcraft.io/install/chip-tool/ubuntu, into the thread network formed by OTBR in docker.

"Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors".

Also OTBR and chip-tool are in linux x86 machine.

And I'm trying to commission Nanoleaf matter bulb.

Could anyone please help me to get rid of this error ?

Top Replies

AHaug over 1 year ago +1

Hi, I recommend you follow the documentation at https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/protocols/matter/index.html so we can follow you through the process of supporting you…

Parents

0 Varun2103 over 1 year ago

Hey AHaug, Thanks for your help.

Can I ask you one more doubt ?
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 AHaug over 1 year ago in reply to Varun2103

Of course! : )
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Varun2103 over 1 year ago in reply to AHaug

I'm trying to commission Tapo Mini Smart Wi-Fi Plug using chip-tool downloaded from https://github.com/nrfconnect/sdk-connectedhomeip/releases V2.4.0 chip-tool-linux_aarch64.zip , and my Linux machine is connected to local Wi-Fi.

The command I used is ./chip-tool-debug pairing code-wifi 0xA874 TP-Link_4722 77189462 MT:YZ7A00C-035AO14GV10

where TP-LINK_4722 is my Wi-Fi SSID, 77189462 is Password of my Wi-Fi and MT:YZ7A00C-035AO14GV10 is my smart plug payload

But I'm getting error as shown below

[1687270353.218157][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687270353.218284][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1687270353.218312][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1687270353.218329][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1687270353.218415][18285:18285] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-HI4tsf)
[1687270353.218549][18285:18285] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687270353.218559][18285:18285] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1687270353.218734][18285:18285] CHIP:DL: Got Ethernet interface: enp2s0
[1687270353.218840][18285:18285] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1687270353.218933][18285:18285] CHIP:DL: Got WiFi interface: wlp3s0
[1687270353.219048][18285:18285] CHIP:DL: Found the primary WiFi interface:wlp3s0
[1687270353.219063][18285:18285] CHIP:IN: UDP::Init bind&listen port=0
[1687270353.219083][18285:18285] CHIP:IN: UDP::Init bound to port=51027
[1687270353.219087][18285:18285] CHIP:IN: UDP::Init bind&listen port=0
[1687270353.219101][18285:18285] CHIP:IN: UDP::Init bound to port=58610
[1687270353.219104][18285:18285] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687270353.219107][18285:18285] CHIP:IN: TransportMgr initialized
[1687270353.219117][18285:18285] CHIP:FP: Initializing FabricTable from persistent storage
[1687270353.219161][18285:18285] CHIP:TS: Last Known Good Time: 2023-06-14T13:57:05
[1687270353.219268][18285:18285] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xBC18D1F1B58BDA4C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687270353.219652][18285:18285] CHIP:ZCL: Using ZAP configuration...
[1687270353.220892][18285:18285] CHIP:DL: Avahi client registered
[1687270353.221092][18285:18285] CHIP:CTL: System State Initialized...
[1687270353.221115][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.221124][18285:18285] CHIP:CTL: Setting attestation nonce to random value
[1687270353.221128][18285:18285] CHIP:CTL: Setting CSR nonce to random value
[1687270353.221234][18285:18287] CHIP:DL: CHIP task running
[1687270353.221279][18285:18287] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1687270353.221350][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.221357][18285:18287] CHIP:CTL: Setting attestation nonce to random value
[1687270353.221361][18285:18287] CHIP:CTL: Setting CSR nonce to random value
[1687270353.224120][18285:18287] CHIP:CTL: Generating NOC
[1687270353.227173][18285:18287] CHIP:FP: Validating NOC chain
[1687270353.238424][18285:18287] CHIP:FP: NOC chain validation successful
[1687270353.238435][18285:18287] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687270353.238440][18285:18287] CHIP:TS: Last Known Good Time: 2023-06-14T13:57:05
[1687270353.238442][18285:18287] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687270353.238444][18285:18287] CHIP:TS: Retaining current Last Known Good Time
[1687270353.239022][18285:18287] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687270353.239322][18285:18287] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-14T13:57:05
[1687270353.239622][18285:18287] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: BC18D1F1B58BDA4C)
[1687270353.241663][18285:18287] CHIP:CTL: Setting wifi credentials from parameters
[1687270353.241668][18285:18287] CHIP:CTL: Setting attestation nonce to random value
[1687270353.241673][18285:18287] CHIP:CTL: Setting CSR nonce to random value
[1687270353.241708][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.241711][18285:18287] CHIP:CTL: Starting commissioning discovery over BLE
[1687270353.241719][18285:18287] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1687270353.243006][18285:18286] CHIP:DL: TRACE: Bus acquired for name C-476d
[1687270353.244596][18285:18287] CHIP:DL: PlatformBlueZInit init success
[1687270353.245579][18285:18286] CHIP:BLE: BLE removing known devices.
[1687270353.245825][18285:18286] CHIP:BLE: BLE initiating scan.
[1687270353.362881][18285:18287] CHIP:DL: Long dispatch time: 121 ms, for event type 2
[1687270353.363042][18285:18287] CHIP:DL: Avahi browse: cache exhausted
[1687270353.377857][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270353.559761][18285:18286] CHIP:BLE: Device 7E:98:15:B0:D1:A8 does not look like a CHIP device.
[1687270353.561606][18285:18286] CHIP:BLE: Device 48:22:54:5F:2B:F3 does not look like a CHIP device.
[1687270354.245744][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.246605][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270354.253582][18285:18287] CHIP:DL: Avahi browse: all for now
[1687270354.601103][18285:18286] CHIP:BLE: Device 08:7C:85:05:34:4B does not look like a CHIP device.
[1687270354.766759][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.767085][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270355.492434][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270356.268395][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270359.929839][18285:18286] CHIP:BLE: Device D5:D0:B4:6C:40:03 does not look like a CHIP device.
[1687270360.034205][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270360.034383][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270363.368003][18285:18287] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1687270363.485400][18285:18286] CHIP:BLE: Scan complete. No matching device found.
[1687270383.259484][18285:18287] CHIP:CTL: Discovery timed out
[1687270383.259514][18285:18287] CHIP:CTL: Stopping commissioning discovery over BLE
[1687270383.259519][18285:18287] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687270383.259530][18285:18287] CHIP:-: src/platform/Linux/BLEManagerImpl.cpp:732: CHIP Error 0x0000002D: Not Implemented at src/controller/SetUpCodePairer.cpp:551
[1687270383.259535][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.259543][18285:18287] CHIP:TOO: Secure Pairing Failed
[1687270383.259837][18285:18285] CHIP:CTL: Shutting down the commissioner
[1687270383.259862][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.259870][18285:18285] CHIP:CTL: Shutting down the controller
[1687270383.259880][18285:18285] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1687270383.259888][18285:18285] CHIP:FP: Forgetting fabric 0x1
[1687270383.259903][18285:18285] CHIP:TS: Pending Last Known Good Time: 2023-06-14T13:57:05
[1687270383.260008][18285:18285] CHIP:TS: Previous Last Known Good Time: 2023-06-14T13:57:05
[1687270383.260019][18285:18285] CHIP:TS: Reverted Last Known Good Time to previous value
[1687270383.260037][18285:18285] CHIP:CTL: Shutting down the commissioner
[1687270383.260041][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.260047][18285:18285] CHIP:CTL: Shutting down the controller
[1687270383.260052][18285:18285] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1687270383.260984][18285:18285] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687270383.261035][18285:18285] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687270383.261058][18285:18285] CHIP:FP: Shutting down FabricTable
[1687270383.261073][18285:18285] CHIP:TS: Pending Last Known Good Time: 2023-06-14T13:57:05
[1687270383.261166][18285:18285] CHIP:TS: Previous Last Known Good Time: 2023-06-14T13:57:05
[1687270383.261174][18285:18285] CHIP:TS: Reverted Last Known Good Time to previous value
[1687270383.261332][18285:18285] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DBdfXb)
[1687270383.261752][18285:18285] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687270383.261782][18285:18285] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1687270383.261790][18285:18285] CHIP:DL: Inet Layer shutdown
[1687270383.261794][18285:18285] CHIP:DL: BLE shutdown
[1687270383.262181][18285:18285] CHIP:DL: System Layer shutdown
[1687270383.262329][18285:18285] CHIP:TOO: Run command failure: examples/chip-tool/commands/pairing/PairingCommand.cpp:240: CHIP Error 0x00000003: Incorrect state

0 AHaug over 1 year ago in reply to Varun2103

Hi,

Based on the lines below it looks like your commissioner can not find any devices that are a Matter device while scanning for one. You should verify and check if the Matter device you want to commission actually is advertising

[1687270353.245825][18285:18286] CHIP:BLE: BLE initiating scan.
[1687270353.362881][18285:18287] CHIP:DL: Long dispatch time: 121 ms, for event type 2
[1687270353.363042][18285:18287] CHIP:DL: Avahi browse: cache exhausted
[1687270353.377857][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270353.559761][18285:18286] CHIP:BLE: Device 7E:98:15:B0:D1:A8 does not look like a CHIP device.
[1687270353.561606][18285:18286] CHIP:BLE: Device 48:22:54:5F:2B:F3 does not look like a CHIP device.
[1687270354.245744][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.246605][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270354.253582][18285:18287] CHIP:DL: Avahi browse: all for now
[1687270354.601103][18285:18286] CHIP:BLE: Device 08:7C:85:05:34:4B does not look like a CHIP device.
[1687270354.766759][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.767085][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270355.492434][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270356.268395][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270359.929839][18285:18286] CHIP:BLE: Device D5:D0:B4:6C:40:03 does not look like a CHIP device.
[1687270360.034205][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270360.034383][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270363.368003][18285:18287] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1687270363.485400][18285:18286] CHIP:BLE: Scan complete. No matching device found.
[1687270383.259484][18285:18287] CHIP:CTL: Discovery timed out
[1687270383.259514][18285:18287] CHIP:CTL: Stopping commissioning discovery over BLE

Kind regards,
Andreas

0 Varun2103 over 1 year ago in reply to AHaug

Yeah it's advertising but now I'm getting error saying "Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors".

The output log of terminal is shown below

1687332180.797206][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_kvs
[1687332180.798764][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_factory.ini
[1687332180.798793][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_config.ini
[1687332180.798805][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_counters.ini
[1687332180.798998][15779:15779] CHIP:DL: writing settings to file (/mnt/chip_counters.ini-0SZGzF)
[1687332180.799323][15779:15779] CHIP:DL: renamed tmp file to file (/mnt/chip_counters.ini)
[1687332180.799330][15779:15779] CHIP:DL: NVS set: chip-counters/reboot-count = 41 (0x29)
[1687332180.799676][15779:15779] CHIP:DL: Got Ethernet interface: enp2s0
[1687332180.799807][15779:15779] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1687332180.799909][15779:15779] CHIP:DL: Got WiFi interface: wlp3s0
[1687332180.800015][15779:15779] CHIP:DL: Found the primary WiFi interface:wlp3s0
[1687332180.800038][15779:15779] CHIP:IN: UDP::Init bind&listen port=0
[1687332180.800056][15779:15779] CHIP:IN: UDP::Init bound to port=46831
[1687332180.800060][15779:15779] CHIP:IN: UDP::Init bind&listen port=0
[1687332180.800073][15779:15779] CHIP:IN: UDP::Init bound to port=57258
[1687332180.800077][15779:15779] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687332180.800080][15779:15779] CHIP:IN: TransportMgr initialized
[1687332180.800088][15779:15779] CHIP:FP: Initializing FabricTable from persistent storage
[1687332180.800123][15779:15779] CHIP:TS: Last Known Good Time: 2023-01-04T15:21:56
[1687332180.800483][15779:15779] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x8DA70BA28B057D3E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687332180.800753][15779:15779] CHIP:ZCL: Using ZAP configuration...
[1687332180.800971][15779:15779] CHIP:DL: MDNS failed to join multicast group on enp2s0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
[1687332180.801288][15779:15779] CHIP:CTL: System State Initialized...
[1687332180.801301][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.801316][15779:15779] CHIP:CTL: Setting attestation nonce to random value
[1687332180.801330][15779:15779] CHIP:CTL: Setting CSR nonce to random value
[1687332180.801342][15779:15779] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.801391][15779:15779] CHIP:IN: UDP::Init bound to port=5550
[1687332180.801395][15779:15779] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.801405][15779:15779] CHIP:IN: UDP::Init bound to port=5550
[1687332180.801408][15779:15779] CHIP:IN: TransportMgr initialized
[1687332180.801528][15779:15805] CHIP:DL: CHIP task running
[1687332180.801685][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.801692][15779:15805] CHIP:CTL: Setting attestation nonce to random value
[1687332180.801710][15779:15805] CHIP:CTL: Setting CSR nonce to random value
[1687332180.801992][15779:15805] CHIP:CTL: Generating NOC
[1687332180.802256][15779:15805] CHIP:FP: Validating NOC chain
[1687332180.802694][15779:15805] CHIP:FP: NOC chain validation successful
[1687332180.802727][15779:15805] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687332180.802731][15779:15805] CHIP:TS: Last Known Good Time: 2023-01-04T15:21:56
[1687332180.802735][15779:15805] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687332180.802738][15779:15805] CHIP:TS: Retaining current Last Known Good Time
[1687332180.803039][15779:15805] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687332180.803239][15779:15805] CHIP:TS: Committing Last Known Good Time to storage: 2023-01-04T15:21:56
[1687332180.803446][15779:15805] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 8DA70BA28B057D3E)
[1687332180.803454][15779:15805] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.803473][15779:15805] CHIP:IN: UDP::Init bound to port=5550
[1687332180.803476][15779:15805] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.803489][15779:15805] CHIP:IN: UDP::Init bound to port=5550
[1687332180.803492][15779:15805] CHIP:IN: TransportMgr initialized
[1687332180.804809][15779:15805] CHIP:CTL: Setting wifi credentials from parameters
[1687332180.804814][15779:15805] CHIP:CTL: Setting attestation nonce to random value
[1687332180.804821][15779:15805] CHIP:CTL: Setting CSR nonce to random value
[1687332180.804825][15779:15805] CHIP:CTL: Setting PASE-only commissioning from parameters
[1687332180.804847][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.804850][15779:15805] CHIP:CTL: Starting commissioning discovery over BLE
[1687332180.804857][15779:15805] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1687332180.804921][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332180.805021][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332180.805026][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 4 successes and 2 failures.
[1687332180.806125][15779:15804] CHIP:DL: TRACE: Bus acquired for name C-3da3
[1687332180.807967][15779:15805] CHIP:DL: PlatformBlueZInit init success
[1687332180.809165][15779:15804] CHIP:BLE: BLE removing known devices.
[1687332180.809756][15779:15804] CHIP:BLE: BLE initiating scan.
[1687332180.929643][15779:15805] CHIP:DL: Long dispatch time: 124 ms, for event type 2
[1687332180.933627][15779:15804] CHIP:BLE: Device FD:43:F6:0B:17:56 does not look like a CHIP device.
[1687332180.939901][15779:15804] CHIP:BLE: Device 0F:30:69:85:1A:30 does not look like a CHIP device.
[1687332180.960228][15779:15804] CHIP:BLE: Device 90:38:0C:EE:5F:BA does not look like a CHIP device.
[1687332181.296349][15779:15804] CHIP:BLE: Device 28:DE:65:69:DA:69 does not look like a CHIP device.
[1687332181.296961][15779:15804] CHIP:BLE: Device 2B:E6:FE:EB:2E:75 does not look like a CHIP device.
[1687332181.297893][15779:15804] CHIP:BLE: Device 03:DB:05:38:1A:B8 does not look like a CHIP device.
[1687332181.298745][15779:15804] CHIP:BLE: New device scanned: 48:22:54:5F:2B:F3
[1687332181.298762][15779:15804] CHIP:BLE: Device discriminator match. Attempting to connect.
[1687332181.310504][15779:15804] CHIP:BLE: Scan complete notification without an active scan.
[1687332181.806871][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332181.807126][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332181.807166][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1687332181.870917][15779:15804] CHIP:DL: ConnectDevice complete
[1687332182.694439][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694453][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694458][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694460][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694464][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694466][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694471][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694474][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694477][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694480][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694483][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694486][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694491][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694494][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694498][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694500][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694508][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694511][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694515][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694517][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694521][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694524][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694532][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694536][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694542][15779:15804] CHIP:DL: New BLE connection 0x7f5948073de0, device 48:22:54:5F:2B:F3, path /org/bluez/hci0/dev_48_22_54_5F_2B_F3
[1687332182.694575][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1687332182.694583][15779:15805] CHIP:CTL: Discovered device to be commissioned over BLE
[1687332182.694592][15779:15805] CHIP:CTL: Attempting PASE connection to BLE
[1687332182.694603][15779:15805] CHIP:IN: BleConnectionComplete: endPoint 0x563852c5eb20
[1687332182.694646][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Allocated Type:1 LSID:19592
[1687332182.694651][15779:15805] CHIP:SC: Assigned local session key ID 19592
[1687332182.694672][15779:15805] CHIP:EM: <<< [E:64287i M:208376926] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1687332182.694683][15779:15805] CHIP:IN: (U) Sending msg 208376926 to IP address 'BLE'
[1687332182.694689][15779:15805] CHIP:IN: Message appended to BLE send queue
[1687332182.694694][15779:15805] CHIP:SC: Sent PBKDF param request
[1687332182.694699][15779:15805] CHIP:CTL: Commission called for node ID 0x0000000000001548
[1687332183.504402][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332183.579966][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1687332183.579992][15779:15805] CHIP:BLE: subscribe complete, ep = 0x563852c5eb20
[1687332183.580017][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332183.580110][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332183.580128][15779:15805] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1687332183.580136][15779:15805] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1687332183.580142][15779:15805] CHIP:BLE: local and remote recv window size = 5
[1687332183.580188][15779:15805] CHIP:IN: BLE EndPoint 0x563852c5eb20 Connection Complete
[1687332183.669513][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332183.760194][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332183.760277][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332183.760351][15779:15805] CHIP:EM: >>> [E:64287i M:146526867] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1687332183.760366][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332183.760384][15779:15805] CHIP:SC: Received PBKDF param response
[1687332183.760405][15779:15805] CHIP:SC: Peer assigned session ID 64722
[1687332183.760419][15779:15805] CHIP:SC: Found MRP parameters in the message
[1687332183.785073][15779:15805] CHIP:EM: <<< [E:64287i M:208376927] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1687332183.785092][15779:15805] CHIP:IN: (U) Sending msg 208376927 to IP address 'BLE'
[1687332183.785125][15779:15805] CHIP:SC: Sent spake2p msg1
[1687332183.806330][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332183.808861][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332183.808870][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1687332183.850412][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332184.795937][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332184.796032][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332184.796100][15779:15805] CHIP:EM: >>> [E:64287i M:146526868] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1687332184.796113][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332184.796127][15779:15805] CHIP:SC: Received spake2p msg2
[1687332184.796876][15779:15805] CHIP:EM: <<< [E:64287i M:208376928] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1687332184.796895][15779:15805] CHIP:IN: (U) Sending msg 208376928 to IP address 'BLE'
[1687332184.796930][15779:15805] CHIP:SC: Sent spake2p msg3
[1687332184.885511][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332184.930866][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332184.931002][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332184.931097][15779:15805] CHIP:EM: >>> [E:64287i M:146526869] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687332184.931117][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332184.931230][15779:15805] CHIP:SC: SecureSession[0x7f594000ff10]: Moving from state 'kEstablishing' --> 'kActive'
[1687332184.931240][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Activated - Type:1 LSID:19592
[1687332184.931244][15779:15805] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:19592 PSID:64722!
[1687332184.931253][15779:15805] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1687332184.931261][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332184.931266][15779:15805] CHIP:TOO: Pairing Success
[1687332184.931270][15779:15805] CHIP:TOO: PASE establishment successful
[1687332184.931276][15779:15805] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1687332184.931284][15779:15805] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1687332184.931290][15779:15805] CHIP:CTL: Sending request for commissioning information
[1687332184.931310][15779:15805] CHIP:DMG: SendReadRequest ReadClient[0x7f594001b4c0]: Sending Read Request
[1687332184.931391][15779:15805] CHIP:EM: <<< [E:64288i M:43174472] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1687332184.931410][15779:15805] CHIP:IN: (S) Sending msg 43174472 on secure session with LSID: 19592
[1687332184.931460][15779:15805] CHIP:DMG: MoveToState ReadClient[0x7f594001b4c0]: Moving to [AwaitingIn]
[1687332185.020497][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.156144][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.156288][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.246137][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.246235][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.246335][15779:15805] CHIP:EM: >>> [E:64288i M:188327128] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1687332185.246350][15779:15805] CHIP:EM: Found matching exchange: 64288i, Delegate: 0x7f594001b4d0
[1687332185.246404][15779:15805] CHIP:DMG: ReportDataMessage =
[1687332185.246413][15779:15805] CHIP:DMG: {
[1687332185.246421][15779:15805] CHIP:DMG:     AttributeReportIBs =
[1687332185.246436][15779:15805] CHIP:DMG:     [
[1687332185.246443][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246459][15779:15805] CHIP:DMG:         {
[1687332185.246466][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246478][15779:15805] CHIP:DMG:             {
[1687332185.246488][15779:15805] CHIP:DMG:                 DataVersion = 0x4ff6d6f2,
[1687332185.246497][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246510][15779:15805] CHIP:DMG:                 {
[1687332185.246522][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246531][15779:15805] CHIP:DMG:                     Cluster = 0x31,
[1687332185.246542][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687332185.246556][15779:15805] CHIP:DMG:                 }
[1687332185.246570][15779:15805] CHIP:DMG:                     
[1687332185.246582][15779:15805] CHIP:DMG:                 Data = 20,
[1687332185.246594][15779:15805] CHIP:DMG:             },
[1687332185.246608][15779:15805] CHIP:DMG:             
[1687332185.246616][15779:15805] CHIP:DMG:         },
[1687332185.246635][15779:15805] CHIP:DMG:         
[1687332185.246644][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246657][15779:15805] CHIP:DMG:         {
[1687332185.246664][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246675][15779:15805] CHIP:DMG:             {
[1687332185.246685][15779:15805] CHIP:DMG:                 DataVersion = 0x6b40079a,
[1687332185.246698][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246710][15779:15805] CHIP:DMG:                 {
[1687332185.246718][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246731][15779:15805] CHIP:DMG:                     Cluster = 0x28,
[1687332185.246743][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0004,
[1687332185.246756][15779:15805] CHIP:DMG:                 }
[1687332185.246769][15779:15805] CHIP:DMG:                     
[1687332185.246780][15779:15805] CHIP:DMG:                 Data = 257,
[1687332185.246790][15779:15805] CHIP:DMG:             },
[1687332185.246805][15779:15805] CHIP:DMG:             
[1687332185.246811][15779:15805] CHIP:DMG:         },
[1687332185.246823][15779:15805] CHIP:DMG:         
[1687332185.246828][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246843][15779:15805] CHIP:DMG:         {
[1687332185.246852][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246862][15779:15805] CHIP:DMG:             {
[1687332185.246872][15779:15805] CHIP:DMG:                 DataVersion = 0x6b40079a,
[1687332185.246882][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246892][15779:15805] CHIP:DMG:                 {
[1687332185.246903][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246914][15779:15805] CHIP:DMG:                     Cluster = 0x28,
[1687332185.246925][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687332185.246935][15779:15805] CHIP:DMG:                 }
[1687332185.246948][15779:15805] CHIP:DMG:                     
[1687332185.246959][15779:15805] CHIP:DMG:                 Data = 4488,
[1687332185.246968][15779:15805] CHIP:DMG:             },
[1687332185.246980][15779:15805] CHIP:DMG:             
[1687332185.246989][15779:15805] CHIP:DMG:         },
[1687332185.247006][15779:15805] CHIP:DMG:         
[1687332185.247012][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247027][15779:15805] CHIP:DMG:         {
[1687332185.247033][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247040][15779:15805] CHIP:DMG:             {
[1687332185.247055][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247064][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247070][15779:15805] CHIP:DMG:                 {
[1687332185.247076][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247082][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247087][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687332185.247092][15779:15805] CHIP:DMG:                 }
[1687332185.247101][15779:15805] CHIP:DMG:                     
[1687332185.247113][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247123][15779:15805] CHIP:DMG:             },
[1687332185.247136][15779:15805] CHIP:DMG:             
[1687332185.247145][15779:15805] CHIP:DMG:         },
[1687332185.247157][15779:15805] CHIP:DMG:         
[1687332185.247163][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247179][15779:15805] CHIP:DMG:         {
[1687332185.247188][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247201][15779:15805] CHIP:DMG:             {
[1687332185.247209][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247218][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247225][15779:15805] CHIP:DMG:                 {
[1687332185.247232][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247245][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247260][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687332185.247269][15779:15805] CHIP:DMG:                 }
[1687332185.247281][15779:15805] CHIP:DMG:                     
[1687332185.247292][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247302][15779:15805] CHIP:DMG:             },
[1687332185.247310][15779:15805] CHIP:DMG:             
[1687332185.247319][15779:15805] CHIP:DMG:         },
[1687332185.247338][15779:15805] CHIP:DMG:         
[1687332185.247344][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247361][15779:15805] CHIP:DMG:         {
[1687332185.247369][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247380][15779:15805] CHIP:DMG:             {
[1687332185.247391][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247401][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247412][15779:15805] CHIP:DMG:                 {
[1687332185.247423][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247439][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247448][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0001,
[1687332185.247458][15779:15805] CHIP:DMG:                 }
[1687332185.247475][15779:15805] CHIP:DMG:                     
[1687332185.247486][15779:15805] CHIP:DMG:                 Data =
[1687332185.247497][15779:15805] CHIP:DMG:                 {
[1687332185.247509][15779:15805] CHIP:DMG:                     0x0 = 60,
[1687332185.247519][15779:15805] CHIP:DMG:                     0x1 = 900,
[1687332185.247530][15779:15805] CHIP:DMG:                 },
[1687332185.247540][15779:15805] CHIP:DMG:             },
[1687332185.247554][15779:15805] CHIP:DMG:             
[1687332185.247563][15779:15805] CHIP:DMG:         },
[1687332185.247579][15779:15805] CHIP:DMG:         
[1687332185.247585][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247602][15779:15805] CHIP:DMG:         {
[1687332185.247611][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247622][15779:15805] CHIP:DMG:             {
[1687332185.247631][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247641][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247650][15779:15805] CHIP:DMG:                 {
[1687332185.247661][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247668][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247680][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0000,
[1687332185.247690][15779:15805] CHIP:DMG:                 }
[1687332185.247702][15779:15805] CHIP:DMG:                     
[1687332185.247712][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247721][15779:15805] CHIP:DMG:             },
[1687332185.247734][15779:15805] CHIP:DMG:             
[1687332185.247742][15779:15805] CHIP:DMG:         },
[1687332185.247758][15779:15805] CHIP:DMG:         
[1687332185.247769][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247781][15779:15805] CHIP:DMG:         {
[1687332185.247787][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247798][15779:15805] CHIP:DMG:             {
[1687332185.247806][15779:15805] CHIP:DMG:                 DataVersion = 0x4ff6d6f2,
[1687332185.247816][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247827][15779:15805] CHIP:DMG:                 {
[1687332185.247837][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247848][15779:15805] CHIP:DMG:                     Cluster = 0x31,
[1687332185.247858][15779:15805] CHIP:DMG:                     Attribute = 0x0000_FFFC,
[1687332185.247867][15779:15805] CHIP:DMG:                 }
[1687332185.247879][15779:15805] CHIP:DMG:                     
[1687332185.247887][15779:15805] CHIP:DMG:                 Data = 1,
[1687332185.247893][15779:15805] CHIP:DMG:             },
[1687332185.247903][15779:15805] CHIP:DMG:             
[1687332185.247911][15779:15805] CHIP:DMG:         },
[1687332185.247926][15779:15805] CHIP:DMG:         
[1687332185.247935][15779:15805] CHIP:DMG:     ],
[1687332185.247970][15779:15805] CHIP:DMG:     
[1687332185.247980][15779:15805] CHIP:DMG:     SuppressResponse = true,
[1687332185.247990][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.247998][15779:15805] CHIP:DMG: }
[1687332185.248423][15779:15805] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0
[1687332185.248462][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1687332185.248473][15779:15805] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1687332185.248486][15779:15805] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1687332185.248495][15779:15805] CHIP:CTL: Arming failsafe (60 seconds)
[1687332185.248528][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.248542][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.248588][15779:15805] CHIP:EM: <<< [E:64289i M:43174473] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.248601][15779:15805] CHIP:IN: (S) Sending msg 43174473 on secure session with LSID: 19592
[1687332185.248637][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.335805][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.336694][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.336785][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.336893][15779:15805] CHIP:EM: >>> [E:64289i M:188327129] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332185.336909][15779:15805] CHIP:EM: Found matching exchange: 64289i, Delegate: 0x7f59480472a8
[1687332185.336927][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332185.336961][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332185.336973][15779:15805] CHIP:DMG: {
[1687332185.337001][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332185.337011][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332185.337274][15779:15805] CHIP:DMG:     [
[1687332185.337285][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332185.337296][15779:15805] CHIP:DMG:         {
[1687332185.337303][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332185.337314][15779:15805] CHIP:DMG:             {
[1687332185.337323][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332185.337336][15779:15805] CHIP:DMG:                 {
[1687332185.337347][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332185.337465][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332185.337478][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332185.337488][15779:15805] CHIP:DMG:                 },
[1687332185.337501][15779:15805] CHIP:DMG:                 
[1687332185.337513][15779:15805] CHIP:DMG:                 CommandFields =
[1687332185.337523][15779:15805] CHIP:DMG:                 {
[1687332185.337536][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332185.337548][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332185.337561][15779:15805] CHIP:DMG:                 },
[1687332185.337570][15779:15805] CHIP:DMG:             },
[1687332185.337584][15779:15805] CHIP:DMG:             
[1687332185.337593][15779:15805] CHIP:DMG:         },
[1687332185.337609][15779:15805] CHIP:DMG:         
[1687332185.337617][15779:15805] CHIP:DMG:     ],
[1687332185.337633][15779:15805] CHIP:DMG:     
[1687332185.337642][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.337652][15779:15805] CHIP:DMG: },
[1687332185.337695][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687332185.337729][15779:15805] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1687332185.337744][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1687332185.337753][15779:15805] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1687332185.337765][15779:15805] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1687332185.337773][15779:15805] CHIP:CTL: Setting Regulatory Config
[1687332185.337781][15779:15805] CHIP:CTL: Device does not support configurable regulatory location
[1687332185.337816][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.337831][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.337884][15779:15805] CHIP:EM: <<< [E:64290i M:43174474] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.337901][15779:15805] CHIP:IN: (S) Sending msg 43174474 on secure session with LSID: 19592
[1687332185.337945][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.337981][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332185.470705][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.516375][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.516487][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.516603][15779:15805] CHIP:EM: >>> [E:64290i M:188327130] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332185.516618][15779:15805] CHIP:EM: Found matching exchange: 64290i, Delegate: 0x7f594000a4c8
[1687332185.516631][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332185.516654][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332185.516662][15779:15805] CHIP:DMG: {
[1687332185.516672][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332185.516679][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332185.516690][15779:15805] CHIP:DMG:     [
[1687332185.516696][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332185.516708][15779:15805] CHIP:DMG:         {
[1687332185.516713][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332185.516725][15779:15805] CHIP:DMG:             {
[1687332185.516731][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332185.516741][15779:15805] CHIP:DMG:                 {
[1687332185.516749][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332185.516766][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332185.516774][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332185.516780][15779:15805] CHIP:DMG:                 },
[1687332185.516789][15779:15805] CHIP:DMG:                 
[1687332185.516796][15779:15805] CHIP:DMG:                 CommandFields =
[1687332185.516805][15779:15805] CHIP:DMG:                 {
[1687332185.516817][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332185.516826][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332185.516834][15779:15805] CHIP:DMG:                 },
[1687332185.516841][15779:15805] CHIP:DMG:             },
[1687332185.516850][15779:15805] CHIP:DMG:             
[1687332185.516856][15779:15805] CHIP:DMG:         },
[1687332185.516867][15779:15805] CHIP:DMG:         
[1687332185.516872][15779:15805] CHIP:DMG:     ],
[1687332185.516883][15779:15805] CHIP:DMG:     
[1687332185.516890][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.516895][15779:15805] CHIP:DMG: },
[1687332185.516921][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1687332185.516936][15779:15805] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1687332185.516947][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1687332185.516954][15779:15805] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1687332185.516964][15779:15805] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1687332185.516969][15779:15805] CHIP:CTL: Sending request for PAI certificate
[1687332185.516974][15779:15805] CHIP:CTL: Sending Certificate Chain request to 0x7f5940019780 device
[1687332185.517014][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.517037][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.517075][15779:15805] CHIP:EM: <<< [E:64291i M:43174475] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.517088][15779:15805] CHIP:IN: (S) Sending msg 43174475 on secure session with LSID: 19592
[1687332185.517127][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.517151][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332185.605674][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.741136][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.741249][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.921282][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.921402][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.011258][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.011405][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.011498][15779:15805] CHIP:EM: >>> [E:64291i M:188327131] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332186.011513][15779:15805] CHIP:EM: Found matching exchange: 64291i, Delegate: 0x7f59480472a8
[1687332186.011531][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332186.011556][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332186.011563][15779:15805] CHIP:DMG: {
[1687332186.011571][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332186.011578][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332186.011590][15779:15805] CHIP:DMG:     [
[1687332186.011596][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332186.011613][15779:15805] CHIP:DMG:         {
[1687332186.011624][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332186.011634][15779:15805] CHIP:DMG:             {
[1687332186.011646][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332186.011653][15779:15805] CHIP:DMG:                 {
[1687332186.011660][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332186.011669][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332186.011682][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332186.011691][15779:15805] CHIP:DMG:                 },
[1687332186.011729][15779:15805] CHIP:DMG:                 
[1687332186.011739][15779:15805] CHIP:DMG:                 CommandFields =
[1687332186.011751][15779:15805] CHIP:DMG:                 {
[1687332186.011772][15779:15805] CHIP:DMG:                     0x0 = [
[1687332186.011847][15779:15805] CHIP:DMG:                             0x30, 0x82, 0x01, 0xda, 0x30, 0x82, 0x01, 0x80, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x4a, 0x55, 0x95, 0xca, 0xad, 0x8e, 0xcb, 0xd9, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x33, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x8e, 0x78, 0x82, 0x5a, 0x5a, 0xa7, 0xc4, 0xc8, 0x9e, 0xd6, 0xa8, 0x78, 0x08, 0x67, 0x32, 0x2e, 0x6a, 0xbb, 0xaa, 0x01, 0x1a, 0xee, 0xa4, 0xec, 0x26, 0xdb, 0x64, 0xd4, 0x47, 0xbe, 0xc7, 0xc3, 0x16, 0x7d, 0xb4, 0x19, 0x8a, 0x21, 0x15, 0x65, 0x7f, 0x63, 0x32, 0xc5, 0x38, 0x15, 0xc2, 0xbd, 0x8f, 0xa2, 0x52, 0x9d, 0x9e, 0xa0, 0xf8, 0xad, 0xb1, 0x42, 0xa2, 0x
[1687332186.011893][15779:15805] CHIP:DMG:                     ] (478 bytes)
[1687332186.011905][15779:15805] CHIP:DMG:                 },
[1687332186.011913][15779:15805] CHIP:DMG:             },
[1687332186.011923][15779:15805] CHIP:DMG:             
[1687332186.011936][15779:15805] CHIP:DMG:         },
[1687332186.011952][15779:15805] CHIP:DMG:         
[1687332186.011960][15779:15805] CHIP:DMG:     ],
[1687332186.011975][15779:15805] CHIP:DMG:     
[1687332186.011984][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332186.011993][15779:15805] CHIP:DMG: },
[1687332186.012030][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687332186.012045][15779:15805] CHIP:CTL: Received certificate chain from the device
[1687332186.012058][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1687332186.012071][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1687332186.012086][15779:15805] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1687332186.012095][15779:15805] CHIP:CTL: Sending request for DAC certificate
[1687332186.012101][15779:15805] CHIP:CTL: Sending Certificate Chain request to 0x7f5940019780 device
[1687332186.012133][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332186.012146][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332186.012196][15779:15805] CHIP:EM: <<< [E:64292i M:43174476] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332186.012213][15779:15805] CHIP:IN: (S) Sending msg 43174476 on secure session with LSID: 19592
[1687332186.012260][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332186.012286][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332186.100647][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332186.236070][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.236203][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.461155][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.461288][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.551731][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.551898][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.552000][15779:15805] CHIP:EM: >>> [E:64292i M:188327132] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332186.552017][15779:15805] CHIP:EM: Found matching exchange: 64292i, Delegate: 0x7f59480058a8
[1687332186.552038][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332186.552079][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332186.552088][15779:15805] CHIP:DMG: {
[1687332186.552097][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332186.552106][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332186.552121][15779:15805] CHIP:DMG:     [
[1687332186.552131][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332186.552145][15779:15805] CHIP:DMG:         {
[1687332186.552152][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332186.552161][15779:15805] CHIP:DMG:             {
[1687332186.552170][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332186.552183][15779:15805] CHIP:DMG:                 {
[1687332186.552194][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332186.552206][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332186.552217][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332186.552228][15779:15805] CHIP:DMG:                 },
[1687332186.552241][15779:15805] CHIP:DMG:                 
[1687332186.552248][15779:15805] CHIP:DMG:                 CommandFields =
[1687332186.552259][15779:15805] CHIP:DMG:                 {
[1687332186.552272][15779:15805] CHIP:DMG:                     0x0 = [
[1687332186.552345][15779:15805] CHIP:DMG:                             0x30, 0x82, 0x01, 0xeb, 0x30, 0x82, 0x01, 0x90, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x50, 0x04, 0xca, 0x35, 0x9a, 0x9e, 0x85, 0x27, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x41, 0x43, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x0c, 0x1d, 0xae, 0x80, 0x17, 0x17, 0xd1, 0x2f, 0xe3, 0xa6, 0x08, 0x50, 0xa2, 0x8b, 0x21, 0x03, 0xf6, 0xc2, 0x15, 0x6f, 0xe8, 0x9c, 0xa1, 0x9b, 0x59, 0xff, 0xf2, 0x2e, 0x42, 0xca, 0x25, 0x30, 0xe3, 0x10, 0xab, 0x72, 0x00, 0x
[1687332186.552375][15779:15805] CHIP:DMG:                     ] (495 bytes)
[1687332186.552389][15779:15805] CHIP:DMG:                 },
[1687332186.552406][15779:15805] CHIP:DMG:             },
[1687332186.552420][15779:15805] CHIP:DMG:             
[1687332186.552429][15779:15805] CHIP:DMG:         },
[1687332186.552441][15779:15805] CHIP:DMG:         
[1687332186.552450][15779:15805] CHIP:DMG:     ],
[1687332186.552466][15779:15805] CHIP:DMG:     
[1687332186.552474][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332186.552486][15779:15805] CHIP:DMG: },
[1687332186.552526][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687332186.552543][15779:15805] CHIP:CTL: Received certificate chain from the device
[1687332186.552558][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1687332186.552568][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1687332186.552581][15779:15805] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1687332186.552590][15779:15805] CHIP:CTL: Sending Attestation Request to the device.
[1687332186.552598][15779:15805] CHIP:CTL: Sending Attestation request to 0x7f5940019780 device
[1687332186.552628][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332186.552639][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332186.552680][15779:15805] CHIP:EM: <<< [E:64293i M:43174477] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332186.552693][15779:15805] CHIP:IN: (S) Sending msg 43174477 on secure session with LSID: 19592
[1687332186.552732][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332186.552742][15779:15805] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1687332186.552763][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332186.640430][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332186.911166][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.911258][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.046112][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332187.046244][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.046333][15779:15805] CHIP:EM: >>> [E:64293i M:188327133] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332187.046348][15779:15805] CHIP:EM: Found matching exchange: 64293i, Delegate: 0x7f5948040458
[1687332187.046362][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332187.046393][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332187.046399][15779:15805] CHIP:DMG: {
[1687332187.046404][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332187.046409][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332187.046419][15779:15805] CHIP:DMG:     [
[1687332187.046423][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332187.046433][15779:15805] CHIP:DMG:         {
[1687332187.046440][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332187.046448][15779:15805] CHIP:DMG:             {
[1687332187.046453][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332187.046464][15779:15805] CHIP:DMG:                 {
[1687332187.046472][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332187.046483][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332187.046496][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332187.046503][15779:15805] CHIP:DMG:                 },
[1687332187.046513][15779:15805] CHIP:DMG:                 
[1687332187.046519][15779:15805] CHIP:DMG:                 CommandFields =
[1687332187.046527][15779:15805] CHIP:DMG:                 {
[1687332187.046535][15779:15805] CHIP:DMG:                     0x0 = [
[1687332187.046586][15779:15805] CHIP:DMG:                             0x15, 0x30, 0x01, 0xeb, 0x30, 0x81, 0xe8, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x81, 0xda, 0x30, 0x81, 0xd7, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x44, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x37, 0x04, 0x35, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0x88, 0x11, 0x36, 0x02, 0x05, 0x01, 0x01, 0x18, 0x25, 0x03, 0x0a, 0x01, 0x2c, 0x04, 0x13, 0x43, 0x53, 0x41, 0x32, 0x32, 0x31, 0x36, 0x35, 0x4d, 0x41, 0x54, 0x34, 0x30, 0x31, 0x36, 0x35, 0x2d, 0x32, 0x34, 0x24, 0x05, 0x00, 0x24, 0x06, 0x00, 0x24, 0x07, 0x01, 0x24, 0x08, 0x02, 0x18, 0x31, 0x7d, 0x30, 0x7b, 0x02, 0x01, 0x03, 0x80, 0x14, 0xfe, 0x34, 0x3f, 0x95, 0x99, 0x47, 0x76, 0x3b, 0x61, 0xee, 0x45, 0x39, 0x13, 0x13, 0x38, 0x49, 0x4f, 0xe6, 0x7d, 0x8e, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x04, 0x47, 0x30, 0x45, 0x02, 0x21, 0x00, 0x89, 0x38, 0x2b, 0xe2, 0x94, 0x74, 0x5a, 0xea, 0x8c, 0x45, 0xf0, 0x5c, 0xf5, 0x8d, 0xb8, 0x41, 0xa2, 0x3e, 0x07, 0x68, 0x43, 0xdc, 0x6e, 0x36, 0xe7, 0x93, 0x99, 0x5c, 0x8f, 0xbb, 0x3d, 0x2f, 0x02, 0x20, 0x7f, 0x86, 0x94, 0xc5, 0xe3, 0x33, 0x7a, 0x5b, 0x28, 0x8f, 0xe1, 0x5c, 0x8b, 0x69, 0x2d, 0x08, 0x45, 0xd0, 0x3b, 0x9a, 0x1b, 0xc5, 0x9a, 0x3d, 0xb5, 0xd8, 0x9f, 0xf9, 0x8d, 0xb1, 0x7e, 0x29, 0x30, 0x02, 0x20, 0xae, 0x90, 0x62, 0x85, 0xb0, 0x60, 0x5a, 0xf8, 0x4f, 0x09, 0xcd, 0x07, 0x08, 0xbd, 0x28, 0x96, 0x4a, 0x4f, 0x05, 0xd5, 0x08, 0x13, 0x11, 0x8a, 0x79, 0x0f, 0x16, 0x37, 0xa4, 0x16, 0xc3, 0x3e, 0x24, 0x03, 0x00, 0x18,
[1687332187.046615][15779:15805] CHIP:DMG:                     ] (278 bytes)
[1687332187.046622][15779:15805] CHIP:DMG:                     0x1 = [
[1687332187.046639][15779:15805] CHIP:DMG:                             0x74, 0xa1, 0xad, 0xe9, 0xf1, 0xae, 0xe3, 0x03, 0x15, 0xdb, 0x7d, 0x49, 0x67, 0x2f, 0x51, 0x74, 0xe9, 0xb8, 0xf2, 0x82, 0xfa, 0x31, 0x0c, 0x43, 0xc5, 0x0b, 0x5c, 0x5a, 0x64, 0x46, 0xa3, 0x30, 0x42, 0xfc, 0xb3, 0x0a, 0x3f, 0x7f, 0x68, 0xd1, 0xd6, 0xd6, 0x16, 0x89, 0xee, 0xeb, 0x7f, 0x69, 0x59, 0x1f, 0xd4, 0x47, 0x7a, 0x73, 0x80, 0x89, 0x6e, 0x10, 0xd4, 0xb6, 0x48, 0x3a, 0x96, 0x6b,
[1687332187.046651][15779:15805] CHIP:DMG:                     ] (64 bytes)
[1687332187.046658][15779:15805] CHIP:DMG:                 },
[1687332187.046664][15779:15805] CHIP:DMG:             },
[1687332187.046674][15779:15805] CHIP:DMG:             
[1687332187.046679][15779:15805] CHIP:DMG:         },
[1687332187.046689][15779:15805] CHIP:DMG:         
[1687332187.046695][15779:15805] CHIP:DMG:     ],
[1687332187.046705][15779:15805] CHIP:DMG:     
[1687332187.046712][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332187.046737][15779:15805] CHIP:DMG: },
[1687332187.046783][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1687332187.046803][15779:15805] CHIP:CTL: Received Attestation Information from the device
[1687332187.046816][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1687332187.046828][15779:15805] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 278/278
[1687332187.046850][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1687332187.046860][15779:15805] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1687332187.046867][15779:15805] CHIP:CTL: Verifying attestation
[1687332187.061090][15779:15805] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors
[1687332187.061126][15779:15805] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
[1687332187.061132][15779:15805] CHIP:CTL: Failed to perform commissioning step 8
[1687332187.061137][15779:15805] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1687332187.061148][15779:15805] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
[1687332187.061153][15779:15805] CHIP:CTL: Expiring failsafe on proxy 0x7f5940019780
[1687332187.061181][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332187.061189][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332187.061246][15779:15805] CHIP:EM: <<< [E:64294i M:43174478] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332187.061256][15779:15805] CHIP:IN: (S) Sending msg 43174478 on secure session with LSID: 19592
[1687332187.061301][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332187.061321][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332187.135649][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332187.137969][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332187.138091][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.138199][15779:15805] CHIP:EM: >>> [E:64294i M:188327134] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332187.138216][15779:15805] CHIP:EM: Found matching exchange: 64294i, Delegate: 0x7f59480405b8
[1687332187.138233][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332187.138258][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332187.138265][15779:15805] CHIP:DMG: {
[1687332187.138275][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332187.138285][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332187.138302][15779:15805] CHIP:DMG:     [
[1687332187.138310][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332187.138327][15779:15805] CHIP:DMG:         {
[1687332187.138336][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332187.138347][15779:15805] CHIP:DMG:             {
[1687332187.138355][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332187.138369][15779:15805] CHIP:DMG:                 {
[1687332187.138383][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332187.138394][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332187.138414][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332187.138424][15779:15805] CHIP:DMG:                 },
[1687332187.138435][15779:15805] CHIP:DMG:                 
[1687332187.138445][15779:15805] CHIP:DMG:                 CommandFields =
[1687332187.138456][15779:15805] CHIP:DMG:                 {
[1687332187.138472][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332187.138486][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332187.138495][15779:15805] CHIP:DMG:                 },
[1687332187.138505][15779:15805] CHIP:DMG:             },
[1687332187.138518][15779:15805] CHIP:DMG:             
[1687332187.138527][15779:15805] CHIP:DMG:         },
[1687332187.138544][15779:15805] CHIP:DMG:         
[1687332187.138551][15779:15805] CHIP:DMG:     ],
[1687332187.138566][15779:15805] CHIP:DMG:     
[1687332187.138574][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332187.138581][15779:15805] CHIP:DMG: },
[1687332187.138616][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687332187.138636][15779:15805] CHIP:CTL: Failsafe disarmed
[1687332187.138649][15779:15805] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1687332187.138669][15779:15805] CHIP:TOO: Device commissioning Failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error
[1687332187.138685][15779:15805] CHIP:DIS: Closing all BLE connections
[1687332187.138692][15779:15805] CHIP:IN: Clearing BLE pending packets.
[1687332187.138718][15779:15805] CHIP:BLE: Auto-closing end point's BLE connection.
[1687332187.138724][15779:15805] CHIP:DL: Closing BLE GATT connection (con 0x7f5948073de0)
[1687332187.138759][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: MarkForEviction Type:1 LSID:19592
[1687332187.138767][15779:15805] CHIP:SC: SecureSession[0x7f594000ff10]: Moving from state 'kActive' --> 'kPendingEviction'
[1687332187.138815][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332187.138830][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Released - Type:1 LSID:19592
[1687332187.138858][15779:15804] CHIP:DL: BluezDisconnect peer=48:22:54:5F:2B:F3
[1687332187.138958][15779:15779] CHIP:CTL: Shutting down the commissioner
[1687332187.138983][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332187.139034][15779:15779] CHIP:CTL: Shutting down the controller
[1687332187.139044][15779:15779] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1687332187.139055][15779:15779] CHIP:FP: Forgetting fabric 0x1
[1687332187.139071][15779:15779] CHIP:TS: Pending Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139162][15779:15779] CHIP:TS: Previous Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139170][15779:15779] CHIP:TS: Reverted Last Known Good Time to previous value
[1687332187.139193][15779:15779] CHIP:CTL: Shutting down the commissioner
[1687332187.139201][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332187.139231][15779:15779] CHIP:CTL: Shutting down the controller
[1687332187.139240][15779:15779] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1687332187.139350][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139357][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139364][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139371][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139380][15779:15779] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687332187.139409][15779:15779] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687332187.139428][15779:15779] CHIP:FP: Shutting down FabricTable
[1687332187.139439][15779:15779] CHIP:TS: Pending Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139494][15779:15779] CHIP:TS: Previous Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139501][15779:15779] CHIP:TS: Reverted Last Known Good Time to previous value
[1687332187.139630][15779:15779] CHIP:DL: writing settings to file (/mnt/chip_counters.ini-SvHZOZ)
[1687332187.139859][15779:15779] CHIP:DL: renamed tmp file to file (/mnt/chip_counters.ini)
[1687332187.139883][15779:15779] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1687332187.139893][15779:15779] CHIP:DL: Inet Layer shutdown
[1687332187.139901][15779:15779] CHIP:DL: BLE shutdown
[1687332187.140579][15779:15779] CHIP:DL: System Layer shutdown
[1687332189.797401][15779:15779] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error

0 AHaug over 1 year ago in reply to Varun2103

Hi

Error 101, during AttestationInformation informs about unavailable PAA on the controller side, if the client use non-default DAC/PAI generated on non-default PAA in their sample (in FactoryData) then he/she needs to provider path to chip-tool where the PAA is stored.
./chip-tool pairing ble-thread <nodeid> hex:<thread_dataset> <setupcode> <discriminator> --paa-trust-store-path <path_to_paa>

https://github.com/nrfconnect/sdk-connectedhomeip/blob/master/src/credentials/attestation_verifier/DeviceAttestationVerifier.h#L35

Let me know if this solves the issue you're observing

Kind regards,
Andreas
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 Varun2103 over 1 year ago in reply to AHaug

Ok but what contains in the path to paa ?
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

Reply

0 Varun2103 over 1 year ago in reply to AHaug

Ok but what contains in the path to paa ?
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

Children

0 ChuckRui over 1 year ago in reply to Varun2103
Hi Varun，

I also encountered the same mistake as you, I would like to ask if you have solved this problem?

([1690962486.549080][5259:5262] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: Err 101. Look at AttestationVerificationResult enum to understand the errors
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel