About Matter's Network Commissioning

Hi,

I'm doing a test with a test harness.
An error occurs in test case TC-CNET-4.16.
I would like to know how to solve this problem.

environment

・TH
raspberry pi 4
Version: v2.11+fall2024
Sha: 8f86ccd

・DUT

nrf52840 custom board

ncsv2.9.0

sample code : matter lock

・TH log

TC-CNET-4_16_2025_02_04_23_53_37_TH_Log.log

・DUT Log

uart:~$ *** Booting My Application v2.9.0 - unknown commit ***
*** Using nRF Connect SDK v2.9.0-7787b2649840 ***
*** Using Zephyr OS v3.7.99-1f8f3dc29142 ***
I: 34 [DL]BLE address: C9:19:25:77:B5:20
I: No users indexes stored
I: No stored indexes for credential of type: 1
I: 51 [DL]CHIP task running
I: Init CHIP stack
I: 56 [DL]OpenThread started: OK
I: 59 [DL]Setting OpenThread device type to SLEEPY END DEVICE
I: 66 [SVR]Subscription persistence not supported
I: 71 [SVR]Server initializing...
I: 74 [TS]Last Known Good Time: 2023-10-14T01:16:48
I: 79 [DMG]AccessControl: initializing
I: 83 [DMG]Examples::AccessControlDelegate::Init
I: 87 [DMG]AccessControl: setting
I: 90 [DMG]DefaultAclStorage: initializing
I: 94 [DMG]DefaultAclStorage: 0 entries loaded
E: 98 [IN]IPV6_PKTINFO failed: 109
I: 106 [ZCL]Using ZAP configuration...
I: 111 [DMG]AccessControlCluster: initializing
I: 115 [ZCL]Initiating Admin Commissioning cluster.
I: 120 [ZCL]Door Lock server initialized
I: 124 [ZCL]Door Lock cluster initialized at endpoint #1
I: 129 [ZCL]0xbff35 ep 1 clus 0x0000_0101 attr 0x0000_0013 not supported
E: 136 [ZCL]Failed to set DoorLock number of RFID users: 86
I: 141 [DIS]Updating services using commissioning mode 0
E: 146 [DIS]Failed to remove advertised services: 3
E: 151 [DIS]Failed to finalize service update: 3
I: 155 [IN]CASE Server enabling CASE session setups
I: 160 [SVR]Joining Multicast groups
I: 164 [SVR]Server Listening...
I: 166 [DL]Device Configuration:
I: 169 [DL]  Serial Number: 11223344556677889900
I: 174 [DL]  Vendor Id: 65521 (0xFFF1)
I: 177 [DL]  Product Id: 32774 (0x8006)
I: 181 [DL]  Product Name: not-specified
I: 185 [DL]  Hardware Version: 0
I: 188 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 193 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 200 [DL]  Manufacturing Date: 2022-01-01
I: 203 [DL]  Device Type: 65535 (0xFFFF)
I: 207 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00]
I: 212 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 218 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00
I: 227 [SVR]Manual pairing code: [34970112332]
E: 231 [DL]Long dispatch time: 178 ms, for event type 2
I: 3979 [DIS]Updating services using commissioning mode 1
E: 3984 [DIS]Failed to remove advertised services: 3
I: 3989 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1 cp=0
E: 3999 [DIS]Failed to advertise commissionable node: 3
E: 4004 [DIS]Failed to finalize service update: 3
I: 4010 [DL]CHIPoBLE advertising started
I: 4014 [DL]NFC Tag emulation started
I: 34014 [DL]CHIPoBLE advertising mode changed to slow
I: 34021 [DL]CHIPoBLE advertising started
I: 37420 [DL]Current number of connections: 1/1
I: 37424 [DL]BLE connection established (ConnId: 0x00)
I: 37429 [DL]CHIPoBLE advertising stopped
I: 37433 [DL]NFC Tag emulation stopped
I: 39029 [BLE]local and remote recv window sizes = 5
I: 39034 [BLE]selected BTP version 4
I: 39037 [BLE]using BTP fragment sizes rx 244 / tx 244.
I: 39119 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 39211 [EM]>>> [E:35071r S:0 M:138682911] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
I: 39226 [EM]<<< [E:35071r S:0 M:168082796] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:154)
I: 39242 [SVR]Commissioning session establishment step started
I: 39300 [EM]>>> [E:35071r S:0 M:138682912] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
I: 39442 [EM]<<< [E:35071r S:0 M:168082797] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
E: 39457 [DL]Long dispatch time: 157 ms, for event type 16388
I: 39525 [EM]>>> [E:35071r S:0 M:138682913] (U) Msg RX from 0:60E6D13E0D62847E [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
I: 39540 [EM]<<< [E:35071r S:0 M:168082798] (U) Msg TX from 0000000000000000 to 0:60E6D13E0D62847E [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
I: 39557 [SC]SecureSession[0x20004448, LSID:18601]: State change 'kEstablishing' --> 'kActive'
I: 39566 [SVR]Commissioning completed session establishment step
I: 39572 [DIS]Updating services using commissioning mode 0
E: 39577 [DIS]Failed to remove advertised services: 3
E: 39582 [DIS]Failed to finalize service update: 3
I: 39587 [SVR]Device completed Rendezvous process
I: 39617 [EM]>>> [E:35072r S:18601 M:87993479] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:131)
I: 39640 [EM]<<< [E:35072r S:18601 M:154240679] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:258)
I: 39841 [EM]>>> [E:35073r S:18601 M:87993480] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:106)
E: 39858 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 586
E: 39869 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 586
I: 39882 [EM]<<< [E:35073r S:18601 M:154240680] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:191)
I: 39976 [EM]>>> [E:35074r S:18601 M:87993481] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 39991 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 39998 [EM]<<< [E:35074r S:18601 M:154240681] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I: 40066 [EM]>>> [E:35075r S:18601 M:87993482] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 40086 [EM]<<< [E:35075r S:18601 M:154240682] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I: 40156 [EM]>>> [E:35076r S:18601 M:87993483] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I: 40171 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 40180 [EM]<<< [E:35076r S:18601 M:154240683] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:527)
I: 40426 [EM]>>> [E:35077r S:18601 M:87993484] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I: 40441 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 40450 [EM]<<< [E:35077r S:18601 M:154240684] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:555)
I: 40696 [EM]>>> [E:35078r S:18601 M:87993485] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I: 40711 [ZCL]OpCreds: Received an AttestationRequest command
I: 40749 [ZCL]OpCreds: AttestationRequest successful.
I: 40758 [EM]<<< [E:35078r S:18601 M:154240685] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:716)
I: 41101 [EM]>>> [E:35079r S:18601 M:87993486] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I: 41116 [ZCL]OpCreds: Received a CSRRequest command
I: 41182 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 41219 [ZCL]OpCreds: CSRRequest successful.
I: 41225 [EM]<<< [E:35079r S:18601 M:154240686] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:392)
E: 41241 [DL]Long dispatch time: 142 ms, for event type 16388
I: 41506 [EM]>>> [E:35080r S:18601 M:87993487] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:293)
I: 41521 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 41584 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 41591 [EM]<<< [E:35080r S:18601 M:154240687] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
E: 41607 [DL]Long dispatch time: 102 ms, for event type 16388
I: 41912 [EM]>>> [E:35081r S:18601 M:87993488] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:573)
I: 41928 [ZCL]OpCreds: Received an AddNOC command
I: 41934 [FP]Validating NOC chain
I: 42053 [FP]NOC chain validation successful
I: 42057 [FP]Added new fabric at index: 0x1
I: 42061 [FP]Assigned compressed fabric ID: 0x63FF53EC0BE1FEC7, node ID: 0x785F8DDA442DE7F7
I: 42069 [TS]Last Known Good Time: 2023-10-14T01:16:48
I: 42074 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 42080 [TS]Retaining current Last Known Good Time
I: 42109 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 42118 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7
E: 42125 [SVR]Operational advertising failed: 3
I: 42129 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 42137 [EM]<<< [E:35081r S:18601 M:154240688] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
E: 42152 [DL]Long dispatch time: 243 ms, for event type 16388
I: 42227 [EM]>>> [E:35082r S:18601 M:87993489] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:160)
I: 42249 [EM]<<< [E:35082r S:18601 M:154240689] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I: 42316 [EM]>>> [E:35083r S:18601 M:87993490] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 42331 [FS]GeneralCommissioning: Received ArmFailSafe (108s)
I: 42338 [EM]<<< [E:35083r S:18601 M:154240690] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I: 42406 [EM]>>> [E:35084r S:18601 M:87993491] (S) Msg RX from 1:FFFFFFFB00000000 [FEC7] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I: 44116 [ZCL]ThreadDiagnosticsDelegate: OnConnectionStatusChanged
I: 44126 [EM]<<< [E:35084r S:18601 M:154240691] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [FEC7] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
I: 44141 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7
E: 44148 [SVR]Operational advertising failed: 3
I: 47165 [DL]SRP Client was started, detected server: fd57:436d:21ec:9665:fbaf:1e56:d0bc:ed80
I: 54587 [SVR]Server initialization complete
I: 54591 [DIS]Updating services using commissioning mode 0
I: 54597 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7
I: 54604 [DL]advertising srp service: 63FF53EC0BE1FEC7-785F8DDA442DE7F7._matter._tcp
I: 54615 [SWU]Stopping the watchdog timer
I: 54619 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 56565 [EM]>>> [E:35085r S:0 M:138682914] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
I: 56580 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20006148
I: 56588 [EM]<<< [E:35085r S:0 M:168082799 (Ack:138682914)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 56608 [SC]Received Sigma1 msg
I: 56618 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x785F8DDA442DE7F7
I: 56712 [EM]<<< [E:35085r S:0 M:168082800 (Ack:138682914)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:758)
I: 56733 [EM]??1 [E:35085r S:0 M:168082800] (U) Msg Retransmission to 0:0000000000000000 in 2074ms [State:Active II:500 AI:300 AT:4000]
I: 56749 [SC]Sent Sigma2 msg
I: 57055 [EM]>>> [E:35085r S:0 M:138682915 (Ack:168082800)] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:598)
I: 57071 [EM]<<< [E:35085r S:0 M:168082801 (Ack:138682915)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 57092 [SC]Received Sigma3 msg
E: 57100 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 57284 [DL]Long dispatch time: 173 ms, for event type 2
I: 57313 [EM]<<< [E:35085r S:0 M:168082802 (Ack:138682915)] (U) Msg TX from 0000000000000000 to 0:3BEF3C6875BDCA1F [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I: 57333 [EM]??1 [E:35085r S:0 M:168082802] (U) Msg Retransmission to 0:0000000000000000 in 2103ms [State:Active II:500 AI:300 AT:4000]
I: 57349 [SC]SecureSession[0x20004370, LSID:18600]: State change 'kEstablishing' --> 'kActive'
I: 57357 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 57457 [EM]>>> [E:35086r S:18600 M:92332627] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 57475 [FS]GeneralCommissioning: Received CommissioningComplete
I: 57490 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 57524 [TS]Committing Last Known Good Time to storage: 2023-10-14T01:16:48
I: 57536 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x63FF53EC0BE1FEC7, FabricId 0000000000000001, NodeId 785F8DDA442DE7F7, VendorId 0xFFF1
I: 57553 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 57560 [FS]Fail-safe cleanly disarmed
I: 57565 [EM]<<< [E:35086r S:18600 M:107865625 (Ack:92332627)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 57586 [EM]??1 [E:35086r S:18600 M:107865625] (S) Msg Retransmission to 1:000000000001B669 in 2068ms [State:Active II:500 AI:300 AT:4000]
I: 57599 [SWU]Device commissioned, schedule a default provider query
I: 57606 [SVR]Commissioning completed successfully
I: 57610 [DIS]Updating services using commissioning mode 0
I: 57616 [DIS]Advertise operational node 63FF53EC0BE1FEC7-785F8DDA442DE7F7
I: 57624 [SC]SecureSession[0x20004448, LSID:18601]: State change 'kActive' --> 'kPendingEviction'
I: 57632 [BLE]Releasing end point's BLE connection back to application.
I: 57639 [DL]Closing BLE GATT connection (ConnId 00)
I: 57646 [EM]>>> [E:35085r S:0 M:138682916 (Ack:168082802)] (U) Msg RX from 0:3BEF3C6875BDCA1F [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 57748 [DL]Current number of connections: 0/1
I: 57752 [DL]BLE GAP connection terminated (reason 0x16)
I: 58070 [EM]>>> [E:35086r S:18600 M:92332628 (Ack:107865625)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 66070 [EM]>>> [E:35087r S:18600 M:92332629] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:52)
I: 66085 [EM]<<< [E:35087r S:18600 M:107865626 (Ack:92332629)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:71)
I: 66105 [EM]??1 [E:35087r S:18600 M:107865626] (S) Msg Retransmission to 1:000000000001B669 in 2053ms [State:Active II:500 AI:300 AT:4000]
I: 66269 [EM]>>> [E:35087r S:18600 M:92332630 (Ack:107865626)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 67271 [EM]>>> [E:35088r S:18600 M:92332631] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:51)
I: 67287 [EM]<<< [E:35088r S:18600 M:107865627 (Ack:92332631)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:70)
I: 67307 [EM]??1 [E:35088r S:18600 M:107865627] (S) Msg Retransmission to 1:000000000001B669 in 2048ms [State:Active II:500 AI:300 AT:4000]
I: 67471 [EM]>>> [E:35088r S:18600 M:92332632 (Ack:107865627)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 68471 [EM]>>> [E:35089r S:18600 M:92332633] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:66)
I: 68486 [FS]GeneralCommissioning: Received ArmFailSafe (900s)
I: 68493 [EM]<<< [E:35089r S:18600 M:107865628 (Ack:92332633)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 68514 [EM]??1 [E:35089r S:18600 M:107865628] (S) Msg Retransmission to 1:000000000001B669 in 2087ms [State:Active II:500 AI:300 AT:4000]
I: 68668 [EM]>>> [E:35089r S:18600 M:92332634 (Ack:107865628)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 69071 [EM]>>> [E:35090r S:18600 M:92332635] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I: 69093 [EM]<<< [E:35090r S:18600 M:107865629 (Ack:92332635)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 69114 [EM]??1 [E:35090r S:18600 M:107865629] (S) Msg Retransmission to 1:000000000001B669 in 2079ms [State:Active II:500 AI:300 AT:4000]
I: 69269 [EM]>>> [E:35090r S:18600 M:92332636 (Ack:107865629)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 69674 [EM]>>> [E:35091r S:18600 M:92332637] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I: 69692 [EM]<<< [E:35091r S:18600 M:107865630 (Ack:92332637)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 69712 [EM]??1 [E:35091r S:18600 M:107865630] (S) Msg Retransmission to 1:000000000001B669 in 2103ms [State:Active II:500 AI:300 AT:4000]
I: 69868 [EM]>>> [E:35091r S:18600 M:92332638 (Ack:107865630)] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 72473 [EM]>>> [E:35092r S:18600 M:92332639] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:02 (IM:ReadRequest) (B:51)
I: 72488 [EM]<<< [E:35092r S:18600 M:107865631 (Ack:92332639)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:05 (IM:ReportData) (B:70)
I: 72509 [EM]??1 [E:35092r S:18600 M:107865631] (S) Msg Retransmission to 1:000000000001B669 in 2067ms [State:Active II:500 AI:300 AT:4000]
I: 72674 [EM]>>> [E:35093r S:18600 M:92332640] (S) Msg RX from 1:000000000001B669 [FEC7] to 785F8DDA442DE7F7 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I: 72692 [ZCL]OpCreds: Received a RemoveFabric Command for FabricIndex 0x1
I: 72700 [EM]<<< [E:35093r S:18600 M:107865632 (Ack:92332640)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [FEC7] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 72735 [FP]Fabric (0x1) deleted.
I: 72738 [ZCL][OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1]
E: 72749 [ZCL][clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1]
I: 72765 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 72770 [DIS]Updating services using commissioning mode 0
I: 72775 [DL]removing srp service: 63FF53EC0BE1FEC7-785F8DDA442DE7F7._matter._tcp
I: 72813 [ZCL]OpCreds: RemoveFabric successful
I: 72818 [SC]SecureSession[0x20004370, LSID:18600]: State change 'kActive' --> 'kPendingEviction'
I: 72828 [EM]<<< [E:35093r S:18600 M:107865633 (Ack:92332640)] (S) Msg TX from 785F8DDA442DE7F7 to 1:000000000001B669 [0000] [UDP:[fd11:22::2e1f:33c8:1738:6c4d]:47666] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 72848 [EM]??1 [E:35093r S:18600 M:107865633] (S) Msg Retransmission to 1:000000000001B669 in 2060ms [State:Active II:500 AI:300 AT:4000]
I: 72863 [EM]>>> [E:35092r S:18600 M:92332641 (Ack:107865631)] (S) Msg RX from 1:000000000001B669 [0000] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 72880 [EM]Dropping message on inactive session that does not match an existing exchange
I: 72891 [EM]>>> [E:35093r S:18600 M:92332642 (Ack:107865633)] (S) Msg RX from 1:000000000001B669 [0000] to 785F8DDA442DE7F7 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 73739 [TS]Pending Last Known Good Time: 2023-10-14T01:16:48
I: 73745 [TS]Previous Last Known Good Time: 2023-10-14T01:16:48
I: 73751 [TS]Reverted Last Known Good Time to previous value
I: 73757 [DL]Performing factory reset
E: 75702 [DL]SRP update error: timed out waiting on server response
I: 76337 [DL]Erasing Thread persistent info...

uart:~$ *** Booting My Application v2.9.0 - unknown commit ***
*** Using nRF Connect SDK v2.9.0-7787b2649840 ***
*** Using Zephyr OS v3.7.99-1f8f3dc29142 ***
I: 41 [DL]BLE address: D5:E6:12:62:E5:D9
I: No users indexes stored
I: No stored indexes for credential of type: 1
I: 59 [DL]CHIP task running
I: Init CHIP stack
I: 64 [DL]OpenThread started: OK
I: 67 [DL]Setting OpenThread device type to SLEEPY END DEVICE
I: 73 [SVR]Subscription persistence not supported
I: 78 [SVR]Server initializing...
I: 81 [TS]Last Known Good Time: [unknown]
I: 85 [TS]Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48
I: 96 [DMG]AccessControl: initializing
I: 100 [DMG]Examples::AccessControlDelegate::Init
I: 104 [DMG]AccessControl: setting
I: 107 [DMG]DefaultAclStorage: initializing
I: 111 [DMG]DefaultAclStorage: 0 entries loaded
E: 116 [IN]IPV6_PKTINFO failed: 109
I: 131 [ZCL]Using ZAP configuration...
I: 136 [DMG]AccessControlCluster: initializing
I: 141 [ZCL]Initiating Admin Commissioning cluster.
I: 145 [ZCL]Door Lock server initialized
I: 149 [ZCL]Door Lock cluster initialized at endpoint #1
I: 154 [ZCL]0xbff35 ep 1 clus 0x0000_0101 attr 0x0000_0013 not supported
E: 161 [ZCL]Failed to set DoorLock number of RFID users: 86
I: 166 [DIS]Updating services using commissioning mode 0
E: 171 [DIS]Failed to remove advertised services: 3
E: 176 [DIS]Failed to finalize service update: 3
I: 180 [IN]CASE Server enabling CASE session setups
I: 185 [SVR]Joining Multicast groups
I: 189 [SVR]Server Listening...
I: 192 [DL]Device Configuration:
I: 195 [DL]  Serial Number: 11223344556677889900
I: 199 [DL]  Vendor Id: 65521 (0xFFF1)
I: 203 [DL]  Product Id: 32774 (0x8006)
I: 206 [DL]  Product Name: not-specified
I: 210 [DL]  Hardware Version: 0
I: 213 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 218 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 225 [DL]  Manufacturing Date: 2022-01-01
I: 229 [DL]  Device Type: 65535 (0xFFFF)
I: 232 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00]
I: 237 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 243 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00
I: 252 [SVR]Manual pairing code: [34970112332]
E: 256 [DL]Long dispatch time: 195 ms, for event type 2

Best regards,

Hiroki

  • Hi Hiroki,

    Based on the logs the DUT passes steps 1, 2 and 3 of the test, but fails at uploading the log due to it being cancelled:

    INFO       | 2025-02-04 23:54:40.036716 | Test Step Completed [PASSED]: Step 3: TH sends ConnectNetwork Command to the DUT with NetworkID value as the extended PAN ID of PIXIT.CNET.THREAD_2ND_OPERATIONALDATASET, which does not match the commissioned network, and Breadcrumb field set to 1
    INFO       | 2025-02-04 23:54:40.040422 | --------------------------------------------------------------------------------
    INFO       | 2025-02-04 23:54:40.051778 | --------------------------------------------------------------------------------
    INFO       | 2025-02-04 23:54:40.053056 | Executing Test Step: Prompt Manual Log Upload
    INFO       | 2025-02-04 23:54:40.305008 | Test Step Completed [PASSED]: Prompt Manual Log Upload
    INFO       | 2025-02-04 23:54:40.306201 | --------------------------------------------------------------------------------
    WARNING    | 2025-02-04 23:54:42.449801 | Test Failure: User cancelled log upload prompt.
    INFO       | 2025-02-04 23:54:42.451645 | Test Case Completed [FAILED]: TC-CNET-4.16 (Semi-automated)
    INFO       | 2025-02-04 23:54:42.452700 | ================================================================================
    INFO       | 2025-02-04 23:54:42.455250 | Unpairing DUT from server

    Are you manually cancelling the log upload or test in some way during this step?

    Best regards,
    Marte

  • Hi,Marte

    Thank you for your reply.
    I haven't stopped it manually during testing.

    Have you tested TC-CNET-2.16 alone?

    I get an error in step2.

    For some reason, networkcommissioning remove-network is responding successfully.

    Also, when I run the chip tool using the same steps as the TC-CNET-2.16 test, I still get the error.
    However, when sending networkcommissioning remove-network a second time, NetworkIDNotFound is returned.

    The log of the command sent with chip-tool is below.

    If there is any mistake in the settings, please let me know.

    TC-CNET-4.16_chip-tool_log.txt

    Best regards,

    Hiroki

  • Have you tested TC-CNET-2.16 alone?

    I made a mistake.
    TC-CNET-4.16.

  • Hi Hiroki,

    I missed that it failed in step 2 in the log you attached, but looking at the logs again, I see that it returns Success instead of NetworkIDNotFound in the NetworkConfigResponse command.

    I will forward this to the developers and get back to you tomorrow or early next week.

    Best regards,
    Marte

  • Hi,Marte

    Thank you for your reply.
    We look forward to hearing from you.

    Best regards,

    Hiroki

Related