Error on commissioning step:operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout

[maheswara]

I am trying to test template sample application with nRF52840DK and see that commissioning fails

My environment:

nRF connect sdk:   v2.3.0

nRF connect toolchain:   v2.3.0

chip-tool running on ubuntu

border router: Raspberry Pi with nRf52840 Dongle

I see that BLE connection is successful, but fails  with error -Failed to perform commissioning step 18

Please see the attached file for logs

Appreciate your quick help

Thanks,

Mahesh

Fullscreen nRF52840dk.log Download

: 92797EEA6C7282EA._matterc._udp
E: 89539 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 89543 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 89549 [IN]Expiring all sessions for fabric 0x1!!
E: 89554 [FP]Reverting pending fabric data for fabric 0x1
D: 89559 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015DD7
D: 89573 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89580 [FP]Warning: metadata not found during delete of fabric 0x1
I: 89651 [FP]Fabric (0x1) deleted.
I: 89655 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 89660 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e3
D: 89667 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e4
I: 89832 [TS]Pending Last Known Good Time: 2023-02-18T10:14:41
I: 89838 [TS]Previous Last Known Good Time: 2023-02-18T10:14:41
I: 89844 [TS]Reverted Last Known Good Time to previous value
D: 89850 [EVL]LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015EF9
D: 89864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89870 [FP]Warning: metadata not found during delete of fabric 0x1
E: 89879 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 89884 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b98af9cc
D: 89891 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
I: 89898 [NP]Reverting Thread operational dataset
E: 89911 [DL]Long dispatch time: 460 ms, for event type 32782
I: 89916 [FS]Fail-safe cleanly disarmed
I: 89922 [DL]CHIPoBLE advertising started
D: 89926 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 89931 [DL]   Device Role: DISABLED
D: 89934 [DL]   Thread Unicast Addresses:
D: 89938 [DL]        fd6a:8c75:12d3:1:2d9d:1522:2c95:e401/64 valid preferred
D: 89946 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 119926 [DL]CHIPoBLE advertising mode changed to slow
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 3, 940
I: data wra: 3, 84c


uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 221 [DL]BLE address: F7:C4:D2:DA:E3:6F
I: 232 [DL]OpenThread started: OK
I: 235 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 241 [SVR]Server initializing...
I: 244 [TS]Last Known Good Time: 2023-02-18T10:14:41
I: 249 [TS]Setting Last Known Good Time to firmware build time 2023-03-09T08:28:35
I: 259 [DMG]AccessControl: initializing
I: 262 [DMG]Examples::AccessControlDelegate::Init
I: 266 [DMG]AccessControl: setting
I: 270 [DMG]DefaultAclStorage: initializing
I: 273 [DMG]DefaultAclStorage: 0 entries loaded
D: 278 [IN]UDP::Init bind&listen port=5540
E: 281 [IN]SO_REUSEPORT failed: 109
D: 285 [IN]UDP::Init bound to port=5540
D: 288 [IN]BLEBase::Init - setting/overriding transport
D: 293 [IN]TransportMgr initialized
I: 303 [ZCL]Using ZAP configuration...
I: 308 [DMG]AccessControlCluster: initializing
I: 312 [ZCL]Initiating Admin Commissioning cluster.
D: 319 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25692
I: 325 [DIS]Updating services using commissioning mode 1
I: 331 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 340 [DIS]Failed to advertise commissionable node: 3
E: 345 [DIS]Failed to finalize service update: 1c
I: 349 [DIS]Updating services using commissioning mode 1
I: 355 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 364 [DIS]Failed to advertise commissionable node: 3
E: 369 [DIS]Failed to finalize service update: 1c
I: 373 [DIS]Delaying proxy of operational discovery: missing delegate
I: 379 [IN]CASE Server enabling CASE session setups
D: 384 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:25693
I: 390 [SVR]Joining Multicast groups
I: 393 [SVR]Server Listening...
I: 396 [DL]Device Configuration:
I: 399 [DL]  Serial Number: 11223344556677889900
I: 404 [DL]  Vendor Id: 65521 (0xFFF1)
I: 407 [DL]  Product Id: 32768 (0x8000)
I: 411 [DL]  Hardware Version: 0
I: 415 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 420 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 427 [DL]  Manufacturing Date: (not set)
I: 431 [DL]  Device Type: 65535 (0xFFFF)
I: 436 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 440 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 446 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 455 [SVR]Manual pairing code: [34970112332]
I: 460 [DL]CHIP task running
I: 465 [DL]CHIPoBLE advertising started
I: 20280 [DL]BLE connection established (ConnId: 0x00)
I: 20285 [DL]Current number of connections: 1/1
I: 20289 [DL]CHIPoBLE advertising stopped
I: 21882 [BLE]local and remote recv window sizes = 5
I: 21886 [BLE]selected BTP version 4
I: 21890 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 21972 [IN]BLE EndPoint 0x2000fd28 Connection Complete
I: 21977 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 22063 [EM]>>> [E:32398r M:133325430] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 22076 [EM]<<< [E:32398r M:103602529] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 22087 [IN](U) Sending msg 103602529 to IP address 'BLE'
I: 22198 [EM]>>> [E:32398r M:133325431] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 24073 [EM]<<< [E:32398r M:103602530] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 24084 [IN](U) Sending msg 103602530 to IP address 'BLE'
E: 24089 [DL]Long dispatch time: 1891 ms, for event type 16388
I: 24223 [EM]>>> [E:32398r M:133325432] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 24234 [EM]<<< [E:32398r M:103602531] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 24245 [IN](U) Sending msg 103602531 to IP address 'BLE'
I: 24252 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive'
D: 24259 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:25692
D: 24266 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:25692 PSID:56322!
I: 24275 [SVR]Commissioning completed session establishment step
I: 24281 [DIS]Updating services using commissioning mode 0
I: 24287 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
E: 24296 [DIS]Failed to advertise extended commissionable node: 3
D: 24302 [DIS]Scheduling extended discovery timeout in 900s
E: 24307 [DIS]Failed to finalize service update: 1c
I: 24312 [SVR]Device completed Rendezvous process
I: 24319 [EM]>>> [E:32399r M:259258149] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 24329 [IM]Received Read request
I: 24338 [EM]<<< [E:32399r M:182183003] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 24348 [IN](S) Sending msg 182183003 on secure session with LSID: 25692
I: 24494 [EM]>>> [E:32400r M:259258150] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24505 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 24512 [EM]<<< [E:32400r M:182183004] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24523 [IN](S) Sending msg 182183004 on secure session with LSID: 25692
I: 24584 [EM]>>> [E:32401r M:259258151] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24597 [EM]<<< [E:32401r M:182183005] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24608 [IN](S) Sending msg 182183005 on secure session with LSID: 25692
I: 24674 [EM]>>> [E:32402r M:259258152] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24685 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 24694 [EM]<<< [E:32402r M:182183006] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24705 [IN](S) Sending msg 182183006 on secure session with LSID: 25692
I: 24944 [EM]>>> [E:32403r M:259258153] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24955 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 24964 [EM]<<< [E:32403r M:182183007] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24975 [IN](S) Sending msg 182183007 on secure session with LSID: 25692
I: 25214 [EM]>>> [E:32404r M:259258154] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25226 [ZCL]OpCreds: Received an AttestationRequest command
I: 25262 [ZCL]OpCreds: AttestationRequest successful.
I: 25270 [EM]<<< [E:32404r M:182183008] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25281 [IN](S) Sending msg 182183008 on secure session with LSID: 25692
I: 25619 [EM]>>> [E:32405r M:259258155] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25630 [ZCL]OpCreds: Received a CSRRequest command
I: 25820 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 25856 [ZCL]OpCreds: CSRRequest successful.
I: 25862 [EM]<<< [E:32405r M:182183009] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25873 [IN](S) Sending msg 182183009 on secure session with LSID: 25692
E: 25880 [DL]Long dispatch time: 262 ms, for event type 16388
I: 26204 [EM]>>> [E:32406r M:259258156] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26216 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 26279 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 26285 [EM]<<< [E:32406r M:182183010] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 26296 [IN](S) Sending msg 182183010 on secure session with LSID: 25692
E: 26303 [DL]Long dispatch time: 101 ms, for event type 16388
I: 26656 [EM]>>> [E:32407r M:259258157] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26667 [ZCL]OpCreds: Received an AddNOC command
I: 26674 [FP]Validating NOC chain
I: 26792 [FP]NOC chain validation successful
I: 26796 [FP]Added new fabric at index: 0x1
I: 26800 [FP]Assigned compressed fabric ID: 0x78D8657DCCA52CBD, node ID: 0x0000000000000001
I: 26808 [TS]Last Known Good Time: 2023-03-09T08:28:35
I: 26813 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 26819 [TS]Retaining current Last Known Good Time
I: 27015 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 27024 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 27030 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 27038 [EM]<<< [E:32407r M:182183011] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27048 [IN](S) Sending msg 182183011 on secure session with LSID: 25692
E: 27055 [DL]Long dispatch time: 402 ms, for event type 16388
I: 27106 [EM]>>> [E:32408r M:259258158] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 27123 [EM]<<< [E:32408r M:182183012] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27134 [IN](S) Sending msg 182183012 on secure session with LSID: 25692
I: 27194 [EM]>>> [E:32409r M:259258159] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28666 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
I: 28679 [EM]<<< [E:32409r M:182183013] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28690 [IN](S) Sending msg 182183013 on secure session with LSID: 25692
I: 28697 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 28704 [SVR]Operational advertising enabled
I: 29450 [DIS]Setting operational delegate post init
I: 29458 [SWU]Stopping the watchdog timer
I: 29462 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 29468 [DIS]Updating services using commissioning mode 0
I: 29473 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 29480 [DL]advertising srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 29489 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 29499 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 73766 [IN]Clearing BLE pending packets.
I: 73770 [BLE]Releasing end point's BLE connection back to application.
I: 73776 [DL]Closing BLE GATT connection (ConnId 00)
I: 73901 [DL]BLE GAP connection terminated (reason 0x16)
I: 73906 [DL]Current number of connections: 0/1
I: 84511 [FS]Fail-safe timer expired
E: 84514 [SVR]Failsafe timer expired
D: 84518 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:25692
I: 84524 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction'
D: 84532 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25692
E: 84538 [SVR]Commissioning failed (attempt 1): 32
D: 84545 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25694
I: 84551 [DIS]Updating services using commissioning mode 1
I: 84556 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 84564 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84574 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
E: 84580 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 84584 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 84591 [IN]Expiring all sessions for fabric 0x1!!
E: 84595 [FP]Reverting pending fabric data for fabric 0x1
E: 84601 [FP]Warning: metadata not found during delete of fabric 0x1
I: 84612 [FP]Fabric (0x1) deleted.
I: 84615 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 84620 [DIS]Updating services using commissioning mode 1
I: 84626 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84635 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
I: 84642 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 84769 [TS]Pending Last Known Good Time: 2023-03-09T08:28:35
I: 84775 [TS]Previous Last Known Good Time: 2023-03-09T08:28:35
I: 84781 [TS]Reverted Last Known Good Time to previous value
E: 84787 [FP]Warning: metadata not found during delete of fabric 0x1
E: 84795 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 84801 [NP]Reverting Thread operational dataset
E: 84813 [DL]Long dispatch time: 299 ms, for event type 32782
I: 84818 [FS]Fail-safe cleanly disarmed
I: 84823 [DL]CHIPoBLE advertising started
I: 114827 [DL]CHIPoBLE advertising mode changed to slow
I: 114834 [DL]CHIPoBLE advertising started
I: 900318 [SVR]Closing pairing window
D: 900321 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25694
I: 900327 [DIS]Updating services using commissioning mode 0
I: 900333 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 900343 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 900349 [DIS]Scheduling extended discovery timeout in 900s
I: 900354 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 900362 [DL]CHIPoBLE advertising stopped

