TC-RR-1.1 test issue (CON-925)

[tonyVopo]

ESP Matter SDK：Matter 1.1 release
Chip:esp32c3
DUT: smartplug

Test cmd on raspberrypi:

1. docker run -v $PATH_TO_PAA_ROOTS:/paa_roots -v /var/run/dbus/system_bus_socket:/var/run/dbus/system_bus_socket -v $(pwd):/launch_dir --privileged --network host -it connectedhomeip/chip-cert-bins:5a21d17fd2bb0a48f4a356937f4741f6c9dc7975
2. rm -f admin_storage.json && python3 python_testing/TC_RR_1_1.py --discriminator 181 --passcode 39114725 --commissioning-method ble-wifi --paa-trust-store-path /paa_roots --storage-path admin_storage.json --wifi-ssid tp-msi --wifi-passphrase 99887766 --ble-interface-id 0

Problem description：

1. TC_RR_1_1.py test cannot pass
   [1701830326.136447][11:14] CHIP:EM: <<< [E:17862i S:44148 M:176857216 (Ack:184683336)] (S) Msg TX to 1:0000000012344321 [D1AE] --- Type 0000:10 (SecureChannel:StandaloneAck) [1701830326.136627][11:14] CHIP:IN: (S) Sending msg 176857216 on secure session with LSID: 44148 [1701830326.136937][11:14] CHIP:EM: Flushed pending ack for MessageCounter:184683336 on exchange 17862i [MatterTest] 12-06 02:38:46.137 INFO Step 13: Setting group key on fabric 1 at index '1' [1701830326.140197][11:14] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000012344321] [1701830326.140300][11:14] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1701830326.140433][11:14] CHIP:DIS: Found an existing secure session to [1:0000000012344321]! [1701830326.140515][11:14] CHIP:DIS: OperationalSessionSetup[1:0000000012344321]: State change 1 --> 5 [1701830326.143924][11:14] CHIP:DMG: ICR moving to [AddingComm] [1701830326.144090][11:14] CHIP:DMG: ICR moving to [AddedComma] [1701830326.144517][11:14] CHIP:EM: <<< [E:17863i S:44148 M:176857217] (S) Msg TX to 1:0000000012344321 [D1AE] --- Type 0001:08 (IM:InvokeCommandRequest) [1701830326.144674][11:14] CHIP:IN: (S) Sending msg 176857217 on secure session with LSID: 44148 [1701830326.145141][11:14] CHIP:DMG: ICR moving to [CommandSen] [1701830326.332677][11:14] CHIP:EM: >>> [E:17863i S:44148 M:184683337 (Ack:176857217)] (S) Msg RX from 1:0000000012344321 [D1AE] --- Type 0001:09 (IM:InvokeCommandResponse) [1701830326.332792][11:14] CHIP:EM: Found matching exchange: 17863i, Delegate: 0xffff80068ea8 [1701830326.332915][11:14] CHIP:EM: Rxd Ack; Removing MessageCounter:176857217 from Retrans Table on exchange 17863i [1701830326.333038][11:14] CHIP:DMG: ICR moving to [ResponseRe] [1701830326.333187][11:14] CHIP:DMG: InvokeResponseMessage = [1701830326.333261][11:14] CHIP:DMG: { [1701830326.333330][11:14] CHIP:DMG: suppressResponse = false, [1701830326.333397][11:14] CHIP:DMG: InvokeResponseIBs = [1701830326.333486][11:14] CHIP:DMG: [ [1701830326.333555][11:14] CHIP:DMG: InvokeResponseIB = [1701830326.333655][11:14] CHIP:DMG: { [1701830326.333728][11:14] CHIP:DMG: CommandStatusIB = [1701830326.333802][11:14] CHIP:DMG: { [1701830326.333866][11:14] CHIP:DMG: CommandPathIB = [1701830326.333959][11:14] CHIP:DMG: { [1701830326.334065][11:14] CHIP:DMG: EndpointId = 0x0, [1701830326.334164][11:14] CHIP:DMG: ClusterId = 0x3f, [1701830326.334260][11:14] CHIP:DMG: CommandId = 0x0, [1701830326.334359][11:14] CHIP:DMG: }, [1701830326.334464][11:14] CHIP:DMG: [1701830326.334557][11:14] CHIP:DMG: StatusIB = [1701830326.334660][11:14] CHIP:DMG: { [1701830326.334753][11:14] CHIP:DMG: status = 0x01 (FAILURE), [1701830326.334843][11:14] CHIP:DMG: }, [1701830326.334936][11:14] CHIP:DMG: [1701830326.335016][11:14] CHIP:DMG: }, [1701830326.335110][11:14] CHIP:DMG: [1701830326.335185][11:14] CHIP:DMG: }, [1701830326.335275][11:14] CHIP:DMG: [1701830326.335348][11:14] CHIP:DMG: ], [1701830326.335484][11:14] CHIP:DMG: [1701830326.335551][11:14] CHIP:DMG: InteractionModelRevision = 1 [1701830326.335616][11:14] CHIP:DMG: }, [1701830326.335783][11:14] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003F Command=0x0000_0000 Status=0x1 [1701830326.336224][11:14] CHIP:DMG: ICR moving to [AwaitingDe] [1701830326.336645][11:14] CHIP:EM: <<< [E:17863i S:44148 M:176857218 (Ack:184683337)] (S) Msg TX to 1:0000000012344321 [D1AE] --- Type 0000:10 (SecureChannel:StandaloneAck) [1701830326.336789][11:14] CHIP:IN: (S) Sending msg 176857218 on secure session with LSID: 44148 [1701830326.337063][11:14] CHIP:EM: Flushed pending ack for MessageCounter:184683337 on exchange 17863i [MatterTest] 12-06 02:38:46.340 ERROR Exception occurred in test_TC_RR_1_1. Traceback (most recent call last): File "/usr/local/lib/python3.10/dist-packages/mobly/base_test.py", line 777, in exec_one_test test_method() File "/root/python_testing/matter_testing_support.py", line 707, in async_runner return asyncio.run(body(*args, **kwargs)) File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run return loop.run_until_complete(main) File "/usr/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete return future.result() File "/root/python_testing/TC_RR_1_1.py", line 460, in test_TC_RR_1_1 Clusters.GroupKeyManagement.Structs.GroupKeySetStruct]] = await self.fill_and_validate_group_key_sets( File "/root/python_testing/TC_RR_1_1.py", line 537, in fill_and_validate_group_key_sets await client.SendCommand(self.dut_node_id, 0, Clusters.GroupKeyManagement.Commands.KeySetWrite( File "/usr/local/lib/python3.10/dist-packages/chip/ChipDeviceCtrl.py", line 751, in SendCommand return await future chip.interaction_model.InteractionModelError: InteractionModelError: Failure (0x1) [MatterTest] 12-06 02:38:46.357 INFO [Test] test_TC_RR_1_1 ERROR [MatterTest] 12-06 02:38:46.380 INFO Teardown: shutting down all subscription to avoid racy callbacks [MatterTest] 12-06 02:38:46.391 INFO Summary for test class TC_RR_1_1: Error 1, Executed 1, Failed 0, Passed 0, Requested 1, Skipped 0 [MatterTest] 12-06 02:38:46.397 INFO Summary for test run MatterTest@12-06-2023_02-37-24-668: Total time elapsed 81.72299357100019s Artifacts are saved in "/tmp/matter_testing/logs/MatterTest/12-06-2023_02-37-24-668" Test summary saved in "/tmp/matter_testing/logs/MatterTest/12-06-2023_02-37-24-668/test_summary.yaml" Test results: Error 1, Executed 2, Failed 0, Passed 1, Requested 2, Skipped 0
   

