Hi,
I want to test Matter over Thread, with the Matter: Light Bulb example from nRF Connect. The Border Router and controller are on the same device RPi 3 Model B+.
I've referred https://www.youtube.com/watch?v=9Ar13rMxGIk
The border router is working correctly, and I tested Matter over Thread and Matter binding as explained in the above video.
When I try to do it again, it gives the error which I am not able to solve even after referring to devzone tickets eg RE: Matter : unable to de-commisioning a device Matter over Thread Commissioning failed , RE: Matter device pairing issue with chip-tool
Environment:
- nRF Connect for Desktop ncs version 2.4.0
- Chip-Tool (controller) version 2.4.0, compile it from source on Ubuntu 22.04.
- Same RPi 3 Model B+ as Threat Border Router coupled with nRF52840dk as radio co-processor
- nRF5340dk as Light Bulb and nRF5340dk as Light Switch
Matter Light-Bulb logs :
uart:~$ *** Booting Zephyr OS build v3.3.99-ncs1 *** I: Init CHIP stack I: 486 [DL]BLE address: D6:D4:2D:E5:96:79 I: 508 [DL]OpenThread started: OK I: 511 [DL]Setting OpenThread device type to ROUTER I: 516 [SVR]Subscription persistence not supported I: 521 [SVR]Server initializing... I: 524 [TS]Last Known Good Time: 2023-08-07T15:17:34 I: 529 [DMG]AccessControl: initializing I: 533 [DMG]Examples::AccessControlDelegate::Init I: 538 [DMG]AccessControl: setting I: 541 [DMG]DefaultAclStorage: initializing I: 545 [DMG]DefaultAclStorage: 0 entries loaded D: 549 [IN]UDP::Init bind&listen port=5540 E: 553 [IN]SO_REUSEPORT failed: 109 D: 556 [IN]UDP::Init bound to port=5540 D: 560 [IN]BLEBase::Init - setting/overriding transport D: 565 [IN]TransportMgr initialized D: 570 [DL]Using Thread extended MAC for hostname. I: 575 [ZCL]Using ZAP configuration... I: 581 [DMG]AccessControlCluster: initializing D: 585 [DL]Boot reason: 1 I: 588 [ZCL]Initiating Admin Commissioning cluster. I: 592 [ZCL]Endpoint 1 On/off already set to new value I: 598 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 605 [IN]SecureSession[0x20004260]: Allocated Type:1 LSID:58177 D: 611 [DL]CHIPoBLE advertising set to on I: 615 [DIS]Updating services using commissioning mode 1 E: 620 [DIS]Failed to remove advertised services: 3 D: 625 [DL]Using Thread extended MAC for hostname. I: 630 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discri minator=3840/15 cm=1 E: 639 [DIS]Failed to advertise commissionable node: 3 E: 644 [DIS]Failed to finalize service update: 3 I: 648 [DIS]Updating services using commissioning mode 1 E: 653 [DIS]Failed to remove advertised services: 3 D: 658 [DL]Using Thread extended MAC for hostname. I: 663 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discri minator=3840/15 cm=1 E: 672 [DIS]Failed to advertise commissionable node: 3 E: 676 [DIS]Failed to finalize service update: 3 I: 681 [DIS]Delaying proxy of operational discovery: missing delegate I: 687 [IN]CASE Server enabling CASE session setups D: 692 [IN]SecureSession[0x20004318]: Allocated Type:2 LSID:58178 I: 698 [SVR]Joining Multicast groups I: 702 [SVR]Server Listening... I: 704 [DL]Device Configuration: I: 708 [DL] Serial Number: 11223344556677889900 I: 712 [DL] Vendor Id: 65521 (0xFFF1) I: 716 [DL] Product Id: 32773 (0x8005) I: 719 [DL] Product Name: not-specified I: 723 [DL] Hardware Version: 0 I: 726 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 732 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 739 [DL] Manufacturing Date: (not set) I: 742 [DL] Device Type: 65535 (0xFFFF) I: 747 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 751 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 757 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3 A6FCJ142C00KA0648G00 I: 766 [SVR]Manual pairing code: [34970112332] I: 772 [DL]CHIP task running I: 778 [DL]CHIPoBLE advertising started I: 782 [ZCL]Cluster OnOff: attribute OnOff set to 0 I: 787 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 I: 793 [DL]NFC Tag emulation started uart:~$ I: 30781 [DL]CHIPoBLE advertising mode changed to slow I: 30791 [DL]CHIPoBLE advertising started uart:~$ I: 66444 [DL]BLE connection established (ConnId: 0x00) I: 66450 [DL]Current number of connections: 1/1 I: 66454 [DL]CHIPoBLE advertising stopped I: 66458 [DL]NFC Tag emulation stopped D: 68320 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 68327 [BLE]local and remote recv window sizes = 5 I: 68332 [BLE]selected BTP version 4 I: 68335 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 68410 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 68414 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 68422 [IN]BLE EndPoint 0x2000a810 Connection Complete I: 68427 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 68544 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 68553 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 68560 [EM]>>> [E:10221r S:0 M:20908917] (U) Msg RX from 0:6BE60A87970DB2B3 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 68573 [EM]<<< [E:10221r S:0 M:59763049] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 68585 [IN](U) Sending msg 59763049 to IP address 'BLE' D: 68591 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140) D: 68679 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 68688 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 68695 [EM]>>> [E:10221r S:0 M:20908918] (U) Msg RX from 0:6BE60A87970DB2B3 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 70107 [EM]<<< [E:10221r S:0 M:59763050] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 70119 [IN](U) Sending msg 59763050 to IP address 'BLE' D: 70124 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132) E: 70132 [DL]Long dispatch time: 1443 ms, for event type 16388 D: 70209 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70218 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 70225 [EM]>>> [E:10221r S:0 M:20908919] (U) Msg RX from 0:6BE60A87970DB2B3 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 70237 [EM]<<< [E:10221r S:0 M:59763051] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 70249 [IN](U) Sending msg 59763051 to IP address 'BLE' D: 70254 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 70263 [SC]SecureSession[0x20004260]: Moving from state 'kEstablishing' --> 'kActive' D: 70270 [IN]SecureSession[0x20004260]: Activated - Type:1 LSID:58177 D: 70277 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:58177 PSID:9181! I: 70286 [SVR]Commissioning completed session establishment step I: 70292 [DIS]Updating services using commissioning mode 0 E: 70297 [DIS]Failed to remove advertised services: 3 D: 70302 [DL]Using Thread extended MAC for hostname. I: 70307 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 70316 [DIS]Failed to advertise extended commissionable node: 3 D: 70322 [DIS]Scheduling extended discovery timeout in 900s E: 70328 [DIS]Failed to finalize service update: 3 D: 70332 [DL]CHIPoBLE advertising set to off I: 70336 [SVR]Device completed Rendezvous process E: 70341 [DL]Long dispatch time: 123 ms, for event type 16388 D: 70347 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70355 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 70363 [EM]>>> [E:10222r S:58177 M:14390293] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 70374 [IM]Received Read request I: 70384 [EM]<<< [E:10222r S:58177 M:97649281] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 70394 [IN](S) Sending msg 97649281 on secure session with LSID: 58177 D: 70401 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 70480 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70487 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21) D: 70614 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70623 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 70631 [EM]>>> [E:10223r S:58177 M:14390294] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 70643 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 70650 [EM]<<< [E:10223r S:58177 M:97649282] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 70661 [IN](S) Sending msg 97649282 on secure session with LSID: 58177 D: 70668 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 70794 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70803 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 70811 [EM]>>> [E:10224r S:58177 M:14390295] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 70825 [EM]<<< [E:10224r S:58177 M:97649283] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 70837 [IN](S) Sending msg 97649283 on secure session with LSID: 58177 D: 70843 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 70974 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 70983 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 70991 [EM]>>> [E:10225r S:58177 M:14390296] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 71003 [ZCL]OpCreds: Certificate Chain request received for PAI I: 71012 [EM]<<< [E:10225r S:58177 M:97649284] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 71024 [IN](S) Sending msg 97649284 on secure session with LSID: 58177 D: 71030 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 71155 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71162 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 71335 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71342 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48) D: 71425 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71471 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 71479 [EM]>>> [E:10226r S:58177 M:14390297] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 71491 [ZCL]OpCreds: Certificate Chain request received for DAC I: 71500 [EM]<<< [E:10226r S:58177 M:97649285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 71512 [IN](S) Sending msg 97649285 on secure session with LSID: 58177 D: 71519 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 71605 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71612 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 71695 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71702 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77) D: 71784 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71793 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 71801 [EM]>>> [E:10227r S:58177 M:14390298] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 71813 [ZCL]OpCreds: Received an AttestationRequest command I: 71850 [ZCL]OpCreds: AttestationRequest successful. I: 71859 [EM]<<< [E:10227r S:58177 M:97649286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 71870 [IN](S) Sending msg 97649286 on secure session with LSID: 58177 D: 71877 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 71965 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 71972 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 72100 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 72107 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235) D: 72279 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 72288 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 72296 [EM]>>> [E:10228r S:58177 M:14390299] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 72308 [ZCL]OpCreds: Received a CSRRequest command I: 72459 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 72496 [ZCL]OpCreds: CSRRequest successful. I: 72502 [EM]<<< [E:10228r S:58177 M:97649287] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 72514 [IN](S) Sending msg 97649287 on secure session with LSID: 58177 D: 72520 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) E: 72528 [DL]Long dispatch time: 240 ms, for event type 16388 D: 72640 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 72647 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138) D: 72730 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 72777 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 72790 [DIS]Updating services using commissioning mode 0 E: 72796 [DIS]Failed to remove advertised services: 3 D: 72800 [DL]Using Thread extended MAC for hostname. I: 72806 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 72815 [DIS]Failed to advertise extended commissionable node: 3 E: 72821 [DIS]Failed to finalize service update: 3 E: OpenBasicCommissioningWindow() failed D: 72865 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 72875 [EM]>>> [E:10229r S:58177 M:14390300] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 72887 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 72951 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 72958 [EM]<<< [E:10229r S:58177 M:97649288] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 72969 [IN](S) Sending msg 97649288 on secure session with LSID: 58177 D: 72976 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68) E: 72984 [DL]Long dispatch time: 119 ms, for event type 16388 D: 73045 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 73053 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 73137 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 73226 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 73236 [EM]>>> [E:10230r S:58177 M:14390301] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 73248 [ZCL]OpCreds: Received an AddNOC command I: 73255 [FP]Validating NOC chain I: 73373 [FP]NOC chain validation successful I: 73377 [FP]Added new fabric at index: 0x1 I: 73381 [FP]Assigned compressed fabric ID: 0xCEFAD72140B20CDA, node ID: 0x0000000000000001 I: 73390 [TS]Last Known Good Time: 2023-08-07T15:17:34 I: 73395 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 73401 [TS]Retaining current Last Known Good Time I: 73413 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 D: 73422 [DL]Using Thread extended MAC for hostname. I: 73427 [DIS]Advertise operational node CEFAD72140B20CDA-0000000000000001 I: 73434 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 73441 [EM]<<< [E:10230r S:58177 M:97649289] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 73453 [IN](S) Sending msg 97649289 on secure session with LSID: 58177 D: 73460 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) E: 73467 [DL]Long dispatch time: 242 ms, for event type 16388 D: 73585 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 73593 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 73601 [EM]>>> [E:10231r S:58177 M:14390302] (S) Msg RX from 1:FFFFFFFB00000000 [0CDA] --- Type 0001:08 (IM:InvokeCommandRequest) I: 73616 [EM]<<< [E:10231r S:58177 M:97649290] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 73628 [IN](S) Sending msg 97649290 on secure session with LSID: 58177 D: 73634 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 73720 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 73728 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 73736 [EM]>>> [E:10232r S:58177 M:14390303] (S) Msg RX from 1:FFFFFFFB00000000 [0CDA] --- Type 0001:08 (IM:InvokeCommandRequest) I: 73748 [FS]GeneralCommissioning: Received ArmFailSafe (76s) I: 73755 [EM]<<< [E:10232r S:58177 M:97649291] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 73766 [IN](S) Sending msg 97649291 on secure session with LSID: 58177 D: 73773 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 73855 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 73863 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 73871 [EM]>>> [E:10233r S:58177 M:14390304] (S) Msg RX from 1:FFFFFFFB00000000 [0CDA] --- Type 0001:08 (IM:InvokeCommandRequest) D: 73893 [DL]OpenThread State Changed (Flags: 0x101fc100) D: 73898 [DL] Network Name: OpenThread-5a7f D: 73902 [DL] PAN Id: 0x5A7F D: 73905 [DL] Extended PAN Id: 0x1CEA9DCCAAC89EDC D: 73910 [DL] Channel: 16 D: 73913 [DL] Mesh Prefix: fdaa:96d0:9e1b:6904::/64 D: 73918 [DL]OpenThread State Changed (Flags: 0x1100101d) D: 73923 [DL] Device Role: DETACHED D: 73927 [DL] Thread Unicast Addresses: D: 73931 [DL] fdaa:96d0:9e1b:6904:765f:4f02:b363:438/64 valid D: 73937 [DL] fe80::58d0:969a:1fe:ede8/64 valid preferred I: 75282 [DL]SRP Client was started, detected server: fdaa:96d0:9e1b:6904:0f6a:acb6:d9f3:1763 D: 75291 [DL]OpenThread State Changed (Flags: 0x200012a4) D: 75296 [DL] Device Role: CHILD D: 75299 [DL] Partition Id: 0x264E277C D: 75304 [DL]OpenThread State Changed (Flags: 0x00000001) D: 75309 [DL] Thread Unicast Addresses: D: 75313 [DL] fd8a:1ee1:ee51:1:38ba:7745:f335:aa0b/64 valid preferred D: 75320 [DL] fdaa:96d0:9e1b:6904:0:ff:fe00:a405/64 valid rloc D: 75326 [DL] fdaa:96d0:9e1b:6904:765f:4f02:b363:438/64 valid D: 75332 [DL] fe80::58d0:969a:1fe:ede8/64 valid preferred I: 75340 [EM]<<< [E:10233r S:58177 M:97649292] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 75351 [IN](S) Sending msg 97649292 on secure session with LSID: 58177 D: 75358 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70) D: 75366 [DL]Using Thread extended MAC for hostname. I: 75370 [DIS]Advertise operational node CEFAD72140B20CDA-0000000000000001 I: 75377 [SVR]Operational advertising enabled D: 75430 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 76134 [DL]SRP update succeeded I: 76137 [DIS]Setting operational delegate post init I: 76145 [SWU]Stopping the watchdog timer I: 76149 [SWU]Starting the periodic query timer, timeout: 86400 seconds E: 76156 [SVR]Server initialization complete I: 76160 [DIS]Updating services using commissioning mode 0 D: 76165 [DL]Using Thread extended MAC for hostname. I: 76170 [DIS]Advertise operational node CEFAD72140B20CDA-0000000000000001 I: 76177 [DL]advertising srp service: CEFAD72140B20CDA-0000000000000001._matter._tcp D: 76185 [DL]Using Thread extended MAC for hostname. I: 76190 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 I: 76199 [DL]advertising srp service: 13A01013B94B964C._matterc._udp E: 76988 [DL]SRP update error: domain name or RRset is duplicated D: 78265 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) E: 78830 [DL]SRP update error: domain name or RRset is duplicated D: 80773 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 80965 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) E: 81922 [DL]SRP update error: domain name or RRset is duplicated D: 83710 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 85165 [DL]OpenThread State Changed (Flags: 0x00000064) D: 85171 [DL] Device Role: ROUTER D: 86217 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 86455 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) E: 87155 [DL]SRP update error: domain name or RRset is duplicated D: 88930 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 91438 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 91630 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 91766 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 91774 [EM]>>> [E:10235r S:58177 M:14390305] (S) Msg RX from 1:FFFFFFFB00000000 [0CDA] --- Type 0001:08 (IM:InvokeCommandRequest) I: 91786 [FS]GeneralCommissioning: Received ArmFailSafe (68s) I: 91793 [EM]<<< [E:10235r S:58177 M:97649293] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 91804 [IN](S) Sending msg 97649293 on secure session with LSID: 58177 D: 91811 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 91900 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 94646 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) E: 96048 [DL]SRP update error: domain name or RRset is duplicated D: 97153 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 97301 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 100091 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 102598 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 102791 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 105536 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 108044 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 108236 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 109002 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 109010 [EM]>>> [E:10237r S:58177 M:14390306] (S) Msg RX from 1:FFFFFFFB00000000 [0CDA] --- Type 0001:08 (IM:InvokeCommandRequest) I: 109022 [FS]GeneralCommissioning: Received ArmFailSafe (103s) I: 109029 [EM]<<< [E:10237r S:58177 M:97649294] (S) Msg TX to 1:FFFFFFFB00000000 [0CDA] --- Type 0001:09 (IM:InvokeCommandResponse) I: 109041 [IN](S) Sending msg 97649294 on secure session with LSID: 58177 D: 109047 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 109136 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) E: 111095 [DL]SRP update error: domain name or RRset is duplicated D: 111881 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 114389 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 114671 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 117326 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 119834 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 120116 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 122907 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 125414 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 125607 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 128352 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 130859 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 131052 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 133797 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 136304 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 136407 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) E: 136676 [DL]SRP update error: domain name or RRset is duplicated D: 139242 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 141750 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 141942 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 144778 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 147286 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 147703 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 150493 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 153000 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 153103 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 155893 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 158401 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 158593 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 161383 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 161473 [DL]ConnId: 0x00, New CCCD value: 0x0000 D: 161478 [IN]Clearing BLE pending packets. I: 161482 [BLE]Releasing end point's BLE connection back to application. I: 161488 [DL]Closing BLE GATT connection (ConnId 00) I: 161608 [DL]BLE GAP connection terminated (reason 0x16) I: 161613 [DL]Current number of connections: 0/1 E: 180100 [DL]SRP update error: domain name or RRset is duplicated I: 212028 [FS]Fail-safe timer expired E: 212031 [SVR]Failsafe timer expired D: 212035 [IN]SecureSession[0x20004260]: MarkForEviction Type:1 LSID:58177 I: 212041 [SC]SecureSession[0x20004260]: Moving from state 'kActive' --> 'kPendingEviction' D: 212050 [IN]SecureSession[0x20004260]: Released - Type:1 LSID:58177 E: 212056 [SVR]Commissioning failed (attempt 1): 32 I: 212060 [DIS]Updating services using commissioning mode 0 D: 212066 [DL]Using Thread extended MAC for hostname. I: 212071 [DIS]Advertise operational node CEFAD72140B20CDA-0000000000000001 D: 212078 [DL]Using Thread extended MAC for hostname. I: 212083 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 212093 [ZCL]OpCreds: Got FailSafeTimerExpired E: 212097 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 212104 [IN]Expiring all sessions for fabric 0x1!! E: 212109 [FP]Reverting pending fabric data for fabric 0x1 E: 212115 [FP]Warning: metadata not found during delete of fabric 0x1 I: 212126 [FP]Fabric (0x1) deleted. I: 212129 [ZCL]OpCreds: Fabric index 0x1 was removed I: 212134 [DIS]Updating services using commissioning mode 0 D: 212139 [DL]Using Thread extended MAC for hostname. I: 212145 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 I: 212154 [DL]advertising srp service: 13A01013B94B964C._matterc._udp I: 212161 [DL]removing srp service: CEFAD72140B20CDA-0000000000000001._matter._tcp I: 212181 [TS]Pending Last Known Good Time: 2023-08-07T15:17:34 I: 212187 [TS]Previous Last Known Good Time: 2023-08-07T15:17:34 I: 212193 [TS]Reverted Last Known Good Time to previous value E: 212199 [FP]Warning: metadata not found during delete of fabric 0x1 E: 212207 [ZCL]OpCreds: failed to delete fabric at index 1: d8 I: 212213 [NP]Reverting Thread operational dataset E: 212223 [DL]Long dispatch time: 192 ms, for event type 32782 I: 212228 [FS]Fail-safe cleanly disarmed D: 212232 [DL]OpenThread State Changed (Flags: 0x11002046) D: 212237 [DL] Device Role: DISABLED D: 212241 [DL] Thread Unicast Addresses: D: 212245 [DL] fd8a:1ee1:ee51:1:38ba:7745:f335:aa0b/64 valid preferred D: 212252 [DL]OpenThread State Changed (Flags: 0x10000000)
Chip tool error log :
lenovo@lenovo-ThinkPad-L470:~/Downloads$ ./chip-tool-debug pairing ble-thread 1 hex:0e080000000000010000000300001035060004001fffe002081cea9dccaac89edc0708fdaa96d09e1b690405101416c358c6964dcc95d99f3d4d068a93030f4f70656e5468726561642d3561376601025a7f0410fe82415a7b2f71353c3b468190356fde0c0402a0f7f8 20202021 3840
[1691403080.695655][7870:7870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1691403080.695798][7870:7870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1691403080.695830][7870:7870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1691403080.695850][7870:7870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1691403080.695955][7870:7870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vbHOcT)
[1691403080.696120][7870:7870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1691403080.696133][7870:7870] CHIP:DL: NVS set: chip-counters/reboot-count = 27 (0x1B)
[1691403080.696265][7870:7870] CHIP:DL: Got Ethernet interface: enp0s31f6
[1691403080.696358][7870:7870] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1691403080.696460][7870:7870] CHIP:DL: Got WiFi interface: wlp5s0
[1691403080.698000][7870:7870] CHIP:DL: Found the primary WiFi interface:wlp5s0
[1691403080.698021][7870:7870] CHIP:IN: UDP::Init bind&listen port=0
[1691403080.698044][7870:7870] CHIP:IN: UDP::Init bound to port=59227
[1691403080.698049][7870:7870] CHIP:IN: UDP::Init bind&listen port=0
[1691403080.698066][7870:7870] CHIP:IN: UDP::Init bound to port=43359
[1691403080.698070][7870:7870] CHIP:IN: BLEBase::Init - setting/overriding transport
[1691403080.698075][7870:7870] CHIP:IN: TransportMgr initialized
[1691403080.698086][7870:7870] CHIP:FP: Initializing FabricTable from persistent storage
[1691403080.698137][7870:7870] CHIP:TS: Last Known Good Time: 2023-06-01T07:38:45
[1691403080.698280][7870:7870] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xCEFAD72140B20CDA, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1691403080.698764][7870:7870] CHIP:ZCL: Using ZAP configuration...
[1691403080.700414][7870:7870] CHIP:DL: Avahi client registered
[1691403080.700842][7870:7870] CHIP:CTL: System State Initialized...
[1691403080.700892][7870:7870] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1691403080.700905][7870:7870] CHIP:CTL: Setting attestation nonce to random value
[1691403080.700910][7870:7870] CHIP:CTL: Setting CSR nonce to random value
[1691403080.700999][7870:7872] CHIP:DL: CHIP task running
[1691403080.701050][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1691403080.701143][7870:7872] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1691403080.701157][7870:7872] CHIP:CTL: Setting attestation nonce to random value
[1691403080.701163][7870:7872] CHIP:CTL: Setting CSR nonce to random value
[1691403080.705197][7870:7872] CHIP:CTL: Generating NOC
[1691403080.708961][7870:7872] CHIP:FP: Validating NOC chain
[1691403080.723069][7870:7872] CHIP:FP: NOC chain validation successful
[1691403080.723089][7870:7872] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1691403080.723096][7870:7872] CHIP:TS: Last Known Good Time: 2023-06-01T07:38:45
[1691403080.723101][7870:7872] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1691403080.723104][7870:7872] CHIP:TS: Retaining current Last Known Good Time
[1691403080.724161][7870:7872] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1691403080.724569][7870:7872] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-01T07:38:45
[1691403080.724932][7870:7872] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: CEFAD72140B20CDA)
[1691403080.728092][7870:7872] CHIP:CTL: Setting thread operational dataset from parameters
[1691403080.728100][7870:7872] CHIP:CTL: Setting attestation nonce to random value
[1691403080.728107][7870:7872] CHIP:CTL: Setting CSR nonce to random value
[1691403080.728112][7870:7872] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1691403080.729827][7870:7871] CHIP:DL: TRACE: Bus acquired for name C-1ebe
[1691403080.735725][7870:7872] CHIP:DL: PlatformBlueZInit init success
[1691403080.740247][7870:7871] CHIP:BLE: BLE removing known devices.
[1691403080.740863][7870:7871] CHIP:BLE: BLE initiating scan.
[1691403080.860396][7870:7872] CHIP:DL: Long dispatch time: 133 ms, for event type 2
[1691403080.869867][7870:7871] CHIP:BLE: Device 4E:30:D0:20:6D:9E does not look like a CHIP device.
[1691403080.873693][7870:7871] CHIP:BLE: Device 39:32:16:2C:07:FB does not look like a CHIP device.
[1691403080.883155][7870:7871] CHIP:BLE: New device scanned: F4:10:CB:75:55:F1
[1691403080.883183][7870:7871] CHIP:BLE: Device discriminator match. Attempting to connect.
[1691403081.051609][7870:7871] CHIP:DL: ConnectDevice complete
[1691403082.571903][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0001
[1691403082.571922][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571931][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0001
[1691403082.571937][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571944][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0001
[1691403082.571949][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571961][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571967][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571977][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571983][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.571994][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.572000][7870:7871] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_10_CB_75_55_F1/service0010
[1691403082.572009][7870:7871] CHIP:DL: New BLE connection 0x7f942c056c60, device F4:10:CB:75:55:F1, path /org/bluez/hci0/dev_F4_10_CB_75_55_F1
[1691403082.572049][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1691403082.572063][7870:7872] CHIP:DIS: Closing all BLE connections
[1691403082.572092][7870:7872] CHIP:IN: BleConnectionComplete: endPoint 0x55a38d3403c0
[1691403082.572209][7870:7872] CHIP:IN: SecureSession[0x7f94240095a0]: Allocated Type:1 LSID:15906
[1691403082.572220][7870:7872] CHIP:SC: Assigned local session key ID 15906
[1691403082.572247][7870:7872] CHIP:EM: <<< [E:58373i S:0 M:166617635] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1691403082.572263][7870:7872] CHIP:IN: (U) Sending msg 166617635 to IP address 'BLE'
[1691403082.572274][7870:7872] CHIP:IN: Message appended to BLE send queue
[1691403082.572282][7870:7872] CHIP:SC: Sent PBKDF param request
[1691403082.894145][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403082.985283][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1691403082.985320][7870:7872] CHIP:BLE: subscribe complete, ep = 0x55a38d3403c0
[1691403082.986166][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403082.986289][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403082.986319][7870:7872] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1691403082.986338][7870:7872] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1691403082.986352][7870:7872] CHIP:BLE: local and remote recv window size = 5
[1691403082.986603][7870:7872] CHIP:IN: BLE EndPoint 0x55a38d3403c0 Connection Complete
[1691403083.074387][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403083.121299][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403083.121472][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403083.121565][7870:7872] CHIP:EM: >>> [E:58373i S:0 M:198850083] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1691403083.121595][7870:7872] CHIP:EM: Found matching exchange: 58373i, Delegate: 0x7f942400c180
[1691403083.121627][7870:7872] CHIP:SC: Received PBKDF param response
[1691403083.121662][7870:7872] CHIP:SC: Peer assigned session ID 22955
[1691403083.121689][7870:7872] CHIP:SC: Found MRP parameters in the message
[1691403083.152744][7870:7872] CHIP:EM: <<< [E:58373i S:0 M:166617636] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1691403083.152770][7870:7872] CHIP:IN: (U) Sending msg 166617636 to IP address 'BLE'
[1691403083.152922][7870:7872] CHIP:SC: Sent spake2p msg1
[1691403083.209023][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403084.650790][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403084.650965][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403084.651043][7870:7872] CHIP:EM: >>> [E:58373i S:0 M:198850084] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1691403084.651069][7870:7872] CHIP:EM: Found matching exchange: 58373i, Delegate: 0x7f942400c180
[1691403084.651101][7870:7872] CHIP:SC: Received spake2p msg2
[1691403084.667719][7870:7872] CHIP:EM: <<< [E:58373i S:0 M:166617637] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1691403084.667761][7870:7872] CHIP:IN: (U) Sending msg 166617637 to IP address 'BLE'
[1691403084.667930][7870:7872] CHIP:SC: Sent spake2p msg3
[1691403084.739650][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403084.784817][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403084.784907][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403084.784996][7870:7872] CHIP:EM: >>> [E:58373i S:0 M:198850085] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1691403084.785030][7870:7872] CHIP:EM: Found matching exchange: 58373i, Delegate: 0x7f942400c180
[1691403084.785120][7870:7872] CHIP:SC: SecureSession[0x7f94240095a0]: Moving from state 'kEstablishing' --> 'kActive'
[1691403084.785139][7870:7872] CHIP:IN: SecureSession[0x7f94240095a0]: Activated - Type:1 LSID:15906
[1691403084.785157][7870:7872] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:15906 PSID:22955!
[1691403084.785179][7870:7872] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1691403084.785195][7870:7872] CHIP:TOO: Pairing Success
[1691403084.785209][7870:7872] CHIP:TOO: PASE establishment successful
[1691403084.785225][7870:7872] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1691403084.785242][7870:7872] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1691403084.785255][7870:7872] CHIP:CTL: Sending request for commissioning information
[1691403084.785283][7870:7872] CHIP:DMG: SendReadRequest ReadClient[0x7f9424025430]: Sending Read Request
[1691403084.785366][7870:7872] CHIP:EM: <<< [E:58374i S:15906 M:216097734] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1691403084.785392][7870:7872] CHIP:IN: (S) Sending msg 216097734 on secure session with LSID: 15906
[1691403084.785637][7870:7872] CHIP:DMG: MoveToState ReadClient[0x7f9424025430]: Moving to [AwaitingIn]
[1691403084.874445][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403084.921894][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403084.922077][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.009616][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.009709][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.009796][7870:7872] CHIP:EM: >>> [E:58374i S:15906 M:122858322] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1691403085.009821][7870:7872] CHIP:EM: Found matching exchange: 58374i, Delegate: 0x7f9424025440
[1691403085.009905][7870:7872] CHIP:DMG: ReportDataMessage =
[1691403085.009925][7870:7872] CHIP:DMG: {
[1691403085.009946][7870:7872] CHIP:DMG: AttributeReportIBs =
[1691403085.009974][7870:7872] CHIP:DMG: [
[1691403085.009986][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.010007][7870:7872] CHIP:DMG: {
[1691403085.010022][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.010038][7870:7872] CHIP:DMG: {
[1691403085.010054][7870:7872] CHIP:DMG: DataVersion = 0xddc765d8,
[1691403085.010069][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.010084][7870:7872] CHIP:DMG: {
[1691403085.010100][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.010117][7870:7872] CHIP:DMG: Cluster = 0x31,
[1691403085.010136][7870:7872] CHIP:DMG: Attribute = 0x0000_0003,
[1691403085.010156][7870:7872] CHIP:DMG: }
[1691403085.010169][7870:7872] CHIP:DMG:
[1691403085.010182][7870:7872] CHIP:DMG: Data = 20,
[1691403085.010193][7870:7872] CHIP:DMG: },
[1691403085.010216][7870:7872] CHIP:DMG:
[1691403085.010230][7870:7872] CHIP:DMG: },
[1691403085.010261][7870:7872] CHIP:DMG:
[1691403085.010275][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.010300][7870:7872] CHIP:DMG: {
[1691403085.010314][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.010333][7870:7872] CHIP:DMG: {
[1691403085.010350][7870:7872] CHIP:DMG: DataVersion = 0x9b61c295,
[1691403085.010366][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.010385][7870:7872] CHIP:DMG: {
[1691403085.010404][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.010423][7870:7872] CHIP:DMG: Cluster = 0x28,
[1691403085.010441][7870:7872] CHIP:DMG: Attribute = 0x0000_0004,
[1691403085.010458][7870:7872] CHIP:DMG: }
[1691403085.010480][7870:7872] CHIP:DMG:
[1691403085.010499][7870:7872] CHIP:DMG: Data = 32773,
[1691403085.010514][7870:7872] CHIP:DMG: },
[1691403085.010537][7870:7872] CHIP:DMG:
[1691403085.010550][7870:7872] CHIP:DMG: },
[1691403085.010581][7870:7872] CHIP:DMG:
[1691403085.010595][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.010619][7870:7872] CHIP:DMG: {
[1691403085.010633][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.010652][7870:7872] CHIP:DMG: {
[1691403085.010669][7870:7872] CHIP:DMG: DataVersion = 0x9b61c295,
[1691403085.010686][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.010705][7870:7872] CHIP:DMG: {
[1691403085.010723][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.010742][7870:7872] CHIP:DMG: Cluster = 0x28,
[1691403085.010761][7870:7872] CHIP:DMG: Attribute = 0x0000_0002,
[1691403085.010777][7870:7872] CHIP:DMG: }
[1691403085.010798][7870:7872] CHIP:DMG:
[1691403085.010816][7870:7872] CHIP:DMG: Data = 65521,
[1691403085.010832][7870:7872] CHIP:DMG: },
[1691403085.010855][7870:7872] CHIP:DMG:
[1691403085.010871][7870:7872] CHIP:DMG: },
[1691403085.010901][7870:7872] CHIP:DMG:
[1691403085.010914][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.010939][7870:7872] CHIP:DMG: {
[1691403085.010953][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.010971][7870:7872] CHIP:DMG: {
[1691403085.010989][7870:7872] CHIP:DMG: DataVersion = 0xfd19fde9,
[1691403085.011005][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.011024][7870:7872] CHIP:DMG: {
[1691403085.011042][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.011061][7870:7872] CHIP:DMG: Cluster = 0x30,
[1691403085.011079][7870:7872] CHIP:DMG: Attribute = 0x0000_0003,
[1691403085.011095][7870:7872] CHIP:DMG: }
[1691403085.011117][7870:7872] CHIP:DMG:
[1691403085.011135][7870:7872] CHIP:DMG: Data = 0,
[1691403085.011151][7870:7872] CHIP:DMG: },
[1691403085.011174][7870:7872] CHIP:DMG:
[1691403085.011188][7870:7872] CHIP:DMG: },
[1691403085.011218][7870:7872] CHIP:DMG:
[1691403085.011231][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.011256][7870:7872] CHIP:DMG: {
[1691403085.011270][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.011288][7870:7872] CHIP:DMG: {
[1691403085.011306][7870:7872] CHIP:DMG: DataVersion = 0xfd19fde9,
[1691403085.011323][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.011340][7870:7872] CHIP:DMG: {
[1691403085.011354][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.011369][7870:7872] CHIP:DMG: Cluster = 0x30,
[1691403085.011384][7870:7872] CHIP:DMG: Attribute = 0x0000_0002,
[1691403085.011398][7870:7872] CHIP:DMG: }
[1691403085.011414][7870:7872] CHIP:DMG:
[1691403085.011429][7870:7872] CHIP:DMG: Data = 0,
[1691403085.011442][7870:7872] CHIP:DMG: },
[1691403085.011460][7870:7872] CHIP:DMG:
[1691403085.011472][7870:7872] CHIP:DMG: },
[1691403085.011498][7870:7872] CHIP:DMG:
[1691403085.011510][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.011531][7870:7872] CHIP:DMG: {
[1691403085.011543][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.011556][7870:7872] CHIP:DMG: {
[1691403085.011570][7870:7872] CHIP:DMG: DataVersion = 0xfd19fde9,
[1691403085.011584][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.011598][7870:7872] CHIP:DMG: {
[1691403085.011617][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.011637][7870:7872] CHIP:DMG: Cluster = 0x30,
[1691403085.011656][7870:7872] CHIP:DMG: Attribute = 0x0000_0001,
[1691403085.011673][7870:7872] CHIP:DMG: }
[1691403085.011695][7870:7872] CHIP:DMG:
[1691403085.011710][7870:7872] CHIP:DMG: Data =
[1691403085.011729][7870:7872] CHIP:DMG: {
[1691403085.011770][7870:7872] CHIP:DMG: 0x0 = 60,
[1691403085.011790][7870:7872] CHIP:DMG: 0x1 = 900,
[1691403085.011808][7870:7872] CHIP:DMG: },
[1691403085.011826][7870:7872] CHIP:DMG: },
[1691403085.011850][7870:7872] CHIP:DMG:
[1691403085.011864][7870:7872] CHIP:DMG: },
[1691403085.011896][7870:7872] CHIP:DMG:
[1691403085.011909][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.011934][7870:7872] CHIP:DMG: {
[1691403085.011948][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.011966][7870:7872] CHIP:DMG: {
[1691403085.011984][7870:7872] CHIP:DMG: DataVersion = 0xfd19fde9,
[1691403085.012001][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.012020][7870:7872] CHIP:DMG: {
[1691403085.012037][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.012057][7870:7872] CHIP:DMG: Cluster = 0x30,
[1691403085.012075][7870:7872] CHIP:DMG: Attribute = 0x0000_0000,
[1691403085.012091][7870:7872] CHIP:DMG: }
[1691403085.012113][7870:7872] CHIP:DMG:
[1691403085.012131][7870:7872] CHIP:DMG: Data = 0,
[1691403085.012147][7870:7872] CHIP:DMG: },
[1691403085.012170][7870:7872] CHIP:DMG:
[1691403085.012197][7870:7872] CHIP:DMG: },
[1691403085.012226][7870:7872] CHIP:DMG:
[1691403085.012238][7870:7872] CHIP:DMG: AttributeReportIB =
[1691403085.012261][7870:7872] CHIP:DMG: {
[1691403085.012274][7870:7872] CHIP:DMG: AttributeDataIB =
[1691403085.012291][7870:7872] CHIP:DMG: {
[1691403085.012307][7870:7872] CHIP:DMG: DataVersion = 0xddc765d8,
[1691403085.012323][7870:7872] CHIP:DMG: AttributePathIB =
[1691403085.012342][7870:7872] CHIP:DMG: {
[1691403085.012359][7870:7872] CHIP:DMG: Endpoint = 0x0,
[1691403085.012376][7870:7872] CHIP:DMG: Cluster = 0x31,
[1691403085.012394][7870:7872] CHIP:DMG: Attribute = 0x0000_FFFC,
[1691403085.012409][7870:7872] CHIP:DMG: }
[1691403085.012429][7870:7872] CHIP:DMG:
[1691403085.012447][7870:7872] CHIP:DMG: Data = 2,
[1691403085.012460][7870:7872] CHIP:DMG: },
[1691403085.012482][7870:7872] CHIP:DMG:
[1691403085.012494][7870:7872] CHIP:DMG: },
[1691403085.012516][7870:7872] CHIP:DMG:
[1691403085.012528][7870:7872] CHIP:DMG: ],
[1691403085.012591][7870:7872] CHIP:DMG:
[1691403085.012605][7870:7872] CHIP:DMG: SuppressResponse = true,
[1691403085.012620][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403085.012634][7870:7872] CHIP:DMG: }
[1691403085.013469][7870:7872] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1691403085.013516][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1691403085.013533][7870:7872] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1691403085.013548][7870:7872] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1691403085.013562][7870:7872] CHIP:CTL: Arming failsafe (60 seconds)
[1691403085.013597][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403085.013614][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403085.013662][7870:7872] CHIP:EM: <<< [E:58375i S:15906 M:216097735] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403085.013686][7870:7872] CHIP:IN: (S) Sending msg 216097735 on secure session with LSID: 15906
[1691403085.013902][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403085.099716][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403085.145278][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.145381][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.145488][7870:7872] CHIP:EM: >>> [E:58375i S:15906 M:122858323] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403085.145518][7870:7872] CHIP:EM: Found matching exchange: 58375i, Delegate: 0x7f942c02f6a8
[1691403085.145550][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403085.145588][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403085.145601][7870:7872] CHIP:DMG: {
[1691403085.145619][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403085.145635][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403085.145662][7870:7872] CHIP:DMG: [
[1691403085.145675][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403085.145702][7870:7872] CHIP:DMG: {
[1691403085.145716][7870:7872] CHIP:DMG: CommandDataIB =
[1691403085.145734][7870:7872] CHIP:DMG: {
[1691403085.145750][7870:7872] CHIP:DMG: CommandPathIB =
[1691403085.145770][7870:7872] CHIP:DMG: {
[1691403085.145789][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403085.145807][7870:7872] CHIP:DMG: ClusterId = 0x30,
[1691403085.145825][7870:7872] CHIP:DMG: CommandId = 0x1,
[1691403085.145841][7870:7872] CHIP:DMG: },
[1691403085.145862][7870:7872] CHIP:DMG:
[1691403085.145877][7870:7872] CHIP:DMG: CommandFields =
[1691403085.145896][7870:7872] CHIP:DMG: {
[1691403085.145915][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403085.145935][7870:7872] CHIP:DMG: 0x1 = "" (0 chars),
[1691403085.145952][7870:7872] CHIP:DMG: },
[1691403085.145968][7870:7872] CHIP:DMG: },
[1691403085.145988][7870:7872] CHIP:DMG:
[1691403085.145999][7870:7872] CHIP:DMG: },
[1691403085.146018][7870:7872] CHIP:DMG:
[1691403085.146030][7870:7872] CHIP:DMG: ],
[1691403085.146050][7870:7872] CHIP:DMG:
[1691403085.146062][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403085.146073][7870:7872] CHIP:DMG: },
[1691403085.146140][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1691403085.146189][7870:7872] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1691403085.146214][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1691403085.146227][7870:7872] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1691403085.146247][7870:7872] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1691403085.146262][7870:7872] CHIP:CTL: Setting Regulatory Config
[1691403085.146272][7870:7872] CHIP:CTL: Device does not support configurable regulatory location
[1691403085.146316][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403085.146352][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403085.146415][7870:7872] CHIP:EM: <<< [E:58376i S:15906 M:216097736] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403085.146446][7870:7872] CHIP:IN: (S) Sending msg 216097736 on secure session with LSID: 15906
[1691403085.146724][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403085.146774][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403085.234188][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403085.325510][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.325600][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.325706][7870:7872] CHIP:EM: >>> [E:58376i S:15906 M:122858324] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403085.325735][7870:7872] CHIP:EM: Found matching exchange: 58376i, Delegate: 0x7f9424008898
[1691403085.325768][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403085.325805][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403085.325819][7870:7872] CHIP:DMG: {
[1691403085.325834][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403085.325849][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403085.325876][7870:7872] CHIP:DMG: [
[1691403085.325888][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403085.325930][7870:7872] CHIP:DMG: {
[1691403085.325946][7870:7872] CHIP:DMG: CommandDataIB =
[1691403085.325961][7870:7872] CHIP:DMG: {
[1691403085.325972][7870:7872] CHIP:DMG: CommandPathIB =
[1691403085.325985][7870:7872] CHIP:DMG: {
[1691403085.325998][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403085.326011][7870:7872] CHIP:DMG: ClusterId = 0x30,
[1691403085.326024][7870:7872] CHIP:DMG: CommandId = 0x3,
[1691403085.326036][7870:7872] CHIP:DMG: },
[1691403085.326049][7870:7872] CHIP:DMG:
[1691403085.326061][7870:7872] CHIP:DMG: CommandFields =
[1691403085.326082][7870:7872] CHIP:DMG: {
[1691403085.326101][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403085.326116][7870:7872] CHIP:DMG: 0x1 = "" (0 chars),
[1691403085.326129][7870:7872] CHIP:DMG: },
[1691403085.326140][7870:7872] CHIP:DMG: },
[1691403085.326156][7870:7872] CHIP:DMG:
[1691403085.326166][7870:7872] CHIP:DMG: },
[1691403085.326182][7870:7872] CHIP:DMG:
[1691403085.326192][7870:7872] CHIP:DMG: ],
[1691403085.326208][7870:7872] CHIP:DMG:
[1691403085.326219][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403085.326228][7870:7872] CHIP:DMG: },
[1691403085.326273][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1691403085.326311][7870:7872] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1691403085.326328][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1691403085.326348][7870:7872] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1691403085.326369][7870:7872] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1691403085.326382][7870:7872] CHIP:CTL: Sending request for PAI certificate
[1691403085.326397][7870:7872] CHIP:CTL: Sending Certificate Chain request to 0x7f942400c130 device
[1691403085.326439][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403085.326471][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403085.326525][7870:7872] CHIP:EM: <<< [E:58377i S:15906 M:216097737] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403085.326553][7870:7872] CHIP:IN: (S) Sending msg 216097737 on secure session with LSID: 15906
[1691403085.326801][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403085.326855][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403085.413966][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403085.461570][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.461726][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.551992][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.552171][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.640601][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.640779][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.640886][7870:7872] CHIP:EM: >>> [E:58377i S:15906 M:122858325] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403085.640916][7870:7872] CHIP:EM: Found matching exchange: 58377i, Delegate: 0x7f942c02f6a8
[1691403085.640945][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403085.640976][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403085.640990][7870:7872] CHIP:DMG: {
[1691403085.641002][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403085.641017][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403085.641043][7870:7872] CHIP:DMG: [
[1691403085.641060][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403085.641081][7870:7872] CHIP:DMG: {
[1691403085.641092][7870:7872] CHIP:DMG: CommandDataIB =
[1691403085.641104][7870:7872] CHIP:DMG: {
[1691403085.641115][7870:7872] CHIP:DMG: CommandPathIB =
[1691403085.641128][7870:7872] CHIP:DMG: {
[1691403085.641141][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403085.641154][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403085.641166][7870:7872] CHIP:DMG: CommandId = 0x3,
[1691403085.641178][7870:7872] CHIP:DMG: },
[1691403085.641192][7870:7872] CHIP:DMG:
[1691403085.641203][7870:7872] CHIP:DMG: CommandFields =
[1691403085.641216][7870:7872] CHIP:DMG: {
[1691403085.641229][7870:7872] CHIP:DMG: 0x0 = [
[1691403085.641319][7870:7872] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x
[1691403085.641383][7870:7872] CHIP:DMG: ] (463 bytes)
[1691403085.641405][7870:7872] CHIP:DMG: },
[1691403085.641423][7870:7872] CHIP:DMG: },
[1691403085.641449][7870:7872] CHIP:DMG:
[1691403085.641463][7870:7872] CHIP:DMG: },
[1691403085.641490][7870:7872] CHIP:DMG:
[1691403085.641504][7870:7872] CHIP:DMG: ],
[1691403085.641531][7870:7872] CHIP:DMG:
[1691403085.641546][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403085.641562][7870:7872] CHIP:DMG: },
[1691403085.641623][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1691403085.641647][7870:7872] CHIP:CTL: Received certificate chain from the device
[1691403085.641669][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1691403085.641687][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1691403085.641708][7870:7872] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1691403085.641721][7870:7872] CHIP:CTL: Sending request for DAC certificate
[1691403085.641735][7870:7872] CHIP:CTL: Sending Certificate Chain request to 0x7f942400c130 device
[1691403085.641779][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403085.641798][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403085.641862][7870:7872] CHIP:EM: <<< [E:58378i S:15906 M:216097738] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403085.641888][7870:7872] CHIP:IN: (S) Sending msg 216097738 on secure session with LSID: 15906
[1691403085.642105][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403085.642167][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403085.729673][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403085.777133][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.777305][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.868276][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.868451][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.955710][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403085.955874][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403085.955992][7870:7872] CHIP:EM: >>> [E:58378i S:15906 M:122858326] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403085.956016][7870:7872] CHIP:EM: Found matching exchange: 58378i, Delegate: 0x7f942c057968
[1691403085.956047][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403085.956087][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403085.956102][7870:7872] CHIP:DMG: {
[1691403085.956120][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403085.956137][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403085.956165][7870:7872] CHIP:DMG: [
[1691403085.956180][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403085.956207][7870:7872] CHIP:DMG: {
[1691403085.956222][7870:7872] CHIP:DMG: CommandDataIB =
[1691403085.956242][7870:7872] CHIP:DMG: {
[1691403085.956272][7870:7872] CHIP:DMG: CommandPathIB =
[1691403085.956287][7870:7872] CHIP:DMG: {
[1691403085.956302][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403085.956317][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403085.956331][7870:7872] CHIP:DMG: CommandId = 0x3,
[1691403085.956345][7870:7872] CHIP:DMG: },
[1691403085.956362][7870:7872] CHIP:DMG:
[1691403085.956375][7870:7872] CHIP:DMG: CommandFields =
[1691403085.956389][7870:7872] CHIP:DMG: {
[1691403085.956404][7870:7872] CHIP:DMG: 0x0 = [
[1691403085.956565][7870:7872] CHIP:DMG: 0x30, 0x82, 0x01, 0xe8, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x6f, 0xdc, 0xb6, 0xed, 0x06, 0xf3, 0x58, 0xf9, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x35, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x35, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x7e, 0xf2, 0xf1, 0x08, 0x2b, 0x2a, 0x56, 0x4a, 0x05, 0x44, 0xc0, 0xa6, 0x13, 0xd2, 0x1b, 0x15, 0x75, 0x00, 0x55, 0x2d, 0x03, 0x5f, 0x23, 0x02, 0x25, 0x2f, 0xce, 0xe8, 0x1d, 0x6e, 0xc6, 0x74, 0x17, 0x34, 0x18, 0xa9, 0x4a, 0x88, 0xdb, 0x
[1691403085.956626][7870:7872] CHIP:DMG: ] (492 bytes)
[1691403085.956641][7870:7872] CHIP:DMG: },
[1691403085.956653][7870:7872] CHIP:DMG: },
[1691403085.956672][7870:7872] CHIP:DMG:
[1691403085.956683][7870:7872] CHIP:DMG: },
[1691403085.956702][7870:7872] CHIP:DMG:
[1691403085.956713][7870:7872] CHIP:DMG: ],
[1691403085.956733][7870:7872] CHIP:DMG:
[1691403085.956745][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403085.956760][7870:7872] CHIP:DMG: },
[1691403085.956817][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1691403085.956839][7870:7872] CHIP:CTL: Received certificate chain from the device
[1691403085.956859][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1691403085.956874][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1691403085.956893][7870:7872] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1691403085.956905][7870:7872] CHIP:CTL: Sending Attestation Request to the device.
[1691403085.956920][7870:7872] CHIP:CTL: Sending Attestation request to 0x7f942400c130 device
[1691403085.956959][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403085.956977][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403085.957029][7870:7872] CHIP:EM: <<< [E:58379i S:15906 M:216097739] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403085.957055][7870:7872] CHIP:IN: (S) Sending msg 216097739 on secure session with LSID: 15906
[1691403085.957336][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403085.957360][7870:7872] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1691403085.957403][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403086.089459][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403086.181978][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403086.182090][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403086.317593][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403086.317778][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403086.407109][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403086.407247][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403086.407372][7870:7872] CHIP:EM: >>> [E:58379i S:15906 M:122858327] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403086.407398][7870:7872] CHIP:EM: Found matching exchange: 58379i, Delegate: 0x7f942c057d58
[1691403086.407430][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403086.407469][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403086.407484][7870:7872] CHIP:DMG: {
[1691403086.407503][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403086.407519][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403086.407547][7870:7872] CHIP:DMG: [
[1691403086.407561][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403086.407587][7870:7872] CHIP:DMG: {
[1691403086.407602][7870:7872] CHIP:DMG: CommandDataIB =
[1691403086.407617][7870:7872] CHIP:DMG: {
[1691403086.407631][7870:7872] CHIP:DMG: CommandPathIB =
[1691403086.407648][7870:7872] CHIP:DMG: {
[1691403086.407664][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403086.407680][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403086.407695][7870:7872] CHIP:DMG: CommandId = 0x1,
[1691403086.407710][7870:7872] CHIP:DMG: },
[1691403086.407728][7870:7872] CHIP:DMG:
[1691403086.407742][7870:7872] CHIP:DMG: CommandFields =
[1691403086.407785][7870:7872] CHIP:DMG: {
[1691403086.407804][7870:7872] CHIP:DMG: 0x0 = [
[1691403086.408010][7870:7872] CHIP:DMG: 0x15, 0x31, 0x01, 0x1b, 0x02, 0x30, 0x82, 0x02, 0x17, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x08, 0x30, 0x82, 0x02, 0x04, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x
[1691403086.408093][7870:7872] CHIP:DMG: ] (583 bytes)
[1691403086.408113][7870:7872] CHIP:DMG: 0x1 = [
[1691403086.408175][7870:7872] CHIP:DMG: 0x61, 0x0a, 0xec, 0x5a, 0xd0, 0x18, 0x4d, 0x19, 0xf1, 0x1a, 0x4e, 0x5d, 0x43, 0x75, 0x18, 0xa8, 0x66, 0xd4, 0x77, 0xab, 0xe4, 0xfe, 0xb3, 0x27, 0xc7, 0x58, 0x97, 0x36, 0xf3, 0x57, 0x31, 0xc4, 0x03, 0xd7, 0xb0, 0x54, 0x06, 0x26, 0x81, 0xaf, 0x06, 0x6b, 0xfe, 0x77, 0x1b, 0x9a, 0xb3, 0xf4, 0xe0, 0x41, 0xe5, 0xa8, 0x3f, 0x00, 0x17, 0xad, 0xda, 0xf8, 0x37, 0x72, 0xd6, 0x8d, 0xb4, 0x65,
[1691403086.408204][7870:7872] CHIP:DMG: ] (64 bytes)
[1691403086.408226][7870:7872] CHIP:DMG: },
[1691403086.408242][7870:7872] CHIP:DMG: },
[1691403086.408268][7870:7872] CHIP:DMG:
[1691403086.408283][7870:7872] CHIP:DMG: },
[1691403086.408310][7870:7872] CHIP:DMG:
[1691403086.408323][7870:7872] CHIP:DMG: ],
[1691403086.408351][7870:7872] CHIP:DMG:
[1691403086.408366][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403086.408381][7870:7872] CHIP:DMG: },
[1691403086.408447][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1691403086.408473][7870:7872] CHIP:CTL: Received Attestation Information from the device
[1691403086.408493][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1691403086.408510][7870:7872] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583
[1691403086.408533][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1691403086.408552][7870:7872] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1691403086.408566][7870:7872] CHIP:CTL: Verifying attestation
[1691403086.427087][7870:7872] CHIP:CR: mbedTLS error: ERROR - Generic error
[1691403086.457052][7870:7872] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1691403086.457071][7870:7872] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1691403086.457080][7870:7872] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1691403086.457091][7870:7872] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1691403086.457097][7870:7872] CHIP:CTL: Sending CSR request to 0x7f942400c130 device
[1691403086.457124][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403086.457134][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403086.457169][7870:7872] CHIP:EM: <<< [E:58380i S:15906 M:216097740] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403086.457181][7870:7872] CHIP:IN: (S) Sending msg 216097740 on secure session with LSID: 15906
[1691403086.457329][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403086.457342][7870:7872] CHIP:CTL: Sent CSR request, waiting for the CSR
[1691403086.457364][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403086.539681][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.006584][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403087.006779][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403087.080840][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403087.081008][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403087.081117][7870:7872] CHIP:EM: >>> [E:58380i S:15906 M:122858328] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403087.081147][7870:7872] CHIP:EM: Found matching exchange: 58380i, Delegate: 0x7f942c057188
[1691403087.081183][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403087.081219][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403087.081233][7870:7872] CHIP:DMG: {
[1691403087.081251][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403087.081267][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403087.081297][7870:7872] CHIP:DMG: [
[1691403087.081311][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403087.081339][7870:7872] CHIP:DMG: {
[1691403087.081354][7870:7872] CHIP:DMG: CommandDataIB =
[1691403087.081376][7870:7872] CHIP:DMG: {
[1691403087.081392][7870:7872] CHIP:DMG: CommandPathIB =
[1691403087.081413][7870:7872] CHIP:DMG: {
[1691403087.081434][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403087.081454][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403087.081473][7870:7872] CHIP:DMG: CommandId = 0x5,
[1691403087.081490][7870:7872] CHIP:DMG: },
[1691403087.081513][7870:7872] CHIP:DMG:
[1691403087.081530][7870:7872] CHIP:DMG: CommandFields =
[1691403087.081551][7870:7872] CHIP:DMG: {
[1691403087.081570][7870:7872] CHIP:DMG: 0x0 = [
[1691403087.081720][7870:7872] CHIP:DMG: 0x15, 0x30, 0x01, 0xce, 0x30, 0x81, 0xcb, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x8a, 0x2d, 0xcf, 0xb2, 0x84, 0xaa, 0x56, 0xcb, 0xe2, 0x72, 0xe6, 0xc7, 0x98, 0xb1, 0xde, 0xf5, 0xd3, 0xbc, 0xc9, 0x61, 0x2f, 0x50, 0xe8, 0xcd, 0x95, 0x2f, 0x5d, 0x79, 0xbd, 0x49, 0x73, 0xad, 0xcf, 0x3a, 0x9a, 0xb0, 0xf1, 0x2f, 0x4d, 0xe2, 0xa6, 0xd5, 0x87, 0xee, 0x06, 0x11, 0x93, 0xbb, 0x4d, 0xfa, 0x85, 0x2e, 0x00, 0x57, 0x3a, 0xcc, 0xde, 0x19, 0x2c, 0x22, 0x77, 0x73, 0x46, 0x28, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x49, 0x00, 0x30, 0x46, 0x02, 0x21, 0x00, 0xfa, 0x2d, 0xb0, 0xfa, 0xf3, 0xd6, 0x29, 0x15, 0x2f, 0xea, 0xa2, 0x91, 0x8b, 0xe4, 0x08, 0xdb, 0xb9, 0x1f, 0xd3, 0xe8, 0x9b, 0x3b, 0xef, 0xef, 0x69, 0x7e, 0xe3, 0x06, 0x1c, 0x44, 0xee, 0xdf, 0x02, 0x21, 0x00, 0x9a, 0xf1, 0x79, 0xff, 0xce, 0x78, 0xa7, 0xd3, 0x8b, 0x88, 0x24, 0x72, 0x00, 0xa3, 0xb1, 0x68, 0x37, 0x39, 0xd2, 0x8f, 0xb7, 0x61, 0x06, 0x12, 0xfb, 0xa4, 0x3d, 0x7a, 0x48, 0x8f, 0xe7, 0x28, 0x30, 0x02, 0x20, 0x17, 0x05, 0xf0, 0xd3, 0xee, 0xa9, 0x0a, 0x10, 0xa1, 0x17, 0xa4, 0x37, 0x86, 0x06, 0x6a, 0x84, 0x60, 0x47, 0xf5, 0xcf, 0x73, 0xc9, 0x9f, 0xa4, 0xee, 0x44, 0x05, 0x5a, 0x9a, 0xdb, 0xc1, 0xd2, 0x18,
[1691403087.081785][7870:7872] CHIP:DMG: ] (246 bytes)
[1691403087.081806][7870:7872] CHIP:DMG: 0x1 = [
[1691403087.081857][7870:7872] CHIP:DMG: 0x5f, 0x19, 0xd6, 0x7f, 0xe9, 0x28, 0x73, 0x41, 0x12, 0x51, 0x4d, 0x75, 0x68, 0x4f, 0xf6, 0x68, 0x55, 0xe8, 0x00, 0x7f, 0xca, 0x03, 0x27, 0x72, 0xe4, 0xfd, 0x38, 0x98, 0xac, 0xc5, 0xaf, 0x08, 0x2d, 0x6d, 0x50, 0x4b, 0x68, 0x07, 0xfc, 0x86, 0x63, 0x70, 0x2e, 0x96, 0x17, 0xab, 0x80, 0x12, 0x71, 0xa9, 0x32, 0x86, 0xfb, 0x4c, 0x67, 0xca, 0x1f, 0xae, 0x19, 0x0a, 0x61, 0x3e, 0xf4, 0x32,
[1691403087.081878][7870:7872] CHIP:DMG: ] (64 bytes)
[1691403087.081894][7870:7872] CHIP:DMG: },
[1691403087.081908][7870:7872] CHIP:DMG: },
[1691403087.081929][7870:7872] CHIP:DMG:
[1691403087.081942][7870:7872] CHIP:DMG: },
[1691403087.081962][7870:7872] CHIP:DMG:
[1691403087.081975][7870:7872] CHIP:DMG: ],
[1691403087.081997][7870:7872] CHIP:DMG:
[1691403087.082010][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403087.082022][7870:7872] CHIP:DMG: },
[1691403087.082080][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1691403087.082103][7870:7872] CHIP:CTL: Received certificate signing request from the device
[1691403087.082123][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1691403087.082136][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1691403087.082153][7870:7872] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1691403087.097671][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1691403087.097698][7870:7872] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1691403087.097712][7870:7872] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1691403087.097721][7870:7872] CHIP:CTL: Getting certificate chain for the device from the issuer
[1691403087.097759][7870:7872] CHIP:CTL: Verifying Certificate Signing Request
[1691403087.112089][7870:7872] CHIP:CTL: Generating NOC
[1691403087.116983][7870:7872] CHIP:CTL: Providing certificate chain to the commissioner
[1691403087.117005][7870:7872] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1691403087.117018][7870:7872] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1691403087.117086][7870:7872] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1691403087.117096][7870:7872] CHIP:CTL: Sending root certificate to the device
[1691403087.117126][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403087.117136][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403087.117178][7870:7872] CHIP:EM: <<< [E:58381i S:15906 M:216097741] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403087.117192][7870:7872] CHIP:IN: (S) Sending msg 216097741 on secure session with LSID: 15906
[1691403087.117386][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403087.117399][7870:7872] CHIP:CTL: Sent root certificate to the device
[1691403087.117525][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403087.168958][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.259154][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.350723][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403087.350899][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403087.351002][7870:7872] CHIP:EM: >>> [E:58381i S:15906 M:122858329] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403087.351027][7870:7872] CHIP:EM: Found matching exchange: 58381i, Delegate: 0x7f942c057d58
[1691403087.351059][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403087.351098][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403087.351112][7870:7872] CHIP:DMG: {
[1691403087.351125][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403087.351137][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403087.351157][7870:7872] CHIP:DMG: [
[1691403087.351171][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403087.351191][7870:7872] CHIP:DMG: {
[1691403087.351203][7870:7872] CHIP:DMG: CommandStatusIB =
[1691403087.351221][7870:7872] CHIP:DMG: {
[1691403087.351236][7870:7872] CHIP:DMG: CommandPathIB =
[1691403087.351253][7870:7872] CHIP:DMG: {
[1691403087.351270][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403087.351286][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403087.351302][7870:7872] CHIP:DMG: CommandId = 0xb,
[1691403087.351318][7870:7872] CHIP:DMG: },
[1691403087.351338][7870:7872] CHIP:DMG:
[1691403087.351353][7870:7872] CHIP:DMG: StatusIB =
[1691403087.351370][7870:7872] CHIP:DMG: {
[1691403087.351386][7870:7872] CHIP:DMG: status = 0x00 (SUCCESS),
[1691403087.351401][7870:7872] CHIP:DMG: },
[1691403087.351418][7870:7872] CHIP:DMG:
[1691403087.351433][7870:7872] CHIP:DMG: },
[1691403087.351452][7870:7872] CHIP:DMG:
[1691403087.351466][7870:7872] CHIP:DMG: },
[1691403087.351487][7870:7872] CHIP:DMG:
[1691403087.351500][7870:7872] CHIP:DMG: ],
[1691403087.351522][7870:7872] CHIP:DMG:
[1691403087.351536][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403087.351550][7870:7872] CHIP:DMG: },
[1691403087.351602][7870:7872] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1691403087.351623][7870:7872] CHIP:CTL: Device confirmed that it has received the root certificate
[1691403087.351644][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1691403087.351658][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1691403087.351678][7870:7872] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1691403087.351725][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403087.351775][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403087.351851][7870:7872] CHIP:EM: <<< [E:58382i S:15906 M:216097742] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403087.351887][7870:7872] CHIP:IN: (S) Sending msg 216097742 on secure session with LSID: 15906
[1691403087.352241][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403087.352270][7870:7872] CHIP:CTL: Sent operational certificate to the device
[1691403087.352322][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403087.439718][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.529431][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.619250][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.861547][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403087.861717][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403087.861837][7870:7872] CHIP:EM: >>> [E:58382i S:15906 M:122858330] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403087.861860][7870:7872] CHIP:EM: Found matching exchange: 58382i, Delegate: 0x7f942c057188
[1691403087.861891][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403087.861932][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403087.861953][7870:7872] CHIP:DMG: {
[1691403087.861970][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403087.861987][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403087.862015][7870:7872] CHIP:DMG: [
[1691403087.862029][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403087.862051][7870:7872] CHIP:DMG: {
[1691403087.862063][7870:7872] CHIP:DMG: CommandDataIB =
[1691403087.862076][7870:7872] CHIP:DMG: {
[1691403087.862087][7870:7872] CHIP:DMG: CommandPathIB =
[1691403087.862101][7870:7872] CHIP:DMG: {
[1691403087.862121][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403087.862148][7870:7872] CHIP:DMG: ClusterId = 0x3e,
[1691403087.862168][7870:7872] CHIP:DMG: CommandId = 0x8,
[1691403087.862187][7870:7872] CHIP:DMG: },
[1691403087.862213][7870:7872] CHIP:DMG:
[1691403087.862229][7870:7872] CHIP:DMG: CommandFields =
[1691403087.862250][7870:7872] CHIP:DMG: {
[1691403087.862272][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403087.862299][7870:7872] CHIP:DMG: 0x1 = 1,
[1691403087.862322][7870:7872] CHIP:DMG: },
[1691403087.862339][7870:7872] CHIP:DMG: },
[1691403087.862364][7870:7872] CHIP:DMG:
[1691403087.862379][7870:7872] CHIP:DMG: },
[1691403087.862406][7870:7872] CHIP:DMG:
[1691403087.862420][7870:7872] CHIP:DMG: ],
[1691403087.862448][7870:7872] CHIP:DMG:
[1691403087.862463][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403087.862478][7870:7872] CHIP:DMG: },
[1691403087.862549][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1691403087.862575][7870:7872] CHIP:CTL: Device returned status 0 on receiving the NOC
[1691403087.862590][7870:7872] CHIP:CTL: Operational credentials provisioned on device 0x7f942400c130
[1691403087.862605][7870:7872] CHIP:TOO: Secure Pairing Success
[1691403087.862624][7870:7872] CHIP:TOO: CASE establishment successful
[1691403087.862648][7870:7872] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1691403087.862663][7870:7872] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1691403087.862674][7870:7872] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
[1691403087.862688][7870:7872] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup'
[1691403087.862742][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403087.862772][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403087.862845][7870:7872] CHIP:EM: <<< [E:58383i S:15906 M:216097743] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403087.862874][7870:7872] CHIP:IN: (S) Sending msg 216097743 on secure session with LSID: 15906
[1691403087.863134][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403087.863195][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403087.979055][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403087.980724][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403087.980905][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403087.981021][7870:7872] CHIP:EM: >>> [E:58383i S:15906 M:122858331] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403087.981055][7870:7872] CHIP:EM: Found matching exchange: 58383i, Delegate: 0x7f942c057d58
[1691403087.981084][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403087.981115][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403087.981126][7870:7872] CHIP:DMG: {
[1691403087.981137][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403087.981148][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403087.981164][7870:7872] CHIP:DMG: [
[1691403087.981174][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403087.981190][7870:7872] CHIP:DMG: {
[1691403087.981201][7870:7872] CHIP:DMG: CommandDataIB =
[1691403087.981214][7870:7872] CHIP:DMG: {
[1691403087.981224][7870:7872] CHIP:DMG: CommandPathIB =
[1691403087.981241][7870:7872] CHIP:DMG: {
[1691403087.981263][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403087.981283][7870:7872] CHIP:DMG: ClusterId = 0x31,
[1691403087.981304][7870:7872] CHIP:DMG: CommandId = 0x5,
[1691403087.981323][7870:7872] CHIP:DMG: },
[1691403087.981347][7870:7872] CHIP:DMG:
[1691403087.981363][7870:7872] CHIP:DMG: CommandFields =
[1691403087.981384][7870:7872] CHIP:DMG: {
[1691403087.981404][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403087.981426][7870:7872] CHIP:DMG: 0x2 = 0,
[1691403087.981446][7870:7872] CHIP:DMG: },
[1691403087.981462][7870:7872] CHIP:DMG: },
[1691403087.981489][7870:7872] CHIP:DMG:
[1691403087.981503][7870:7872] CHIP:DMG: },
[1691403087.981530][7870:7872] CHIP:DMG:
[1691403087.981544][7870:7872] CHIP:DMG: ],
[1691403087.981571][7870:7872] CHIP:DMG:
[1691403087.981586][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403087.981601][7870:7872] CHIP:DMG: },
[1691403087.981664][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1691403087.981754][7870:7872] CHIP:CTL: Received NetworkConfig response, networkingStatus=0
[1691403087.981776][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup'
[1691403087.981793][7870:7872] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'FailsafeBeforeThreadEnable'
[1691403087.981814][7870:7872] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeThreadEnable'
[1691403087.981840][7870:7872] CHIP:CTL: Arming failsafe (76 seconds)
[1691403087.981880][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403087.981899][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403087.981955][7870:7872] CHIP:EM: <<< [E:58384i S:15906 M:216097744] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403087.981981][7870:7872] CHIP:IN: (S) Sending msg 216097744 on secure session with LSID: 15906
[1691403087.982243][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403087.982305][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403088.069641][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403088.115552][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403088.115660][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403088.115801][7870:7872] CHIP:EM: >>> [E:58384i S:15906 M:122858332] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403088.115829][7870:7872] CHIP:EM: Found matching exchange: 58384i, Delegate: 0x7f942c057188
[1691403088.115877][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403088.115924][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403088.115939][7870:7872] CHIP:DMG: {
[1691403088.115957][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403088.115974][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403088.116009][7870:7872] CHIP:DMG: [
[1691403088.116023][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403088.116052][7870:7872] CHIP:DMG: {
[1691403088.116065][7870:7872] CHIP:DMG: CommandDataIB =
[1691403088.116087][7870:7872] CHIP:DMG: {
[1691403088.116104][7870:7872] CHIP:DMG: CommandPathIB =
[1691403088.116125][7870:7872] CHIP:DMG: {
[1691403088.116146][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403088.116169][7870:7872] CHIP:DMG: ClusterId = 0x30,
[1691403088.116191][7870:7872] CHIP:DMG: CommandId = 0x1,
[1691403088.116210][7870:7872] CHIP:DMG: },
[1691403088.116234][7870:7872] CHIP:DMG:
[1691403088.116252][7870:7872] CHIP:DMG: CommandFields =
[1691403088.116274][7870:7872] CHIP:DMG: {
[1691403088.116296][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403088.116319][7870:7872] CHIP:DMG: 0x1 = "" (0 chars),
[1691403088.116340][7870:7872] CHIP:DMG: },
[1691403088.116358][7870:7872] CHIP:DMG: },
[1691403088.116386][7870:7872] CHIP:DMG:
[1691403088.116401][7870:7872] CHIP:DMG: },
[1691403088.116429][7870:7872] CHIP:DMG:
[1691403088.116443][7870:7872] CHIP:DMG: ],
[1691403088.116471][7870:7872] CHIP:DMG:
[1691403088.116486][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403088.116501][7870:7872] CHIP:DMG: },
[1691403088.116564][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1691403088.116591][7870:7872] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1691403088.116612][7870:7872] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeThreadEnable'
[1691403088.116626][7870:7872] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeThreadEnable' -> 'ThreadNetworkEnable'
[1691403088.116647][7870:7872] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable'
[1691403088.116691][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403088.116712][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403088.116768][7870:7872] CHIP:EM: <<< [E:58385i S:15906 M:216097745] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403088.116795][7870:7872] CHIP:IN: (S) Sending msg 216097745 on secure session with LSID: 15906
[1691403088.117034][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403088.117088][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403088.204543][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403089.330590][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403089.330709][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403089.330814][7870:7872] CHIP:EM: >>> [E:58385i S:15906 M:122858333] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403089.330844][7870:7872] CHIP:EM: Found matching exchange: 58385i, Delegate: 0x7f942c057d58
[1691403089.330869][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403089.330907][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403089.330922][7870:7872] CHIP:DMG: {
[1691403089.330938][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403089.330954][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403089.330980][7870:7872] CHIP:DMG: [
[1691403089.330995][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403089.331021][7870:7872] CHIP:DMG: {
[1691403089.331036][7870:7872] CHIP:DMG: CommandDataIB =
[1691403089.331056][7870:7872] CHIP:DMG: {
[1691403089.331072][7870:7872] CHIP:DMG: CommandPathIB =
[1691403089.331098][7870:7872] CHIP:DMG: {
[1691403089.331118][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403089.331137][7870:7872] CHIP:DMG: ClusterId = 0x31,
[1691403089.331157][7870:7872] CHIP:DMG: CommandId = 0x7,
[1691403089.331174][7870:7872] CHIP:DMG: },
[1691403089.331194][7870:7872] CHIP:DMG:
[1691403089.331210][7870:7872] CHIP:DMG: CommandFields =
[1691403089.331228][7870:7872] CHIP:DMG: {
[1691403089.331250][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403089.331269][7870:7872] CHIP:DMG: 0x2 = NULL
[1691403089.331294][7870:7872] CHIP:DMG: },
[1691403089.331310][7870:7872] CHIP:DMG: },
[1691403089.331334][7870:7872] CHIP:DMG:
[1691403089.331349][7870:7872] CHIP:DMG: },
[1691403089.331374][7870:7872] CHIP:DMG:
[1691403089.331388][7870:7872] CHIP:DMG: ],
[1691403089.331413][7870:7872] CHIP:DMG:
[1691403089.331428][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403089.331443][7870:7872] CHIP:DMG: },
[1691403089.331508][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1691403089.331533][7870:7872] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1691403089.331554][7870:7872] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
[1691403089.331571][7870:7872] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
[1691403089.331590][7870:7872] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1691403089.331604][7870:7872] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1691403089.331620][7870:7872] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1691403089.331644][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1691403089.331664][7870:7872] CHIP:DIS: Resolving CEFAD72140B20CDA:0000000000000001 ...
[1691403089.332412][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403089.332779][7870:7872] CHIP:DL: Avahi resolve found
[1691403089.332817][7870:7872] CHIP:DIS: Node ID resolved for CEFAD72140B20CDA:0000000000000001
[1691403089.332845][7870:7872] CHIP:DIS: Hostname: 127E39564B673908
[1691403089.332864][7870:7872] CHIP:DIS: IP Address #1: fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7
[1691403089.332875][7870:7872] CHIP:DIS: Port: 5540
[1691403089.332887][7870:7872] CHIP:DIS: Mrp Interval idle: 1000 ms
[1691403089.332900][7870:7872] CHIP:DIS: Mrp Interval active: 1000 ms
[1691403089.332912][7870:7872] CHIP:DIS: TCP Supported: 0
[1691403089.333107][7870:7872] CHIP:DIS: Lookup clearing interface for non LL address
[1691403089.333150][7870:7872] CHIP:DIS: UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7%wlp5s0]:5540: new best score: 4
[1691403089.333163][7870:7872] CHIP:DIS: Checking node lookup status after 1 ms
[1691403089.333175][7870:7872] CHIP:DIS: Keeping DNSSD lookup active
[1691403089.532304][7870:7872] CHIP:DIS: Checking node lookup status after 201 ms
[1691403089.532357][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540 while in state 2
[1691403089.532378][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1691403089.532440][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Allocated Type:2 LSID:15907
[1691403089.532505][7870:7872] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1691403089.540340][7870:7872] CHIP:EM: <<< [E:58386i S:0 M:166617638] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1691403089.540400][7870:7872] CHIP:IN: (U) Sending msg 166617638 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403089.540486][7870:7872] CHIP:SC: Sent Sigma1 msg
[1691403089.540500][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1691403090.803873][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617638 on exchange 58386i Send Cnt 1
[1691403090.803923][7870:7872] CHIP:IN: (U) Sending msg 166617638 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403090.861150][7870:7872] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1691403091.894189][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403092.050497][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617638 on exchange 58386i Send Cnt 2
[1691403092.050560][7870:7872] CHIP:IN: (U) Sending msg 166617638 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403094.099605][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617638 on exchange 58386i Send Cnt 3
[1691403094.099672][7870:7872] CHIP:IN: (U) Sending msg 166617638 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403094.453325][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403094.453410][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403097.159149][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403097.400545][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617638 on exchange 58386i Send Cnt 4
[1691403097.400601][7870:7872] CHIP:IN: (U) Sending msg 166617638 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403099.717736][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403099.717922][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403102.012114][7870:7872] CHIP:EM: Failed to Send CHIP MessageCounter:166617638 on exchange 58386i sendCount: 4 max retries: 4
[1691403102.469157][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403105.029819][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403105.029932][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403105.628685][7870:7872] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 1
[1691403105.628729][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Released - Type:2 LSID:15907
[1691403105.628761][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
[1691403105.628790][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
[1691403105.628820][7870:7872] CHIP:DIS: OperationalSessionSetup:attempts done: 1, attempts left: 2, retry delay 1s, status src/system/SystemLayerImplSelect.cpp:167: Success
[1691403105.628830][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 6
[1691403105.628860][7870:7872] CHIP:CTL: Session establishment failed for <0000000000000001, 1>, error: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout. Next retry expected to get a response to Sigma1 or fail within 8 seconds
[1691403105.628885][7870:7872] CHIP:CTL: Arming failsafe (68 seconds)
[1691403105.628932][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403105.628951][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403105.629013][7870:7872] CHIP:EM: <<< [E:58387i S:15906 M:216097746] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403105.629037][7870:7872] CHIP:IN: (S) Sending msg 216097746 on secure session with LSID: 15906
[1691403105.629287][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403105.710078][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403105.755846][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403105.756027][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403105.756128][7870:7872] CHIP:EM: >>> [E:58387i S:15906 M:122858334] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403105.756153][7870:7872] CHIP:EM: Found matching exchange: 58387i, Delegate: 0x7f942c057188
[1691403105.756176][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403105.756216][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403105.756229][7870:7872] CHIP:DMG: {
[1691403105.756240][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403105.756250][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403105.756267][7870:7872] CHIP:DMG: [
[1691403105.756276][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403105.756292][7870:7872] CHIP:DMG: {
[1691403105.756302][7870:7872] CHIP:DMG: CommandDataIB =
[1691403105.756314][7870:7872] CHIP:DMG: {
[1691403105.756324][7870:7872] CHIP:DMG: CommandPathIB =
[1691403105.756336][7870:7872] CHIP:DMG: {
[1691403105.756348][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403105.756369][7870:7872] CHIP:DMG: ClusterId = 0x30,
[1691403105.756388][7870:7872] CHIP:DMG: CommandId = 0x1,
[1691403105.756407][7870:7872] CHIP:DMG: },
[1691403105.756428][7870:7872] CHIP:DMG:
[1691403105.756445][7870:7872] CHIP:DMG: CommandFields =
[1691403105.756464][7870:7872] CHIP:DMG: {
[1691403105.756493][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403105.756515][7870:7872] CHIP:DMG: 0x1 = "" (0 chars),
[1691403105.756532][7870:7872] CHIP:DMG: },
[1691403105.756544][7870:7872] CHIP:DMG: },
[1691403105.756567][7870:7872] CHIP:DMG:
[1691403105.756580][7870:7872] CHIP:DMG: },
[1691403105.756602][7870:7872] CHIP:DMG:
[1691403105.756615][7870:7872] CHIP:DMG: ],
[1691403105.756639][7870:7872] CHIP:DMG:
[1691403105.756652][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403105.756664][7870:7872] CHIP:DMG: },
[1691403105.756725][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1691403105.756751][7870:7872] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1691403105.756781][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403106.629799][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 6 --> 2
[1691403106.629835][7870:7872] CHIP:DIS: Resolving CEFAD72140B20CDA:0000000000000001 ...
[1691403106.631114][7870:7872] CHIP:DL: Avahi resolve found
[1691403106.631156][7870:7872] CHIP:DIS: Node ID resolved for CEFAD72140B20CDA:0000000000000001
[1691403106.631166][7870:7872] CHIP:DIS: Hostname: 127E39564B673908
[1691403106.631177][7870:7872] CHIP:DIS: IP Address #1: fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7
[1691403106.631185][7870:7872] CHIP:DIS: Port: 5540
[1691403106.631193][7870:7872] CHIP:DIS: Mrp Interval idle: 1000 ms
[1691403106.631202][7870:7872] CHIP:DIS: Mrp Interval active: 1000 ms
[1691403106.631211][7870:7872] CHIP:DIS: TCP Supported: 0
[1691403106.631411][7870:7872] CHIP:DIS: Lookup clearing interface for non LL address
[1691403106.631456][7870:7872] CHIP:DIS: UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7%wlp5s0]:5540: new best score: 4
[1691403106.631469][7870:7872] CHIP:DIS: Checking node lookup status after 2 ms
[1691403106.631483][7870:7872] CHIP:DIS: Keeping DNSSD lookup active
[1691403106.830766][7870:7872] CHIP:DIS: Checking node lookup status after 201 ms
[1691403106.830817][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540 while in state 2
[1691403106.830839][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1691403106.830889][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Allocated Type:2 LSID:15908
[1691403106.830916][7870:7872] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1691403106.838442][7870:7872] CHIP:EM: <<< [E:58388i S:0 M:166617639] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1691403106.838480][7870:7872] CHIP:IN: (U) Sending msg 166617639 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403106.838572][7870:7872] CHIP:SC: Sent Sigma1 msg
[1691403106.838587][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1691403108.016007][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617639 on exchange 58388i Send Cnt 1
[1691403108.016064][7870:7872] CHIP:IN: (U) Sending msg 166617639 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403108.319259][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403109.308314][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617639 on exchange 58388i Send Cnt 2
[1691403109.308364][7870:7872] CHIP:IN: (U) Sending msg 166617639 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403110.877949][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403110.878078][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403111.364268][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617639 on exchange 58388i Send Cnt 3
[1691403111.364323][7870:7872] CHIP:IN: (U) Sending msg 166617639 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403113.584371][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403114.351265][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617639 on exchange 58388i Send Cnt 4
[1691403114.351312][7870:7872] CHIP:IN: (U) Sending msg 166617639 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403116.141775][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403116.141923][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403118.849486][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403119.882682][7870:7872] CHIP:EM: Failed to Send CHIP MessageCounter:166617639 on exchange 58388i sendCount: 4 max retries: 4
[1691403121.409785][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403121.409958][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403122.927666][7870:7872] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 1
[1691403122.927707][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Released - Type:2 LSID:15908
[1691403122.927744][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
[1691403122.927794][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
[1691403122.927833][7870:7872] CHIP:DIS: OperationalSessionSetup:attempts done: 2, attempts left: 1, retry delay 36s, status src/system/SystemLayerImplSelect.cpp:167: Success
[1691403122.927849][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 6
[1691403122.927876][7870:7872] CHIP:CTL: Session establishment failed for <0000000000000001, 1>, error: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout. Next retry expected to get a response to Sigma1 or fail within 43 seconds
[1691403122.927898][7870:7872] CHIP:CTL: Arming failsafe (103 seconds)
[1691403122.927964][7870:7872] CHIP:DMG: ICR moving to [AddingComm]
[1691403122.927987][7870:7872] CHIP:DMG: ICR moving to [AddedComma]
[1691403122.928058][7870:7872] CHIP:EM: <<< [E:58389i S:15906 M:216097747] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1691403122.928093][7870:7872] CHIP:IN: (S) Sending msg 216097747 on secure session with LSID: 15906
[1691403122.928393][7870:7872] CHIP:DMG: ICR moving to [CommandSen]
[1691403122.989612][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403123.035598][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403123.035808][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403123.035926][7870:7872] CHIP:EM: >>> [E:58389i S:15906 M:122858335] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1691403123.035962][7870:7872] CHIP:EM: Found matching exchange: 58389i, Delegate: 0x7f942c057188
[1691403123.035994][7870:7872] CHIP:DMG: ICR moving to [ResponseRe]
[1691403123.036036][7870:7872] CHIP:DMG: InvokeResponseMessage =
[1691403123.036050][7870:7872] CHIP:DMG: {
[1691403123.036067][7870:7872] CHIP:DMG: suppressResponse = false,
[1691403123.036088][7870:7872] CHIP:DMG: InvokeResponseIBs =
[1691403123.036118][7870:7872] CHIP:DMG: [
[1691403123.036131][7870:7872] CHIP:DMG: InvokeResponseIB =
[1691403123.036159][7870:7872] CHIP:DMG: {
[1691403123.036173][7870:7872] CHIP:DMG: CommandDataIB =
[1691403123.036193][7870:7872] CHIP:DMG: {
[1691403123.036209][7870:7872] CHIP:DMG: CommandPathIB =
[1691403123.036231][7870:7872] CHIP:DMG: {
[1691403123.036250][7870:7872] CHIP:DMG: EndpointId = 0x0,
[1691403123.036271][7870:7872] CHIP:DMG: ClusterId = 0x30,
[1691403123.036291][7870:7872] CHIP:DMG: CommandId = 0x1,
[1691403123.036306][7870:7872] CHIP:DMG: },
[1691403123.036324][7870:7872] CHIP:DMG:
[1691403123.036339][7870:7872] CHIP:DMG: CommandFields =
[1691403123.036355][7870:7872] CHIP:DMG: {
[1691403123.036376][7870:7872] CHIP:DMG: 0x0 = 0,
[1691403123.036395][7870:7872] CHIP:DMG: 0x1 = "" (0 chars),
[1691403123.036411][7870:7872] CHIP:DMG: },
[1691403123.036425][7870:7872] CHIP:DMG: },
[1691403123.036446][7870:7872] CHIP:DMG:
[1691403123.036459][7870:7872] CHIP:DMG: },
[1691403123.036479][7870:7872] CHIP:DMG:
[1691403123.036492][7870:7872] CHIP:DMG: ],
[1691403123.036513][7870:7872] CHIP:DMG:
[1691403123.036526][7870:7872] CHIP:DMG: InteractionModelRevision = 1
[1691403123.036538][7870:7872] CHIP:DMG: },
[1691403123.036596][7870:7872] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1691403123.036620][7870:7872] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1691403123.036653][7870:7872] CHIP:DMG: ICR moving to [AwaitingDe]
[1691403125.599308][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403128.161938][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403128.162110][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403128.580896][7870:7871] CHIP:DL: Got IP address on interface: wlp5s0 IP: 192.168.7.165
[1691403128.581477][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 32770
[1691403128.788655][7870:7871] CHIP:DL: Got IP address on interface: wlp5s0 IP: 192.168.7.165
[1691403128.788765][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 32770
[1691403130.865106][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403133.422103][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403133.422202][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403136.129798][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403138.690179][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403138.690264][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403141.394584][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403143.953602][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403143.953759][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403146.705003][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403149.221947][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403149.222076][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403151.924728][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403154.481664][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403154.481825][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403157.189677][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403158.928277][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 6 --> 2
[1691403158.928314][7870:7872] CHIP:DIS: Resolving CEFAD72140B20CDA:0000000000000001 ...
[1691403158.929602][7870:7872] CHIP:DL: Avahi resolve found
[1691403158.929654][7870:7872] CHIP:DIS: Node ID resolved for CEFAD72140B20CDA:0000000000000001
[1691403158.929671][7870:7872] CHIP:DIS: Hostname: 127E39564B673908
[1691403158.929691][7870:7872] CHIP:DIS: IP Address #1: fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7
[1691403158.929703][7870:7872] CHIP:DIS: Port: 5540
[1691403158.929716][7870:7872] CHIP:DIS: Mrp Interval idle: 1000 ms
[1691403158.929730][7870:7872] CHIP:DIS: Mrp Interval active: 1000 ms
[1691403158.929746][7870:7872] CHIP:DIS: TCP Supported: 0
[1691403158.929926][7870:7872] CHIP:DIS: Lookup clearing interface for non LL address
[1691403158.929970][7870:7872] CHIP:DIS: UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7%wlp5s0]:5540: new best score: 4
[1691403158.929984][7870:7872] CHIP:DIS: Checking node lookup status after 1 ms
[1691403158.929998][7870:7872] CHIP:DIS: Keeping DNSSD lookup active
[1691403159.128923][7870:7872] CHIP:DIS: Checking node lookup status after 200 ms
[1691403159.128980][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540 while in state 2
[1691403159.129006][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1691403159.129061][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Allocated Type:2 LSID:15909
[1691403159.129093][7870:7872] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1691403159.135600][7870:7872] CHIP:EM: <<< [E:58390i S:0 M:166617640] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1691403159.135624][7870:7872] CHIP:IN: (U) Sending msg 166617640 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403159.135679][7870:7872] CHIP:SC: Sent Sigma1 msg
[1691403159.135687][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1691403159.749403][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403159.749607][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403160.465477][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617640 on exchange 58390i Send Cnt 1
[1691403160.465529][7870:7872] CHIP:IN: (U) Sending msg 166617640 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403161.642886][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617640 on exchange 58390i Send Cnt 2
[1691403161.642949][7870:7872] CHIP:IN: (U) Sending msg 166617640 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403162.500317][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403163.522782][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617640 on exchange 58390i Send Cnt 3
[1691403163.522827][7870:7872] CHIP:IN: (U) Sending msg 166617640 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403165.013984][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403165.014165][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403166.699874][7870:7872] CHIP:EM: Retransmitting MessageCounter:166617640 on exchange 58390i Send Cnt 4
[1691403166.699919][7870:7872] CHIP:IN: (U) Sending msg 166617640 to IP address 'UDP:[fd8a:1ee1:ee51:1:88c8:90a5:f389:9ac7]:5540'
[1691403167.720303][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403170.277544][7870:7871] CHIP:DL: Indication received, conn = 0x7f942c056c60
[1691403170.277655][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1691403171.420308][7870:7872] CHIP:EM: Failed to Send CHIP MessageCounter:166617640 on exchange 58390i sendCount: 4 max retries: 4
[1691403172.984995][7870:7872] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1691403175.225420][7870:7872] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 1
[1691403175.225468][7870:7872] CHIP:IN: SecureSession[0x7f94240176b0]: Released - Type:2 LSID:15909
[1691403175.225513][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
[1691403175.225539][7870:7872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
[1691403175.225570][7870:7872] CHIP:CTL: Device connection failed. Error src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout
[1691403175.225606][7870:7872] CHIP:CTL: Error on commissioning step 'FindOperational': 'src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout'
[1691403175.225631][7870:7872] CHIP:CTL: Failed to perform commissioning step 20
[1691403175.225655][7870:7872] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = 'src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1691403175.225686][7870:7872] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout'
[1691403175.225711][7870:7872] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1691403175.225740][7870:7872] CHIP:TOO: Device commissioning Failure: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout
[1691403175.225992][7870:7870] CHIP:CTL: Shutting down the commissioner
[1691403175.226015][7870:7870] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1691403175.226024][7870:7870] CHIP:DIS: Closing all BLE connections
[1691403175.226035][7870:7870] CHIP:IN: Clearing BLE pending packets.
[1691403175.226251][7870:7870] CHIP:BLE: Auto-closing end point's BLE connection.
[1691403175.226274][7870:7870] CHIP:DL: Closing BLE GATT connection (con 0x7f942c056c60)
[1691403175.226389][7870:7871] CHIP:DL: BluezDisconnect peer=F4:10:CB:75:55:F1
[1691403175.371432][7870:7870] CHIP:IN: SecureSession[0x7f94240095a0]: MarkForEviction Type:1 LSID:15906
[1691403175.371467][7870:7870] CHIP:SC: SecureSession[0x7f94240095a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1691403175.371495][7870:7870] CHIP:IN: SecureSession[0x7f94240095a0]: Released - Type:1 LSID:15906
[1691403175.371516][7870:7870] CHIP:CTL: Shutting down the controller
[1691403175.371531][7870:7870] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1691403175.371542][7870:7870] CHIP:FP: Forgetting fabric 0x1
[1691403175.371561][7870:7870] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371696][7870:7870] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371716][7870:7870] CHIP:TS: Reverted Last Known Good Time to previous value
[1691403175.371739][7870:7870] CHIP:CTL: Shutting down the commissioner
[1691403175.371778][7870:7870] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1691403175.371792][7870:7870] CHIP:CTL: Shutting down the controller
[1691403175.371804][7870:7870] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1691403175.372028][7870:7871] CHIP:DL: Bluez disconnected
[1691403175.372053][7870:7871] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1691403175.372908][7870:7870] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1691403175.372971][7870:7870] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1691403175.373010][7870:7870] CHIP:FP: Shutting down FabricTable
[1691403175.373037][7870:7870] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1691403175.373150][7870:7870] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1691403175.373163][7870:7870] CHIP:TS: Reverted Last Known Good Time to previous value
[1691403175.373357][7870:7870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-mcUdZA)
[1691403175.373759][7870:7870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1691403175.373803][7870:7870] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1691403175.373819][7870:7870] CHIP:DL: Inet Layer shutdown
[1691403175.373831][7870:7870] CHIP:DL: BLE shutdown
[1691403175.374584][7870:7870] CHIP:DL: System Layer shutdown
[1691403175.374869][7870:7870] CHIP:TOO: Run command failure: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout
lenovo@lenovo-ThinkPad-L470:~/Downloads$ 7f94240095a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1691403175.371495][7870:7870] CHIP:IN: SecureSession[0x7f94240095a0]: Released - Type:1 LSID:15906
[1691403175.371516][7870:7870] CHIP:CTL: Shutting down the controller
[1691403175.371531][7870:7870] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1691403175.371542][7870:7870] CHIP:FP: Forgetting fabric 0x1
[1691403175.371561][7870:7870] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371696][7870:7870] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371716][7870:7870] CHIP:TS: Reverted Last Known Good Time to previous value
[1691403175.371739][7870:7870] CHIP:CTL: Shutting down the commissioner
[1691403175.371778][7870:7870] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1691403175.371792][7870:7870] CHIP:CTL: Shutting down the controller
[1691403175.371804][7870:7870] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1691403175.372028][7870:7871] CHIP:DL: Bluez disconnected
[1691403175.372053][7870:7871] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1691403175.372908][7870:7870] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1691403175.372971][7870:7870] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1691403175.373010][7870:7870] CHIP:FP: Shutting down FabricTable
[1691403175.373037][7870:7870] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1691403175.373150][7870:7870] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1691403175.373163][7870:7870] CHIP:TS: Reverted Last Known Good Time to previous value
[1691403175.373357][7870:7870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-mcUdZA)
[1691403175.373759][7870:7870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1691403175.373803][7870:7870] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1691403175.373819][7870:7870] CHIP:DL: Inet Layer shutdown
[1691403175.373831][7870:7870] CHIP:DL: BLE shutdown
[1691403175.374584][7870:7870] CHIP:DL: System Layer shutdown
[1691403175.374869][7870:7870] CHIP:TOO: Run command failure: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout7f94240095a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1691403175.371495][7870:7870] CHIP:IN: SecureSession[0x7f94240095a0]: Released - Type:1 LSID:15906
[1691403175.371516][7870:7870] CHIP:CTL: Shutting down the controller
[1691403175.371531][7870:7870] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1691403175.371542][7870:7870] CHIP:FP: Forgetting fabric 0x1
[1691403175.371561][7870:7870] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371696][7870:7870] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1691403175.371716][7870:7870] CHIP:TS: Reverted Last Known Good Time to previous value
[1691403175.371739][7870:7870] CHIP:CTL: Shutting down the commissioner
[
I've tried
1. Factory reset the nRF 5340dk board
2. Reboot the Border Router
3. Try to unpair the node device in Chip-tool (it gave error : retry resolve)
Still, the error is not resolved
Am I missing something?
Need Help