chip-tool.log

[Priyanka]

Hi Mahesh,

I have contacted internally regarding the issue and will get back to you as soon as I get a response.

Best Regards,

Priyanka

[maheswara]

Any update on this issue?

[Priyanka]

Thanks. I have updated this to the team as well. Will get back to you as soon as I get a response from the experts.

[maheswara]

Any Update on this? 

Thanks,

Mahesh

[Priyanka]

Hi,

Sorry for the delay. The team is currently a bit busy and please do bear with us. I will get back to you as soon as possible, with a solution.

[Priyanka]

Hi Mahesh,

I have heard back from them.

Regarding this,

maheswara said:

I am using ubuntu to commission the device through BLE  using following command (I believe IPv6 support on ubuntu should not matter)

They say the following:

"Actually it does matter. The first stage of a commissioning is done using BLE and I believe it succeeded. Then the device successfully joined the Thread network, what we can see based on this log from CHIPTool: "Successfully finished commissioning step 'ThreadNetworkEnable'".

Then the CHIPTool wants to resolve the Matter device IP address using the DNS-SD and I can see in logs that it fails."

So, as in the previous comments that I had mentioned, the Raspberry Pi must support RIO, so that the CHIPTool could receive IPv6 prefix from Thread Border Router and then perform DNS discovery in Thread network created by the Thread Border Router. Could you confirm that you performed the steps that we had mentioned in the previous comments?

-

[maheswara]

Thanks for the help. Now I am using chipttol with ubuntu over wifi and discovery seems be successful but failing in OperationalSessionSetup

Appreciate your quick help to resolve the issues

attached the failure logs

Thanks,

Mahesh.

Fullscreen nRF52840-template-errors.txt Download

Connected via Serial Port with settings /dev/ttyACM0 115200 8n1 rtscts:off


