I'm following this tutorial https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.3.0/nrf/protocols/matter/index.html - I use the nrf52840 dongle as a co-processor connected to a raspberry pi running OTBR, nrf52840 DK flashed with matter door lock sample and I downloaded chip tool (release version 2.3.0) on my laptop with Linux and i am using the mobile hotspot (as the access point as WLAN) and at the pairing stage.
These are the logs of the OTBR and Chip-tool on linux.
OTBR LOGS
I: BLE advertising is already enabled
I: BLE advertising is already enabled
I: 2913505 [DL]BLE connection established (ConnId: 0x00)
I: 2913510 [DL]Current number of connections: 1/1
I: 2913514 [DL]CHIPoBLE advertising stopped
I: 2913518 [DL]NFC Tag emulation stopped
I: 2915298 [BLE]local and remote recv window sizes = 5
I: 2915302 [BLE]selected BTP version 4
I: 2915306 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 2915388 [IN]BLE EndPoint 0x20010120 Connection Complete
I: 2915393 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 2915479 [EM]>>> [E:55208r M:73756448] (U) Msg RX from 0:89F48D19456299D4 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 2915492 [EM]<<< [E:55208r M:245742135] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 2915503 [IN](U) Sending msg 245742135 to IP address 'BLE'
I: 2915659 [EM]>>> [E:55208r M:73756449] (U) Msg RX from 0:89F48D19456299D4 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 2917601 [EM]<<< [E:55208r M:245742136] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 2917612 [IN](U) Sending msg 245742136 to IP address 'BLE'
E: 2917618 [DL]Long dispatch time: 1959 ms, for event type 16388
I: 2917684 [EM]>>> [E:55208r M:73756450] (U) Msg RX from 0:89F48D19456299D4 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 2917696 [EM]<<< [E:55208r M:245742137] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 2917707 [IN](U) Sending msg 245742137 to IP address 'BLE'
I: 2917713 [SC]SecureSession[0x200039e0]: Moving from state 'kEstablishing' --> 'kActive'
D: 2917721 [IN]SecureSession[0x200039e0]: Activated - Type:1 LSID:38191
D: 2917728 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:38191 PSID:54710!
I: 2917737 [SVR]Commissioning completed session establishment step
I: 2917744 [DIS]Updating services using commissioning mode 0
I: 2917750 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
E: 2917760 [DIS]Failed to advertise extended commissionable node: 3
D: 2917766 [DIS]Scheduling extended discovery timeout in 900s
E: 2917771 [DIS]Failed to finalize service update: 1c
I: 2917777 [SVR]Device completed Rendezvous process
I: 2917783 [EM]>>> [E:55209r M:145636178] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 2917793 [IM]Received Read request
I: 2917803 [EM]<<< [E:55209r M:216294494] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:Re
portData)
I: 2917813 [IN](S) Sending msg 216294494 on secure session with LSID: 38191
I: 2917999 [EM]>>> [E:55210r M:145636179] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:
InvokeCommandRequest)
I: 2918011 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 2918018 [EM]<<< [E:55210r M:216294495] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2918029 [IN](S) Sending msg 216294495 on secure session with LSID: 38191
I: 2918089 [EM]>>> [E:55211r M:145636180] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2918103 [EM]<<< [E:55211r M:216294496] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2918114 [IN](S) Sending msg 216294496 on secure session with LSID: 38191
I: 2918179 [EM]>>> [E:55212r M:145636181] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2918191 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 2918200 [EM]<<< [E:55212r M:216294497] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2918211 [IN](S) Sending msg 216294497 on secure session with LSID: 38191
I: 2918539 [EM]>>> [E:55213r M:145636182] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2918551 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 2918560 [EM]<<< [E:55213r M:216294498] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2918571 [IN](S) Sending msg 216294498 on secure session with LSID: 38191
I: 2918855 [EM]>>> [E:55214r M:145636183] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2918866 [ZCL]OpCreds: Received an AttestationRequest command
I: 2918903 [ZCL]OpCreds: AttestationRequest successful.
I: 2918912 [EM]<<< [E:55214r M:216294499] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2918923 [IN](S) Sending msg 216294499 on secure session with LSID: 38191
I: 2919170 [EM]>>> [E:55215r M:145636184] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2919181 [ZCL]OpCreds: Received a CSRRequest command
I: 2919376 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 2919412 [ZCL]OpCreds: CSRRequest successful.
I: 2919419 [EM]<<< [E:55215r M:216294500] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2919430 [IN](S) Sending msg 216294500 on secure session with LSID: 38191
E: 2919437 [DL]Long dispatch time: 268 ms, for event type 16388
I: 2919710 [EM]>>> [E:55216r M:145636185] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2919721 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 2919785 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 2919791 [EM]<<< [E:55216r M:216294501] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2919803 [IN](S) Sending msg 216294501 on secure session with LSID: 38191
E: 2919810 [DL]Long dispatch time: 102 ms, for event type 16388
I: 2920071 [EM]>>> [E:55217r M:145636186] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2920083 [ZCL]OpCreds: Received an AddNOC command
I: 2920090 [FP]Validating NOC chain
I: 2920208 [FP]NOC chain validation successful
I: 2920213 [FP]Added new fabric at index: 0x1
I: 2920217 [FP]Assigned compressed fabric ID: 0x0C8085763C7AE3FD, node ID: 0x0000000000000001
I: 2920225 [TS]Last Known Good Time: 2023-06-23T10:50:23
I: 2920230 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 2920237 [TS]Retaining current Last Known Good Time
I: 2920261 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 2920271 [DIS]Advertise operational node 0C8085763C7AE3FD-0000000000000001
I: 2920278 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 2920285 [EM]<<< [E:55217r M:216294502] (S) Msg TX to 1:FFFFFFFB00000000 [E3FD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2920296 [IN](S) Sending msg 216294502 on secure session with LSID: 38191
E: 2920304 [DL]Long dispatch time: 235 ms, for event type 16388
I: 2920386 [EM]>>> [E:55218r M:145636187] (S) Msg RX from 1:FFFFFFFB00000000 [E3FD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2920403 [EM]<<< [E:55218r M:216294503] (S) Msg TX to 1:FFFFFFFB00000000 [E3FD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2920414 [IN](S) Sending msg 216294503 on secure session with LSID: 38191
I: 2920564 [EM]>>> [E:55219r M:145636188] (S) Msg RX from 1:FFFFFFFB00000000 [E3FD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 2923853 [EM]<<< [E:55219r M:216294504] (S) Msg TX to 1:FFFFFFFB00000000 [E3FD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 2923864 [IN](S) Sending msg 216294504 on secure session with LSID: 38191
I: 2923871 [DIS]Advertise operational node 0C8085763C7AE3FD-0000000000000001
I: 2923878 [SVR]Operational advertising enabled
D: 2968937 [IN]Clearing BLE pending packets.
I: 2968941 [BLE]Releasing end point's BLE connection back to application.
I: 2968947 [DL]Closing BLE GATT connection (ConnId 00)
I: 2969072 [DL]BLE GAP connection terminated (reason 0x16)
I: 2969077 [DL]Current number of connections: 0/1
I: 2978018 [FS]Fail-safe timer expired
E: 2978021 [SVR]Failsafe timer expired
D: 2978025 [IN]SecureSession[0x200039e0]: MarkForEviction Type:1 LSID:38191
I: 2978031 [SC]SecureSession[0x200039e0]: Moving from state 'kActive' --> 'kPendingEviction'
D: 2978040 [IN]SecureSession[0x200039e0]: Released - Type:1 LSID:38191
E: 2978046 [SVR]Commissioning failed (attempt 1): 32
D: 2978053 [IN]SecureSession[0x200039e0]: Allocated Type:1 LSID:38192
I: 2978059 [DIS]Updating services using commissioning mode 1
I: 2978065 [DIS]Advertise operational node 0C8085763C7AE3FD-0000000000000001
E: 2978072 [DIS]Failed to advertise operational node: 3
I: 2978077 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
E: 2978087 [DIS]Failed to advertise commissionable node: 3
E: 2978093 [DIS]Failed to finalize service update: 1c
E: 2978098 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 2978103 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 2978109 [IN]Expiring all sessions for fabric 0x1!!
E: 2978114 [FP]Reverting pending fabric data for fabric 0x1
E: 2978121 [FP]Warning: metadata not found during delete of fabric 0x1
I: 2978132 [FP]Fabric (0x1) deleted.
I: 2978135 [ZCL][OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1]
I: 2978145 [ZCL]Getting lock user 1: available
I: 2978149 [ZCL]Getting lock user 2: available
I: 2978154 [ZCL]Getting lock user 3: available
I: 2978158 [ZCL]Getting lock user 4: available
I: 2978162 [ZCL]Getting lock user 5: available
I: 2978166 [ZCL]Getting lock user 6: available
I: 2978170 [ZCL]Getting lock user 7: available
I: 2978175 [ZCL]Getting lock user 8: available
I: 2978179 [ZCL]Getting lock user 9: available
I: 2978183 [ZCL]Getting lock user 10: available
I: 2978187 [ZCL]Getting lock credential 1: available
I: 2978192 [ZCL]Getting lock credential 2: available
I: 2978197 [ZCL]Getting lock credential 3: available
I: 2978201 [ZCL]Getting lock credential 4: available
I: 2978206 [ZCL]Getting lock credential 5: available
I: 2978211 [ZCL]Getting lock credential 6: available
I: 2978216 [ZCL]Getting lock credential 7: available
I: 2978220 [ZCL]Getting lock credential 8: available
I: 2978225 [ZCL]Getting lock credential 9: available
I: 2978230 [ZCL]Getting lock credential 10: available
E: 2978235 [ZCL][clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1]
I: 2978252 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 2978257 [DIS]Updating services using commissioning mode 1
I: 2978263 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
E: 2978273 [DIS]Failed to advertise commissionable node: 3
E: 2978278 [DIS]Failed to finalize service update: 1c
I: 2978303 [TS]Pending Last Known Good Time: 2023-06-23T10:50:23
I: 2978310 [TS]Previous Last Known Good Time: 2023-06-23T10:50:23
I: 2978315 [TS]Reverted Last Known Good Time to previous value
E: 2978322 [FP]Warning: metadata not found during delete of fabric 0x1
E: 2978330 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 2978336 [NP]Reverting Thread operational dataset
E: 2978347 [DL]Long dispatch time: 326 ms, for event type 32782
I: 2978353 [FS]Fail-safe cleanly disarmed
I: 2978359 [DL]CHIPoBLE advertising started
I: 2978365 [DL]NFC Tag emulation started
I: 3008362 [DL]CHIPoBLE advertising mode changed to slow
I: 3008369 [DL]CHIPoBLE advertising started
chip-tool logs
./chip-tool-debug pairing ble-thread 1 hex:0e08000000000001000035060004001fffe00708fd0c6be86c921ed10c0402a0f7f8051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f0410445f2b5ca6f2a93a55ce570a70efeecb000300000f0208111111112222222201021234 20202021 3840
[1689919009.724974][67759:67759] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1689919009.725025][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_kvs-LvazLa)
[1689919009.725089][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1689919009.725189][67759:67759] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1689919009.725216][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-Mj8EG0)
[1689919009.725269][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1689919009.725330][67759:67759] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1689919009.725358][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_config.ini-ZOEXwp)
[1689919009.725410][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1689919009.725463][67759:67759] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1689919009.725495][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-107S2a)
[1689919009.725546][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1689919009.725629][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-a030ty)
[1689919009.725753][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1689919009.725770][67759:67759] CHIP:DL: NVS set: chip-factory/unique-id = "2BE3CF2CCE1BCC4E"
[1689919009.725800][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-3ZFeAl)
[1689919009.725878][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1689919009.725892][67759:67759] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1)
[1689919009.725918][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-Cqeo4o)
[1689919009.725996][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1689919009.726009][67759:67759] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001)
[1689919009.726037][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-e5r7MU)
[1689919009.726118][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1689919009.726133][67759:67759] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1)
[1689919009.726161][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BH7oYn)
[1689919009.726226][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1689919009.726236][67759:67759] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1689919009.726267][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-mOBTeB)
[1689919009.726340][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1689919009.726353][67759:67759] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0)
[1689919009.726376][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_config.ini-5WxlIW)
[1689919009.726447][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1689919009.726460][67759:67759] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0)
[1689919009.726485][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_config.ini-8XOAqr)
[1689919009.727635][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1689919009.727683][67759:67759] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2)
[1689919009.727933][67759:67759] CHIP:DL: Got Ethernet interface: enp2s0
[1689919009.728109][67759:67759] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1689919009.728283][67759:67759] CHIP:DL: Got WiFi interface: wlp0s20f3
[1689919009.728971][67759:67759] CHIP:DL: Found the primary WiFi interface:wlp0s20f3
[1689919009.728994][67759:67759] CHIP:IN: UDP::Init bind&listen port=0
[1689919009.729034][67759:67759] CHIP:IN: UDP::Init bound to port=35346
[1689919009.729039][67759:67759] CHIP:IN: UDP::Init bind&listen port=0
[1689919009.729073][67759:67759] CHIP:IN: UDP::Init bound to port=37289
[1689919009.729077][67759:67759] CHIP:IN: BLEBase::Init - setting/overriding transport
[1689919009.729082][67759:67759] CHIP:IN: TransportMgr initialized
[1689919009.729091][67759:67759] CHIP:FP: Initializing FabricTable from persistent storage
[1689919009.729104][67759:67759] CHIP:TS: Last Known Good Time: [unknown]
[1689919009.729110][67759:67759] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-03-02T09:25:05
[1689919009.729601][67759:67759] CHIP:ZCL: Using ZAP configuration...
[1689919009.730874][67759:67759] CHIP:DL: Avahi client registered
[1689919009.731155][67759:67759] CHIP:CTL: System State Initialized...
[1689919009.731184][67759:67759] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1689919009.731200][67759:67759] CHIP:CTL: Setting attestation nonce to random value
[1689919009.731204][67759:67759] CHIP:CTL: Setting CSR nonce to random value
[1689919009.731286][67759:67761] CHIP:DL: CHIP task running
[1689919009.731321][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1689919009.731702][67759:67761] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1689919009.731715][67759:67761] CHIP:CTL: Setting attestation nonce to random value
[1689919009.731720][67759:67761] CHIP:CTL: Setting CSR nonce to random value
[1689919009.731772][67759:67761] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../src/controller/ExamplePersistentStorage.cpp:93: CHIP Error 0x000000A0: Value not found in the persisted storage
[1689919009.734359][67759:67761] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../src/controller/ExamplePersistentStorage.cpp:93: CHIP Error 0x000000A0: Value not found in the persisted storage
[1689919009.739001][67759:67761] CHIP:CTL: Generating RCAC
[1689919009.741397][67759:67761] CHIP:CTL: Generating ICAC
[1689919009.743894][67759:67761] CHIP:CTL: Generating NOC
[1689919009.746962][67759:67761] CHIP:FP: Validating NOC chain
[1689919009.755657][67759:67761] CHIP:FP: NOC chain validation successful
[1689919009.755670][67759:67761] CHIP:FP: Added new fabric at index: 0x1
[1689919009.755673][67759:67761] CHIP:FP: Assigned compressed fabric ID: 0x0C8085763C7AE3FD, node ID: 0x000000000001B669
[1689919009.755678][67759:67761] CHIP:TS: Last Known Good Time: 2023-03-02T09:25:05
[1689919009.755681][67759:67761] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1689919009.755685][67759:67761] CHIP:TS: Retaining current Last Known Good Time
[1689919009.755982][67759:67761] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1689919009.756309][67759:67761] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-02T09:25:05
[1689919009.756623][67759:67761] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 0C8085763C7AE3FD)
[1689919009.760698][67759:67761] CHIP:CTL: Setting thread operational dataset from parameters
[1689919009.760707][67759:67761] CHIP:CTL: Setting attempt thread scan from parameters
[1689919009.760710][67759:67761] CHIP:CTL: Setting attestation nonce to random value
[1689919009.760718][67759:67761] CHIP:CTL: Setting CSR nonce to random value
[1689919009.760721][67759:67761] CHIP:CTL: Setting PASE-only commissioning from parameters
[1689919009.760725][67759:67761] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1689919009.761816][67759:67760] CHIP:DL: TRACE: Bus acquired for name C-08af
[1689919009.763044][67759:67761] CHIP:DL: PlatformBlueZInit init success
[1689919009.763980][67759:67760] CHIP:BLE: BLE removing known devices.
[1689919009.764215][67759:67760] CHIP:BLE: BLE initiating scan.
[1689919009.779613][67759:67760] CHIP:BLE: Device 61:36:9E:93:E5:9D does not look like a CHIP device.
[1689919009.780657][67759:67760] CHIP:BLE: Device 64:07:F6:60:58:6D does not look like a CHIP device.
[1689919009.795738][67759:67760] CHIP:BLE: Device 64:35:30:50:CA:9D does not look like a CHIP device.
[1689919009.800661][67759:67760] CHIP:BLE: Device 3E:4D:BC:57:B3:1C does not look like a CHIP device.
[1689919009.803663][67759:67760] CHIP:BLE: New device scanned: F8:1D:AA:42:21:4F
[1689919009.803671][67759:67760] CHIP:BLE: Device discriminator match. Attempting to connect.
[1689919009.826542][67759:67760] CHIP:BLE: Scan complete notification without an active scan.
[1689919009.959243][67759:67760] CHIP:DL: ConnectDevice complete
[1689919011.187549][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187571][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187578][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187584][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187592][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187600][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187608][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187614][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187627][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187633][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187641][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187647][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187656][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187662][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187674][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187681][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187689][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187695][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187704][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0001
[1689919011.187712][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187721][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187728][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187736][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187743][67759:67760] CHIP:DL: Char1 /org/bluez/hci0/dev_F8_1D_AA_42_21_4F/service0010
[1689919011.187754][67759:67760] CHIP:DL: New BLE connection 0x7fede004a3e0, device F8:1D:AA:42:21:4F, path /org/bluez/hci0/dev_F8_1D_AA_42_21_4F
[1689919011.187804][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1689919011.187829][67759:67761] CHIP:DIS: Closing all BLE connections
[1689919011.187860][67759:67761] CHIP:IN: BleConnectionComplete: endPoint 0x55f14beb7420
[1689919011.187930][67759:67761] CHIP:IN: SecureSession[0x7fedd8013800]: Allocated Type:1 LSID:54710
[1689919011.187944][67759:67761] CHIP:SC: Assigned local session key ID 54710
[1689919011.187988][67759:67761] CHIP:EM: <<< [E:55208i M:73756448] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1689919011.188008][67759:67761] CHIP:IN: (U) Sending msg 73756448 to IP address 'BLE'
[1689919011.188020][67759:67761] CHIP:IN: Message appended to BLE send queue
[1689919011.188028][67759:67761] CHIP:SC: Sent PBKDF param request
[1689919011.712695][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919011.803523][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1689919011.803597][67759:67761] CHIP:BLE: subscribe complete, ep = 0x55f14beb7420
[1689919011.803701][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919011.803785][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919011.803815][67759:67761] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1689919011.803825][67759:67761] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1689919011.803832][67759:67761] CHIP:BLE: local and remote recv window size = 5
[1689919011.803881][67759:67761] CHIP:IN: BLE EndPoint 0x55f14beb7420 Connection Complete
[1689919011.892701][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919011.894680][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919011.894780][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919011.894866][67759:67761] CHIP:EM: >>> [E:55208i M:245742135] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1689919011.894883][67759:67761] CHIP:EM: Found matching exchange: 55208i, Delegate: 0x7fedd800c110
[1689919011.894899][67759:67761] CHIP:SC: Received PBKDF param response
[1689919011.894920][67759:67761] CHIP:SC: Peer assigned session ID 38191
[1689919011.894932][67759:67761] CHIP:SC: Found MRP parameters in the message
[1689919011.918132][67759:67761] CHIP:EM: <<< [E:55208i M:73756449] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1689919011.918156][67759:67761] CHIP:IN: (U) Sending msg 73756449 to IP address 'BLE'
[1689919011.918186][67759:67761] CHIP:SC: Sent spake2p msg1
[1689919012.117951][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.009628][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.009788][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.009867][67759:67761] CHIP:EM: >>> [E:55208i M:245742136] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1689919014.009883][67759:67761] CHIP:EM: Found matching exchange: 55208i, Delegate: 0x7fedd800c110
[1689919014.009898][67759:67761] CHIP:SC: Received spake2p msg2
[1689919014.030590][67759:67761] CHIP:EM: <<< [E:55208i M:73756450] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1689919014.030613][67759:67761] CHIP:IN: (U) Sending msg 73756450 to IP address 'BLE'
[1689919014.030656][67759:67761] CHIP:SC: Sent spake2p msg3
[1689919014.097813][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.098888][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.098949][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.099035][67759:67761] CHIP:EM: >>> [E:55208i M:245742137] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1689919014.099057][67759:67761] CHIP:EM: Found matching exchange: 55208i, Delegate: 0x7fedd800c110
[1689919014.099133][67759:67761] CHIP:SC: SecureSession[0x7fedd8013800]: Moving from state 'kEstablishing' --> 'kActive'
[1689919014.099144][67759:67761] CHIP:IN: SecureSession[0x7fedd8013800]: Activated - Type:1 LSID:54710
[1689919014.099152][67759:67761] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:54710 PSID:38191!
[1689919014.099165][67759:67761] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1689919014.099173][67759:67761] CHIP:TOO: Pairing Success
[1689919014.099180][67759:67761] CHIP:TOO: PASE establishment successful
[1689919014.099190][67759:67761] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1689919014.099201][67759:67761] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1689919014.099211][67759:67761] CHIP:CTL: Sending request for commissioning information
[1689919014.099234][67759:67761] CHIP:DMG: SendReadRequest ReadClient[0x7fedd801b770]: Sending Read Request
[1689919014.099306][67759:67761] CHIP:EM: <<< [E:55209i M:145636178] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1689919014.099320][67759:67761] CHIP:IN: (S) Sending msg 145636178 on secure session with LSID: 54710
[1689919014.099360][67759:67761] CHIP:DMG: MoveToState ReadClient[0x7fedd801b770]: Moving to [AwaitingIn]
[1689919014.187738][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.235658][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.235787][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.323762][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.323976][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.324093][67759:67761] CHIP:EM: >>> [E:55209i M:216294494] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1689919014.324117][67759:67761] CHIP:EM: Found matching exchange: 55209i, Delegate: 0x7fedd801b780
[1689919014.324207][67759:67761] CHIP:DMG: ReportDataMessage =
[1689919014.324219][67759:67761] CHIP:DMG: {
[1689919014.324232][67759:67761] CHIP:DMG: AttributeReportIBs =
[1689919014.324253][67759:67761] CHIP:DMG: [
[1689919014.324265][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.324287][67759:67761] CHIP:DMG: {
[1689919014.324300][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.324316][67759:67761] CHIP:DMG: {
[1689919014.324333][67759:67761] CHIP:DMG: DataVersion = 0x84b4cc0,
[1689919014.324348][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.324364][67759:67761] CHIP:DMG: {
[1689919014.324381][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.324397][67759:67761] CHIP:DMG: Cluster = 0x31,
[1689919014.324413][67759:67761] CHIP:DMG: Attribute = 0x0000_0003,
[1689919014.324427][67759:67761] CHIP:DMG: }
[1689919014.324444][67759:67761] CHIP:DMG:
[1689919014.324462][67759:67761] CHIP:DMG: Data = 20,
[1689919014.324476][67759:67761] CHIP:DMG: },
[1689919014.324496][67759:67761] CHIP:DMG:
[1689919014.324510][67759:67761] CHIP:DMG: },
[1689919014.324538][67759:67761] CHIP:DMG:
[1689919014.324551][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.324572][67759:67761] CHIP:DMG: {
[1689919014.324585][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.324601][67759:67761] CHIP:DMG: {
[1689919014.324616][67759:67761] CHIP:DMG: DataVersion = 0xc1349a9d,
[1689919014.324633][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.324649][67759:67761] CHIP:DMG: {
[1689919014.324664][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.324680][67759:67761] CHIP:DMG: Cluster = 0x28,
[1689919014.324696][67759:67761] CHIP:DMG: Attribute = 0x0000_0004,
[1689919014.324712][67759:67761] CHIP:DMG: }
[1689919014.324732][67759:67761] CHIP:DMG:
[1689919014.324748][67759:67761] CHIP:DMG: Data = 32774,
[1689919014.324762][67759:67761] CHIP:DMG: },
[1689919014.324781][67759:67761] CHIP:DMG:
[1689919014.324794][67759:67761] CHIP:DMG: },
[1689919014.324822][67759:67761] CHIP:DMG:
[1689919014.324834][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.324854][67759:67761] CHIP:DMG: {
[1689919014.324867][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.324882][67759:67761] CHIP:DMG: {
[1689919014.324897][67759:67761] CHIP:DMG: DataVersion = 0xc1349a9d,
[1689919014.324911][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.324927][67759:67761] CHIP:DMG: {
[1689919014.324943][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.324959][67759:67761] CHIP:DMG: Cluster = 0x28,
[1689919014.324974][67759:67761] CHIP:DMG: Attribute = 0x0000_0002,
[1689919014.324989][67759:67761] CHIP:DMG: }
[1689919014.325007][67759:67761] CHIP:DMG:
[1689919014.325024][67759:67761] CHIP:DMG: Data = 65521,
[1689919014.325038][67759:67761] CHIP:DMG: },
[1689919014.325056][67759:67761] CHIP:DMG:
[1689919014.325069][67759:67761] CHIP:DMG: },
[1689919014.325096][67759:67761] CHIP:DMG:
[1689919014.325108][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.325129][67759:67761] CHIP:DMG: {
[1689919014.325142][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.325157][67759:67761] CHIP:DMG: {
[1689919014.325173][67759:67761] CHIP:DMG: DataVersion = 0xe8279d06,
[1689919014.325186][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.325202][67759:67761] CHIP:DMG: {
[1689919014.325218][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.325234][67759:67761] CHIP:DMG: Cluster = 0x30,
[1689919014.325250][67759:67761] CHIP:DMG: Attribute = 0x0000_0003,
[1689919014.325265][67759:67761] CHIP:DMG: }
[1689919014.325283][67759:67761] CHIP:DMG:
[1689919014.325300][67759:67761] CHIP:DMG: Data = 0,
[1689919014.325315][67759:67761] CHIP:DMG: },
[1689919014.325334][67759:67761] CHIP:DMG:
[1689919014.325348][67759:67761] CHIP:DMG: },
[1689919014.325375][67759:67761] CHIP:DMG:
[1689919014.325388][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.325410][67759:67761] CHIP:DMG: {
[1689919014.325423][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.325462][67759:67761] CHIP:DMG: {
[1689919014.325477][67759:67761] CHIP:DMG: DataVersion = 0xe8279d06,
[1689919014.325490][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.325505][67759:67761] CHIP:DMG: {
[1689919014.325520][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.325534][67759:67761] CHIP:DMG: Cluster = 0x30,
[1689919014.325549][67759:67761] CHIP:DMG: Attribute = 0x0000_0002,
[1689919014.325562][67759:67761] CHIP:DMG: }
[1689919014.325578][67759:67761] CHIP:DMG:
[1689919014.325593][67759:67761] CHIP:DMG: Data = 0,
[1689919014.325605][67759:67761] CHIP:DMG: },
[1689919014.325629][67759:67761] CHIP:DMG:
[1689919014.325640][67759:67761] CHIP:DMG: },
[1689919014.325666][67759:67761] CHIP:DMG:
[1689919014.325678][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.325699][67759:67761] CHIP:DMG: {
[1689919014.325711][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.325724][67759:67761] CHIP:DMG: {
[1689919014.325738][67759:67761] CHIP:DMG: DataVersion = 0xe8279d06,
[1689919014.325751][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.325765][67759:67761] CHIP:DMG: {
[1689919014.325778][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.325793][67759:67761] CHIP:DMG: Cluster = 0x30,
[1689919014.325808][67759:67761] CHIP:DMG: Attribute = 0x0000_0001,
[1689919014.325821][67759:67761] CHIP:DMG: }
[1689919014.325837][67759:67761] CHIP:DMG:
[1689919014.325851][67759:67761] CHIP:DMG: Data =
[1689919014.325866][67759:67761] CHIP:DMG: {
[1689919014.325881][67759:67761] CHIP:DMG: 0x0 = 60,
[1689919014.325896][67759:67761] CHIP:DMG: 0x1 = 900,
[1689919014.325911][67759:67761] CHIP:DMG: },
[1689919014.325924][67759:67761] CHIP:DMG: },
[1689919014.325942][67759:67761] CHIP:DMG:
[1689919014.325954][67759:67761] CHIP:DMG: },
[1689919014.325979][67759:67761] CHIP:DMG:
[1689919014.325990][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.326008][67759:67761] CHIP:DMG: {
[1689919014.326020][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.326034][67759:67761] CHIP:DMG: {
[1689919014.326048][67759:67761] CHIP:DMG: DataVersion = 0xe8279d06,
[1689919014.326061][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.326074][67759:67761] CHIP:DMG: {
[1689919014.326095][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.326110][67759:67761] CHIP:DMG: Cluster = 0x30,
[1689919014.326124][67759:67761] CHIP:DMG: Attribute = 0x0000_0000,
[1689919014.326138][67759:67761] CHIP:DMG: }
[1689919014.326154][67759:67761] CHIP:DMG:
[1689919014.326171][67759:67761] CHIP:DMG: Data = 0,
[1689919014.326184][67759:67761] CHIP:DMG: },
[1689919014.326202][67759:67761] CHIP:DMG:
[1689919014.326213][67759:67761] CHIP:DMG: },
[1689919014.326237][67759:67761] CHIP:DMG:
[1689919014.326248][67759:67761] CHIP:DMG: AttributeReportIB =
[1689919014.326267][67759:67761] CHIP:DMG: {
[1689919014.326279][67759:67761] CHIP:DMG: AttributeDataIB =
[1689919014.326293][67759:67761] CHIP:DMG: {
[1689919014.326306][67759:67761] CHIP:DMG: DataVersion = 0x84b4cc0,
[1689919014.326320][67759:67761] CHIP:DMG: AttributePathIB =
[1689919014.326334][67759:67761] CHIP:DMG: {
[1689919014.326348][67759:67761] CHIP:DMG: Endpoint = 0x0,
[1689919014.326362][67759:67761] CHIP:DMG: Cluster = 0x31,
[1689919014.326377][67759:67761] CHIP:DMG: Attribute = 0x0000_FFFC,
[1689919014.326390][67759:67761] CHIP:DMG: }
[1689919014.326406][67759:67761] CHIP:DMG:
[1689919014.326421][67759:67761] CHIP:DMG: Data = 2,
[1689919014.326433][67759:67761] CHIP:DMG: },
[1689919014.326451][67759:67761] CHIP:DMG:
[1689919014.326463][67759:67761] CHIP:DMG: },
[1689919014.326481][67759:67761] CHIP:DMG:
[1689919014.326492][67759:67761] CHIP:DMG: ],
[1689919014.326550][67759:67761] CHIP:DMG:
[1689919014.326560][67759:67761] CHIP:DMG: SuppressResponse = true,
[1689919014.326572][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919014.326583][67759:67761] CHIP:DMG: }
[1689919014.327076][67759:67761] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1689919014.327123][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1689919014.327140][67759:67761] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1689919014.327157][67759:67761] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1689919014.327168][67759:67761] CHIP:CTL: Arming failsafe (60 seconds)
[1689919014.327211][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919014.327229][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919014.327284][67759:67761] CHIP:EM: <<< [E:55210i M:145636179] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919014.327302][67759:67761] CHIP:IN: (S) Sending msg 145636179 on secure session with LSID: 54710
[1689919014.327356][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919014.412878][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.414177][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.414258][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.414371][67759:67761] CHIP:EM: >>> [E:55210i M:216294495] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919014.414387][67759:67761] CHIP:EM: Found matching exchange: 55210i, Delegate: 0x7fede004d988
[1689919014.414400][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919014.414424][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919014.414434][67759:67761] CHIP:DMG: {
[1689919014.414446][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919014.414456][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919014.414470][67759:67761] CHIP:DMG: [
[1689919014.414477][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919014.414489][67759:67761] CHIP:DMG: {
[1689919014.414497][67759:67761] CHIP:DMG: CommandDataIB =
[1689919014.414506][67759:67761] CHIP:DMG: {
[1689919014.414514][67759:67761] CHIP:DMG: CommandPathIB =
[1689919014.414523][67759:67761] CHIP:DMG: {
[1689919014.414532][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919014.414542][67759:67761] CHIP:DMG: ClusterId = 0x30,
[1689919014.414550][67759:67761] CHIP:DMG: CommandId = 0x1,
[1689919014.414558][67759:67761] CHIP:DMG: },
[1689919014.414568][67759:67761] CHIP:DMG:
[1689919014.414576][67759:67761] CHIP:DMG: CommandFields =
[1689919014.414585][67759:67761] CHIP:DMG: {
[1689919014.414595][67759:67761] CHIP:DMG: 0x0 = 0,
[1689919014.414606][67759:67761] CHIP:DMG: 0x1 = "" (0 chars),
[1689919014.414615][67759:67761] CHIP:DMG: },
[1689919014.414623][67759:67761] CHIP:DMG: },
[1689919014.414633][67759:67761] CHIP:DMG:
[1689919014.414641][67759:67761] CHIP:DMG: },
[1689919014.414652][67759:67761] CHIP:DMG:
[1689919014.414659][67759:67761] CHIP:DMG: ],
[1689919014.414671][67759:67761] CHIP:DMG:
[1689919014.414678][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919014.414685][67759:67761] CHIP:DMG: },
[1689919014.414715][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1689919014.414731][67759:67761] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1689919014.414743][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1689919014.414751][67759:67761] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1689919014.414762][67759:67761] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1689919014.414769][67759:67761] CHIP:CTL: Setting Regulatory Config
[1689919014.414776][67759:67761] CHIP:CTL: Device does not support configurable regulatory location
[1689919014.414805][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919014.414817][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919014.414850][67759:67761] CHIP:EM: <<< [E:55211i M:145636180] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919014.414864][67759:67761] CHIP:IN: (S) Sending msg 145636180 on secure session with LSID: 54710
[1689919014.414897][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919014.414931][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919014.502937][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.504277][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.504363][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.504472][67759:67761] CHIP:EM: >>> [E:55211i M:216294496] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919014.504489][67759:67761] CHIP:EM: Found matching exchange: 55211i, Delegate: 0x7fedd8009198
[1689919014.504510][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919014.504547][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919014.504558][67759:67761] CHIP:DMG: {
[1689919014.504569][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919014.504580][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919014.504600][67759:67761] CHIP:DMG: [
[1689919014.504611][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919014.504631][67759:67761] CHIP:DMG: {
[1689919014.504643][67759:67761] CHIP:DMG: CommandDataIB =
[1689919014.504656][67759:67761] CHIP:DMG: {
[1689919014.504667][67759:67761] CHIP:DMG: CommandPathIB =
[1689919014.504681][67759:67761] CHIP:DMG: {
[1689919014.504695][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919014.504709][67759:67761] CHIP:DMG: ClusterId = 0x30,
[1689919014.504723][67759:67761] CHIP:DMG: CommandId = 0x3,
[1689919014.504735][67759:67761] CHIP:DMG: },
[1689919014.504751][67759:67761] CHIP:DMG:
[1689919014.504762][67759:67761] CHIP:DMG: CommandFields =
[1689919014.504776][67759:67761] CHIP:DMG: {
[1689919014.504790][67759:67761] CHIP:DMG: 0x0 = 0,
[1689919014.504806][67759:67761] CHIP:DMG: 0x1 = "" (0 chars),
[1689919014.504820][67759:67761] CHIP:DMG: },
[1689919014.504831][67759:67761] CHIP:DMG: },
[1689919014.504848][67759:67761] CHIP:DMG:
[1689919014.504860][67759:67761] CHIP:DMG: },
[1689919014.504877][67759:67761] CHIP:DMG:
[1689919014.504888][67759:67761] CHIP:DMG: ],
[1689919014.504905][67759:67761] CHIP:DMG:
[1689919014.504916][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919014.504926][67759:67761] CHIP:DMG: },
[1689919014.504977][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1689919014.504996][67759:67761] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1689919014.505013][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1689919014.505024][67759:67761] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1689919014.505039][67759:67761] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1689919014.505049][67759:67761] CHIP:CTL: Sending request for PAI certificate
[1689919014.505059][67759:67761] CHIP:CTL: Sending Certificate Chain request to 0x7fedd800c0c0 device
[1689919014.505096][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919014.505131][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919014.505180][67759:67761] CHIP:EM: <<< [E:55212i M:145636181] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919014.505197][67759:67761] CHIP:IN: (S) Sending msg 145636181 on secure session with LSID: 54710
[1689919014.505244][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919014.505273][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919014.592781][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919014.640808][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.640892][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.775865][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.775970][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.864106][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919014.864202][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919014.864307][67759:67761] CHIP:EM: >>> [E:55212i M:216294497] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919014.864328][67759:67761] CHIP:EM: Found matching exchange: 55212i, Delegate: 0x7fede004d988
[1689919014.864347][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919014.864375][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919014.864386][67759:67761] CHIP:DMG: {
[1689919014.864396][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919014.864405][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919014.864421][67759:67761] CHIP:DMG: [
[1689919014.864430][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919014.864442][67759:67761] CHIP:DMG: {
[1689919014.864451][67759:67761] CHIP:DMG: CommandDataIB =
[1689919014.864461][67759:67761] CHIP:DMG: {
[1689919014.864473][67759:67761] CHIP:DMG: CommandPathIB =
[1689919014.864485][67759:67761] CHIP:DMG: {
[1689919014.864496][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919014.864507][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919014.864518][67759:67761] CHIP:DMG: CommandId = 0x3,
[1689919014.864527][67759:67761] CHIP:DMG: },
[1689919014.864539][67759:67761] CHIP:DMG:
[1689919014.864549][67759:67761] CHIP:DMG: CommandFields =
[1689919014.864564][67759:67761] CHIP:DMG: {
[1689919014.864576][67759:67761] CHIP:DMG: 0x0 = [
[1689919014.864649][67759:67761] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 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, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x
[1689919014.864687][67759:67761] CHIP:DMG: ] (463 bytes)
[1689919014.864698][67759:67761] CHIP:DMG: },
[1689919014.864708][67759:67761] CHIP:DMG: },
[1689919014.864720][67759:67761] CHIP:DMG:
[1689919014.864729][67759:67761] CHIP:DMG: },
[1689919014.864745][67759:67761] CHIP:DMG:
[1689919014.864752][67759:67761] CHIP:DMG: ],
[1689919014.864765][67759:67761] CHIP:DMG:
[1689919014.864773][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919014.864780][67759:67761] CHIP:DMG: },
[1689919014.864810][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1689919014.864825][67759:67761] CHIP:CTL: Received certificate chain from the device
[1689919014.864841][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1689919014.864852][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1689919014.864865][67759:67761] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1689919014.864872][67759:67761] CHIP:CTL: Sending request for DAC certificate
[1689919014.864880][67759:67761] CHIP:CTL: Sending Certificate Chain request to 0x7fedd800c0c0 device
[1689919014.864914][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919014.864925][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919014.864963][67759:67761] CHIP:EM: <<< [E:55213i M:145636182] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919014.864978][67759:67761] CHIP:IN: (S) Sending msg 145636182 on secure session with LSID: 54710
[1689919014.865020][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919014.865056][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919014.998015][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919015.001204][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.001286][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.091287][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.091385][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.179195][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.179297][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.179404][67759:67761] CHIP:EM: >>> [E:55213i M:216294498] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919015.179425][67759:67761] CHIP:EM: Found matching exchange: 55213i, Delegate: 0x7fede004dc98
[1689919015.179456][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919015.179486][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919015.179495][67759:67761] CHIP:DMG: {
[1689919015.179506][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919015.179515][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919015.179531][67759:67761] CHIP:DMG: [
[1689919015.179540][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919015.179555][67759:67761] CHIP:DMG: {
[1689919015.179565][67759:67761] CHIP:DMG: CommandDataIB =
[1689919015.179576][67759:67761] CHIP:DMG: {
[1689919015.179586][67759:67761] CHIP:DMG: CommandPathIB =
[1689919015.179600][67759:67761] CHIP:DMG: {
[1689919015.179612][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919015.179628][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919015.179639][67759:67761] CHIP:DMG: CommandId = 0x3,
[1689919015.179649][67759:67761] CHIP:DMG: },
[1689919015.179660][67759:67761] CHIP:DMG:
[1689919015.179673][67759:67761] CHIP:DMG: CommandFields =
[1689919015.179686][67759:67761] CHIP:DMG: {
[1689919015.179697][67759:67761] CHIP:DMG: 0x0 = [
[1689919015.179768][67759:67761] CHIP:DMG: 0x30, 0x82, 0x01, 0xe7, 0x30, 0x82, 0x01, 0x8d, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x07, 0x21, 0xf6, 0x6d, 0xf5, 0x1d, 0x72, 0x58, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x36, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x36, 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, 0x5e, 0x91, 0xed, 0x92, 0x50, 0x16, 0xcc, 0x82, 0x67, 0x19, 0x7a, 0x09, 0x0b, 0x75, 0x33, 0xe5, 0x54, 0xe2, 0x5c, 0x8b, 0x09, 0x3c, 0xdd, 0xca, 0x9e, 0xaf, 0xcb, 0xa7, 0x47, 0xfe, 0xb8, 0xb5, 0xb8, 0xdc, 0x78, 0x9f, 0x0f, 0x9d, 0xb0, 0xd8, 0x
[1689919015.179807][67759:67761] CHIP:DMG: ] (491 bytes)
[1689919015.179817][67759:67761] CHIP:DMG: },
[1689919015.179827][67759:67761] CHIP:DMG: },
[1689919015.179839][67759:67761] CHIP:DMG:
[1689919015.179847][67759:67761] CHIP:DMG: },
[1689919015.179862][67759:67761] CHIP:DMG:
[1689919015.179871][67759:67761] CHIP:DMG: ],
[1689919015.179885][67759:67761] CHIP:DMG:
[1689919015.179895][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919015.179902][67759:67761] CHIP:DMG: },
[1689919015.179935][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1689919015.179953][67759:67761] CHIP:CTL: Received certificate chain from the device
[1689919015.179969][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1689919015.179982][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1689919015.179995][67759:67761] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1689919015.180003][67759:67761] CHIP:CTL: Sending Attestation Request to the device.
[1689919015.180011][67759:67761] CHIP:CTL: Sending Attestation request to 0x7fedd800c0c0 device
[1689919015.180044][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919015.180058][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919015.180098][67759:67761] CHIP:EM: <<< [E:55214i M:145636183] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919015.180114][67759:67761] CHIP:IN: (S) Sending msg 145636183 on secure session with LSID: 54710
[1689919015.180158][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919015.180175][67759:67761] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1689919015.180211][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919015.268165][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919015.315499][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.315569][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.406164][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.406256][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.495646][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.495784][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.495929][67759:67761] CHIP:EM: >>> [E:55214i M:216294499] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919015.495950][67759:67761] CHIP:EM: Found matching exchange: 55214i, Delegate: 0x7fede004df58
[1689919015.495975][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919015.496006][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919015.496016][67759:67761] CHIP:DMG: {
[1689919015.496028][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919015.496041][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919015.496069][67759:67761] CHIP:DMG: [
[1689919015.496080][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919015.496103][67759:67761] CHIP:DMG: {
[1689919015.496116][67759:67761] CHIP:DMG: CommandDataIB =
[1689919015.496132][67759:67761] CHIP:DMG: {
[1689919015.496146][67759:67761] CHIP:DMG: CommandPathIB =
[1689919015.496161][67759:67761] CHIP:DMG: {
[1689919015.496177][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919015.496194][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919015.496205][67759:67761] CHIP:DMG: CommandId = 0x1,
[1689919015.496215][67759:67761] CHIP:DMG: },
[1689919015.496228][67759:67761] CHIP:DMG:
[1689919015.496238][67759:67761] CHIP:DMG: CommandFields =
[1689919015.496249][67759:67761] CHIP:DMG: {
[1689919015.496263][67759:67761] CHIP:DMG: 0x0 = [
[1689919015.496337][67759:67761] CHIP:DMG: 0x15, 0x31, 0x01, 0x1b, 0x02, 0x30, 0x82, 0x02, 0x17, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x08, 0x30, 0x82, 0x02, 0x04, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x
[1689919015.496376][67759:67761] CHIP:DMG: ] (583 bytes)
[1689919015.496386][67759:67761] CHIP:DMG: 0x1 = [
[1689919015.496408][67759:67761] CHIP:DMG: 0x0b, 0x18, 0x8f, 0xe3, 0xb4, 0xca, 0x66, 0x08, 0xda, 0x86, 0xbb, 0x3f, 0xa6, 0xb7, 0x83, 0x70, 0xcf, 0x9f, 0xa5, 0x44, 0xce, 0xdf, 0x93, 0x1e, 0xe0, 0xc7, 0x87, 0x79, 0x32, 0x5c, 0x05, 0x29, 0xe7, 0x9f, 0x52, 0x57, 0x6e, 0x22, 0x58, 0x25, 0x7c, 0x09, 0xbb, 0x13, 0x83, 0x4a, 0xc4, 0xc8, 0x74, 0xbe, 0x4c, 0x21, 0xad, 0x2b, 0xf2, 0x9d, 0xce, 0x22, 0xf5, 0x8f, 0x47, 0x69, 0x22, 0xf3,
[1689919015.496426][67759:67761] CHIP:DMG: ] (64 bytes)
[1689919015.496437][67759:67761] CHIP:DMG: },
[1689919015.496447][67759:67761] CHIP:DMG: },
[1689919015.496460][67759:67761] CHIP:DMG:
[1689919015.496469][67759:67761] CHIP:DMG: },
[1689919015.496483][67759:67761] CHIP:DMG:
[1689919015.496491][67759:67761] CHIP:DMG: ],
[1689919015.496505][67759:67761] CHIP:DMG:
[1689919015.496514][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919015.496522][67759:67761] CHIP:DMG: },
[1689919015.496557][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1689919015.496575][67759:67761] CHIP:CTL: Received Attestation Information from the device
[1689919015.496591][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1689919015.496603][67759:67761] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583
[1689919015.496618][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1689919015.496632][67759:67761] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1689919015.496640][67759:67761] CHIP:CTL: Verifying attestation
[1689919015.503727][67759:67761] CHIP:CR: mbedTLS error: ERROR - Generic error
[1689919015.516081][67759:67761] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1689919015.516087][67759:67761] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1689919015.516090][67759:67761] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1689919015.516094][67759:67761] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1689919015.516097][67759:67761] CHIP:CTL: Sending CSR request to 0x7fedd800c0c0 device
[1689919015.516113][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919015.516117][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919015.516134][67759:67761] CHIP:EM: <<< [E:55215i M:145636184] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919015.516139][67759:67761] CHIP:IN: (S) Sending msg 145636184 on secure session with LSID: 54710
[1689919015.516154][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919015.516158][67759:67761] CHIP:CTL: Sent CSR request, waiting for the CSR
[1689919015.516165][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919015.584386][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919015.855769][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.855865][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.944794][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919015.944879][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919015.944972][67759:67761] CHIP:EM: >>> [E:55215i M:216294500] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919015.944992][67759:67761] CHIP:EM: Found matching exchange: 55215i, Delegate: 0x7fede004e0b8
[1689919015.945018][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919015.945048][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919015.945059][67759:67761] CHIP:DMG: {
[1689919015.945072][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919015.945084][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919015.945104][67759:67761] CHIP:DMG: [
[1689919015.945112][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919015.945130][67759:67761] CHIP:DMG: {
[1689919015.945138][67759:67761] CHIP:DMG: CommandDataIB =
[1689919015.945147][67759:67761] CHIP:DMG: {
[1689919015.945156][67759:67761] CHIP:DMG: CommandPathIB =
[1689919015.945166][67759:67761] CHIP:DMG: {
[1689919015.945177][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919015.945188][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919015.945198][67759:67761] CHIP:DMG: CommandId = 0x5,
[1689919015.945207][67759:67761] CHIP:DMG: },
[1689919015.945260][67759:67761] CHIP:DMG:
[1689919015.945268][67759:67761] CHIP:DMG: CommandFields =
[1689919015.945278][67759:67761] CHIP:DMG: {
[1689919015.945289][67759:67761] CHIP:DMG: 0x0 = [
[1689919015.945343][67759:67761] CHIP:DMG: 0x15, 0x30, 0x01, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 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, 0x4b, 0xff, 0xed, 0x83, 0x5b, 0x12, 0x09, 0xc0, 0x94, 0x07, 0x83, 0x4c, 0x6f, 0x01, 0xfd, 0x68, 0x74, 0x91, 0x94, 0x6a, 0x12, 0xd2, 0x88, 0xbb, 0xeb, 0x53, 0x94, 0xe6, 0x2c, 0x86, 0x1d, 0xd5, 0xdd, 0x3f, 0xf1, 0xcb, 0x13, 0xc8, 0xa4, 0x5f, 0x5b, 0x80, 0x13, 0xe8, 0x71, 0x03, 0x3b, 0xf8, 0xfa, 0x33, 0x40, 0xdf, 0x9c, 0x73, 0xbd, 0x75, 0xc8, 0x36, 0xc4, 0x62, 0xca, 0xbe, 0x82, 0x5a, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x48, 0x00, 0x30, 0x45, 0x02, 0x20, 0x47, 0xf9, 0x24, 0xb9, 0x36, 0x53, 0xf0, 0xab, 0xb9, 0x5e, 0xa9, 0x8f, 0x45, 0x41, 0x7c, 0x2c, 0x16, 0x02, 0x38, 0x89, 0x4b, 0x91, 0xe3, 0xf9, 0x6b, 0x1b, 0xa7, 0xd9, 0x17, 0x0c, 0x68, 0xc5, 0x02, 0x21, 0x00, 0xa4, 0xfe, 0x8d, 0xbf, 0xbe, 0x65, 0x0a, 0xd0, 0xbd, 0xf1, 0xf3, 0xcc, 0x5f, 0xad, 0xa3, 0x4a, 0x8c, 0x84, 0x28, 0x53, 0xee, 0xe5, 0x22, 0x77, 0x64, 0xb5, 0xe9, 0x00, 0x4e, 0x0c, 0x92, 0xba, 0x30, 0x02, 0x20, 0xd3, 0x6a, 0x11, 0x04, 0x86, 0x4d, 0xe8, 0xaf, 0xf3, 0xb9, 0x17, 0x43, 0xc6, 0x40, 0x0b, 0x62, 0xe8, 0xac, 0x62, 0x1a, 0x05, 0x99, 0x16, 0x8b, 0x05, 0x95, 0x41, 0x34, 0x40, 0x16, 0x4d, 0xae, 0x18,
[1689919015.945374][67759:67761] CHIP:DMG: ] (245 bytes)
[1689919015.945386][67759:67761] CHIP:DMG: 0x1 = [
[1689919015.945413][67759:67761] CHIP:DMG: 0xb7, 0x6f, 0x1f, 0x2c, 0x4c, 0xf3, 0xc0, 0xd9, 0x40, 0x32, 0x0f, 0x64, 0xd9, 0x62, 0x87, 0xac, 0x2c, 0x7d, 0x74, 0x61, 0x4a, 0x39, 0x4f, 0x21, 0x3a, 0x72, 0x57, 0xe3, 0x31, 0xf6, 0xa3, 0xdd, 0x94, 0xbd, 0xcc, 0x04, 0xfa, 0x25, 0xea, 0x46, 0xd8, 0x32, 0xa3, 0xe4, 0xb6, 0x5c, 0x0f, 0xac, 0xa4, 0x0f, 0x4c, 0x01, 0x8c, 0xaa, 0x80, 0xad, 0x78, 0x35, 0x90, 0xe5, 0xcc, 0xe0, 0x00, 0xf1,
[1689919015.945429][67759:67761] CHIP:DMG: ] (64 bytes)
[1689919015.945463][67759:67761] CHIP:DMG: },
[1689919015.945472][67759:67761] CHIP:DMG: },
[1689919015.945484][67759:67761] CHIP:DMG:
[1689919015.945493][67759:67761] CHIP:DMG: },
[1689919015.945509][67759:67761] CHIP:DMG:
[1689919015.945516][67759:67761] CHIP:DMG: ],
[1689919015.945529][67759:67761] CHIP:DMG:
[1689919015.945537][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919015.945545][67759:67761] CHIP:DMG: },
[1689919015.945578][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1689919015.945599][67759:67761] CHIP:CTL: Received certificate signing request from the device
[1689919015.945618][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1689919015.945631][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1689919015.945645][67759:67761] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1689919015.960953][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1689919015.960962][67759:67761] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1689919015.960968][67759:67761] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1689919015.960972][67759:67761] CHIP:CTL: Getting certificate chain for the device from the issuer
[1689919015.960990][67759:67761] CHIP:CTL: Verifying Certificate Signing Request
[1689919015.967236][67759:67761] CHIP:CTL: Generating NOC
[1689919015.969238][67759:67761] CHIP:CTL: Providing certificate chain to the commissioner
[1689919015.969241][67759:67761] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1689919015.969244][67759:67761] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1689919015.969266][67759:67761] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1689919015.969268][67759:67761] CHIP:CTL: Sending root certificate to the device
[1689919015.969280][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919015.969283][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919015.969298][67759:67761] CHIP:EM: <<< [E:55216i M:145636185] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919015.969303][67759:67761] CHIP:IN: (S) Sending msg 145636185 on secure session with LSID: 54710
[1689919015.969316][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919015.969318][67759:67761] CHIP:CTL: Sent root certificate to the device
[1689919015.969364][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919016.033195][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.124101][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.214104][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919016.214198][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919016.214318][67759:67761] CHIP:EM: >>> [E:55216i M:216294501] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919016.214336][67759:67761] CHIP:EM: Found matching exchange: 55216i, Delegate: 0x7fede004df58
[1689919016.214350][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919016.214374][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919016.214385][67759:67761] CHIP:DMG: {
[1689919016.214397][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919016.214407][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919016.214424][67759:67761] CHIP:DMG: [
[1689919016.214433][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919016.214452][67759:67761] CHIP:DMG: {
[1689919016.214464][67759:67761] CHIP:DMG: CommandStatusIB =
[1689919016.214478][67759:67761] CHIP:DMG: {
[1689919016.214489][67759:67761] CHIP:DMG: CommandPathIB =
[1689919016.214503][67759:67761] CHIP:DMG: {
[1689919016.214517][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919016.214530][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919016.214543][67759:67761] CHIP:DMG: CommandId = 0xb,
[1689919016.214555][67759:67761] CHIP:DMG: },
[1689919016.214580][67759:67761] CHIP:DMG:
[1689919016.214592][67759:67761] CHIP:DMG: StatusIB =
[1689919016.214608][67759:67761] CHIP:DMG: {
[1689919016.214621][67759:67761] CHIP:DMG: status = 0x00 (SUCCESS),
[1689919016.214633][67759:67761] CHIP:DMG: },
[1689919016.214647][67759:67761] CHIP:DMG:
[1689919016.214664][67759:67761] CHIP:DMG: },
[1689919016.214681][67759:67761] CHIP:DMG:
[1689919016.214692][67759:67761] CHIP:DMG: },
[1689919016.214708][67759:67761] CHIP:DMG:
[1689919016.214718][67759:67761] CHIP:DMG: ],
[1689919016.214735][67759:67761] CHIP:DMG:
[1689919016.214747][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919016.214757][67759:67761] CHIP:DMG: },
[1689919016.214802][67759:67761] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1689919016.214816][67759:67761] CHIP:CTL: Device confirmed that it has received the root certificate
[1689919016.214833][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1689919016.214845][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1689919016.214861][67759:67761] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1689919016.214905][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919016.214925][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919016.214979][67759:67761] CHIP:EM: <<< [E:55217i M:145636186] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919016.214998][67759:67761] CHIP:IN: (S) Sending msg 145636186 on secure session with LSID: 54710
[1689919016.215048][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919016.215060][67759:67761] CHIP:CTL: Sent operational certificate to the device
[1689919016.215097][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919016.303036][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.392995][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.482870][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.708962][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919016.709074][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919016.709173][67759:67761] CHIP:EM: >>> [E:55217i M:216294502] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919016.709189][67759:67761] CHIP:EM: Found matching exchange: 55217i, Delegate: 0x7fede004e0b8
[1689919016.709204][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919016.709228][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919016.709236][67759:67761] CHIP:DMG: {
[1689919016.709244][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919016.709252][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919016.709264][67759:67761] CHIP:DMG: [
[1689919016.709271][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919016.709283][67759:67761] CHIP:DMG: {
[1689919016.709291][67759:67761] CHIP:DMG: CommandDataIB =
[1689919016.709299][67759:67761] CHIP:DMG: {
[1689919016.709309][67759:67761] CHIP:DMG: CommandPathIB =
[1689919016.709318][67759:67761] CHIP:DMG: {
[1689919016.709327][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919016.709338][67759:67761] CHIP:DMG: ClusterId = 0x3e,
[1689919016.709347][67759:67761] CHIP:DMG: CommandId = 0x8,
[1689919016.709356][67759:67761] CHIP:DMG: },
[1689919016.709365][67759:67761] CHIP:DMG:
[1689919016.709373][67759:67761] CHIP:DMG: CommandFields =
[1689919016.709382][67759:67761] CHIP:DMG: {
[1689919016.709392][67759:67761] CHIP:DMG: 0x0 = 0,
[1689919016.709402][67759:67761] CHIP:DMG: 0x1 = 1,
[1689919016.709411][67759:67761] CHIP:DMG: },
[1689919016.709419][67759:67761] CHIP:DMG: },
[1689919016.709430][67759:67761] CHIP:DMG:
[1689919016.709462][67759:67761] CHIP:DMG: },
[1689919016.709472][67759:67761] CHIP:DMG:
[1689919016.709479][67759:67761] CHIP:DMG: ],
[1689919016.709491][67759:67761] CHIP:DMG:
[1689919016.709498][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919016.709505][67759:67761] CHIP:DMG: },
[1689919016.709534][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1689919016.709551][67759:67761] CHIP:CTL: Device returned status 0 on receiving the NOC
[1689919016.709559][67759:67761] CHIP:CTL: Operational credentials provisioned on device 0x7fedd800c0c0
[1689919016.709566][67759:67761] CHIP:TOO: Secure Pairing Success
[1689919016.709573][67759:67761] CHIP:TOO: CASE establishment successful
[1689919016.709585][67759:67761] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1689919016.709594][67759:67761] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1689919016.709602][67759:67761] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
[1689919016.709612][67759:67761] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup'
[1689919016.709644][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919016.709655][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919016.709691][67759:67761] CHIP:EM: <<< [E:55218i M:145636187] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919016.709705][67759:67761] CHIP:IN: (S) Sending msg 145636187 on secure session with LSID: 54710
[1689919016.709741][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919016.709765][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919016.797939][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919016.843984][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919016.844090][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919016.844190][67759:67761] CHIP:EM: >>> [E:55218i M:216294503] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919016.844207][67759:67761] CHIP:EM: Found matching exchange: 55218i, Delegate: 0x7fede004df58
[1689919016.844227][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919016.844254][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919016.844264][67759:67761] CHIP:DMG: {
[1689919016.844276][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919016.844287][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919016.844306][67759:67761] CHIP:DMG: [
[1689919016.844315][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919016.844334][67759:67761] CHIP:DMG: {
[1689919016.844343][67759:67761] CHIP:DMG: CommandDataIB =
[1689919016.844357][67759:67761] CHIP:DMG: {
[1689919016.844369][67759:67761] CHIP:DMG: CommandPathIB =
[1689919016.844383][67759:67761] CHIP:DMG: {
[1689919016.844398][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919016.844411][67759:67761] CHIP:DMG: ClusterId = 0x31,
[1689919016.844425][67759:67761] CHIP:DMG: CommandId = 0x5,
[1689919016.844436][67759:67761] CHIP:DMG: },
[1689919016.844452][67759:67761] CHIP:DMG:
[1689919016.844463][67759:67761] CHIP:DMG: CommandFields =
[1689919016.844476][67759:67761] CHIP:DMG: {
[1689919016.844490][67759:67761] CHIP:DMG: 0x0 = 0,
[1689919016.844503][67759:67761] CHIP:DMG: 0x2 = 0,
[1689919016.844517][67759:67761] CHIP:DMG: },
[1689919016.844527][67759:67761] CHIP:DMG: },
[1689919016.844542][67759:67761] CHIP:DMG:
[1689919016.844552][67759:67761] CHIP:DMG: },
[1689919016.844565][67759:67761] CHIP:DMG:
[1689919016.844572][67759:67761] CHIP:DMG: ],
[1689919016.844583][67759:67761] CHIP:DMG:
[1689919016.844593][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919016.844604][67759:67761] CHIP:DMG: },
[1689919016.844640][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1689919016.844674][67759:67761] CHIP:CTL: Received NetworkConfig response, networkingStatus=0
[1689919016.844689][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup'
[1689919016.844701][67759:67761] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable'
[1689919016.844716][67759:67761] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable'
[1689919016.844753][67759:67761] CHIP:DMG: ICR moving to [AddingComm]
[1689919016.844768][67759:67761] CHIP:DMG: ICR moving to [AddedComma]
[1689919016.844807][67759:67761] CHIP:EM: <<< [E:55219i M:145636188] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1689919016.844824][67759:67761] CHIP:IN: (S) Sending msg 145636188 on secure session with LSID: 54710
[1689919016.844866][67759:67761] CHIP:DMG: ICR moving to [CommandSen]
[1689919016.844890][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919016.978173][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919019.453944][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919019.454047][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919020.264361][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919020.264446][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919020.264528][67759:67761] CHIP:EM: >>> [E:55219i M:216294504] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1689919020.264544][67759:67761] CHIP:EM: Found matching exchange: 55219i, Delegate: 0x7fede004e0b8
[1689919020.264561][67759:67761] CHIP:DMG: ICR moving to [ResponseRe]
[1689919020.264586][67759:67761] CHIP:DMG: InvokeResponseMessage =
[1689919020.264594][67759:67761] CHIP:DMG: {
[1689919020.264603][67759:67761] CHIP:DMG: suppressResponse = false,
[1689919020.264610][67759:67761] CHIP:DMG: InvokeResponseIBs =
[1689919020.264623][67759:67761] CHIP:DMG: [
[1689919020.264630][67759:67761] CHIP:DMG: InvokeResponseIB =
[1689919020.264643][67759:67761] CHIP:DMG: {
[1689919020.264650][67759:67761] CHIP:DMG: CommandDataIB =
[1689919020.264660][67759:67761] CHIP:DMG: {
[1689919020.264668][67759:67761] CHIP:DMG: CommandPathIB =
[1689919020.264677][67759:67761] CHIP:DMG: {
[1689919020.264688][67759:67761] CHIP:DMG: EndpointId = 0x0,
[1689919020.264700][67759:67761] CHIP:DMG: ClusterId = 0x31,
[1689919020.264709][67759:67761] CHIP:DMG: CommandId = 0x7,
[1689919020.264717][67759:67761] CHIP:DMG: },
[1689919020.264730][67759:67761] CHIP:DMG:
[1689919020.264738][67759:67761] CHIP:DMG: CommandFields =
[1689919020.264748][67759:67761] CHIP:DMG: {
[1689919020.264757][67759:67761] CHIP:DMG: 0x0 = 0,
[1689919020.264767][67759:67761] CHIP:DMG: 0x2 = NULL
[1689919020.264776][67759:67761] CHIP:DMG: },
[1689919020.264784][67759:67761] CHIP:DMG: },
[1689919020.264795][67759:67761] CHIP:DMG:
[1689919020.264803][67759:67761] CHIP:DMG: },
[1689919020.264814][67759:67761] CHIP:DMG:
[1689919020.264820][67759:67761] CHIP:DMG: ],
[1689919020.264833][67759:67761] CHIP:DMG:
[1689919020.264841][67759:67761] CHIP:DMG: InteractionModelRevision = 1
[1689919020.264848][67759:67761] CHIP:DMG: },
[1689919020.264878][67759:67761] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1689919020.264895][67759:67761] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1689919020.264908][67759:67761] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
[1689919020.264917][67759:67761] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
[1689919020.264928][67759:67761] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1689919020.264936][67759:67761] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1689919020.264945][67759:67761] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1689919020.264961][67759:67761] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1689919020.264973][67759:67761] CHIP:DIS: Resolving 0C8085763C7AE3FD:0000000000000001 ...
[1689919020.265759][67759:67761] CHIP:DMG: ICR moving to [AwaitingDe]
[1689919020.465182][67759:67761] CHIP:DIS: Checking node lookup status after 201 ms
[1689919022.063424][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919024.540082][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919024.540164][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919025.268872][67759:67761] CHIP:DL: Re-trying resolve
[1689919027.103543][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919029.578157][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919029.578211][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919030.273690][67759:67761] CHIP:DL: Re-trying resolve
[1689919032.188691][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919034.619545][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919034.619687][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919035.274764][67759:67761] CHIP:DL: Re-trying resolve
[1689919037.183763][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919039.659563][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919039.659714][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919040.278231][67759:67761] CHIP:DL: Avahi resolve failed
[1689919042.223979][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919044.789740][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919044.789826][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919047.354135][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919049.829593][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919049.829683][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919052.394512][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919054.870244][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919054.870354][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919057.434502][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919059.910347][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919059.910502][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919062.519814][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1689919064.950522][67759:67760] CHIP:DL: Indication received, conn = 0x7fede004a3e0
[1689919064.950637][67759:67761] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1689919065.265188][67759:67761] CHIP:DIS: Checking node lookup status after 45001 ms
[1689919065.265246][67759:67761] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
[1689919065.265259][67759:67761] CHIP:CTL: Device connection failed. Error ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
[1689919065.265278][67759:67761] CHIP:CTL: Error on commissioning step 'FindOperational': '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout'
[1689919065.265286][67759:67761] CHIP:CTL: Failed to perform commissioning step 18
[1689919065.265294][67759:67761] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1689919065.265310][67759:67761] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout'
[1689919065.265322][67759:67761] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1689919065.265345][67759:67761] CHIP:TOO: Device commissioning Failure: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
[1689919065.265773][67759:67759] CHIP:CTL: Shutting down the commissioner
[1689919065.265799][67759:67759] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1689919065.265809][67759:67759] CHIP:DIS: Closing all BLE connections
[1689919065.265818][67759:67759] CHIP:IN: Clearing BLE pending packets.
[1689919065.265858][67759:67759] CHIP:BLE: Auto-closing end point's BLE connection.
[1689919065.265866][67759:67759] CHIP:DL: Closing BLE GATT connection (con 0x7fede004a3e0)
[1689919065.265892][67759:67759] CHIP:IN: SecureSession[0x7fedd8013800]: MarkForEviction Type:1 LSID:54710
[1689919065.265904][67759:67759] CHIP:SC: SecureSession[0x7fedd8013800]: Moving from state 'kActive' --> 'kPendingEviction'
[1689919065.265929][67759:67759] CHIP:IN: SecureSession[0x7fedd8013800]: Released - Type:1 LSID:54710
[1689919065.265947][67759:67759] CHIP:CTL: Shutting down the controller
[1689919065.265959][67759:67759] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1689919065.265971][67759:67759] CHIP:FP: Forgetting fabric 0x1
[1689919065.265992][67759:67759] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1689919065.266046][67759:67760] CHIP:DL: BluezDisconnect peer=F8:1D:AA:42:21:4F
[1689919065.266106][67759:67759] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1689919065.266116][67759:67759] CHIP:TS: Reverted Last Known Good Time to previous value
[1689919065.266129][67759:67759] CHIP:CTL: Shutting down the commissioner
[1689919065.266143][67759:67759] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1689919065.266153][67759:67759] CHIP:CTL: Shutting down the controller
[1689919065.266164][67759:67759] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1689919065.267830][67759:67759] CHIP:DMG: IM WH moving to [Uninitialized]
[1689919065.267859][67759:67759] CHIP:DMG: IM WH moving to [Uninitialized]
[1689919065.267876][67759:67759] CHIP:DMG: IM WH moving to [Uninitialized]
[1689919065.267890][67759:67759] CHIP:DMG: IM WH moving to [Uninitialized]
[1689919065.267906][67759:67759] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1689919065.267953][67759:67759] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1689919065.267985][67759:67759] CHIP:FP: Shutting down FabricTable
[1689919065.268006][67759:67759] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1689919065.268093][67759:67759] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1689919065.268104][67759:67759] CHIP:TS: Reverted Last Known Good Time to previous value
[1689919065.268306][67759:67759] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-TsgtF0)
[1689919065.268735][67759:67759] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1689919065.268801][67759:67759] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1689919065.268844][67759:67759] CHIP:DL: Inet Layer shutdown
[1689919065.268864][67759:67759] CHIP:DL: BLE shutdown
[1689919065.269528][67759:67759] CHIP:DL: System Layer shutdown
[1689919065.446392][67759:67759] CHIP:TOO: Run command failure: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
And the state of the otbr is leader while pairing.
Can anybody help me figure it out? Thank you.
