Error on commissioning step 'FindOperational' while pairing matter sample over ble-thread

[filipmrazek]

Hi,

I'm following this tutorial https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.0.0/nrf/ug_matter.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.0.0) on my laptop with Linux. I want to connect the door lock sample to OTBR as described here. Unfortunately, step 6 causes the problem. When I execute this command:

./chip-tool-release pairing ble-thread 1000 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd05128ef262a22b051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840

I get the following error:

 

CHIP:DIS: Operational discovery failed for 0x00000000000003E8: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout

and I have no idea what should be wrong. (Does it mean there is something wrong with OTBR? But if I execute `service otbr-agent status` on raspberry pi I get otbr-agent is running and for command  `ot-ctl state` the response is Leader.  

Can anybody help me figure it out? Thank you.

If you want to see full output from the command, you can find it here.

[Charlie]

Hi Filipmarzek,

Did you press button 4 to make the device discoverable over Bluetooth LE?

Best regards,

Charlie

[filipmrazek]

Hi,

thank you for your answer.

Yes, I pressed button 4 before executing the command. I also tried to execute the command without pressing button 4 and the command outputs lines something like: "device {address} does not seem to be matter device".

I also looked at the terminal from the development kit and it seems it's doing something. I don't have the development kit with me right now, but I can send you the output from the uart terminal in few hours. 

[filipmrazek]

Here is the promised output from the chip-tool, the device and the otbr.

output from the chip-tool:

sudo ./chip-tool pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd9c435a1fd9a8e1051000112233445566778899aabbccddeeff030f4f70656e54687265616444656d6f32010212340410f9da1828a0e54e6b91178123dde5fa0e0c0402a0f7f8 20202021 3840
[1662402540.573237][22841:22841] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1662402540.573439][22841:22841] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1662402540.573485][22841:22841] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1662402540.573513][22841:22841] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1662402540.573652][22841:22841] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-PdHLji)
[1662402540.573850][22841:22841] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1662402540.573891][22841:22841] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1662402540.574507][22841:22841] CHIP:DL: Got Ethernet interface: enp9s0
[1662402540.575402][22841:22841] CHIP:DL: Found the primary Ethernet interface:enp9s0
[1662402540.575943][22841:22841] CHIP:DL: Got WiFi interface: wlp8s0
[1662402540.577536][22841:22841] CHIP:DL: Found the primary WiFi interface:wlp8s0
[1662402540.577566][22841:22841] CHIP:IN: UDP::Init bind&listen port=0
[1662402540.577595][22841:22841] CHIP:IN: UDP::Init bound to port=40632
[1662402540.577602][22841:22841] CHIP:IN: UDP::Init bind&listen port=0
[1662402540.577626][22841:22841] CHIP:IN: UDP::Init bound to port=39970
[1662402540.577633][22841:22841] CHIP:IN: BLEBase::Init - setting/overriding transport
[1662402540.577639][22841:22841] CHIP:IN: TransportMgr initialized
[1662402540.577650][22841:22841] CHIP:FP: Initializing FabricTable from persistent storage
[1662402540.577711][22841:22841] CHIP:TS: Last Known Good Time: 2022-09-03T19:45:02
[1662402540.577877][22841:22841] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE422C74F326417E2, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1662402540.578500][22841:22841] CHIP:ZCL: Using ZAP configuration...
[1662402540.579547][22841:22841] CHIP:DL: MDNS failed to join multicast group on enp9s0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:758: Inet Error 0x00000110: Address not found
[1662402540.581112][22841:22841] CHIP:CTL: System State Initialized...
[1662402540.581193][22841:22841] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662402540.581217][22841:22841] CHIP:CTL: Setting attestation nonce to random value
[1662402540.581240][22841:22841] CHIP:CTL: Setting CSR nonce to random value
[1662402540.581267][22841:22841] CHIP:IN: UDP::Init bind&listen port=5550
[1662402540.581301][22841:22841] CHIP:IN: UDP::Init bound to port=5550
[1662402540.581315][22841:22841] CHIP:IN: UDP::Init bind&listen port=5550
[1662402540.581343][22841:22841] CHIP:IN: UDP::Init bound to port=5550
[1662402540.581355][22841:22841] CHIP:IN: TransportMgr initialized
[1662402540.581480][22841:22846] CHIP:DL: CHIP task running
[1662402540.581555][22841:22846] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662402540.581576][22841:22846] CHIP:CTL: Setting attestation nonce to random value
[1662402540.581604][22841:22846] CHIP:CTL: Setting CSR nonce to random value
[1662402540.583150][22841:22846] CHIP:CTL: Generating NOC
[1662402540.583522][22841:22846] CHIP:FP: Validating NOC chain
[1662402540.584038][22841:22846] CHIP:FP: NOC chain validation successful
[1662402540.584096][22841:22846] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1662402540.584107][22841:22846] CHIP:TS: Last Known Good Time: 2022-09-03T19:45:02
[1662402540.584114][22841:22846] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1662402540.584121][22841:22846] CHIP:TS: Retaining current Last Known Good Time
[1662402540.584673][22841:22846] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1662402540.585168][22841:22846] CHIP:TS: Committing Last Known Good Time to storage: 2022-09-03T19:45:02
[1662402540.585599][22841:22846] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1662402540.585615][22841:22846] CHIP:IN: UDP::Init bind&listen port=5550
[1662402540.585665][22841:22846] CHIP:IN: UDP::Init bound to port=5550
[1662402540.585672][22841:22846] CHIP:IN: UDP::Init bind&listen port=5550
[1662402540.585695][22841:22846] CHIP:IN: UDP::Init bound to port=5550
[1662402540.585701][22841:22846] CHIP:IN: TransportMgr initialized
[1662402540.588163][22841:22846] CHIP:IN: SecureSession[0x7fbaa8020f00]: Allocated Type:1 LSID:52546
[1662402540.588180][22841:22846] CHIP:SC: Assigned local session key ID 52546
[1662402540.588205][22841:22846] CHIP:SC: Including MRP parameters in PBKDF param request
[1662402540.588228][22841:22846] CHIP:IN: Prepared unauthenticated message 0x7fbaafffe3a0 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 53197i with MessageCounter:76660738.
[1662402540.588242][22841:22846] CHIP:IN: Sending unauthenticated msg 0x7fbaafffe3a0 with MessageCounter:76660738 to 0x0000000000000000 at monotonic time: 000000000090226C msec
[1662402540.588253][22841:22846] CHIP:IN: Message appended to BLE send queue
[1662402540.588261][22841:22846] CHIP:SC: Sent PBKDF param request
[1662402540.588271][22841:22846] CHIP:CTL: Setting thread operational dataset from parameters
[1662402540.588278][22841:22846] CHIP:CTL: Setting attempt thread scan from parameters
[1662402540.588285][22841:22846] CHIP:CTL: Setting attestation nonce to random value
[1662402540.588297][22841:22846] CHIP:CTL: Setting CSR nonce to random value
[1662402540.588308][22841:22846] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1662402540.588427][22841:22847] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1662402540.588883][22841:22844] CHIP:DL: TRACE: Bus acquired for name C-5939
[1662402540.602786][22841:22846] CHIP:DL: PlatformBlueZInit init success
[1662402540.612001][22841:22844] CHIP:BLE: BLE removing known devices.
[1662402540.623014][22841:22844] CHIP:BLE: BLE initiating scan.
[1662402540.751672][22841:22846] CHIP:DL: Long dispatch time: 164 ms, for event type 2
[1662402540.770868][22841:22844] CHIP:BLE: New device scanned: C2:1D:EE:AB:64:AB
[1662402540.770891][22841:22844] CHIP:BLE: Device discriminator match. Attempting to connect.
[1662402540.779668][22841:22844] CHIP:BLE: Scan complete notification without an active scan.
[1662402540.884706][22841:22844] CHIP:DL: ConnectDevice complete
[1662402541.903312][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903361][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903389][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903412][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903437][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903459][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903487][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service003f
[1662402541.903511][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903535][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service003f
[1662402541.903557][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903580][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service003f
[1662402541.903602][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903629][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903650][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903674][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903695][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903718][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903739][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903764][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903785][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903809][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903831][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903854][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.903875][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903910][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.903932][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.903958][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.903980][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904005][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904026][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904055][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904077][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904101][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904122][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904147][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904168][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904197][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904218][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904244][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904265][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904288][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904309][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904344][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904366][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904393][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904415][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904444][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service0008
[1662402541.904466][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904490][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service0008
[1662402541.904511][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904535][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service0008
[1662402541.904556][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904585][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904607][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904631][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904652][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904677][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904698][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904727][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904748][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904776][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904797][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904822][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0001
[1662402541.904843][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904871][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904893][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904917][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904939][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.904963][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_D4_DC_17_26_DA_51/service000c
[1662402541.904985][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.905017][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.905039][22841:22844] CHIP:DL: Char1 /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB/service0010
[1662402541.905072][22841:22844] CHIP:DL: New BLE connection 0x7fbab40571d0, device C2:1D:EE:AB:64:AB, path /org/bluez/hci0/dev_C2_1D_EE_AB_64_AB
[1662402541.905172][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1662402541.905202][22841:22846] CHIP:IN: BleConnectionComplete: endPoint 0x55a2e336dd00
[1662402542.324078][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402542.415101][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1662402542.415127][22841:22846] CHIP:BLE: subscribe complete, ep = 0x55a2e336dd00
[1662402542.459885][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402542.460112][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402542.460128][22841:22846] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1662402542.460136][22841:22846] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1662402542.460143][22841:22846] CHIP:BLE: local and remote recv window size = 5
[1662402542.460193][22841:22846] CHIP:IN: BLE EndPoint 0x55a2e336dd00 Connection Complete
[1662402542.594595][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402542.731593][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402542.731776][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402542.731826][22841:22846] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:3709129030 on exchange 53197i
[1662402542.731843][22841:22846] CHIP:EM: Found matching exchange: 53197i, Delegate: 0x7fbaa8023790
[1662402542.731890][22841:22846] CHIP:SC: Received PBKDF param response
[1662402542.731944][22841:22846] CHIP:SC: Peer assigned session ID 20419
[1662402542.732000][22841:22846] CHIP:SC: Found MRP parameters in the message
[1662402542.734450][22841:22846] CHIP:IN: Prepared unauthenticated message 0x7fbaafffdfb0 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 53197i with MessageCounter:76660739.
[1662402542.734475][22841:22846] CHIP:IN: Sending unauthenticated msg 0x7fbaafffdfb0 with MessageCounter:76660739 to 0x0000000000000000 at monotonic time: 0000000000902ACE msec
[1662402542.734509][22841:22846] CHIP:SC: Sent spake2p msg1
[1662402542.818729][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402544.804735][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402544.810117][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402544.810313][22841:22846] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:3709129031 on exchange 53197i
[1662402544.810495][22841:22846] CHIP:EM: Found matching exchange: 53197i, Delegate: 0x7fbaa8023790
[1662402544.810567][22841:22846] CHIP:SC: Received spake2p msg2
[1662402544.811753][22841:22846] CHIP:IN: Prepared unauthenticated message 0x7fbaafffe0b0 to 0x0000000000000000 (0)  of type 0x24 and protocolId (0, 0) on exchange 53197i with MessageCounter:76660740.
[1662402544.812052][22841:22846] CHIP:IN: Sending unauthenticated msg 0x7fbaafffe0b0 with MessageCounter:76660740 to 0x0000000000000000 at monotonic time: 00000000009032EC msec
[1662402544.812329][22841:22846] CHIP:SC: Sent spake2p msg3
[1662402544.978672][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402545.069492][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402545.069628][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402545.069684][22841:22846] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3709129032 on exchange 53197i
[1662402545.069697][22841:22846] CHIP:EM: Found matching exchange: 53197i, Delegate: 0x7fbaa8023790
[1662402545.069746][22841:22846] CHIP:SC: SecureSession[0x7fbaa8020f00]: Moving from state 'kEstablishing' --> 'kActive'
[1662402545.069754][22841:22846] CHIP:IN: SecureSession[0x7fbaa8020f00]: Activated - Type:1 LSID:52546
[1662402545.069763][22841:22846] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:52546 PSID:20419!
[1662402545.069773][22841:22846] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1662402545.069781][22841:22846] CHIP:TOO: Pairing Success
[1662402545.069788][22841:22846] CHIP:TOO: PASE establishment successful
[1662402545.069797][22841:22846] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1662402545.069806][22841:22846] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1662402545.069814][22841:22846] CHIP:CTL: Sending request for commissioning information
[1662402545.069830][22841:22846] CHIP:DMG: SendReadRequest ReadClient[0x7fbaa8043400]: Sending Read Request
[1662402545.069942][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd900 to 0xFFFFFFFB00000000 (0)  of type 0x2 and protocolId (0, 1) on exchange 53198i with MessageCounter:264659631.
[1662402545.069957][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd900 with MessageCounter:264659631 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000009033EE msec
[1662402545.069993][22841:22846] CHIP:DMG: MoveToState ReadClient[0x7fbaa8043400]: Moving to [AwaitingIn]
[1662402545.203640][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402545.525694][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402545.525858][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402545.613614][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402545.614924][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402545.615067][22841:22846] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:4875582 on exchange 53198i
[1662402545.615133][22841:22846] CHIP:EM: Found matching exchange: 53198i, Delegate: 0x7fbaa8043410
[1662402545.616076][22841:22846] CHIP:DMG: ReportDataMessage =
[1662402545.616521][22841:22846] CHIP:DMG: {
[1662402545.616575][22841:22846] CHIP:DMG: 	AttributeReportIBs =
[1662402545.616931][22841:22846] CHIP:DMG: 	[
[1662402545.617085][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.617171][22841:22846] CHIP:DMG: 		{
[1662402545.617319][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.617474][22841:22846] CHIP:DMG: 			{
[1662402545.617631][22841:22846] CHIP:DMG: 				DataVersion = 0xc9f1ed5d,
[1662402545.617789][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.617885][22841:22846] CHIP:DMG: 				{
[1662402545.618073][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.618249][22841:22846] CHIP:DMG: 					Cluster = 0x31,
[1662402545.618427][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0003,
[1662402545.618527][22841:22846] CHIP:DMG: 				}
[1662402545.618693][22841:22846] CHIP:DMG: 					
[1662402545.618858][22841:22846] CHIP:DMG: 				Data = 20, 
[1662402545.619024][22841:22846] CHIP:DMG: 			},
[1662402545.619184][22841:22846] CHIP:DMG: 			
[1662402545.619321][22841:22846] CHIP:DMG: 		},
[1662402545.619467][22841:22846] CHIP:DMG: 		
[1662402545.619613][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.619767][22841:22846] CHIP:DMG: 		{
[1662402545.619838][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.619991][22841:22846] CHIP:DMG: 			{
[1662402545.620145][22841:22846] CHIP:DMG: 				DataVersion = 0x26a87f38,
[1662402545.620311][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.620402][22841:22846] CHIP:DMG: 				{
[1662402545.620566][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.620738][22841:22846] CHIP:DMG: 					Cluster = 0x28,
[1662402545.620912][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0004,
[1662402545.621083][22841:22846] CHIP:DMG: 				}
[1662402545.621252][22841:22846] CHIP:DMG: 					
[1662402545.621418][22841:22846] CHIP:DMG: 				Data = 32774, 
[1662402545.621586][22841:22846] CHIP:DMG: 			},
[1662402545.621679][22841:22846] CHIP:DMG: 			
[1662402545.621829][22841:22846] CHIP:DMG: 		},
[1662402545.622183][22841:22846] CHIP:DMG: 		
[1662402545.622247][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.622415][22841:22846] CHIP:DMG: 		{
[1662402545.622486][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.622655][22841:22846] CHIP:DMG: 			{
[1662402545.622812][22841:22846] CHIP:DMG: 				DataVersion = 0x26a87f38,
[1662402545.622988][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.623168][22841:22846] CHIP:DMG: 				{
[1662402545.623268][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.623458][22841:22846] CHIP:DMG: 					Cluster = 0x28,
[1662402545.623641][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0002,
[1662402545.624973][22841:22846] CHIP:DMG: 				}
[1662402545.627065][22841:22846] CHIP:DMG: 					
[1662402545.627182][22841:22846] CHIP:DMG: 				Data = 65521, 
[1662402545.627274][22841:22846] CHIP:DMG: 			},
[1662402545.627363][22841:22846] CHIP:DMG: 			
[1662402545.627500][22841:22846] CHIP:DMG: 		},
[1662402545.627592][22841:22846] CHIP:DMG: 		
[1662402545.627650][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.627725][22841:22846] CHIP:DMG: 		{
[1662402545.627793][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.627895][22841:22846] CHIP:DMG: 			{
[1662402545.628754][22841:22846] CHIP:DMG: 				DataVersion = 0xd2708b3b,
[1662402545.628851][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.635194][22841:22846] CHIP:DMG: 				{
[1662402545.638371][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.638787][22841:22846] CHIP:DMG: 					Cluster = 0x30,
[1662402545.638894][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0003,
[1662402545.638993][22841:22846] CHIP:DMG: 				}
[1662402545.639173][22841:22846] CHIP:DMG: 					
[1662402545.639272][22841:22846] CHIP:DMG: 				Data = 0, 
[1662402545.639360][22841:22846] CHIP:DMG: 			},
[1662402545.639450][22841:22846] CHIP:DMG: 			
[1662402545.639517][22841:22846] CHIP:DMG: 		},
[1662402545.639604][22841:22846] CHIP:DMG: 		
[1662402545.639704][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.639814][22841:22846] CHIP:DMG: 		{
[1662402545.639882][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.639962][22841:22846] CHIP:DMG: 			{
[1662402545.640042][22841:22846] CHIP:DMG: 				DataVersion = 0xd2708b3b,
[1662402545.640131][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.640222][22841:22846] CHIP:DMG: 				{
[1662402545.640312][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.640417][22841:22846] CHIP:DMG: 					Cluster = 0x30,
[1662402545.640516][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0002,
[1662402545.640615][22841:22846] CHIP:DMG: 				}
[1662402545.640706][22841:22846] CHIP:DMG: 					
[1662402545.640796][22841:22846] CHIP:DMG: 				Data = 0, 
[1662402545.640885][22841:22846] CHIP:DMG: 			},
[1662402545.640967][22841:22846] CHIP:DMG: 			
[1662402545.641035][22841:22846] CHIP:DMG: 		},
[1662402545.641118][22841:22846] CHIP:DMG: 		
[1662402545.641175][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.641252][22841:22846] CHIP:DMG: 		{
[1662402545.641319][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.641776][22841:22846] CHIP:DMG: 			{
[1662402545.641860][22841:22846] CHIP:DMG: 				DataVersion = 0xd2708b3b,
[1662402545.641963][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.642051][22841:22846] CHIP:DMG: 				{
[1662402545.642140][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.642238][22841:22846] CHIP:DMG: 					Cluster = 0x30,
[1662402545.642340][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0001,
[1662402545.642437][22841:22846] CHIP:DMG: 				}
[1662402545.642528][22841:22846] CHIP:DMG: 					
[1662402545.642616][22841:22846] CHIP:DMG: 				Data = 
[1662402545.642705][22841:22846] CHIP:DMG: 				{
[1662402545.642795][22841:22846] CHIP:DMG: 					0x0 = 60, 
[1662402545.642893][22841:22846] CHIP:DMG: 				},
[1662402545.642980][22841:22846] CHIP:DMG: 			},
[1662402545.643065][22841:22846] CHIP:DMG: 			
[1662402545.643133][22841:22846] CHIP:DMG: 		},
[1662402545.643220][22841:22846] CHIP:DMG: 		
[1662402545.643279][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.643362][22841:22846] CHIP:DMG: 		{
[1662402545.643430][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.646623][22841:22846] CHIP:DMG: 			{
[1662402545.646744][22841:22846] CHIP:DMG: 				DataVersion = 0xd2708b3b,
[1662402545.646845][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.646941][22841:22846] CHIP:DMG: 				{
[1662402545.647036][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.647148][22841:22846] CHIP:DMG: 					Cluster = 0x30,
[1662402545.647249][22841:22846] CHIP:DMG: 					Attribute = 0x0000_0000,
[1662402545.647346][22841:22846] CHIP:DMG: 				}
[1662402545.647448][22841:22846] CHIP:DMG: 					
[1662402545.647542][22841:22846] CHIP:DMG: 				Data = 0, 
[1662402545.647635][22841:22846] CHIP:DMG: 			},
[1662402545.647743][22841:22846] CHIP:DMG: 			
[1662402545.647815][22841:22846] CHIP:DMG: 		},
[1662402545.647904][22841:22846] CHIP:DMG: 		
[1662402545.647981][22841:22846] CHIP:DMG: 		AttributeReportIB =
[1662402545.648072][22841:22846] CHIP:DMG: 		{
[1662402545.648144][22841:22846] CHIP:DMG: 			AttributeDataIB =
[1662402545.648230][22841:22846] CHIP:DMG: 			{
[1662402545.648315][22841:22846] CHIP:DMG: 				DataVersion = 0xc9f1ed5d,
[1662402545.648412][22841:22846] CHIP:DMG: 				AttributePathIB =
[1662402545.648504][22841:22846] CHIP:DMG: 				{
[1662402545.648596][22841:22846] CHIP:DMG: 					Endpoint = 0x0,
[1662402545.648700][22841:22846] CHIP:DMG: 					Cluster = 0x31,
[1662402545.648812][22841:22846] CHIP:DMG: 					Attribute = 0x0000_FFFC,
[1662402545.648913][22841:22846] CHIP:DMG: 				}
[1662402545.649027][22841:22846] CHIP:DMG: 					
[1662402545.649128][22841:22846] CHIP:DMG: 				Data = 2, 
[1662402545.649216][22841:22846] CHIP:DMG: 			},
[1662402545.649301][22841:22846] CHIP:DMG: 			
[1662402545.649373][22841:22846] CHIP:DMG: 		},
[1662402545.649449][22841:22846] CHIP:DMG: 		
[1662402545.649506][22841:22846] CHIP:DMG: 	],
[1662402545.649615][22841:22846] CHIP:DMG: 	
[1662402545.649670][22841:22846] CHIP:DMG: 	SuppressResponse = true, 
[1662402545.649732][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402545.649790][22841:22846] CHIP:DMG: }
[1662402545.650826][22841:22846] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1662402545.652972][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1662402545.653039][22841:22846] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1662402545.653089][22841:22846] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1662402545.653128][22841:22846] CHIP:CTL: Arming failsafe (60 seconds)
[1662402545.653203][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402545.653251][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402545.653390][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd540 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53199i with MessageCounter:264659632.
[1662402545.653457][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd540 with MessageCounter:264659632 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000903635 msec
[1662402545.658217][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402545.743674][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402545.924679][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402545.924762][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402545.924822][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875583 on exchange 53199i
[1662402545.924834][22841:22846] CHIP:EM: Found matching exchange: 53199i, Delegate: 0x7fbab4055ea8
[1662402545.924845][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402545.924860][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402545.924866][22841:22846] CHIP:DMG: {
[1662402545.924874][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402545.924881][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402545.924899][22841:22846] CHIP:DMG: 	[
[1662402545.924906][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402545.924915][22841:22846] CHIP:DMG: 		{
[1662402545.924921][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402545.924928][22841:22846] CHIP:DMG: 			{
[1662402545.924936][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402545.924944][22841:22846] CHIP:DMG: 				{
[1662402545.924952][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402545.924960][22841:22846] CHIP:DMG: 					ClusterId = 0x30,
[1662402545.924968][22841:22846] CHIP:DMG: 					CommandId = 0x1,
[1662402545.924976][22841:22846] CHIP:DMG: 				},
[1662402545.924988][22841:22846] CHIP:DMG: 				
[1662402545.924996][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402545.925004][22841:22846] CHIP:DMG: 				{
[1662402545.925012][22841:22846] CHIP:DMG: 					0x0 = 0, 
[1662402545.925021][22841:22846] CHIP:DMG: 					0x1 = "" (0 chars), 
[1662402545.925029][22841:22846] CHIP:DMG: 				},
[1662402545.925036][22841:22846] CHIP:DMG: 			},
[1662402545.925045][22841:22846] CHIP:DMG: 			
[1662402545.925051][22841:22846] CHIP:DMG: 		},
[1662402545.925061][22841:22846] CHIP:DMG: 		
[1662402545.925067][22841:22846] CHIP:DMG: 	],
[1662402545.925076][22841:22846] CHIP:DMG: 	
[1662402545.925083][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402545.925090][22841:22846] CHIP:DMG: },
[1662402545.925109][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1662402545.925121][22841:22846] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1662402545.925132][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1662402545.925139][22841:22846] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1662402545.925147][22841:22846] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1662402545.925157][22841:22846] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1662402545.925163][22841:22846] CHIP:CTL: Setting Regulatory Config
[1662402545.925170][22841:22846] CHIP:CTL: Device does not support configurable regulatory location
[1662402545.925189][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402545.925198][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402545.925220][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd0d0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53200i with MessageCounter:264659633.
[1662402545.925232][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd0d0 with MessageCounter:264659633 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000903745 msec
[1662402545.925275][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402545.925294][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402546.059336][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402546.240032][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402546.240253][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402546.240406][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875584 on exchange 53200i
[1662402546.240424][22841:22846] CHIP:EM: Found matching exchange: 53200i, Delegate: 0x7fbab0055c08
[1662402546.240444][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402546.240471][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402546.240482][22841:22846] CHIP:DMG: {
[1662402546.240490][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402546.240499][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402546.240511][22841:22846] CHIP:DMG: 	[
[1662402546.240533][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402546.240546][22841:22846] CHIP:DMG: 		{
[1662402546.240554][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402546.240563][22841:22846] CHIP:DMG: 			{
[1662402546.240571][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402546.240582][22841:22846] CHIP:DMG: 				{
[1662402546.240590][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402546.240600][22841:22846] CHIP:DMG: 					ClusterId = 0x30,
[1662402546.240608][22841:22846] CHIP:DMG: 					CommandId = 0x3,
[1662402546.240618][22841:22846] CHIP:DMG: 				},
[1662402546.240627][22841:22846] CHIP:DMG: 				
[1662402546.240656][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402546.240666][22841:22846] CHIP:DMG: 				{
[1662402546.240677][22841:22846] CHIP:DMG: 					0x0 = 0, 
[1662402546.240687][22841:22846] CHIP:DMG: 					0x1 = "" (0 chars), 
[1662402546.240698][22841:22846] CHIP:DMG: 				},
[1662402546.240706][22841:22846] CHIP:DMG: 			},
[1662402546.240716][22841:22846] CHIP:DMG: 			
[1662402546.240724][22841:22846] CHIP:DMG: 		},
[1662402546.240733][22841:22846] CHIP:DMG: 		
[1662402546.240740][22841:22846] CHIP:DMG: 	],
[1662402546.240750][22841:22846] CHIP:DMG: 	
[1662402546.240757][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402546.240762][22841:22846] CHIP:DMG: },
[1662402546.240783][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1662402546.240810][22841:22846] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1662402546.240823][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1662402546.240830][22841:22846] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1662402546.240841][22841:22846] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1662402546.240852][22841:22846] CHIP:CTL: Sending request for PAI certificate
[1662402546.240861][22841:22846] CHIP:CTL: Sending Certificate Chain request to 0x7fbaa8023740 device
[1662402546.240880][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402546.240896][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402546.240933][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd000 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53201i with MessageCounter:264659634.
[1662402546.240945][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd000 with MessageCounter:264659634 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000903881 msec
[1662402546.240973][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402546.240993][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402546.373718][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402546.515085][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402546.515298][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402546.694860][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402546.695132][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402546.871283][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402546.871825][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402546.872024][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875585 on exchange 53201i
[1662402546.872244][22841:22846] CHIP:EM: Found matching exchange: 53201i, Delegate: 0x7fbab4055ea8
[1662402546.872289][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402546.872337][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402546.872363][22841:22846] CHIP:DMG: {
[1662402546.872386][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402546.872415][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402546.872446][22841:22846] CHIP:DMG: 	[
[1662402546.872471][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402546.872502][22841:22846] CHIP:DMG: 		{
[1662402546.872524][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402546.872549][22841:22846] CHIP:DMG: 			{
[1662402546.872571][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402546.872597][22841:22846] CHIP:DMG: 				{
[1662402546.872639][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402546.872667][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402546.872693][22841:22846] CHIP:DMG: 					CommandId = 0x3,
[1662402546.872719][22841:22846] CHIP:DMG: 				},
[1662402546.872745][22841:22846] CHIP:DMG: 				
[1662402546.872771][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402546.872797][22841:22846] CHIP:DMG: 				{
[1662402546.872824][22841:22846] CHIP:DMG: 					0x0 = [
[1662402546.872947][22841:22846] CHIP:DMG: 							0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 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, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1,
[1662402546.873018][22841:22846] CHIP:DMG: 					] (463 bytes)
[1662402546.873042][22841:22846] CHIP:DMG: 				},
[1662402546.873065][22841:22846] CHIP:DMG: 			},
[1662402546.873094][22841:22846] CHIP:DMG: 			
[1662402546.873116][22841:22846] CHIP:DMG: 		},
[1662402546.873153][22841:22846] CHIP:DMG: 		
[1662402546.873175][22841:22846] CHIP:DMG: 	],
[1662402546.873205][22841:22846] CHIP:DMG: 	
[1662402546.873227][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402546.873248][22841:22846] CHIP:DMG: },
[1662402546.873311][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1662402546.873343][22841:22846] CHIP:CTL: Received certificate chain from the device
[1662402546.873373][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1662402546.873399][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1662402546.873430][22841:22846] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1662402546.873451][22841:22846] CHIP:CTL: Sending request for DAC certificate
[1662402546.873468][22841:22846] CHIP:CTL: Sending Certificate Chain request to 0x7fbaa8023740 device
[1662402546.873521][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402546.873547][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402546.873617][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd030 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53202i with MessageCounter:264659635.
[1662402546.873654][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd030 with MessageCounter:264659635 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000903AFA msec
[1662402546.873746][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402546.873801][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402547.049023][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402547.234231][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402547.236598][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402547.415680][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402547.416013][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402547.590273][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402547.590389][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402547.590443][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875586 on exchange 53202i
[1662402547.590463][22841:22846] CHIP:EM: Found matching exchange: 53202i, Delegate: 0x7fbab4057ee8
[1662402547.590477][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402547.590495][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402547.590504][22841:22846] CHIP:DMG: {
[1662402547.590518][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402547.590527][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402547.590537][22841:22846] CHIP:DMG: 	[
[1662402547.590544][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402547.590558][22841:22846] CHIP:DMG: 		{
[1662402547.590566][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402547.590574][22841:22846] CHIP:DMG: 			{
[1662402547.590582][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402547.590591][22841:22846] CHIP:DMG: 				{
[1662402547.590631][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402547.590641][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402547.590649][22841:22846] CHIP:DMG: 					CommandId = 0x3,
[1662402547.590656][22841:22846] CHIP:DMG: 				},
[1662402547.590665][22841:22846] CHIP:DMG: 				
[1662402547.590676][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402547.590690][22841:22846] CHIP:DMG: 				{
[1662402547.590700][22841:22846] CHIP:DMG: 					0x0 = [
[1662402547.590745][22841:22846] CHIP:DMG: 							0x30, 0x82, 0x1, 0xe7, 0x30, 0x82, 0x1, 0x8d, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x7, 0x21, 0xf6, 0x6d, 0xf5, 0x1d, 0x72, 0x58, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 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, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 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, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x36, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x5e, 0x91, 0xed, 0x92, 0x50, 0x16, 0xcc, 0x82, 0x67, 0x19, 0x7a, 0x9, 0xb, 0x75, 0x33, 0xe5, 0x54, 0xe2, 0x5c, 0x8b, 0x9, 0x3c, 0xdd, 0xca, 0x9e, 0xaf, 0xcb, 0xa7, 0x47, 0xfe, 0xb8, 0xb5, 0xb8, 0xdc, 0x78, 0x9f, 0xf, 0x9d, 0xb0, 0xd8, 0xfc, 0xae, 0xac, 0x6c, 0xfd, 0x83, 0x9c, 0x51, 0xb3, 0xbd, 0xe, 0x4b, 0xc
[1662402547.590772][22841:22846] CHIP:DMG: 					] (491 bytes)
[1662402547.590781][22841:22846] CHIP:DMG: 				},
[1662402547.590789][22841:22846] CHIP:DMG: 			},
[1662402547.590800][22841:22846] CHIP:DMG: 			
[1662402547.590808][22841:22846] CHIP:DMG: 		},
[1662402547.590818][22841:22846] CHIP:DMG: 		
[1662402547.590825][22841:22846] CHIP:DMG: 	],
[1662402547.590836][22841:22846] CHIP:DMG: 	
[1662402547.590844][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402547.590852][22841:22846] CHIP:DMG: },
[1662402547.590876][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1662402547.590889][22841:22846] CHIP:CTL: Received certificate chain from the device
[1662402547.590901][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1662402547.590912][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1662402547.590923][22841:22846] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1662402547.590930][22841:22846] CHIP:CTL: Sending Attestation Request to the device.
[1662402547.590938][22841:22846] CHIP:CTL: Sending Attestation request to 0x7fbaa8023740 device
[1662402547.590959][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402547.590969][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402547.591011][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd010 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53203i with MessageCounter:264659636.
[1662402547.591025][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd010 with MessageCounter:264659636 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000903DC7 msec
[1662402547.591056][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402547.591067][22841:22846] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1662402547.591099][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402547.814053][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402547.955063][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402547.955217][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402548.135665][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402548.135900][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402548.492985][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402548.493203][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402548.493307][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875587 on exchange 53203i
[1662402548.493340][22841:22846] CHIP:EM: Found matching exchange: 53203i, Delegate: 0x7fbab40581a8
[1662402548.493386][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402548.493439][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402548.493462][22841:22846] CHIP:DMG: {
[1662402548.493485][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402548.493527][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402548.493611][22841:22846] CHIP:DMG: 	[
[1662402548.493673][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402548.493758][22841:22846] CHIP:DMG: 		{
[1662402548.493782][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402548.493809][22841:22846] CHIP:DMG: 			{
[1662402548.493833][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402548.493860][22841:22846] CHIP:DMG: 				{
[1662402548.493886][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402548.493913][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402548.493976][22841:22846] CHIP:DMG: 					CommandId = 0x1,
[1662402548.494000][22841:22846] CHIP:DMG: 				},
[1662402548.494028][22841:22846] CHIP:DMG: 				
[1662402548.494053][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402548.494079][22841:22846] CHIP:DMG: 				{
[1662402548.494183][22841:22846] CHIP:DMG: 					0x0 = [
[1662402548.494334][22841:22846] CHIP:DMG: 							0x15, 0x31, 0x1, 0x1d, 0x2, 0x30, 0x82, 0x2, 0x19, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x2, 0xa0, 0x82, 0x2, 0xa, 0x30, 0x82, 0x2, 0x6, 0x2, 0x1, 0x3, 0x31, 0xd, 0x30, 0xb, 0x6, 0x9, 0x60, 0x86, 0x48, 0x1, 0x65, 0x3, 0x4, 0x2, 0x1, 0x30, 0x82, 0x1, 0x71, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x1, 0xa0, 0x82, 0x1, 0x62, 0x4, 0x82, 0x1, 0x5e, 0x15, 0x24, 0x0, 0x1, 0x25, 0x1, 0xf1, 0xff, 0x36, 0x2, 0x5, 0x0, 0x80, 0x5, 0x1, 0x80, 0x5, 0x2, 0x80, 0x5, 0x3, 0x80, 0x5, 0x4, 0x80, 0x5, 0x5, 0x80, 0x5, 0x6, 0x80, 0x5, 0x7, 0x80, 0x5, 0x8, 0x80, 0x5, 0x9, 0x80, 0x5, 0xa, 0x80, 0x5, 0xb, 0x80, 0x5, 0xc, 0x80, 0x5, 0xd, 0x80, 0x5, 0xe, 0x80, 0x5, 0xf, 0x80, 0x5, 0x10, 0x80, 0x5, 0x11, 0x80, 0x5, 0x12, 0x80, 0x5, 0x13, 0x80, 0x5, 0x14, 0x80, 0x5, 0x15, 0x80, 0x5, 0x16, 0x80, 0x5, 0x17, 0x80, 0x5, 0x18, 0x80, 0x5, 0x19, 0x80, 0x5, 0x1a, 0x80, 0x5, 0x1b, 0x80, 0x5, 0x1c, 0x80, 0x5, 0x1d, 0x80, 0x5, 0x1e, 0x80, 0x5, 0x1f, 0x80, 0x5, 0x20, 0x80, 0x5, 0x21, 0x80, 0x5, 0x22, 0x80, 0x5, 0x23, 0x80, 0x5, 0x24, 0x80, 0x5, 0x25, 0x80, 0x5, 0x26, 0x80, 0x5, 0x27, 0x80, 0x5, 0x28, 0x80, 0x5, 0x29, 0x80, 0x5, 0x2a, 0x80, 0x5, 0x2b, 0x80, 0x5, 0x2c, 0x80, 0x5, 0x2d, 0x80, 0x5, 0x2e, 0x80, 0x5, 0x2f, 0x80, 0x5, 0x30, 0x80, 0x5, 0x31, 0x80, 0x5, 0x32, 0x80, 0x5, 0x33, 0x80, 0x5, 0x34, 0x80, 0x5, 0x35, 0x80, 0x5, 0x36, 0x80, 0x5, 0x37, 0x80, 0x5, 0x38, 0x80, 0x5, 0x39, 0x80, 0x5, 0x3a, 0x80, 0x5, 0x3b, 0x80, 0x5, 0x3c, 0x80, 0x5, 0x3d, 0x80, 0x5, 0x3e, 0x80, 0x5, 0x3f, 0x80, 0x5, 0x40, 0x80, 0x5, 0x41, 0x80, 0x5, 0x42, 0x80, 0x5, 0x43, 0x80, 0x5, 0x44, 0x80, 0x5, 0x45, 0x80, 0x5, 0x46, 0x80, 0x5, 0x47, 0x80, 0x5, 0x48, 0x80, 0x5, 0x49, 0x80, 0x5, 0x4a, 0x80, 0x5, 0
[1662402548.494412][22841:22846] CHIP:DMG: 					] (585 bytes)
[1662402548.494439][22841:22846] CHIP:DMG: 					0x1 = [
[1662402548.494485][22841:22846] CHIP:DMG: 							0xac, 0xd0, 0xbc, 0x6c, 0x71, 0x34, 0x40, 0xcf, 0x98, 0x93, 0x39, 0xb9, 0x6b, 0xf7, 0xeb, 0x6b, 0xa6, 0x68, 0x44, 0x80, 0x82, 0xa, 0x17, 0x8, 0x1e, 0xeb, 0xd4, 0x1a, 0xfc, 0x4, 0x9d, 0x46, 0xf7, 0x4a, 0x44, 0x6d, 0x45, 0xa9, 0xa4, 0x60, 0x7a, 0xf1, 0xf, 0x63, 0x43, 0x5a, 0xd9, 0xea, 0x68, 0xae, 0xff, 0x18, 0xc6, 0x5f, 0xcd, 0x7c, 0xcd, 0x70, 0xf, 0x40, 0xb1, 0x36, 0xba, 0x36, 
[1662402548.494521][22841:22846] CHIP:DMG: 					] (64 bytes)
[1662402548.494561][22841:22846] CHIP:DMG: 				},
[1662402548.494585][22841:22846] CHIP:DMG: 			},
[1662402548.494616][22841:22846] CHIP:DMG: 			
[1662402548.494638][22841:22846] CHIP:DMG: 		},
[1662402548.494670][22841:22846] CHIP:DMG: 		
[1662402548.494692][22841:22846] CHIP:DMG: 	],
[1662402548.494760][22841:22846] CHIP:DMG: 	
[1662402548.494804][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402548.494877][22841:22846] CHIP:DMG: },
[1662402548.494950][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1662402548.494995][22841:22846] CHIP:CTL: Received Attestation Information from the device
[1662402548.495026][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1662402548.495096][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1662402548.495150][22841:22846] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1662402548.495192][22841:22846] CHIP:CTL: Verifying attestation
[1662402548.500012][22841:22846] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1662402548.500344][22841:22846] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1662402548.500473][22841:22846] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1662402548.500593][22841:22846] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1662402548.500619][22841:22846] CHIP:CTL: Sending CSR request to 0x7fbaa8023740 device
[1662402548.500699][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402548.500750][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402548.500842][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffc5d0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53204i with MessageCounter:264659637.
[1662402548.500882][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffc5d0 with MessageCounter:264659637 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000904155 msec
[1662402548.500995][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402548.501062][22841:22846] CHIP:CTL: Sent CSR request, waiting for the CSR
[1662402548.501152][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402548.714215][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402549.215586][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402549.215668][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402549.391964][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402549.392081][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402549.392152][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875588 on exchange 53204i
[1662402549.392169][22841:22846] CHIP:EM: Found matching exchange: 53204i, Delegate: 0x7fbab4057ee8
[1662402549.392189][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402549.392215][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402549.392227][22841:22846] CHIP:DMG: {
[1662402549.392238][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402549.392249][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402549.392265][22841:22846] CHIP:DMG: 	[
[1662402549.392276][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402549.392291][22841:22846] CHIP:DMG: 		{
[1662402549.392303][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402549.392322][22841:22846] CHIP:DMG: 			{
[1662402549.392333][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402549.392347][22841:22846] CHIP:DMG: 				{
[1662402549.392360][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402549.392376][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402549.392388][22841:22846] CHIP:DMG: 					CommandId = 0x5,
[1662402549.392400][22841:22846] CHIP:DMG: 				},
[1662402549.392413][22841:22846] CHIP:DMG: 				
[1662402549.392426][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402549.392438][22841:22846] CHIP:DMG: 				{
[1662402549.392450][22841:22846] CHIP:DMG: 					0x0 = [
[1662402549.392499][22841:22846] CHIP:DMG: 							0x15, 0x30, 0x1, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x5e, 0x84, 0x78, 0x55, 0x31, 0xfc, 0xe9, 0x63, 0xbe, 0x8c, 0x2a, 0xa2, 0x49, 0x39, 0xe5, 0x95, 0xf1, 0x27, 0x29, 0xee, 0xac, 0xba, 0xdc, 0x86, 0x4d, 0xef, 0x13, 0x5, 0xa8, 0x52, 0x21, 0x54, 0x30, 0xac, 0x7a, 0x77, 0xba, 0x6e, 0xf0, 0xeb, 0x34, 0xcc, 0x54, 0x73, 0x71, 0xd5, 0x68, 0x2b, 0x37, 0x98, 0xe, 0xf8, 0x58, 0x8d, 0x1b, 0xdc, 0xc6, 0xed, 0xb2, 0x64, 0x71, 0xd5, 0x3c, 0x2c, 0xa0, 0x0, 0x30, 0xc, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x5, 0x0, 0x3, 0x48, 0x0, 0x30, 0x45, 0x2, 0x20, 0x75, 0xaf, 0xbf, 0xac, 0x6c, 0x71, 0xff, 0xc0, 0x7b, 0x29, 0x42, 0xd, 0x5b, 0x14, 0xc9, 0xd1, 0x5e, 0xa, 0xf8, 0x10, 0x86, 0xe0, 0xe0, 0xe8, 0x2c, 0xff, 0x1d, 0x23, 0x1, 0x97, 0x5f, 0x79, 0x2, 0x21, 0x0, 0xb9, 0x5f, 0x7d, 0x8d, 0x4f, 0x9a, 0x6e, 0x73, 0x17, 0xc, 0x75, 0xcf, 0xc1, 0x8c, 0xe7, 0x48, 0x26, 0xf8, 0x8f, 0x1, 0x7a, 0x9f, 0x40, 0xe3, 0xa3, 0xca, 0xb, 0xa0, 0x39, 0x9f, 0xa2, 0x72, 0x30, 0x2, 0x20, 0xfe, 0x40, 0xa4, 0x2, 0x46, 0xcd, 0x4a, 0xac, 0x5d, 0x67, 0x7b, 0xe7, 0x36, 0xe3, 0xb0, 0x55, 0xf2, 0x1d, 0x6f, 0xa2, 0x43, 0x1c, 0xd3, 0x98, 0x1c, 0xd, 0xf, 0xa8, 0x8e, 0x21, 0x18, 0x32, 0x18, 
[1662402549.392531][22841:22846] CHIP:DMG: 					] (245 bytes)
[1662402549.392543][22841:22846] CHIP:DMG: 					0x1 = [
[1662402549.392564][22841:22846] CHIP:DMG: 							0xa9, 0xee, 0xf8, 0x13, 0x3c, 0x18, 0x50, 0xa0, 0xd9, 0xcf, 0xfe, 0x37, 0xac, 0x46, 0xfe, 0x3f, 0x65, 0x13, 0x79, 0x2c, 0x7c, 0xe5, 0x16, 0x57, 0x3b, 0xca, 0x15, 0xf8, 0xe5, 0xbe, 0xbe, 0x4a, 0xf3, 0x5a, 0xac, 0x9f, 0x25, 0xb5, 0xb5, 0x25, 0xa0, 0x86, 0x15, 0xb7, 0x68, 0x47, 0xa3, 0x73, 0x1b, 0x32, 0x7b, 0xf0, 0xf8, 0x49, 0x5c, 0x51, 0xd1, 0x5f, 0xe7, 0x88, 0x9, 0xaa, 0xa9, 0x72, 
[1662402549.392581][22841:22846] CHIP:DMG: 					] (64 bytes)
[1662402549.392595][22841:22846] CHIP:DMG: 				},
[1662402549.392606][22841:22846] CHIP:DMG: 			},
[1662402549.392620][22841:22846] CHIP:DMG: 			
[1662402549.392631][22841:22846] CHIP:DMG: 		},
[1662402549.392645][22841:22846] CHIP:DMG: 		
[1662402549.392654][22841:22846] CHIP:DMG: 	],
[1662402549.392669][22841:22846] CHIP:DMG: 	
[1662402549.392679][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402549.392688][22841:22846] CHIP:DMG: },
[1662402549.392721][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1662402549.392739][22841:22846] CHIP:CTL: Received certificate signing request from the device
[1662402549.392755][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1662402549.392766][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1662402549.392779][22841:22846] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1662402549.393270][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1662402549.393285][22841:22846] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1662402549.393296][22841:22846] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1662402549.393307][22841:22846] CHIP:CTL: Getting certificate chain for the device from the issuer
[1662402549.393412][22841:22846] CHIP:CTL: Verifying Certificate Signing Request
[1662402549.393759][22841:22846] CHIP:CTL: Generating NOC
[1662402549.393890][22841:22846] CHIP:CTL: Providing certificate chain to the commissioner
[1662402549.393906][22841:22846] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1662402549.393937][22841:22846] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1662402549.394018][22841:22846] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1662402549.394029][22841:22846] CHIP:CTL: Sending root certificate to the device
[1662402549.394055][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402549.394067][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402549.394099][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffbe40 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53205i with MessageCounter:264659638.
[1662402549.394118][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffbe40 with MessageCounter:264659638 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000009044D2 msec
[1662402549.394160][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402549.394175][22841:22846] CHIP:CTL: Sent root certificate to the device
[1662402549.394310][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402549.794494][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402549.973964][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402550.110786][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402550.111083][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402550.111160][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875589 on exchange 53205i
[1662402550.111208][22841:22846] CHIP:EM: Found matching exchange: 53205i, Delegate: 0x7fbab40581a8
[1662402550.111227][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402550.111283][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402550.111342][22841:22846] CHIP:DMG: {
[1662402550.111385][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402550.111394][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402550.111405][22841:22846] CHIP:DMG: 	[
[1662402550.111411][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402550.111420][22841:22846] CHIP:DMG: 		{
[1662402550.111426][22841:22846] CHIP:DMG: 			CommandStatusIB =
[1662402550.111433][22841:22846] CHIP:DMG: 			{
[1662402550.111439][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402550.111446][22841:22846] CHIP:DMG: 				{
[1662402550.111489][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402550.111496][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402550.111503][22841:22846] CHIP:DMG: 					CommandId = 0xb,
[1662402550.111510][22841:22846] CHIP:DMG: 				},
[1662402550.111518][22841:22846] CHIP:DMG: 				
[1662402550.111526][22841:22846] CHIP:DMG: 				StatusIB =
[1662402550.111544][22841:22846] CHIP:DMG: 				{
[1662402550.111553][22841:22846] CHIP:DMG: 					status = 0x00 (SUCCESS),
[1662402550.111561][22841:22846] CHIP:DMG: 				},
[1662402550.111569][22841:22846] CHIP:DMG: 				
[1662402550.111577][22841:22846] CHIP:DMG: 			},
[1662402550.111586][22841:22846] CHIP:DMG: 			
[1662402550.111593][22841:22846] CHIP:DMG: 		},
[1662402550.111603][22841:22846] CHIP:DMG: 		
[1662402550.111610][22841:22846] CHIP:DMG: 	],
[1662402550.111619][22841:22846] CHIP:DMG: 	
[1662402550.111627][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402550.111633][22841:22846] CHIP:DMG: },
[1662402550.111653][22841:22846] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1662402550.111666][22841:22846] CHIP:CTL: Device confirmed that it has received the root certificate
[1662402550.111679][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1662402550.111687][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1662402550.111698][22841:22846] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1662402550.111723][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402550.111734][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402550.111762][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd040 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53206i with MessageCounter:264659639.
[1662402550.111775][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd040 with MessageCounter:264659639 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000009047A0 msec
[1662402550.111839][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402550.111849][22841:22846] CHIP:CTL: Sent operational certificate to the device
[1662402550.111864][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402550.334523][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402550.694609][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402550.874051][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402551.281101][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402551.281315][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402551.281455][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875590 on exchange 53206i
[1662402551.281493][22841:22846] CHIP:EM: Found matching exchange: 53206i, Delegate: 0x7fbab4057ee8
[1662402551.281517][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402551.281545][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402551.281554][22841:22846] CHIP:DMG: {
[1662402551.281563][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402551.281571][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402551.281581][22841:22846] CHIP:DMG: 	[
[1662402551.281588][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402551.281598][22841:22846] CHIP:DMG: 		{
[1662402551.281605][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402551.281615][22841:22846] CHIP:DMG: 			{
[1662402551.281623][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402551.281632][22841:22846] CHIP:DMG: 				{
[1662402551.281641][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402551.281682][22841:22846] CHIP:DMG: 					ClusterId = 0x3e,
[1662402551.281718][22841:22846] CHIP:DMG: 					CommandId = 0x8,
[1662402551.281748][22841:22846] CHIP:DMG: 				},
[1662402551.281771][22841:22846] CHIP:DMG: 				
[1662402551.281780][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402551.281789][22841:22846] CHIP:DMG: 				{
[1662402551.281806][22841:22846] CHIP:DMG: 					0x0 = 0, 
[1662402551.281813][22841:22846] CHIP:DMG: 					0x1 = 21, 
[1662402551.281821][22841:22846] CHIP:DMG: 				},
[1662402551.281833][22841:22846] CHIP:DMG: 			},
[1662402551.281843][22841:22846] CHIP:DMG: 			
[1662402551.281851][22841:22846] CHIP:DMG: 		},
[1662402551.281861][22841:22846] CHIP:DMG: 		
[1662402551.281869][22841:22846] CHIP:DMG: 	],
[1662402551.281891][22841:22846] CHIP:DMG: 	
[1662402551.281907][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402551.281938][22841:22846] CHIP:DMG: },
[1662402551.281970][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1662402551.281989][22841:22846] CHIP:CTL: Device returned status 0 on receiving the NOC
[1662402551.281996][22841:22846] CHIP:CTL: Operational credentials provisioned on device 0x7fbaa8023740
[1662402551.282003][22841:22846] CHIP:TOO: Secure Pairing Success
[1662402551.282010][22841:22846] CHIP:TOO: CASE establishment successful
[1662402551.282020][22841:22846] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1662402551.282037][22841:22846] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
[1662402551.282047][22841:22846] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup'
[1662402551.282066][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402551.282075][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402551.282100][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd060 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53207i with MessageCounter:264659640.
[1662402551.282113][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd060 with MessageCounter:264659640 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000904C32 msec
[1662402551.282158][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402551.282178][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402551.504573][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402551.640516][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402551.640710][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402551.640775][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875591 on exchange 53207i
[1662402551.640796][22841:22846] CHIP:EM: Found matching exchange: 53207i, Delegate: 0x7fbab40581a8
[1662402551.640816][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402551.640841][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402551.640855][22841:22846] CHIP:DMG: {
[1662402551.640868][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402551.640887][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402551.640910][22841:22846] CHIP:DMG: 	[
[1662402551.640962][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402551.641001][22841:22846] CHIP:DMG: 		{
[1662402551.641052][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402551.641128][22841:22846] CHIP:DMG: 			{
[1662402551.641162][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402551.641199][22841:22846] CHIP:DMG: 				{
[1662402551.641229][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402551.641261][22841:22846] CHIP:DMG: 					ClusterId = 0x31,
[1662402551.641295][22841:22846] CHIP:DMG: 					CommandId = 0x5,
[1662402551.641327][22841:22846] CHIP:DMG: 				},
[1662402551.641358][22841:22846] CHIP:DMG: 				
[1662402551.641387][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402551.641399][22841:22846] CHIP:DMG: 				{
[1662402551.641423][22841:22846] CHIP:DMG: 					0x0 = 0, 
[1662402551.641452][22841:22846] CHIP:DMG: 					0x2 = 0, 
[1662402551.641485][22841:22846] CHIP:DMG: 				},
[1662402551.641516][22841:22846] CHIP:DMG: 			},
[1662402551.641544][22841:22846] CHIP:DMG: 			
[1662402551.641567][22841:22846] CHIP:DMG: 		},
[1662402551.641581][22841:22846] CHIP:DMG: 		
[1662402551.641603][22841:22846] CHIP:DMG: 	],
[1662402551.641628][22841:22846] CHIP:DMG: 	
[1662402551.641644][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402551.641664][22841:22846] CHIP:DMG: },
[1662402551.641691][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1662402551.641716][22841:22846] CHIP:CTL: Received NetworkConfig response, networkingStatus=0
[1662402551.641728][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup'
[1662402551.641737][22841:22846] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable'
[1662402551.641752][22841:22846] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable'
[1662402551.641781][22841:22846] CHIP:DMG: ICR moving to [AddingComm]
[1662402551.641791][22841:22846] CHIP:DMG: ICR moving to [AddedComma]
[1662402551.641817][22841:22846] CHIP:IN: Prepared secure message 0x7fbaafffd0c0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 53208i with MessageCounter:264659641.
[1662402551.641830][22841:22846] CHIP:IN: Sending encrypted msg 0x7fbaafffd0c0 with MessageCounter:264659641 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000904D9A msec
[1662402551.641862][22841:22846] CHIP:DMG: ICR moving to [CommandSen]
[1662402551.641881][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402551.864589][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402552.225294][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402552.225385][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402552.225467][22841:22846] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4875592 on exchange 53208i
[1662402552.225532][22841:22846] CHIP:EM: Found matching exchange: 53208i, Delegate: 0x7fbab4057ee8
[1662402552.225546][22841:22846] CHIP:DMG: ICR moving to [ResponseRe]
[1662402552.225564][22841:22846] CHIP:DMG: InvokeResponseMessage =
[1662402552.225572][22841:22846] CHIP:DMG: {
[1662402552.225579][22841:22846] CHIP:DMG: 	suppressResponse = false, 
[1662402552.225587][22841:22846] CHIP:DMG: 	InvokeResponseIBs =
[1662402552.225597][22841:22846] CHIP:DMG: 	[
[1662402552.225604][22841:22846] CHIP:DMG: 		InvokeResponseIB =
[1662402552.225614][22841:22846] CHIP:DMG: 		{
[1662402552.225621][22841:22846] CHIP:DMG: 			CommandDataIB =
[1662402552.225630][22841:22846] CHIP:DMG: 			{
[1662402552.225636][22841:22846] CHIP:DMG: 				CommandPathIB =
[1662402552.225644][22841:22846] CHIP:DMG: 				{
[1662402552.225653][22841:22846] CHIP:DMG: 					EndpointId = 0x0,
[1662402552.225662][22841:22846] CHIP:DMG: 					ClusterId = 0x31,
[1662402552.225670][22841:22846] CHIP:DMG: 					CommandId = 0x7,
[1662402552.225678][22841:22846] CHIP:DMG: 				},
[1662402552.225689][22841:22846] CHIP:DMG: 				
[1662402552.225700][22841:22846] CHIP:DMG: 				CommandFields = 
[1662402552.225709][22841:22846] CHIP:DMG: 				{
[1662402552.225717][22841:22846] CHIP:DMG: 					0x0 = 0, 
[1662402552.225726][22841:22846] CHIP:DMG: 					0x2 = NULL
[1662402552.225734][22841:22846] CHIP:DMG: 				},
[1662402552.225742][22841:22846] CHIP:DMG: 			},
[1662402552.225751][22841:22846] CHIP:DMG: 			
[1662402552.225758][22841:22846] CHIP:DMG: 		},
[1662402552.225767][22841:22846] CHIP:DMG: 		
[1662402552.225774][22841:22846] CHIP:DMG: 	],
[1662402552.225784][22841:22846] CHIP:DMG: 	
[1662402552.225791][22841:22846] CHIP:DMG: 	InteractionModelRevision = 1
[1662402552.225798][22841:22846] CHIP:DMG: },
[1662402552.225823][22841:22846] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1662402552.225836][22841:22846] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1662402552.225848][22841:22846] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
[1662402552.225857][22841:22846] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
[1662402552.225866][22841:22846] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1662402552.225874][22841:22846] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1662402552.225882][22841:22846] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1662402552.225894][22841:22846] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1662402552.226018][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp9s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402552.226376][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402552.226388][22841:22846] CHIP:DIS: mDNS broadcast had only partial success: 4 successes and 2 failures.
[1662402552.226419][22841:22846] CHIP:DMG: ICR moving to [AwaitingDe]
[1662402552.426782][22841:22846] CHIP:DIS: Checking node lookup status after 201 ms
[1662402553.226788][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp9s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402553.227994][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402553.228171][22841:22846] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1662402554.969977][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402555.227563][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp9s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402555.228422][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402555.228655][22841:22846] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1662402557.535681][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402557.535904][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402559.228936][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp9s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402559.229498][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402559.229686][22841:22846] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1662402560.280104][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402562.853870][22841:22844] CHIP:DL: Indication received, conn = 0x7fbab40571d0
[1662402562.854150][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1662402565.590537][22841:22846] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1662402567.228363][22841:22846] CHIP:DIS: Checking node lookup status after 15002 ms
[1662402567.228433][22841:22846] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: operational discovery failed: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1662402567.228516][22841:22846] CHIP:CTL: Device connection failed. Error ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1662402567.228577][22841:22846] CHIP:CTL: Error on commissioning step 'FindOperational': '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
[1662402567.228604][22841:22846] CHIP:CTL: Failed to perform commissioning step 18
[1662402567.228627][22841:22846] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1662402567.228664][22841:22846] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
[1662402567.228720][22841:22846] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1662402567.228762][22841:22846] CHIP:TOO: Device commissioning Failure: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1662402567.229051][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp9s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402567.230190][22841:22846] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:406: OS Error 0x02000065: Network is unreachable
[1662402567.230227][22841:22846] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1662402567.230520][22841:22841] CHIP:CTL: Shutting down the commissioner
[1662402567.230566][22841:22841] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662402567.230679][22841:22841] CHIP:DIS: Closing all BLE connections
[1662402567.230707][22841:22841] CHIP:IN: Clearing BLE pending packets.
[1662402567.230780][22841:22841] CHIP:BLE: Auto-closing end point's BLE connection.
[1662402567.230806][22841:22841] CHIP:DL: Closing BLE GATT connection (con 0x7fbab40571d0)
[1662402567.230859][22841:22841] CHIP:IN: SecureSession[0x7fbaa8020f00]: MarkForEviction Type:1 LSID:52546
[1662402567.230883][22841:22841] CHIP:SC: SecureSession[0x7fbaa8020f00]: Moving from state 'kActive' --> 'kPendingEviction'
[1662402567.230953][22841:22841] CHIP:IN: SecureSession[0x7fbaa8020f00]: Released - Type:1 LSID:52546
[1662402567.230985][22841:22841] CHIP:CTL: Shutting down the controller
[1662402567.231023][22841:22841] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1662402567.231059][22841:22841] CHIP:FP: Forgetting fabric 0x1
[1662402567.231107][22841:22841] CHIP:TS: Pending Last Known Good Time: 2022-09-03T19:45:02
[1662402567.231033][22841:22844] CHIP:DL: BluezDisconnect peer=C2:1D:EE:AB:64:AB
[1662402567.231256][22841:22841] CHIP:TS: Previous Last Known Good Time: 2022-09-03T19:45:02
[1662402567.231276][22841:22841] CHIP:TS: Reverted Last Known Good Time to previous value
[1662402567.231312][22841:22841] CHIP:CTL: Shutting down the commissioner
[1662402567.231330][22841:22841] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1662402567.231394][22841:22841] CHIP:CTL: Shutting down the controller
[1662402567.231412][22841:22841] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1662402567.232021][22841:22841] CHIP:DMG: IM WH moving to [Uninitialized]
[1662402567.232050][22841:22841] CHIP:DMG: IM WH moving to [Uninitialized]
[1662402567.232068][22841:22841] CHIP:DMG: IM WH moving to [Uninitialized]
[1662402567.232084][22841:22841] CHIP:DMG: IM WH moving to [Uninitialized]
[1662402567.232106][22841:22841] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1662402567.232176][22841:22841] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1662402567.232518][22841:22841] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-J1oI4i)
[1662402567.233069][22841:22841] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1662402567.233126][22841:22841] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1662402567.233149][22841:22841] CHIP:DL: Inet Layer shutdown
[1662402567.233167][22841:22841] CHIP:DL: BLE shutdown
[1662402567.235656][22841:22841] CHIP:DL: System Layer shutdown
[1662402567.235763][22841:22841] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout

output from the nrf52840 dk with doorlock sample flashed:

I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 3, f68
I: data wra: 3, 2c
*** Booting Zephyr OS build v3.0.99-ncs1  ***
I: Init CHIP stack
D: 128 [DL]Boot reason: 1


uaI: 229 [DL]BLE address: C2:1D:EE:AB:64:AB
I: SoftDevice Controller build revision:
I: 33 78 2a 18 20 f5 61 61 |3x*. .aa
I: a6 8b 77 60 62 83 39 2a |..w`b.9*
I: 7c f1 14 e4             ||...
rt:~$ I: 253 [DL]OpenThread started: OK
I: 256 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 263 [SVR]Server initializing...
D: 266 [DIS]Init fabric pairing table with server storage
I: 272 [DMG]AccessControl: initializing
I: 276 [DMG]Examples::AccessControlDelegate::Init
I: 280 [DMG]AccessControl: setting
I: 283 [DMG]DefaultAclStorage: initializing
I: 287 [DMG]DefaultAclStorage: 0 entries loaded
I: 292 [ZCL]Using ZAP configuration...
I: 296 [DMG]AccessControlCluster: initializing
I: 300 [ZCL]Initiating Admin Commissioning cluster.
I: 305 [ZCL]Door Lock server initialized
D: 309 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to d2708b3b
I: 315 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 323 [DIS]Add fabric pairing table delegate
E: 327 [ZCL]DeviceInfoProvider is not registered
E: 331 [ZCL]Trying to write invalid Calendar Type
E: 336 [ZCL]Failed to write calendar type with error: 0x87
I: 341 [ZCL]Door Lock cluster initialized at endpoint #1
D: 346 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 32376c89
E: 352 [ZCL]Failed to log event: err=0x3, event_id=0x2
D: 357 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 32376c8a
D: 364 [IN]UDP::Init bind&listen port=5540
E: 368 [IN]SO_REUSEPORT failed: 109
D: 371 [IN]UDP::Init bound to port=5540
D: 374 [IN]BLEBase::Init - setting/overriding transport
D: 379 [IN]TransportMgr initialized
D: 389 [DIS]Add fabric pairing table delegate
D: 393 [DL]Using Thread extended MAC for hostname.
I: 400 [DIS]Updating services using commissioning mode 0
D: 405 [DL]Using Thread extended MAC for hostname.
D: 410 [DL]Using Thread extended MAC for hostname.
I: 416 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
E: 424 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
D: 432 [DIS]Scheduling extended discovery timeout in 900s
E: 437 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 443 [DIS]Delaying proxy of operational discovery: missing delegate
I: 449 [IN]CASE Server enabling CASE session setups
I: 454 [SVR]Joining Multicast groups
D: 457 [ZCL]Emitting StartUp event
D: 460 [EVL]LogEvent event number: 0x00000000000A0000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001CC
D: 474 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
D: 479 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to c1255c48
D: 486 [EVL]LogEvent event number: 0x00000000000A0001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x00000000000001E5
I: 499 [SVR]Server Listening...
I: 502 [DL]Device Configuration:
I: 506 [DL]  Serial Number: TEST_SN
I: 509 [DL]  Vendor Id: 65521 (0xFFF1)
I: 512 [DL]  Product Id: 32774 (0x8006)
I: 516 [DL]  Hardware Version: 0
I: 520 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 526 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 533 [DL]  Manufacturing Date: (not set)
I: 537 [DL]  Device Type: 65535 (0xFFFF)
I: 542 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00]
I: 547 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 553 [SVR]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00
I: 561 [SVR]Manual pairing code: [34970112332]
I: 566 [DL]CHIP task running
D: Updating LockState attribute
D: 573 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 32376c8b
D: 579 [EVL]LogEvent event number: 0x00000000000A0002 priority: 2, endpoint id:  0x1 cluster id: 0x0000_0101 event id: 0x2 Sys timestamp: 0x0000000000000243
D: 4493 [SC]Assigned local session key ID 20419
D: 4498 [SC]Waiting for PBKDF param request
D: 4501 [DL]CHIPoBLE advertising set to on
I: 4505 [DIS]Updating services using commissioning mode 1
D: 4510 [DL]Using Thread extended MAC for hostname.
D: 4515 [DL]Using Thread extended MAC for hostname.
I: 4521 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
E: 4530 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 4536 [DIS]Scheduling discovery timeout in 900s
E: 4541 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 4550 [DL]CHIPoBLE advertising started
I: 4555 [DL]NFC Tag emulation started
I: 24414 [DL]BLE connection established (ConnId: 0x00)
I: 24419 [DL]Current number of connections: 1/1
I: 24423 [DL]CHIPoBLE advertising stopped
I: 24427 [DL]NFC Tag emulation stopped
D: 25857 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 25863 [BLE]local and remote recv window sizes = 5
I: 25867 [BLE]selected BTP version 4
I: 25871 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 25947 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 25951 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 25957 [IN]BLE EndPoint 0x20009ac8 Connection Complete
I: 25962 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 26082 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26128 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 26134 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:76660738 on exchange 53197r
D: 26144 [EM]Handling via exchange: 53197r, Delegate: 0x20005940
D: 26150 [SC]Received PBKDF param request
D: 26153 [SC]Peer assigned session ID 52546
D: 26157 [SC]Found MRP parameters in the message
D: 26162 [SC]Including MRP parameters in PBKDF param response
I: 26168 [IN]Prepared unauthenticated message 0x2002b0f8 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 53197r with MessageCounter:3709129030.
I: 26183 [IN]Sending unauthenticated msg 0x2002b0f8 with MessageCounter:3709129030 to 0x0000000000000000 at monotonic time: 0000000000006647 msec
D: 26196 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 140)
D: 26202 [SC]Sent PBKDF param response
D: 26352 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26358 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 26364 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:76660739 on exchange 53197r
D: 26374 [EM]Found matching exchange: 53197r, Delegate: 0x20005940
D: 26380 [SC]Received spake2p msg1
I: 28311 [IN]Prepared unauthenticated message 0x2002b088 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 53197r with MessageCounter:3709129031.
I: 28326 [IN]Sending unauthenticated msg 0x2002b088 with MessageCounter:3709129031 to 0x0000000000000000 at monotonic time: 0000000000006EA5 msec
D: 28338 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 132)
D: 28345 [SC]Sent spake2p msg2
E: 28348 [DL]Long dispatch time: 1990 ms, for event type 16388
D: 28422 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28512 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 28518 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:76660740 on exchange 53197r
D: 28528 [EM]Found matching exchange: 53197r, Delegate: 0x20005940
D: 28533 [SC]Received spake2p msg3
D: 28537 [SC]Sending status report. Protocol code 0, exchange 53197
I: 28543 [IN]Prepared unauthenticated message 0x2002b118 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 53197r with MessageCounter:3709129032.
I: 28558 [IN]Sending unauthenticated msg 0x2002b118 with MessageCounter:3709129032 to 0x0000000000000000 at monotonic time: 0000000000006F8E msec
D: 28571 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 35)
D: 28578 [IN]New secure session created for device <FFFFFFFB00000000, 0>, LSID:20419 PSID:52546!
I: 28587 [SVR]Commissioning completed session establishment step
I: 28593 [DIS]Updating services using commissioning mode 0
D: 28598 [DL]Using Thread extended MAC for hostname.
D: 28604 [DL]Using Thread extended MAC for hostname.
I: 28609 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
E: 28618 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
D: 28625 [DIS]Scheduling extended discovery timeout in 900s
E: 28631 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 28637 [DL]CHIPoBLE advertising set to off
I: 28651 [SVR]Device completed Rendezvous process
E: 28656 [DL]Long dispatch time: 144 ms, for event type 16388
D: 28692 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28739 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 28746 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:264659631 on exchange 53198r
D: 28756 [EM]Handling via exchange: 53198r, Delegate: 0x200078bc
D: 28761 [IM]Received Read request
D: 28766 [DMG]IM RH moving to [GeneratingReports]
D: 28771 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 28780 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 28785 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 28794 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 28799 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 28808 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 28813 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 28821 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 28827 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 28836 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 28841 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 28850 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 28855 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 28864 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 28869 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 28878 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 28883 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 28892 [DMG]<RE> Sending report (payload has 224 bytes)...
I: 28899 [IN]Prepared secure message 0x2002b2c0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 53198r with MessageCounter:4875582.
I: 28913 [IN]Sending encrypted msg 0x2002b2c0 with MessageCounter:4875582 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000070F0 msec
D: 28925 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 28932 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 28936 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 28943 [DMG]IM RH moving to [AwaitingDestruction]
D: 28948 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 29141 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29147 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 29231 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29278 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 29285 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659632 on exchange 53199r
D: 29294 [EM]Handling via exchange: 53199r, Delegate: 0x200078bc
D: 29301 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
D: 29309 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to d2708b3c
D: 29315 [DMG]ICR moving to [ Preparing]
D: 29319 [DMG]ICR moving to [AddingComm]
D: 29323 [DMG]ICR moving to [AddedComma]
D: 29327 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 29334 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53199r with MessageCounter:4875583.
I: 29348 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875583 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000072A3 msec
D: 29360 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 29367 [DMG]ICR moving to [CommandSen]
D: 29370 [DMG]ICR moving to [AwaitingDe]
D: 29546 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29591 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 29598 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659633 on exchange 53200r
D: 29608 [EM]Handling via exchange: 53200r, Delegate: 0x200078bc
D: 29614 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 29623 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to d2708b3d
D: 29630 [DMG]ICR moving to [ Preparing]
D: 29633 [DMG]ICR moving to [AddingComm]
D: 29638 [DMG]ICR moving to [AddedComma]
D: 29641 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 29648 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53200r with MessageCounter:4875584.
I: 29662 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875584 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000073DE msec
D: 29675 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 29682 [DMG]ICR moving to [CommandSen]
D: 29685 [DMG]ICR moving to [AwaitingDe]
D: 29862 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29907 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 29914 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659634 on exchange 53201r
D: 29924 [EM]Handling via exchange: 53201r, Delegate: 0x200078bc
D: 29930 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 29937 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 29943 [DMG]ICR moving to [ Preparing]
D: 29947 [DMG]ICR moving to [AddingComm]
D: 29951 [DMG]ICR moving to [AddedComma]
D: 29955 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 29964 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53201r with MessageCounter:4875585.
I: 29978 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875585 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000007519 msec
D: 29990 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 29997 [DMG]ICR moving to [CommandSen]
D: 30001 [DMG]ICR moving to [AwaitingDe]
D: 30131 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30137 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 30311 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30317 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 48)
D: 30492 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30582 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 30588 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659635 on exchange 53202r
D: 30598 [EM]Handling via exchange: 53202r, Delegate: 0x200078bc
D: 30604 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 30612 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 30618 [DMG]ICR moving to [ Preparing]
D: 30621 [DMG]ICR moving to [AddingComm]
D: 30625 [DMG]ICR moving to [AddedComma]
D: 30629 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 30638 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53202r with MessageCounter:4875586.
I: 30652 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875586 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000077BC msec
D: 30664 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 30671 [DMG]ICR moving to [CommandSen]
D: 30675 [DMG]ICR moving to [AwaitingDe]
D: 30851 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30857 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 31031 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31037 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 76)
D: 31212 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31347 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 31353 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659636 on exchange 53203r
D: 31363 [EM]Handling via exchange: 53203r, Delegate: 0x200078bc
D: 31369 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 31377 [ZCL]OpCreds: received an AttestationRequest
D: 31413 [DMG]ICR moving to [ Preparing]
D: 31416 [DMG]ICR moving to [AddingComm]
D: 31420 [DMG]ICR moving to [AddedComma]
D: 31424 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 31434 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53203r with MessageCounter:4875587.
I: 31448 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875587 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000007AD8 msec
D: 31461 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 31467 [DMG]ICR moving to [CommandSen]
D: 31471 [DMG]ICR moving to [AwaitingDe]
E: 31474 [DL]Long dispatch time: 127 ms, for event type 16388
D: 31571 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31577 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 31751 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31757 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 237)
D: 32112 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32247 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 32253 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659637 on exchange 53204r
D: 32263 [EM]Handling via exchange: 53204r, Delegate: 0x200078bc
D: 32269 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 32277 [ZCL]OpCreds: commissioner has requested a CSR
I: 32634 [ZCL]OpCreds: NewCertificateSigningRequest returned 0
D: 32670 [DMG]ICR moving to [ Preparing]
D: 32674 [DMG]ICR moving to [AddingComm]
D: 32678 [DMG]ICR moving to [AddedComma]
D: 32681 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 32690 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53204r with MessageCounter:4875588.
I: 32704 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875588 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000007FC0 msec
D: 32716 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 32723 [DMG]ICR moving to [CommandSen]
D: 32726 [DMG]ICR moving to [AwaitingDe]
E: 32730 [DL]Long dispatch time: 483 ms, for event type 16388
D: 32831 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32837 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 138)
D: 33011 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33328 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 33506 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 33514 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659638 on exchange 53205r
D: 33524 [EM]Handling via exchange: 53205r, Delegate: 0x200078bc
D: 33530 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 33538 [ZCL]OpCreds: commissioner has added a trusted root Cert
D: 33543 [DMG]ICR moving to [ Preparing]
D: 33547 [DMG]ICR moving to [AddingComm]
D: 33551 [DMG]ICR moving to [AddedComma]
D: 33555 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a487ae18
D: 33561 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 33568 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 53205r with MessageCounter:4875589.
I: 33582 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875589 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000000832E msec
D: 33595 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
D: 33601 [DMG]ICR moving to [CommandSen]
D: 33605 [DMG]ICR moving to [AwaitingDe]
E: 33609 [DL]Long dispatch time: 103 ms, for event type 16388
D: 33731 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33870 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 34228 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 34407 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 34416 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659639 on exchange 53206r
D: 34426 [EM]Handling via exchange: 53206r, Delegate: 0x200078bc
D: 34432 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 34440 [ZCL]OpCreds: Received AddNOC command
I: 34444 [DIS]Verifying the received credentials
I: 34564 [DIS]Added new fabric at index: 0x15, Initialized: 1
I: 34569 [DIS]Assigned compressed fabric ID: 0xE422C74F326417E2, node ID: 0x0000000000000001
I: 34616 [DIS]Fabric (21) persisted to storage. Calling OnFabricPersistedToStorage
I: 34623 [ZCL]OpCreds: Fabric  index 0x15 was persisted to storage. FabricId 0000000000000001, NodeId 0000000000000001, VendorId 0xFFF1
I: 34635 [ZCL]OpCreds: Call to fabricListChanged
D: 34640 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a487ae19
D: 34646 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a487ae1a
D: 34685 [EVL]LogEvent event number: 0x00000000000A0003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000877C
I: 34699 [ZCL]OpCreds: ACL entry created for Fabric 15 CASE Admin NodeId 0x000000000001B669
D: 34707 [DL]Using Thread extended MAC for hostname.
I: 34711 [DIS]Advertise operational node E422C74F326417E2-0000000000000001
D: 34718 [DMG]ICR moving to [ Preparing]
D: 34722 [DMG]ICR moving to [AddingComm]
D: 34726 [DMG]ICR moving to [AddedComma]
I: 34729 [ZCL]OpCreds: successfully created fabric index 21 via AddNOC
D: 34736 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 34743 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (21)  of type 0x9 and protocolId (0, 1) on exchange 53206r with MessageCounter:4875590.
I: 34757 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875590 to 0xFFFFFFFB00000000 (21) at monotonic time: 00000000000087C5 msec
D: 34769 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 34776 [DMG]ICR moving to [CommandSen]
D: 34779 [DMG]ICR moving to [AwaitingDe]
E: 34783 [DL]Long dispatch time: 376 ms, for event type 16388
D: 34901 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35039 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 35046 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659640 on exchange 53207r
D: 35055 [EM]Handling via exchange: 53207r, Delegate: 0x200078bc
D: 35062 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 35082 [DMG]ICR moving to [ Preparing]
D: 35086 [DMG]ICR moving to [AddingComm]
D: 35089 [DMG]ICR moving to [AddedComma]
D: 35093 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 35100 [IN]Prepared secure message 0x2002b188 to 0xFFFFFFFB00000000 (21)  of type 0x9 and protocolId (0, 1) on exchange 53207r with MessageCounter:4875591.
I: 35114 [IN]Sending encrypted msg 0x2002b188 with MessageCounter:4875591 to 0xFFFFFFFB00000000 (21) at monotonic time: 000000000000892A msec
D: 35127 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 35133 [DMG]ICR moving to [CommandSen]
D: 35137 [DMG]ICR moving to [AwaitingDe]
E: 35141 [DL]Long dispatch time: 103 ms, for event type 16388
D: 35261 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35396 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 35403 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:264659641 on exchange 53208r
D: 35413 [EM]Handling via exchange: 53208r, Delegate: 0x200078bc
D: 35419 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 35480 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 35487 [DL]OpenThread State Changed (Flags: 0x1017c100)
D: 35492 [DL]   Network Name: OpenThreadDemo2
D: 35497 [DL]   PAN Id: 0x1234
D: 35500 [DL]   Extended PAN Id: 0x1111111122222222
D: 35504 [DL]   Channel: 15
D: 35507 [DL]   Mesh Prefix: fd9c:435a:1fd9:a8e1::/64
I: 35515 [DL]CHIPoBLE advertising disabled because device is fully provisioned
D: 35522 [DL]OpenThread State Changed (Flags: 0x0100103d)
D: 35528 [DL]   Device Role: CHILD
D: 35531 [DL]   Thread Unicast Addresses:
D: 35535 [DL]        fd9c:435a:1fd9:a8e1:0:ff:fe00:804/64 valid rloc
D: 35541 [DL]        fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589/64 valid
D: 35547 [DL]        fe80::ec31:5de5:4f35:52a6/64 valid preferred
D: 35555 [DL]OpenThread State Changed (Flags: 0x00000084)
D: 35561 [DL]   Device Role: CHILD
D: 35564 [DL]   Partition Id: 0x3D997F2A
I: 35574 [SWU]Stopping the watchdog timer
I: 35579 [SWU]Starting the periodic query timer, timeout: 86400 seconds
D: 35585 [DL]Using Thread extended MAC for hostname.
I: 35593 [DL]SRP Client was started, detected server: fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d
I: 35602 [DIS]Advertise operational node E422C74F326417E2-0000000000000001
I: 35645 [SVR]Operational advertising enabled
D: 35649 [DMG]ICR moving to [ Preparing]
D: 35653 [DMG]ICR moving to [AddingComm]
D: 35657 [DMG]ICR moving to [AddedComma]
D: 35661 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 35669 [IN]Prepared secure message 0x2002b370 to 0xFFFFFFFB00000000 (21)  of type 0x9 and protocolId (0, 1) on exchange 53208r with MessageCounter:4875592.
I: 35683 [IN]Sending encrypted msg 0x2002b370 with MessageCounter:4875592 to 0xFFFFFFFB00000000 (21) at monotonic time: 0000000000008B63 msec
D: 35696 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 70)
D: 35704 [DMG]ICR moving to [CommandSen]
D: 35708 [DMG]ICR moving to [AwaitingDe]
E: 35712 [DL]Long dispatch time: 127 ms, for event type 3
D: 35718 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 925df6f3
D: 35725 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 925df6f4
D: 35733 [DL]OpenThread State Changed (Flags: 0x00000200)
D: 35739 [DL]OnSrpClientNotification: Last requested operation completed successfully
I: 35746 [DIS]Setting operational delegate post init
D: 35753 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 35758 [DL]   Thread Unicast Addresses:
D: 35762 [DL]        fd11:22::7744:b4ee:2f9d:28da/64 valid preferred
D: 35768 [DL]        fd9c:435a:1fd9:a8e1:0:ff:fe00:804/64 valid rloc
D: 35774 [DL]        fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589/64 valid
D: 35781 [DL]        fe80::ec31:5de5:4f35:52a6/64 valid preferred
I: 35788 [DIS]Updating services using commissioning mode 0
D: 35793 [DL]Using Thread extended MAC for hostname.
I: 35798 [DIS]Advertise operational node E422C74F326417E2-0000000000000001
I: 35805 [DL]advertising srp service: E422C74F326417E2-0000000000000001._matter._tcp
D: 35813 [DL]Using Thread extended MAC for hostname.
I: 35818 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
I: 35864 [DL]advertising srp service: D1D90DFEC09FA54C._matterc._udp
D: 35871 [DIS]Scheduling extended discovery timeout in 900s
E: 35913 [DL]Long dispatch time: 125 ms, for event type 32787
D: 35920 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 36672 [DL]OnSrpClientNotification: Last requested operation completed successfully
D: 38501 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 41007 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 41066 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 43811 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 46317 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 46376 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 49121 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 50831 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 50836 [IN]Clearing BLE pending packets.
I: 50839 [BLE]Releasing end point's BLE connection back to application.
I: 50846 [DL]Closing BLE GATT connection (ConnId 00)
I: 50966 [DL]BLE GAP connection terminated (reason 0x16)
I: 50971 [DL]Current number of connections: 0/1
E: 89308 [SVR]Failsafe timer expired
E: 89312 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032
D: 89321 [SC]Assigned local session key ID 20420
D: 89325 [SC]Waiting for PBKDF param request
D: 89329 [DL]CHIPoBLE advertising set to on
I: 89333 [DIS]Updating services using commissioning mode 1
D: 89338 [DL]Using Thread extended MAC for hostname.
I: 89343 [DIS]Advertise operational node E422C74F326417E2-0000000000000001
I: 89350 [DL]advertising srp service: E422C74F326417E2-0000000000000001._matter._tcp
D: 89358 [DL]Using Thread extended MAC for hostname.
I: 89399 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
I: 89409 [DL]advertising srp service: D1D90DFEC09FA54C._matterc._udp
I: 89416 [ZCL]OpCreds: Call to FailSafeCleanup
D: 89458 [IN]Expiring all connections for fabric 21!!
I: 89617 [DIS]Fabric (0x15) deleted. Calling OnFabricDeletedFromStorage
I: 89712 [ZCL]OpCreds: Fabric index 0x15 was deleted from fabric storage.
I: 89718 [ZCL]OpCreds: Call to fabricListChanged
D: 89722 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a487ae1b
D: 89729 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a487ae1c
D: 89736 [EVL]LogEvent event number: 0x00000000000A0004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015E87
D: 89750 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 89783 [DIS]Updating services using commissioning mode 1
D: 89789 [DL]Using Thread extended MAC for hostname.
I: 89794 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15
I: 89803 [DL]advertising srp service: D1D90DFEC09FA54C._matterc._udp
D: 89810 [DIS]Scheduling discovery timeout in 900s
I: 89851 [DL]removing srp service: E422C74F326417E2-0000000000000001._matter._tcp
D: 89858 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to d2708b3e
D: 89865 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 89943 [DL]Long dispatch time: 635 ms, for event type 32785
I: 89954 [DL]CHIPoBLE advertising started
D: 89958 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 89965 [DL]   Device Role: DISABLED
D: 89968 [DL]   Thread Unicast Addresses:
D: 89972 [DL]        fd11:22::7744:b4ee:2f9d:28da/64 valid preferred
D: 89979 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 89991 [DL]NFC Tag emulation started
I: 119958 [DL]CHIPoBLE advertising mode changed to slow

Sep  5 18:29:07 eb75652d08f2 otbr-agent[163]: 22:59:11.394 [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
Sep  5 18:29:07 eb75652d08f2 otbr-agent[163]: 22:59:11.400 [I] MeshForwarder-: Sent IPv6 UDP msg, len:90, chksum:6aa8, ecn:no, to:0xffff, sec:no, prio:net
Sep  5 18:29:07 eb75652d08f2 otbr-agent[163]: 22:59:11.400 [I] MeshForwarder-:     src:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:07 eb75652d08f2 otbr-agent[163]: 22:59:11.400 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] MeshForwarder-: Received IPv6 UDP msg, len:88, chksum:2c3d, ecn:no, from:ee315de54f3552a6, sec:no, prio:net, rss:-41.0
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] MeshForwarder-:     src:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] MeshForwarder-:     dst:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] Mle-----------: Receive Child Update Request from child (fe80:0:0:0:ec31:5de5:4f35:52a6)
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] Mle-----------: Child 0x0804 IPv6 address[1]=fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] Mle-----------: Child 0x0804 has 1 registered IPv6 address, 1 address stored
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.205 [I] Mle-----------: Send Child Update Response to child (fe80:0:0:0:ec31:5de5:4f35:52a6,0x0804)
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.214 [I] MeshForwarder-: Sent IPv6 UDP msg, len:105, chksum:0b5d, ecn:no, to:ee315de54f3552a6, sec:no, prio:net
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.214 [I] MeshForwarder-:     src:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.214 [I] MeshForwarder-:     dst:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.279 [I] MeshForwarder-: Received IPv6 UDP msg, len:77, chksum:8fc9, ecn:no, from:ee315de54f3552a6, sec:no, prio:net, rss:-42.0
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.279 [I] MeshForwarder-:     src:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.279 [I] MeshForwarder-:     dst:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.279 [I] Mle-----------: Receive Data Request (fe80:0:0:0:ec31:5de5:4f35:52a6)
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.279 [I] Mle-----------: Send Data Response (fe80:0:0:0:ec31:5de5:4f35:52a6)
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.301 [I] MeshForwarder-: Sent IPv6 UDP msg, len:172, chksum:c11e, ecn:no, to:ee315de54f3552a6, sec:yes, prio:net
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.301 [I] MeshForwarder-:     src:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:11 eb75652d08f2 otbr-agent[163]: 22:59:16.301 [I] MeshForwarder-:     dst:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.423 [I] MeshForwarder-: Received IPv6 UDP msg, len:313, chksum:11a1, ecn:no, from:0x0804, sec:yes, prio:normal, rss:-41.0
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.423 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.423 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.423 [I] SrpServer-----: Received DNS update from fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.434 [I] SrpServer-----: SRP update handler is notified (updatedId = 1638691224)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Advertise SRP service updates: host=EE315DE54F3552A6.default.service.arpa.
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Unpublish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Removing service E422C74F326417E2-0000000000000001._matter._tcp
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle unpublish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.': OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Waiting for more publishing callbacks 2
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Unpublish SRP service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Removing service 9FB1CB22B8B2362B._matterc._udp
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle unpublish SRP service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.': OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Waiting for more publishing callbacks 1
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Unpublish SRP host 'EE315DE54F3552A6.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Removing host EE315DE54F3552A6
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Removed host EE315DE54F3552A6
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Send goodbye message for host EE315DE54F3552A6.local address fd11:22::7744:b4ee:2f9d:28da: OK: OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Remove record for host EE315DE54F3552A6.local address fd11:22::7744:b4ee:2f9d:28da: OK: OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle unpublish SRP host 'EE315DE54F3552A6.default.service.arpa.': OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Handler result of SRP update (id = 1638691224) is received: OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove host EE315DE54F3552A6.default.service.arpa. (but retain its name)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.' subtype:_CM
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.' subtype:_V65521
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.' subtype:_S15
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '9FB1CB22B8B2362B._matterc._udp.default.service.arpa.' subtype:_L3840
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.' subtype:_IE422C74F326417E2
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'FD4B81C3C662331F._matterc._udp.default.service.arpa.' subtype:_CM
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'FD4B81C3C662331F._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'FD4B81C3C662331F._matterc._udp.default.service.arpa.' subtype:_V65521
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'FD4B81C3C662331F._matterc._udp.default.service.arpa.' subtype:_S15
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'FD4B81C3C662331F._matterc._udp.default.service.arpa.' subtype:_L3840
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'B5AE56709FBCA93D._matterc._udp.default.service.arpa.' subtype:_CM
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'B5AE56709FBCA93D._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'B5AE56709FBCA93D._matterc._udp.default.service.arpa.' subtype:_V65521
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'B5AE56709FBCA93D._matterc._udp.default.service.arpa.' subtype:_S15
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service 'B5AE56709FBCA93D._matterc._udp.default.service.arpa.' subtype:_L3840
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '2392C7AEB8E6786E._matterc._udp.default.service.arpa.' subtype:_CM
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '2392C7AEB8E6786E._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '2392C7AEB8E6786E._matterc._udp.default.service.arpa.' subtype:_V65521
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '2392C7AEB8E6786E._matterc._udp.default.service.arpa.' subtype:_S15
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '2392C7AEB8E6786E._matterc._udp.default.service.arpa.' subtype:_L3840
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '0BE7E3D5C69D528F-0000000000000002._matter._tcp.default.service.arpa.' subtype:_I0BE7E3D5C69D528F
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Remove but retain name of service '0BE7E3D5C69D528F-0000000000000002._matter._tcp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] SrpServer-----: Send success response
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] MeshForwarder-: Received IPv6 UDP msg, len:107, chksum:5339, ecn:no, from:ee315de54f3552a6, sec:no, prio:net, rss:-42.0
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] MeshForwarder-:     src:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] MeshForwarder-:     dst:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] Mle-----------: Receive Child Update Request from child (fe80:0:0:0:ec31:5de5:4f35:52a6)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] Mle-----------: Child 0x0804 IPv6 address[1]=fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] Mle-----------: Child 0x0804 IPv6 address[2]=fd11:22:0:0:7744:b4ee:2f9d:28da
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] Mle-----------: Child 0x0804 has 2 registered IPv6 addresses, 2 addresses stored
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.435 [I] Mle-----------: Send Child Update Response to child (fe80:0:0:0:ec31:5de5:4f35:52a6,0x0804)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.442 [I] MeshForwarder-: Sent IPv6 UDP msg, len:98, chksum:34f0, ecn:no, to:ee315de54f3552a6, sec:no, prio:net
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.442 [I] MeshForwarder-:     src:[fe80:0:0:0:cc49:50f3:46b1:2083]:19788
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.442 [I] MeshForwarder-:     dst:[fe80:0:0:0:ec31:5de5:4f35:52a6]:19788
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.448 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:5045, ecn:no, to:0x0804, sec:yes, prio:low
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.448 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.448 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.665 [I] MeshForwarder-: Received IPv6 UDP msg, len:505, chksum:e127, ecn:no, from:0x0804, sec:yes, prio:normal, rss:-41.0
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.665 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.665 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.665 [I] SrpServer-----: Received DNS update from fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.686 [I] SrpServer-----: SRP update handler is notified (updatedId = 1638691225)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Advertise SRP service updates: host=EE315DE54F3552A6.default.service.arpa.
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Publish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Registering new service E422C74F326417E2-0000000000000001._matter._tcp,_IE422C74F326417E2.local, serviceRef = (nil)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Publish SRP host 'EE315DE54F3552A6.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Registering new host EE315DE54F3552A6
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Received reply for host EE315DE54F3552A6.local: OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Successfully registered host EE315DE54F3552A6.local
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle publish SRP host 'EE315DE54F3552A6.default.service.arpa.': OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Waiting for more publishing callbacks 1
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.720 [I] MeshForwarder-: Received IPv6 UDP msg, len:719, chksum:fc1d, ecn:no, from:0x0804, sec:yes, prio:normal, rss:-41.125
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.720 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.720 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.720 [I] SrpServer-----: Received DNS update from fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: 22:59:16.739 [I] SrpServer-----: SRP update handler is notified (updatedId = 1638691226)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Advertise SRP service updates: host=EE315DE54F3552A6.default.service.arpa.
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Publish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Publish SRP service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Registering new service D1D90DFEC09FA54C._matterc._udp,_L3840,_S15,_V65521.local, serviceRef = (nil)
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [DEBG]-ADPROXY-: Publish SRP host 'EE315DE54F3552A6.default.service.arpa.'
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle publish SRP host 'EE315DE54F3552A6.default.service.arpa.': OK
Sep  5 18:29:12 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Waiting for more publishing callbacks 2
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Received reply for service D1D90DFEC09FA54C._matterc._udp., serviceRef = 0x55d80fc38160
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Successfully registered service D1D90DFEC09FA54C._matterc._udp.
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle publish SRP service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.': OK
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Waiting for more publishing callbacks 1
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Received reply for service E422C74F326417E2-0000000000000001._matter._tcp., serviceRef = 0x55d80fc385a0
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-MDNS----: Successfully registered service E422C74F326417E2-0000000000000001._matter._tcp.
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle publish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.': OK
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.371 [I] SrpServer-----: Handler result of SRP update (id = 1638691225) is received: OK
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.371 [I] SrpServer-----: Update host EE315DE54F3552A6.default.service.arpa.
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.371 [I] SrpServer-----: Update existing service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.' subtype:_IE422C74F326417E2
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Update existing service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Send success response
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: [INFO]-ADPROXY-: Handle publish SRP service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.': OK
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Handler result of SRP update (id = 1638691226) is received: OK
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Update host EE315DE54F3552A6.default.service.arpa.
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Update existing service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.' subtype:_IE422C74F326417E2
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Update existing service 'E422C74F326417E2-0000000000000001._matter._tcp.default.service.arpa.'
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Add new service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.' subtype:_L3840
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Add new service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.' subtype:_S15
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Add new service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.' subtype:_V65521
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Add new service 'D1D90DFEC09FA54C._matterc._udp.default.service.arpa.'
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.372 [I] SrpServer-----: Send success response
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.379 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:08a3, ecn:no, to:0x0804, sec:yes, prio:low
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.379 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.379 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.386 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:0f7b, ecn:no, to:0x0804, sec:yes, prio:low
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.386 [I] MeshForwarder-:     src:[fd9c:435a:1fd9:a8e1:6421:5b4d:9879:766d]:53535
Sep  5 18:29:13 eb75652d08f2 otbr-agent[163]: 22:59:17.386 [I] MeshForwarder-:     dst:[fd9c:435a:1fd9:a8e1:9f70:cb85:5d62:3589]:49155

output from the open thread border router:

[Charlie]

Hi filipmrazek,

Sorry for the late reply. I am traveling this week.

I will try to test with the same setup next week and see if I can reproduce this issue. Hope to give you feedback soon.

Best regards,

Charlie

[Charlie]

Hi Filipmrazek,

See the following suggestion for a similar issue, is this your case?

The possible reason may be that you are trying to use an already-reserved nodeID to commission the device. A typical mistake is the following scenario:

1) Developer commissions device using node ID 1

2) Developer factory resets the device

3) Developer tries to commission the same device using node ID=1.

In such a case, OTBR won't allow to register the same service again because it thinks it's already reserved. Resetting OTBR can be a workaround. Please also make sure that you are using the latest OTBR.

Best regards,

Charlie