~x~~x~: command not found
uart:~$
uart:~$ I: 100495 [DL]BLE connection established (ConnId: 0x00)
I: 100500 [DL]Current number of connections: 1/1
I: 100504 [DL]CHIPoBLE advertising stopped
I: 100508 [DL]NFC Tag emulation stopped
I: 102232 [BLE]local and remote recv window sizes = 5
I: 102236 [BLE]selected BTP version 4
I: 102240 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 102322 [IN]BLE EndPoint 0x200124d8 Connection Complete
I: 102327 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 102413 [EM]>>> [E:40953r M:43039066] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 102426 [EM]<<< [E:40953r M:257634583] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 102437 [IN](U) Sending msg 257634583 to IP address 'BLE'
I: 102548 [EM]>>> [E:40953r M:43039067] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 104454 [EM]<<< [E:40953r M:257634584] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 104465 [IN](U) Sending msg 257634584 to IP address 'BLE'
E: 104470 [DL]Long dispatch time: 1922 ms, for event type 16388
I: 104573 [EM]>>> [E:40953r M:43039068] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 104584 [EM]<<< [E:40953r M:257634585] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 104595 [IN](U) Sending msg 257634585 to IP address 'BLE'
I: 104602 [SC]SecureSession[0x20003568]: Moving from state 'kEstablishing' --> 'kActive'
D: 104609 [IN]SecureSession[0x20003568]: Activated - Type:1 LSID:29298
D: 104616 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:29298 PSID:26634!
I: 104625 [SVR]Commissioning completed session establishment step
I: 104631 [DIS]Updating services using commissioning mode 0
I: 104637 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 104647 [DIS]Failed to advertise extended commissionable node: 3
D: 104652 [DIS]Scheduling extended discovery timeout in 900s
E: 104658 [DIS]Failed to finalize service update: 1c
I: 104663 [SVR]Device completed Rendezvous process
I: 104710 [EM]>>> [E:40954r M:217898161] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 104720 [IM]Received Read request
I: 104729 [EM]<<< [E:40954r M:208773525] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 104739 [IN](S) Sending msg 208773525 on secure session with LSID: 29298
I: 104979 [EM]>>> [E:40955r M:217898162] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 104990 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 104997 [EM]<<< [E:40955r M:208773526] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 105008 [IN](S) Sending msg 208773526 on secure session with LSID: 29298
I: 105069 [EM]>>> [E:40956r M:217898163] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 105083 [EM]<<< [E:40956r M:208773527] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 105094 [IN](S) Sending msg 208773527 on secure session with LSID: 29298
I: 105159 [EM]>>> [E:40957r M:217898164] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 105170 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 105179 [EM]<<< [E:40957r M:208773528] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 105190 [IN](S) Sending msg 208773528 on secure session with LSID: 29298
I: 105474 [EM]>>> [E:40958r M:217898165] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 105485 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 105494 [EM]<<< [E:40958r M:208773529] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 105505 [IN](S) Sending msg 208773529 on secure session with LSID: 29298
I: 105744 [EM]>>> [E:40959r M:217898166] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 105756 [ZCL]OpCreds: Received an AttestationRequest command
I: 105792 [ZCL]OpCreds: AttestationRequest successful.
I: 105800 [EM]<<< [E:40959r M:208773530] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 105811 [IN](S) Sending msg 208773530 on secure session with LSID: 29298
I: 106194 [EM]>>> [E:40960r M:217898167] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 106205 [ZCL]OpCreds: Received a CSRRequest command
I: 106396 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 106432 [ZCL]OpCreds: CSRRequest successful.
I: 106438 [EM]<<< [E:40960r M:208773531] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 106449 [IN](S) Sending msg 208773531 on secure session with LSID: 29298
E: 106456 [DL]Long dispatch time: 263 ms, for event type 16388
I: 106779 [EM]>>> [E:40961r M:217898168] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 106791 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 106853 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 106859 [EM]<<< [E:40961r M:208773532] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 106871 [IN](S) Sending msg 208773532 on secure session with LSID: 29298
I: 107276 [EM]>>> [E:40962r M:217898169] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 107287 [ZCL]OpCreds: Received an AddNOC command
I: 107295 [FP]Validating NOC chain
I: 107411 [FP]NOC chain validation successful
I: 107415 [FP]Added new fabric at index: 0x1
I: 107419 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001
I: 107427 [TS]Last Known Good Time: 2023-03-19T22:11:21
I: 107432 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 107438 [TS]Retaining current Last Known Good Time
I: 107465 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 107474 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 107480 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 107488 [EM]<<< [E:40962r M:208773533] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 107499 [IN](S) Sending msg 208773533 on secure session with LSID: 29298
E: 107506 [DL]Long dispatch time: 233 ms, for event type 16388
I: 107591 [EM]>>> [E:40963r M:217898170] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 107608 [EM]<<< [E:40963r M:208773534] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 107619 [IN](S) Sending msg 208773534 on secure session with LSID: 29298
I: 107679 [EM]>>> [E:40964r M:217898171] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 108701 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
I: 108714 [EM]<<< [E:40964r M:208773535] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 108725 [IN](S) Sending msg 208773535 on secure session with LSID: 29298
I: 108732 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 108739 [SVR]Operational advertising enabled
I: 109112 [DIS]Setting operational delegate post init
I: 109121 [SWU]Stopping the watchdog timer
I: 109125 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 109131 [DIS]Updating services using commissioning mode 0
I: 109137 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 109144 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 109152 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 109162 [DL]advertising srp service: 39C191837C681C04._matterc._udp
I: 111155 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 111166 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e98
I: 111174 [IN]CASE Server disabling CASE session setups
I: 111179 [EM]<<< [E:40965r M:257634586 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 111192 [IN](U) Sending msg 257634586 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 111202 [SC]Received Sigma1 msg
I: 111210 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
I: 111438 [EM]<<< [E:40965r M:257634587 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 111450 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 111462 [SC]Sent Sigma2 msg
D: 112271 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
I: 112279 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 112291 [EM]<<< [E:40965r M:257634588 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 112303 [IN](U) Sending msg 257634588 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 112339 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 113200 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
D: 113477 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
I: 113486 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 113497 [EM]<<< [E:40965r M:257634589 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 113510 [IN](U) Sending msg 257634589 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 114291 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
I: 115693 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
D: 115939 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
I: 115947 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 115959 [EM]<<< [E:40965r M:257634590 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 115972 [IN](U) Sending msg 257634590 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
E: 117693 [EM]Failed to Send CHIP MessageCounter:257634587 on exchange 40965r sendCount: 4 max retries: 4
D: 118817 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
I: 118825 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 118837 [EM]<<< [E:40965r M:257634591 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 118850 [IN](U) Sending msg 257634591 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
D: 127026 [IN]Clearing BLE pending packets.
I: 127030 [BLE]Releasing end point's BLE connection back to application.
I: 127037 [DL]Closing BLE GATT connection (ConnId 00)
I: 127161 [DL]BLE GAP connection terminated (reason 0x16)
I: 127166 [DL]Current number of connections: 0/1
E: 148162 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2
E: 148171 [IN]CASE Session establishment failed: 32
I: 148176 [IN]CASE Server enabling CASE session setups
D: 148181 [IN]SecureSession[0x20003620]: Released - Type:2 LSID:29299
D: 148187 [IN]SecureSession[0x20003620]: Allocated Type:2 LSID:29300
I: 164996 [FS]Fail-safe timer expired
E: 165000 [SVR]Failsafe timer expired
D: 165003 [IN]SecureSession[0x20003568]: MarkForEviction Type:1 LSID:29298
I: 165010 [SC]SecureSession[0x20003568]: Moving from state 'kActive' --> 'kPendingEviction'
D: 165018 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29298
E: 165024 [SVR]Commissioning failed (attempt 1): 32
D: 165031 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:29301
I: 165037 [DIS]Updating services using commissioning mode 1
I: 165043 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 165051 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
I: 165060 [DL]advertising srp service: 39C191837C681C04._matterc._udp
E: 165067 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 165071 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 165078 [IN]Expiring all sessions for fabric 0x1!!
E: 165082 [FP]Reverting pending fabric data for fabric 0x1
E: 165089 [FP]Warning: metadata not found during delete of fabric 0x1
I: 165100 [FP]Fabric (0x1) deleted.
I: 165103 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 165108 [DIS]Updating services using commissioning mode 1
I: 165114 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
I: 165124 [DL]advertising srp service: 39C191837C681C04._matterc._udp
I: 165130 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 165293 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21
I: 165300 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21
I: 165306 [TS]Reverted Last Known Good Time to previous value
E: 165313 [FP]Warning: metadata not found during delete of fabric 0x1
E: 165323 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 165330 [NP]Reverting Thread operational dataset
E: 165342 [DL]Long dispatch time: 342 ms, for event type 32782
I: 165348 [FS]Fail-safe cleanly disarmed
I: 165353 [DL]CHIPoBLE advertising started
I: 165360 [DL]NFC Tag emulation started
I: 195357 [DL]CHIPoBLE advertising mode changed to slow
I: 195364 [DL]CHIPoBLE advertising started
I: 900328 [SVR]Closing pairing window
D: 900332 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29301
I: 900338 [DIS]Updating services using commissioning mode 0
I: 900344 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 900353 [DL]advertising srp service: 39C191837C681C04._matterc._udp
D: 900359 [DIS]Scheduling extended discovery timeout in 900s
I: 900365 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 900372 [DL]CHIPoBLE advertising stopped
I: 900376 [DL]NFC Tag emulation stopped
D: 1800365 [DIS]Extended discovery timed out
I: 1800369 [DIS]Updating services using commissioning mode 0
I: 1800374 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 1800382 [DL]removing srp service: 39C191837C681C04._matterc._udp
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 1, e68
I: data wra: 1, 2a8


uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 223 [DL]BLE address: C4:59:9B:B5:0D:6F
I: 234 [DL]OpenThread started: OK
I: 237 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 242 [SVR]Server initializing...
I: 246 [TS]Last Known Good Time: 2023-03-19T22:11:21
I: 252 [DMG]AccessControl: initializing
I: 255 [DMG]Examples::AccessControlDelegate::Init
I: 260 [DMG]AccessControl: setting
I: 263 [DMG]DefaultAclStorage: initializing
I: 266 [DMG]DefaultAclStorage: 0 entries loaded
D: 271 [IN]UDP::Init bind&listen port=5540
E: 275 [IN]SO_REUSEPORT failed: 109
D: 278 [IN]UDP::Init bound to port=5540
D: 281 [IN]BLEBase::Init - setting/overriding transport
D: 286 [IN]TransportMgr initialized
I: 296 [ZCL]Using ZAP configuration...
I: 301 [DMG]AccessControlCluster: initializing
I: 305 [ZCL]Initiating Admin Commissioning cluster.
D: 312 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26314
I: 318 [DIS]Updating services using commissioning mode 1
I: 324 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 333 [DIS]Failed to advertise commissionable node: 3
E: 338 [DIS]Failed to finalize service update: 1c
I: 342 [DIS]Updating services using commissioning mode 1
I: 349 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 358 [DIS]Failed to advertise commissionable node: 3
E: 362 [DIS]Failed to finalize service update: 1c
I: 367 [DIS]Delaying proxy of operational discovery: missing delegate
I: 373 [IN]CASE Server enabling CASE session setups
D: 378 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26315
I: 383 [SVR]Joining Multicast groups
I: 387 [SVR]Server Listening...
I: 390 [DL]Device Configuration:
I: 393 [DL]  Serial Number: 11223344556677889900
I: 397 [DL]  Vendor Id: 65521 (0xFFF1)
I: 401 [DL]  Product Id: 32768 (0x8000)
I: 405 [DL]  Hardware Version: 0
I: 408 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 414 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 421 [DL]  Manufacturing Date: (not set)
I: 425 [DL]  Device Type: 65535 (0xFFFF)
I: 430 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 434 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 440 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 449 [SVR]Manual pairing code: [34970112332]
I: 454 [DL]CHIP task running
I: 459 [DL]CHIPoBLE advertising started
I: 30463 [DL]CHIPoBLE advertising mode changed to slow
I: 30470 [DL]CHIPoBLE advertising started
I: 96070 [DL]BLE connection established (ConnId: 0x00)
I: 96075 [DL]Current number of connections: 1/1
I: 96079 [DL]CHIPoBLE advertising stopped
I: 97625 [BLE]local and remote recv window sizes = 5
I: 97630 [BLE]selected BTP version 4
I: 97633 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 97715 [IN]BLE EndPoint 0x2000fd28 Connection Complete
I: 97720 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 97807 [EM]>>> [E:5139r M:223393267] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 97819 [EM]<<< [E:5139r M:49097240] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 97831 [IN](U) Sending msg 49097240 to IP address 'BLE'
I: 97942 [EM]>>> [E:5139r M:223393268] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 99819 [EM]<<< [E:5139r M:49097241] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 99830 [IN](U) Sending msg 49097241 to IP address 'BLE'
E: 99835 [DL]Long dispatch time: 1894 ms, for event type 16388
I: 99966 [EM]>>> [E:5139r M:223393269] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 99978 [EM]<<< [E:5139r M:49097242] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 99989 [IN](U) Sending msg 49097242 to IP address 'BLE'
I: 99995 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive'
D: 100003 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:26314
D: 100009 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:26314 PSID:55740!
I: 100018 [SVR]Commissioning completed session establishment step
I: 100024 [DIS]Updating services using commissioning mode 0
I: 100031 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
E: 100040 [DIS]Failed to advertise extended commissionable node: 3
D: 100046 [DIS]Scheduling extended discovery timeout in 900s
E: 100051 [DIS]Failed to finalize service update: 1c
I: 100057 [SVR]Device completed Rendezvous process
I: 100063 [EM]>>> [E:5140r M:155586262] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 100073 [IM]Received Read request
I: 100082 [EM]<<< [E:5140r M:227813834] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 100092 [IN](S) Sending msg 227813834 on secure session with LSID: 26314
I: 100238 [EM]>>> [E:5141r M:155586263] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 100249 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 100255 [EM]<<< [E:5141r M:227813835] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 100266 [IN](S) Sending msg 227813835 on secure session with LSID: 26314
I: 100372 [EM]>>> [E:5142r M:155586264] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 100386 [EM]<<< [E:5142r M:227813836] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 100397 [IN](S) Sending msg 227813836 on secure session with LSID: 26314
I: 100462 [EM]>>> [E:5143r M:155586265] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 100474 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 100483 [EM]<<< [E:5143r M:227813837] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 100493 [IN](S) Sending msg 227813837 on secure session with LSID: 26314
I: 100732 [EM]>>> [E:5144r M:155586266] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 100744 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 100753 [EM]<<< [E:5144r M:227813838] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 100764 [IN](S) Sending msg 227813838 on secure session with LSID: 26314
I: 101003 [EM]>>> [E:5145r M:155586267] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 101014 [ZCL]OpCreds: Received an AttestationRequest command
I: 101051 [ZCL]OpCreds: AttestationRequest successful.
I: 101059 [EM]<<< [E:5145r M:227813839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 101070 [IN](S) Sending msg 227813839 on secure session with LSID: 26314
I: 101407 [EM]>>> [E:5146r M:155586268] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 101419 [ZCL]OpCreds: Received a CSRRequest command
I: 101609 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 101645 [ZCL]OpCreds: CSRRequest successful.
I: 101652 [EM]<<< [E:5146r M:227813840] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 101662 [IN](S) Sending msg 227813840 on secure session with LSID: 26314
E: 101669 [DL]Long dispatch time: 263 ms, for event type 16388
I: 101993 [EM]>>> [E:5147r M:155586269] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 102004 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 102067 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 102074 [EM]<<< [E:5147r M:227813841] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 102085 [IN](S) Sending msg 227813841 on secure session with LSID: 26314
E: 102092 [DL]Long dispatch time: 101 ms, for event type 16388
I: 102444 [EM]>>> [E:5148r M:155586270] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 102456 [ZCL]OpCreds: Received an AddNOC command
I: 102463 [FP]Validating NOC chain
I: 102581 [FP]NOC chain validation successful
I: 102585 [FP]Added new fabric at index: 0x1
I: 102589 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001
I: 102597 [TS]Last Known Good Time: 2023-03-19T22:11:21
I: 102602 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 102609 [TS]Retaining current Last Known Good Time
I: 102633 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 102642 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 102649 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 102656 [EM]<<< [E:5148r M:227813842] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 102667 [IN](S) Sending msg 227813842 on secure session with LSID: 26314
E: 102674 [DL]Long dispatch time: 233 ms, for event type 16388
I: 102760 [EM]>>> [E:5149r M:155586271] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 102777 [EM]<<< [E:5149r M:227813843] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 102787 [IN](S) Sending msg 227813843 on secure session with LSID: 26314
I: 102848 [EM]>>> [E:5150r M:155586272] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 106165 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
I: 106178 [EM]<<< [E:5150r M:227813844] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 106189 [IN](S) Sending msg 227813844 on secure session with LSID: 26314
I: 106195 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 106202 [SVR]Operational advertising enabled
I: 106835 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 106847 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e80
I: 106854 [IN]CASE Server disabling CASE session setups
I: 106861 [EM]<<< [E:5151r M:49097243 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 106873 [IN](U) Sending msg 49097243 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 106884 [SC]Received Sigma1 msg
I: 106891 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
I: 106946 [DIS]Setting operational delegate post init
I: 107123 [EM]<<< [E:5151r M:49097244 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 107136 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 107146 [SC]Sent Sigma2 msg
I: 107153 [SWU]Stopping the watchdog timer
I: 107158 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 107165 [DIS]Updating services using commissioning mode 0
I: 107171 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 107179 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 107188 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 107198 [DL]advertising srp service: 44619005BF223B89._matterc._udp
D: 107935 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
I: 107944 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 107955 [EM]<<< [E:5151r M:49097245 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 107968 [IN](U) Sending msg 49097245 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 108049 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 108918 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
D: 109167 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
I: 109175 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 109187 [EM]<<< [E:5151r M:49097246 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 109200 [IN](U) Sending msg 49097246 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 109962 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
D: 111030 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
I: 111039 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 111050 [EM]<<< [E:5151r M:49097247 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 111063 [IN](U) Sending msg 49097247 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
I: 111405 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
E: 113538 [EM]Failed to Send CHIP MessageCounter:49097244 on exchange 5151r sendCount: 4 max retries: 4
D: 114123 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
I: 114131 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 114143 [EM]<<< [E:5151r M:49097248 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 114156 [IN](U) Sending msg 49097248 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
D: 122735 [IN]Clearing BLE pending packets.
I: 122739 [BLE]Releasing end point's BLE connection back to application.
I: 122745 [DL]Closing BLE GATT connection (ConnId 00)
I: 122870 [DL]BLE GAP connection terminated (reason 0x16)
I: 122875 [DL]Current number of connections: 0/1
E: 143847 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2
E: 143856 [IN]CASE Session establishment failed: 32
I: 143860 [IN]CASE Server enabling CASE session setups
D: 143865 [IN]SecureSession[0x20003608]: Released - Type:2 LSID:26315
D: 143872 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26316
I: 160254 [FS]Fail-safe timer expired
E: 160257 [SVR]Failsafe timer expired
D: 160261 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:26314
I: 160267 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction'
D: 160276 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:26314
E: 160282 [SVR]Commissioning failed (attempt 1): 32
D: 160289 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26317
I: 160295 [DIS]Updating services using commissioning mode 1
I: 160300 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
I: 160308 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 160318 [DL]advertising srp service: 44619005BF223B89._matterc._udp
E: 160324 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 160329 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 160335 [IN]Expiring all sessions for fabric 0x1!!
E: 160340 [FP]Reverting pending fabric data for fabric 0x1
E: 160346 [FP]Warning: metadata not found during delete of fabric 0x1
I: 160357 [FP]Fabric (0x1) deleted.
I: 160361 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 160365 [DIS]Updating services using commissioning mode 1
I: 160372 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 160381 [DL]advertising srp service: 44619005BF223B89._matterc._udp
I: 160388 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
I: 160509 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21
I: 160515 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21
I: 160521 [TS]Reverted Last Known Good Time to previous value
E: 160527 [FP]Warning: metadata not found during delete of fabric 0x1
E: 160536 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 160542 [NP]Reverting Thread operational dataset
E: 160554 [DL]Long dispatch time: 297 ms, for event type 32782
I: 160559 [FS]Fail-safe cleanly disarmed
I: 160565 [DL]CHIPoBLE advertising started
I: 190569 [DL]CHIPoBLE advertising mode changed to slow
I: 190576 [DL]CHIPoBLE advertising started

chiptool-template-errors.txt

[maheswara]

Need help with this quickly

[Priyanka]

Hi,

I understand that it's an urgent issue and I have relayed it internally as well. Please do bear with us and will get back to you by next week.

-Priyanka

[Priyanka]

It looks like you have not set RIO on wifi interface in Ubuntu, which is required in order to get communication, according to the OpenThread Border Router documentation. Please try to follow the steps mentioned in the documentation exactly.

-Priyanka

[maheswara]

Thanks for the quick response.

$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra
1
$sudo sysctl -n net.ipv6.conf.wlx18a6f712c1ee.accept_ra_rt_info_max_plen
64
$ifconfig wlx18a6f712c1ee
wlx18a6f712c1ee: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.100.170 netmask 255.255.255.0 broadcast 192.168.100.255
inet6 fe80::51bd:e05f:3127:2b5e prefixlen 64 scopeid 0x20<link>
inet6 fdde:ad00:beef:cafe:1aa6:f7ff:fe12:c1ee prefixlen 64 scopeid 0x0<global>
inet6 fdde:ad00:beef:cafe:ec12:ad5b:5aa7:41d prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:f903:9af6:420a:321 prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:1aa6:f7ff:fe12:c1ee prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:ab68:9cb6:c799:9f9f prefixlen 64 scopeid 0x0<global>
inet6 fd6d:8c75:79aa::ad2 prefixlen 128 scopeid 0x0<global>
inet6 fd6d:8c75:79aa:0:10b7:9573:6508:a924 prefixlen 64 scopeid 0x0<global>
ether 18:a6:f7:12:c1:ee txqueuelen 1000 (Ethernet)
RX packets 84961 bytes 67576011 (67.5 MB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 58154 bytes 11608576 (11.6 MB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

As suggested I have configured RA settings, Above is the dump from the ubuntu PC

[maheswara]

Any update on this. Appreciate quick help