Matter Test Harness for certification

[Himansu]

Hi,

I'm doing a test with a matter test harness.
An error occurs in test case _TC-CNET-4.16, _TC-CADMIN-1.22 and _TC-DGGEN-2.3.

1. _TC-CNET-4.16: Step 2: should receive NetworkIDNotFound which is '3'
2. _TC-CADMIN-1.22: step 5: got success response instead of Invalid command
3. _TC-DGGEN-2.3: Step 3: got Constraint Error instead of Invalid Command

I would like to know how to solve this problem.

Test Harness Enviornment:

Board: Rraspberry PI4
Version: 2.10.2+spring2024

Sha: 2a350c8

DUT:

Board: nrf52840(BL654) custom board

SDK:2.7.0

Sample Application : Matter Door Lock

Please see attached log and PICS file for more information.

Thanks,

Himansu Donga
FAIL-TC-DGGEN-2.3.logFAIL_TC-CNET-4.16.logAML_PICS_XML_version V_27_SVE_1.3.1.zip

[Himansu]

FAIL_TC-ADMIN-1.22_2.txt

Fullscreen FAIL-TC-CADMIN-1.22-Step5.txt Download

ubuntu@ubuntu:~/apps$ ./chip-tool  pairing open-commissioning-window 1 1 901 2000 3423
[1747181689.846912][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1747181689.848043][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1747181689.848086][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1747181689.853309][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1747181689.853626][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1747181689.853768][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1747181689.854087][3900:3900] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Fhy44B)
[1747181689.854726][3900:3900] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747181689.854783][3900:3900] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1747181689.855719][3900:3900] CHIP:DL: Got Ethernet interface: eth0
[1747181689.856365][3900:3900] CHIP:DL: Found the primary Ethernet interface:eth0
[1747181689.857046][3900:3900] CHIP:DL: Got WiFi interface: wlan0
[1747181689.857119][3900:3900] CHIP:DL: Failed to reset WiFi statistic counts
[1747181689.857175][3900:3900] CHIP:IN: UDP::Init bind&listen port=0
[1747181689.857302][3900:3900] CHIP:IN: UDP::Init bound to port=59696
[1747181689.857326][3900:3900] CHIP:IN: BLEBase::Init - setting/overriding transport
[1747181689.857355][3900:3900] CHIP:IN: TransportMgr initialized
[1747181689.857408][3900:3900] CHIP:FP: Initializing FabricTable from persistent storage
[1747181689.857581][3900:3900] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747181689.859159][3900:3900] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x9FF6358D4C9156A9, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1747181689.861352][3900:3900] CHIP:ZCL: Using ZAP configuration...
[1747181689.865075][3900:3900] CHIP:DL: Avahi client registered
[1747181689.865194][3900:3900] CHIP:CTL: System State Initialized...
[1747181689.865376][3900:3900] CHIP:CTL: Setting attestation nonce to random value
[1747181689.865436][3900:3900] CHIP:CTL: Setting CSR nonce to random value
[1747181689.865521][3900:3900] CHIP:IN: UDP::Init bind&listen port=5550
[1747181689.865673][3900:3900] CHIP:IN: UDP::Init bound to port=5550
[1747181689.865697][3900:3900] CHIP:IN: TransportMgr initialized
[1747181689.866013][3900:3902] CHIP:DL: CHIP task running
[1747181689.866248][3900:3902] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1747181689.866625][3900:3902] CHIP:CTL: Setting attestation nonce to random value
[1747181689.866852][3900:3902] CHIP:CTL: Setting CSR nonce to random value
[1747181689.867895][3900:3902] CHIP:CTL: Generating NOC
[1747181689.868860][3900:3902] CHIP:FP: Validating NOC chain
[1747181689.870827][3900:3902] CHIP:FP: NOC chain validation successful
[1747181689.870996][3900:3902] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1747181689.871030][3900:3902] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747181689.871054][3900:3902] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1747181689.871074][3900:3902] CHIP:TS: Retaining current Last Known Good Time
[1747181689.876098][3900:3902] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1747181689.877930][3900:3902] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1747181689.879560][3900:3902] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 9FF6358D4C9156A9)
[1747181689.879612][3900:3902] CHIP:IN: UDP::Init bind&listen port=5550
[1747181689.879722][3900:3902] CHIP:IN: UDP::Init bound to port=5550
[1747181689.879744][3900:3902] CHIP:IN: TransportMgr initialized
[1747181689.902398][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1747181689.902450][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1747181689.902484][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1747181689.902516][3900:3902] CHIP:DIS: Resolving 9FF6358D4C9156A9:0000000000000001 ...
[1747181689.904085][3900:3902] CHIP:DL: Avahi resolve found
[1747181689.904153][3900:3902] CHIP:DIS: Node ID resolved for 9FF6358D4C9156A9:0000000000000001
[1747181689.904174][3900:3902] CHIP:DIS:        Hostname: 7E09CFA3BB2EF4F3
[1747181689.904198][3900:3902] CHIP:DIS:        IP Address #1: fd11:22::3982:2271:515d:4a83
[1747181689.904218][3900:3902] CHIP:DIS:        Port: 5540
[1747181689.904237][3900:3902] CHIP:DIS:        Mrp Interval idle: 5000 ms
[1747181689.904255][3900:3902] CHIP:DIS:        Mrp Interval active: 2500 ms
[1747181689.904274][3900:3902] CHIP:DIS:        Mrp Active Threshold: 500 ms
[1747181689.904292][3900:3902] CHIP:DIS:        TCP Supported: 0
[1747181689.904309][3900:3902] CHIP:DIS:        ICD: not present
[1747181689.905098][3900:3902] CHIP:DIS: Lookup clearing interface for non LL address
[1747181689.905188][3900:3902] CHIP:DIS: UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540: new best score: 3
[1747181689.905211][3900:3902] CHIP:DIS: Checking node lookup status after 2 ms
[1747181689.905229][3900:3902] CHIP:DIS: Keeping DNSSD lookup active
[1747181690.103565][3900:3902] CHIP:DIS: Checking node lookup status after 201 ms
[1747181690.103705][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::3982:2271:515d:4a83]:5540 while in state 2
[1747181690.103768][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1747181690.104088][3900:3902] CHIP:IN: SecureSession[0xffff7000edd0]: Allocated Type:2 LSID:4449
[1747181690.104191][3900:3902] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1747181690.106396][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371205] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1747181690.106973][3900:3902] CHIP:SC: Sent Sigma1 msg
[1747181690.107053][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1747181690.475051][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386237 (Ack:215371205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181690.475153][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28
[1747181690.475234][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:215371205 from Retrans Table on exchange 37782i
[1747181690.622962][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386238 (Ack:215371205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1747181690.623068][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28
[1747181690.623132][3900:3902] CHIP:EM: CHIP MessageCounter:215371205 not in RetransTable on exchange 37782i
[1747181690.623240][3900:3902] CHIP:SC: Received Sigma2 msg
[1747181690.623327][3900:3902] CHIP:SC: Peer assigned session session ID 6268
[1747181690.632020][3900:3902] CHIP:SC: Found MRP parameters in the message
[1747181690.632143][3900:3902] CHIP:SC: Sending Sigma3
[1747181690.633433][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371206 (Ack:157386238)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1747181690.633884][3900:3902] CHIP:SC: Sent Sigma3 msg
[1747181691.060155][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386239 (Ack:215371206)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181691.060216][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28
[1747181691.060264][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:215371206 from Retrans Table on exchange 37782i
[1747181691.247417][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386240 (Ack:215371206)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1747181691.247518][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28
[1747181691.247582][3900:3902] CHIP:EM: CHIP MessageCounter:215371206 not in RetransTable on exchange 37782i
[1747181691.247688][3900:3902] CHIP:SC: Success status report received. Session was established
[1747181691.254415][3900:3902] CHIP:SC: SecureSession[0xffff7000edd0, LSID:4449]: State change 'kEstablishing' --> 'kActive'
[1747181691.254514][3900:3902] CHIP:IN: SecureSession[0xffff7000edd0]: Activated - Type:2 LSID:4449
[1747181691.254568][3900:3902] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:4449 PSID:6268!
[1747181691.254634][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1747181691.254876][3900:3902] CHIP:DMG: SendReadRequest ReadClient[0xffff7000a4c0]: Sending Read Request
[1747181691.255413][3900:3902] CHIP:EM: <<< [E:37783i S:4449 M:120802994] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest)
[1747181691.256003][3900:3902] CHIP:DMG: MoveToState ReadClient[0xffff7000a4c0]: Moving to [AwaitingIn]
[1747181691.256339][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371207 (Ack:157386240)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181691.256652][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:157386240 on exchange 37782i
[1747181691.580238][3900:3902] CHIP:EM: >>> [E:37783i S:4449 M:99251886 (Ack:120802994)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:05 (IM:ReportData)
[1747181691.580305][3900:3902] CHIP:EM: Found matching exchange: 37783i, Delegate: 0xffff7000a4d0
[1747181691.580358][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802994 from Retrans Table on exchange 37783i
[1747181691.580439][3900:3902] CHIP:DMG: ReportDataMessage =
[1747181691.580473][3900:3902] CHIP:DMG: {
[1747181691.580501][3900:3902] CHIP:DMG:        AttributeReportIBs =
[1747181691.580541][3900:3902] CHIP:DMG:        [
[1747181691.580570][3900:3902] CHIP:DMG:                AttributeReportIB =
[1747181691.580636][3900:3902] CHIP:DMG:                {
[1747181691.580669][3900:3902] CHIP:DMG:                        AttributeDataIB =
[1747181691.580705][3900:3902] CHIP:DMG:                        {
[1747181691.580758][3900:3902] CHIP:DMG:                                DataVersion = 0xfd1b1703,
[1747181691.580805][3900:3902] CHIP:DMG:                                AttributePathIB =
[1747181691.580856][3900:3902] CHIP:DMG:                                {
[1747181691.580895][3900:3902] CHIP:DMG:                                        Endpoint = 0x0,
[1747181691.580949][3900:3902] CHIP:DMG:                                        Cluster = 0x28,
[1747181691.580990][3900:3902] CHIP:DMG:                                        Attribute = 0x0000_0002,
[1747181691.581039][3900:3902] CHIP:DMG:                                }
[1747181691.581081][3900:3902] CHIP:DMG:
[1747181691.581122][3900:3902] CHIP:DMG:                                Data = 5547,
[1747181691.581171][3900:3902] CHIP:DMG:                        },
[1747181691.581211][3900:3902] CHIP:DMG:
[1747181691.581254][3900:3902] CHIP:DMG:                },
[1747181691.581291][3900:3902] CHIP:DMG:
[1747181691.581332][3900:3902] CHIP:DMG:        ],
[1747181691.581372][3900:3902] CHIP:DMG:
[1747181691.581403][3900:3902] CHIP:DMG:        SuppressResponse = true,
[1747181691.581447][3900:3902] CHIP:DMG:        InteractionModelRevision = 11
[1747181691.581476][3900:3902] CHIP:DMG: }
[1747181691.581691][3900:3902] CHIP:CTL: Received VID for the device. Value 5547
[1747181691.581726][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1747181691.581755][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1747181691.581799][3900:3902] CHIP:DIS: Found an existing secure session to [1:0000000000000001]!
[1747181691.581835][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1747181691.581926][3900:3902] CHIP:DMG: SendReadRequest ReadClient[0xffff700092c0]: Sending Read Request
[1747181691.582215][3900:3902] CHIP:EM: <<< [E:37784i S:4449 M:120802995] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest)
[1747181691.582509][3900:3902] CHIP:DMG: MoveToState ReadClient[0xffff700092c0]: Moving to [AwaitingIn]
[1747181691.582769][3900:3902] CHIP:EM: <<< [E:37783i S:4449 M:120802996 (Ack:99251886)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181691.582926][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251886 on exchange 37783i
[1747181692.091910][3900:3902] CHIP:EM: >>> [E:37784i S:4449 M:99251887 (Ack:120802995)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:05 (IM:ReportData)
[1747181692.091996][3900:3902] CHIP:EM: Found matching exchange: 37784i, Delegate: 0xffff700092d0
[1747181692.092065][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802995 from Retrans Table on exchange 37784i
[1747181692.092173][3900:3902] CHIP:DMG: ReportDataMessage =
[1747181692.092222][3900:3902] CHIP:DMG: {
[1747181692.092269][3900:3902] CHIP:DMG:        AttributeReportIBs =
[1747181692.092337][3900:3902] CHIP:DMG:        [
[1747181692.092389][3900:3902] CHIP:DMG:                AttributeReportIB =
[1747181692.092457][3900:3902] CHIP:DMG:                {
[1747181692.092512][3900:3902] CHIP:DMG:                        AttributeDataIB =
[1747181692.092582][3900:3902] CHIP:DMG:                        {
[1747181692.092645][3900:3902] CHIP:DMG:                                DataVersion = 0xfd1b1703,
[1747181692.092708][3900:3902] CHIP:DMG:                                AttributePathIB =
[1747181692.092775][3900:3902] CHIP:DMG:                                {
[1747181692.092955][3900:3902] CHIP:DMG:                                        Endpoint = 0x0,
[1747181692.093029][3900:3902] CHIP:DMG:                                        Cluster = 0x28,
[1747181692.093099][3900:3902] CHIP:DMG:                                        Attribute = 0x0000_0004,
[1747181692.093221][3900:3902] CHIP:DMG:                                }
[1747181692.093297][3900:3902] CHIP:DMG:
[1747181692.093365][3900:3902] CHIP:DMG:                                Data = 1,
[1747181692.093427][3900:3902] CHIP:DMG:                        },
[1747181692.093497][3900:3902] CHIP:DMG:
[1747181692.093610][3900:3902] CHIP:DMG:                },
[1747181692.093676][3900:3902] CHIP:DMG:
[1747181692.093726][3900:3902] CHIP:DMG:        ],
[1747181692.093789][3900:3902] CHIP:DMG:
[1747181692.093840][3900:3902] CHIP:DMG:        SuppressResponse = true,
[1747181692.093892][3900:3902] CHIP:DMG:        InteractionModelRevision = 11
[1747181692.093940][3900:3902] CHIP:DMG: }
[1747181692.094148][3900:3902] CHIP:CTL: Received PID for the device. Value 1
[1747181692.094200][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1747181692.094246][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1747181692.094451][3900:3902] CHIP:DIS: Found an existing secure session to [1:0000000000000001]!
[1747181692.094512][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1747181692.094576][3900:3902] CHIP:CTL: OpenCommissioningWindow for device ID 0x0000000000000001
[1747181692.094740][3900:3902] CHIP:DMG: ICR moving to [AddingComm]
[1747181692.094860][3900:3902] CHIP:DMG: ICR moving to [AddedComma]
[1747181692.095249][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120802997] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:0A (IM:TimedRequest)
[1747181692.095580][3900:3902] CHIP:DMG: ICR moving to [AwaitingTi]
[1747181692.095920][3900:3902] CHIP:EM: <<< [E:37784i S:4449 M:120802998 (Ack:99251887)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181692.096117][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251887 on exchange 37784i
[1747181692.606218][3900:3902] CHIP:EM: >>> [E:37785i S:4449 M:99251888 (Ack:120802997)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:01 (IM:StatusResponse)
[1747181692.606342][3900:3902] CHIP:EM: Found matching exchange: 37785i, Delegate: 0xffff70008628
[1747181692.606415][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802997 from Retrans Table on exchange 37785i
[1747181692.606512][3900:3902] CHIP:DMG: StatusResponseMessage =
[1747181692.606574][3900:3902] CHIP:DMG: {
[1747181692.606625][3900:3902] CHIP:DMG:        Status = 0x00 (SUCCESS),
[1747181692.606678][3900:3902] CHIP:DMG:        InteractionModelRevision = 11
[1747181692.606727][3900:3902] CHIP:DMG: }
[1747181692.606778][3900:3902] CHIP:IM: Received status response, status is 0x00 (SUCCESS)
[1747181692.607127][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120802999 (Ack:99251888)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1747181692.607533][3900:3902] CHIP:DMG: ICR moving to [AwaitingRe]
[1747181693.136297][3900:3902] CHIP:EM: >>> [E:37785i S:4449 M:99251889 (Ack:120802999)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:09 (IM:InvokeCommandResponse)
[1747181693.136390][3900:3902] CHIP:EM: Found matching exchange: 37785i, Delegate: 0xffff70008628
[1747181693.136468][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802999 from Retrans Table on exchange 37785i
[1747181693.136544][3900:3902] CHIP:DMG: ICR moving to [ResponseRe]
[1747181693.136640][3900:3902] CHIP:DMG: InvokeResponseMessage =
[1747181693.136693][3900:3902] CHIP:DMG: {
[1747181693.136741][3900:3902] CHIP:DMG:        suppressResponse = false,
[1747181693.136791][3900:3902] CHIP:DMG:        InvokeResponseIBs =
[1747181693.136858][3900:3902] CHIP:DMG:        [
[1747181693.136907][3900:3902] CHIP:DMG:                InvokeResponseIB =
[1747181693.136976][3900:3902] CHIP:DMG:                {
[1747181693.137029][3900:3902] CHIP:DMG:                        CommandStatusIB =
[1747181693.137090][3900:3902] CHIP:DMG:                        {
[1747181693.137145][3900:3902] CHIP:DMG:                                CommandPathIB =
[1747181693.137218][3900:3902] CHIP:DMG:                                {
[1747181693.137288][3900:3902] CHIP:DMG:                                        EndpointId = 0x0,
[1747181693.137357][3900:3902] CHIP:DMG:                                        ClusterId = 0x3c,
[1747181693.137428][3900:3902] CHIP:DMG:                                        CommandId = 0x0,
[1747181693.137495][3900:3902] CHIP:DMG:                                },
[1747181693.137571][3900:3902] CHIP:DMG:
[1747181693.137628][3900:3902] CHIP:DMG:                                StatusIB =
[1747181693.137694][3900:3902] CHIP:DMG:                                {
[1747181693.137763][3900:3902] CHIP:DMG:                                        status = 0x00 (SUCCESS),
[1747181693.137831][3900:3902] CHIP:DMG:                                },
[1747181693.137898][3900:3902] CHIP:DMG:
[1747181693.137956][3900:3902] CHIP:DMG:                        },
[1747181693.138022][3900:3902] CHIP:DMG:
[1747181693.138083][3900:3902] CHIP:DMG:                },
[1747181693.138148][3900:3902] CHIP:DMG:
[1747181693.138196][3900:3902] CHIP:DMG:        ],
[1747181693.138260][3900:3902] CHIP:DMG:
[1747181693.138387][3900:3902] CHIP:DMG:        InteractionModelRevision = 11
[1747181693.138437][3900:3902] CHIP:DMG: },
[1747181693.138571][3900:3902] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0
[1747181693.138629][3900:3902] CHIP:CTL: Successfully opened pairing window on the device
[1747181693.138733][3900:3902] CHIP:CTL: Manual pairing code: [31711002791]
[1747181693.138793][3900:3902] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ427..O74P300]
[1747181693.138931][3900:3902] CHIP:DMG: ICR moving to [AwaitingDe]
[1747181693.139283][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120803000 (Ack:99251889)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747181693.139611][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251889 on exchange 37785i
[1747181693.140008][3900:3900] CHIP:CTL: Shutting down the commissioner
[1747181693.140185][3900:3900] CHIP:CTL: Shutting down the controller
[1747181693.140239][3900:3900] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1747181693.140284][3900:3900] CHIP:IN: SecureSession[0xffff7000edd0]: MarkForEviction Type:2 LSID:4449
[1747181693.140331][3900:3900] CHIP:SC: SecureSession[0xffff7000edd0, LSID:4449]: State change 'kActive' --> 'kPendingEviction'
[1747181693.140378][3900:3900] CHIP:IN: SecureSession[0xffff7000edd0]: Released - Type:2 LSID:4449
[1747181693.140489][3900:3900] CHIP:FP: Forgetting fabric 0x1
[1747181693.140555][3900:3900] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747181693.140863][3900:3900] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747181693.140932][3900:3900] CHIP:TS: Reverted Last Known Good Time to previous value
[1747181693.141024][3900:3900] CHIP:CTL: Shutting down the commissioner
[1747181693.141198][3900:3900] CHIP:CTL: Shutting down the controller
[1747181693.141253][3900:3900] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1747181693.141546][3900:3900] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1747181693.141731][3900:3900] CHIP:FP: Shutting down FabricTable
[1747181693.141800][3900:3900] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747181693.142031][3900:3900] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747181693.142096][3900:3900] CHIP:TS: Reverted Last Known Good Time to previous value
[1747181693.142544][3900:3900] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-xkR8xQ)
[1747181693.143676][3900:3900] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747181693.143792][3900:3900] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1747181693.143843][3900:3900] CHIP:DL: Inet Layer shutdown
[1747181693.143886][3900:3900] CHIP:DL: BLE shutdown
[1747181693.143934][3900:3900] CHIP:DL: System Layer shutdown

FAIL_TC-CADMIN-1.22.txt