search

project-chip / certification-tool

A test harness and tooling designed to simplify development, testing, and certification for devices, guided by the Connectivity Standards Alliance.
https://csa-iot.org/
Apache License 2.0
38 stars 22 forks source link

[Bug] Failure in semi-automated test steps #286

Closed samryanuofl closed 3 months ago

samryanuofl commented 3 months ago

Describe the bug

Running chip-tool commands for semi-automated test case steps fails consistently for me.

Seeing similar behavior on every semi-automated test but these logs in particular are form test case TC-GRPKEY-2.2.

This is the command I ran for step 21 of the test and the output (the Readme says to use th-sdk as the container name, that doesn't exist for me so I assume th-chip-tool is correct):

ubuntu@ubuntu:/run$ docker exec -it th-chip-tool ./chip-tool groupkeymanagement key-set-write '{"groupKeySetID": 1,"groupKeySecurityPolicy": 0, "epochKey0":"d0d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime0": 1,"epochKey1":"d1d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime1": 18446744073709551613,"epochKey2":"d2d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime2": 18446744073709551614 }' 1 0
[1718652944.613339][16:16] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1718652944.615357][16:16] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1718652944.615399][16:16] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1718652944.621500][16:16] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1718652944.621871][16:16] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1718652944.622015][16:16] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1718652944.622470][16:16] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rvz91B)
[1718652944.623334][16:16] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1718652944.623424][16:16] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1718652944.624312][16:16] CHIP:DL: Got Ethernet interface: eth0
[1718652944.624887][16:16] CHIP:DL: Found the primary Ethernet interface:eth0
[1718652944.625499][16:16] CHIP:DL: Got WiFi interface: wlan0
[1718652944.631394][16:16] CHIP:DL: Found the primary WiFi interface:wlan0
[1718652944.631478][16:16] CHIP:IN: UDP::Init bind&listen port=0
[1718652944.631585][16:16] CHIP:IN: UDP::Init bound to port=56104
[1718652944.631609][16:16] CHIP:IN: BLEBase::Init - setting/overriding transport
[1718652944.631629][16:16] CHIP:IN: TransportMgr initialized
[1718652944.631667][16:16] CHIP:FP: Initializing FabricTable from persistent storage
[1718652944.631824][16:16] CHIP:TS: Last Known Good Time: 2023-10-03T16:51:18
[1718652944.633442][16:16] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDCE5305488E6FB31, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1718652944.635807][16:16] CHIP:ZCL: Using ZAP configuration...
[1718652944.640406][16:16] CHIP:DL: Avahi client registered
[1718652944.640537][16:16] CHIP:CTL: System State Initialized...
[1718652944.640696][16:16] CHIP:CTL: Setting attestation nonce to random value
[1718652944.640736][16:16] CHIP:CTL: Setting CSR nonce to random value
[1718652944.640794][16:16] CHIP:IN: UDP::Init bind&listen port=5550
[1718652944.640949][16:16] CHIP:IN: UDP::Init bound to port=5550
[1718652944.640974][16:16] CHIP:IN: TransportMgr initialized
[1718652944.641280][16:24] CHIP:DL: CHIP task running
[1718652944.641558][16:24] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1718652944.642033][16:24] CHIP:CTL: Setting attestation nonce to random value
[1718652944.642322][16:24] CHIP:CTL: Setting CSR nonce to random value
[1718652944.643361][16:24] CHIP:CTL: Generating NOC
[1718652944.644406][16:24] CHIP:FP: Validating NOC chain
[1718652944.646285][16:24] CHIP:FP: NOC chain validation successful
[1718652944.646449][16:24] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1718652944.646482][16:24] CHIP:TS: Last Known Good Time: 2023-10-03T16:51:18
[1718652944.646503][16:24] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1718652944.646521][16:24] CHIP:TS: Retaining current Last Known Good Time
[1718652944.651538][16:24] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1718652944.653704][16:24] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-03T16:51:18
[1718652944.656236][16:24] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: DCE5305488E6FB31)
[1718652944.656289][16:24] CHIP:IN: UDP::Init bind&listen port=5550
[1718652944.656399][16:24] CHIP:IN: UDP::Init bound to port=5550
[1718652944.656422][16:24] CHIP:IN: TransportMgr initialized
[1718652944.674521][16:24] CHIP:TOO: Sending command to node 0x1
[1718652944.675128][16:24] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1718652944.675192][16:24] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1718652944.675230][16:24] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1718652944.675263][16:24] CHIP:DIS: Resolving DCE5305488E6FB31:0000000000000001 ...
[1718652944.875886][16:24] CHIP:DIS: Checking node lookup status after 201 ms
[1718652949.678660][16:24] CHIP:DL: Re-trying resolve
[1718652954.682140][16:24] CHIP:DIS: Invalid context for handling resolves: 281472695014832
[1718652964.641768][16:16] CHIP:CTL: Shutting down the commissioner
[1718652964.641890][16:16] CHIP:CTL: Shutting down the controller
[1718652964.641938][16:16] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Cancelling incomplete address resolution as device is being deleted.
[1718652964.643419][16:16] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1718652964.643466][16:16] CHIP:FP: Forgetting fabric 0x1
[1718652964.643496][16:16] CHIP:TS: Pending Last Known Good Time: 2023-10-03T16:51:18
[1718652964.643659][16:16] CHIP:TS: Previous Last Known Good Time: 2023-10-03T16:51:18
[1718652964.643681][16:16] CHIP:TS: Reverted Last Known Good Time to previous value
[1718652964.643733][16:16] CHIP:CTL: Shutting down the commissioner
[1718652964.644091][16:16] CHIP:CTL: Shutting down the controller
[1718652964.644116][16:16] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1718652964.644303][16:16] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1718652964.645039][16:16] CHIP:FP: Shutting down FabricTable
[1718652964.645097][16:16] CHIP:TS: Pending Last Known Good Time: 2023-10-03T16:51:18
[1718652964.645248][16:16] CHIP:TS: Previous Last Known Good Time: 2023-10-03T16:51:18
[1718652964.645269][16:16] CHIP:TS: Reverted Last Known Good Time to previous value
[1718652964.645785][16:16] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-d2RECx)
[1718652964.646491][16:16] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1718652964.646557][16:16] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1718652964.646655][16:16] CHIP:DL: Inet Layer shutdown
[1718652964.646745][16:16] CHIP:DL: BLE shutdown
[1718652964.646766][16:16] CHIP:DL: System Layer shutdown
[1718652964.647510][16:16] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:588: CHIP Error 0x00000032: Timeout

From what I can tell it doesn't seem to be discovering the DUT. I was able to find it in avahi in the rpi console though:

ubuntu@ubuntu:/run$ avahi-browse _matter._tcp
+  wlan0 IPv6 DCE5305488E6FB31-E28E414F45712003             _matter._tcp         local
+   eth0 IPv6 DCE5305488E6FB31-E28E414F45712003             _matter._tcp         local

Any ideas on what could be going on here or how to resolve it?

Running version TH-Fall2023

Steps to reproduce the behavior

No response

Expected behavior

No response

Log files

No response

PICS file

Group Communication.xml.txt

Screenshots

No response

Environment

No response

Additional Information

No response

samryanuofl commented 3 months ago

This was user error, missed the spot in the documentation where it tells you to substitute the node ID from the log