TC-CADMIN-1.19 failing on 5th commission (CON-935)

[PhLuReh]

Describe the bug
My device is on a official testing. Up to now (40 passed tests) system is working fine. Now the TC-CADMIN-1.19 popped up failing.

The TC is running several consecutive commissionings. The 5th succeeds, but avahi-broadcast doesn't succeed, and the commissioner cannot resolve the device. The new device gets broadcast by the ESP.

These are the calls that I made on the TH:

./chip-tool pairing ble-wifi 1 xxx xxx 38332127 1402
./chip-tool pairing open-commissioning-window 1 1 300 1000 3840
./chip-tool pairing code 2 #  --commissioner-name beta
./chip-tool pairing open-commissioning-window 1 1 300 1000 3840
./chip-tool pairing code 3 #  --commissioner-name gamma
./chip-tool pairing open-commissioning-window 1 1 300 1000 3840
./chip-tool pairing code 4 #  --commissioner-name 4
./chip-tool pairing open-commissioning-window 1 1 300 1000 3840
./chip-tool pairing code 5 #  --commissioner-name 5

The last one is never finishing with success.

Environment

• ESP-Matter Commit Id: dd4f34e
• ESP-IDF Commit Id: e088c3766ba440e72268b458a68f27b6e7d63986
• SoC (eg: ESP32 or ESP32-C3): ESP32
• Device Logs (Please attach the log file): TC-CADMIN-1_19_dut.txt
• Host Machine OS: Linux version 6.1.29-1-MANJARO (builduser@fv-az292-908) (gcc (GCC) 12.2.1 20230201, GNU ld (GNU Binutils) 2.40) #1 SMP PREEMPT_DYNAMIC Wed May 17 14:00:55 UTC 2023
• Commissioner app and versions if present:
• Commissioner's logs if present: TC-CADMIN-1_19_th.txt

Any additional details
...

[PhLuReh]

I just checked if increasing MAX_FABRICS to 6 would fix the test result, but no, still commissioning to the 5th fabric fails while discovery. I thought it would allow commissioning to the 5th and then failing at the 6th commissioning.

Pls support...

[VaishaliAvhale]

@PhLuReh, I have tested the same test case on the latest esp-matter main branch's light example [commit-id de46e80], and it worked as expected. I have attached its logs here: TC-CADMIN-1-19-chip-tool.log and TC-CADMIN-1-19.DUT.log.

Please pull the latest changes, retry, and attach complete logs if you face any issues.

[PhLuReh]

Thank you for testing this. But still I have a problem with always developing against the latest main branch. I currently under certification testing, and therefore I need some (more or less) stable branch. Problem is, that Espressif is promoting a manufacturing ready implementation for Matter. We jumped on this promotion and therefore expect the stack to work. This should not be an affront, but I think you know how its working...

Could you do the test on the release/v1.1 branch, please?

[dhrishi]

@PhLuReh You are right. This should be tested with the exact same commit/branch you've mentioned. Sorry about that. We will revert soon.

[VaishaliAvhale]

@PhLuReh, sorry for the inconvenience.

I have retested the test case (TC) on the same commit you mentioned, and it worked on my end. Please find the attached logs below:

• CADMIN-1-19-DUT.log
• CADMIN-1-19-chip-tool.log
  

Observations regarding your log file:

1. It seems that in the 5th fabric commissioning, chip-tool got stuck. Please execute the command rm -rf /tmp/chip* in the host machine/chip-tool terminal and then re-execute the TC.
   Note: Sometimes, due to a network issue, adding fabric or the open-commissioning-window command might fail. Simply re-execute that command and continue with the TC.

[shubhamdp]

@PhLuReh the DUT logs clearly shows that it is advertising all five available services, but TH is unable to resolve CAB7ECE084501F4C-0000000000000005. Not sure what could be wrong here, if you get a chance, can you try with a different router please.

I (196851) chip[DIS]: Advertise operational node 251F8B1809EBDA1F-0000000000000001
I (196891) chip[DIS]: Advertise operational node E5B6A792B590FE30-0000000000000002
I (196941) chip[DIS]: Advertise operational node 65CC5C1EAAA5AAAA-0000000000000003
I (196991) chip[DIS]: Advertise operational node F6FCE1C4368133F5-0000000000000004
I (197041) chip[DIS]: Advertise operational node CAB7ECE084501F4C-0000000000000005

[PhLuReh]

This looks somewhat strange to me. I see, that the Espressif code seems to work properly. But, that's why I retested also with MAX_FABRICS 6 and then commissioning to fabric 6 fails (see #774 (comment)). Sure I could build some example app and it might work, but how can I create a working application here? Could it be some config issue?

I don't think that the TH or even the router is problematic (though it is a Fritz!box), because it would fail after some while and not exactly at the hightest configured fabric number - reproducibly.

Could this issue be related to project-chip/certification-tool#103?

[VaishaliAvhale]

@PhLuReh, are you still facing issues with TC-CADMIN-1.19?
If yes, please retry the same process and send me the DUT and chip-tool logs again.
I tried to reproduce it on connectedhomeip/lighting-app and linux/all-cluster-app using the same commit which you have used, but I failed to reproduce.

[dhrishi]

@PhLuReh Can you please check? We were able to get it work with the above mentioned configurations. Please close the issue if it is solved at your end.

[PhLuReh]

just did a retest on this issue and it still fails. here is the
chiptool log and the
DUT log.

It seems that there's some error on the DUT leading to remove the fabric again. I tried to commission the 5th fabric twice (after it failed after the first time, so no worries about Fabric index 0x6):

I (8784252) chip[FS]: GeneralCommissioning: Received CommissioningComplete
I (8784402) chip[FP]: Metadata for Fabric 0x6 persisted to storage.
E (8785162) chip[FP]: Failed to commit pending operational certificates 5001105
I (8785172) chip[TS]: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
I (8785252) chip[FP]: Fabric (0x6) deleted.
I (8785252) chip[ZCL]: OpCreds: Fabric index 0x6 was removed
I (8785252) chip[DIS]: Updating services using commissioning mode 0

What's happening during storing. I tells the fabric was persisted, but the it failed to commit and deletes it again. Do I have some memory issues or at least the partition is too small?

sec_cert,  0x3F, ,0xd000,    0x3000, ,  # Never mark this as an encrypted partition
nvs,      data, nvs,     0x10000,   0x6000,
otadata,  data, ota,     ,          0x2000
phy_init, data, phy,     ,          0x1000,
ota_0,    app,  ota_0,   0x20000,   0x1E0000,
ota_1,    app,  ota_1,   0x200000,  0x1E0000,
fctry,    data, nvs,     0x3E0000,  0x6000

Hopefully we can catch the bug.

[PhLuReh]

changed my partition table now and increased both nvs and nvs_keys. Working now. Found this by reading #395