2. After TC_RR_1_1.py test,power on the device again, the device is running abnormally
   `I (2628) esp_netif_handlers: sta ip: 192.168.1.224, mask: 255.255.255.0, gw: 192.168.1.1
   I (2628) chip[DL]: IP_EVENT_STA_GOT_IP
   I (2628) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.224/255.255.255.0 gateway 192.168.1.1
   I (2638) chip[DL]: IPv4 Internet connectivity ESTABLISHED
   I (2648) chiot_app_matter: [chiot_app_matter.cpp:55]:Interface IP Address changed

I (2658) chip[DIS]: Updating services using commissioning mode 0
I (2668) chip[DIS]: CHIP minimal mDNS started advertising.

abort() was called at PC 0x4201bb11 on core 0
Core 0 register dump:
MEPC : 0x403808a8 RA : 0x4038b416 SP : 0x3fcbf900 GP : 0x3fc94600
TP : 0x3fc7bf18 T0 : 0x37363534 T1 : 0x7271706f T2 : 0x33323130
S0/FP : 0x3fcbf93c S1 : 0x3fcbf920 A0 : 0x3fcbf93c A1 : 0x3fcbf91e
A2 : 0x00000000 A3 : 0x3fcbf969 A4 : 0x00000001 A5 : 0x3fca8000
A6 : 0x7a797877 A7 : 0x76757473 S2 : 0x00000000 S3 : 0x420d3fde
S4 : 0x00000001 S5 : 0x3fca6e90 S6 : 0x3fca6e88 S7 : 0x3c165000
S8 : 0x00000000 S9 : 0x00000000 S10 : 0x00000000 S11 : 0x00000000
T3 : 0x6e6d6c6b T4 : 0x6a696867 T5 : 0x66656463 T6 : 0x62613938
MSTATUS : 0x00001801 MTVEC : 0x40380001 MCAUSE : 0x00000007 MTVAL : 0x00000000
MHARTID : 0x00000000

Stack memory:
3fcbf900: 0x3fca0101 0x3fcbf910 0x3fcbf91c 0x4039129a 0x00000000 0xffff0000 0xe001a8c0 0x420e0030
3fcbf920: 0x31303234 0x31316262 0x00000000 0x3fc97104 0x3fcbf920 0x3fc97120 0x3fcbf91c 0x726f6261
3fcbf940: 0x20292874 0x20736177 0x6c6c6163 0x61206465 0x43502074 0x34783020 0x62313032 0x20313162
3fcbf960: 0x63206e6f 0x2065726f 0x00000030 0x3fca0000 0x3fca6e88 0x3fc992e0 0x00000000 0x4201bb14
3fcbf980: 0x3fcac244 0x3fcb53c0 0x3fcabfc0 0x3fcb53c0 0x00000001 0x00000000 0x00000000 0x00000000
3fcbf9a0: 0xffff0000 0xe001a8c0 0x00000000 0x00000000 0xffff0000 0xe001a8c0 0x00000000 0x00000000
3fcbf9c0: 0xffff0000 0xfb0000e0 0x3fcb53c0 0x14e914e9 0x0001000c 0x3fcbf900 0x00000000 0x00000000
3fcbf9e0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcbfa00: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcbfa20: 0x00000000 0x00000000 0x00000000 0x3fcbfa01 0x3fca4c64 0x3fca4c58 0x3fca4c64 0x00000000
3fcbfa40: 0x00000000 0x00000000 0x00000000 0x3c165000 0x3fca6e88 0x3fca6e90 0x00000001 0x420d3fde
3fcbfa60: 0x3fca4c58 0x3fc992e0 0x00000000 0x4201c00c 0x00000a5e 0x3fca8000 0x3fc99000 0x3fca6ea1
3fcbfa80: 0x00000a5e 0x00000000 0x3fcbfae0 0x420e4c56 0x0000038e 0x3fca6e80 0x3fcbfae0 0x420e4ce6
3fcbfaa0: 0x3fca6e88 0x3fca6e90 0x00000001 0x3fca6ea1 0x3fca6e80 0x00000001 0x3fca6e80 0x420e5028
3fcbfac0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xffffffff 0x4038e018 0x00000000 0x00000000 0x00c94600
3fcbfae0: 0x0000800c 0x00000000 0x00000000 0x3fcbfa7c 0x00000000 0x00000000 0x420d78aa 0x420e7432
3fcbfb00: 0x3fcbfae0 0x00000000 0x3fcbfae0 0x00008000 0x00000003 0x00000000 0xfa000000 0x00000003
3fcbfb20: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcbfb40: 0x00000000 0x00000000 0x00000000 0x4038e01e 0x00000000 0x00000000 0x00000000 0x00000000
3fcbfb60: 0x00000000 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0x00000800 0xa5a5a5a5
3fcbfb80: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfba0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfbc0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfbe0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfc00: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfc20: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfc40: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfc60: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfc80: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfca0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfcc0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fcbfce0: 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5

ELF file SHA256: f51217c80d19d44f

Rebooting...
ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x40380680
SPIWP:0xee
mode:DIO, clock div:1
Valid secure boot key blocks: 0
secure boot verification succeeded
load:0x3fcd5988,len:0x273c
load:0x403cc710,len:0x738
load:0x403ce710,len:0x5230
entry 0x403cc710
`

Log:
this is log file of raspberrypi:
ch_tc_rr_1.1.txt

this is log of smartplug:
tc_rr_1.1_device.txt

[wqx6]

The TC-RR-1.1 could fail when the NVS is not enough. We have increased the partition size of nvs in b292cf0. Could you please increase the partition size and try again?

[tonyVopo]

@wqx6 Yes, we solved the problem by increasing the size of the NVS partition. Thx

[emesamwong]

hi, @wqx6

My partition for nvs is already 48K but still fail in the TC-RR-1.1 and the same issue as tonyVopo mentioned
DUT report Failure in KeySetWrite command

Do I need the increase the nvs size???

Cert: Matter 1.2
ESP-32S3
esp-matter@2f692ac1
connectedhomeip@8e3d98c0