search

project-chip / matter-test-scripts

Test scripts related to Matter Certification
https://csa-iot.org/
Apache License 2.0
9 stars 3 forks source link

[TC-OPSTATE-2.5]The added field "PIXIT_ENDPOINT:1" does not work. #210

Open ZeddChen opened 7 months ago

ZeddChen commented 7 months ago

Summary Title:

[SVE2] Test case TC-OPSTATE-2.5 can not be running.

Description:

1. Test script in UI-Python Testing Suite - Legacy, runs and waits for an hour and still won't finish.

image

  1. Using docker manually to test, added field "PIXIT_ENDPOINT:1" is not work. image

Steps to reproduce:

ubuntu@ubuntu:~$docker run -v /home/ubuntu/certification-tool/backend/test_collections/matter/sdk_tests/sdk_checkout/python_testing:/root/python_temp_testing -v /var/credentials:/credentials -v /var/run/dbus:/var/run/dbus -v $(pwd):/launch_dir --privileged --network host -it connectedhomeip/chip-cert-bins:9f6d627e0262e1d023986291948bb4e845be803e root@ubuntu:~# rm -f admin_storage.json && python3 python_testing/TC_OPSTATE_2_5.py --discriminator 3840 --passcode 20202021 --commissioning-method ble-wifi --paa-trust-store-path /credentials/development/paa-root-certs/ --storage-path admin_storage.json --wifi-ssid dekra --wifi-passphrase dekra2019 --ble-interface-id 0 --PICS /credentials/ci-pics --int-arg PIXIT_ENDPOINT:1 PIXIT.WAITTIME.REBOOT:100

Logs:

TH UI UI_Test_Run_2024_03_08_13_14_38.log

manully in the docker OPSTATE-2.5_0308.txt

ZeddChen commented 7 months ago

Adding "-- endpoint 1" can enable STEP4 to execute on EP1. New issue: DUT cannot receive the first command after restarting DUT. Using manually to check, seem any type chip-tool command could not receive after restart.

ZeddChen commented 7 months ago

Manully test log: [1709882028.959667][18253:18255] CHIP:TOO: OperationalState: 0 [1709882028.960010][18253:18255] CHIP:EM: <<< [E:6656i S:63435 M:108147001 (Ack:63179123)] (S) Msg TX to 1:0000000000000001 [CBA8] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882028.960189][18253:18255] CHIP:EM: Flushed pending ack for MessageCounter:63179123 on exchange 6656i

operationalstate start 1 1 [1709882101.762415][18253:18253] CHIP:TOO: Command: operationalstate start 1 1 [1709882101.763330][18253:18255] CHIP:TOO: Sending command to node 0x1 [1709882101.765610][18253:18255] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1709882101.765689][18253:18255] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1709882101.765770][18253:18255] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1709882101.765836][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1709882101.765922][18253:18255] CHIP:TOO: Sending cluster (0x00000060) command (0x00000002) on endpoint 1 [1709882101.766041][18253:18255] CHIP:DMG: ICR moving to [AddingComm] [1709882101.766109][18253:18255] CHIP:DMG: ICR moving to [AddedComma] [1709882101.766588][18253:18255] CHIP:EM: <<< [E:6657i S:63435 M:108147002] (S) Msg TX to 1:0000000000000001 [CBA8] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1709882101.766951][18253:18255] CHIP:DMG: ICR moving to [AwaitingRe] [1709882102.146703][18253:18255] CHIP:EM: Retransmitting MessageCounter:108147002 on exchange 6657i Send Cnt 1 [1709882102.511656][18253:18255] CHIP:EM: Retransmitting MessageCounter:108147002 on exchange 6657i Send Cnt 2 [1709882103.090839][18253:18255] CHIP:EM: Retransmitting MessageCounter:108147002 on exchange 6657i Send Cnt 3 [1709882104.110462][18253:18255] CHIP:EM: Retransmitting MessageCounter:108147002 on exchange 6657i Send Cnt 4 [1709882105.726690][18253:18255] CHIP:EM: Failed to Send CHIP MessageCounter:108147002 on exchange 6657i sendCount: 4 max retries: 4 [1709882107.992275][18253:18255] CHIP:IN: SecureSession[0xffff9400fbc0]: MarkAsDefunct Type:2 LSID:63435 [1709882107.992378][18253:18255] CHIP:SC: SecureSession[0xffff9400fbc0, LSID:63435]: State change 'kActive' --> 'kDefunct' [1709882107.992443][18253:18255] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 6657i [1709882107.992573][18253:18255] CHIP:TOO: Error: src/app/CommandSender.cpp:336: CHIP Error 0x00000032: Timeout [1709882107.992630][18253:18255] CHIP:DMG: ICR moving to [AwaitingDe] [1709882107.992716][18253:18255] CHIP:TOO: Run command failure: src/app/CommandSender.cpp:336: CHIP Error 0x00000032: Timeout operationalstate start 1 1 [1709882125.420716][18253:18253] CHIP:TOO: Command: operationalstate start 1 1 [1709882125.421703][18253:18255] CHIP:TOO: Sending command to node 0x1 [1709882125.423692][18253:18255] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1709882125.423766][18253:18255] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1709882125.423842][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1709882125.423919][18253:18255] CHIP:DIS: Resolving 548B4D53FCF3CBA8:0000000000000001 ... [1709882125.427950][18253:18255] CHIP:DL: Avahi resolve found [1709882125.428073][18253:18255] CHIP:DIS: Node ID resolved for 548B4D53FCF3CBA8:0000000000000001 [1709882125.428133][18253:18255] CHIP:DIS: Hostname: 683988588CF5 [1709882125.428200][18253:18255] CHIP:DIS: IP Address #1: fe80::604:b8ff:fe00:eb90 [1709882125.428259][18253:18255] CHIP:DIS: Port: 5540 [1709882125.428315][18253:18255] CHIP:DIS: Mrp Interval idle: not present [1709882125.428370][18253:18255] CHIP:DIS: Mrp Interval active: not present [1709882125.428424][18253:18255] CHIP:DIS: Mrp Active Threshold: not present [1709882125.428478][18253:18255] CHIP:DIS: TCP Supported: 1 [1709882125.428584][18253:18255] CHIP:DIS: ICD: not present [1709882125.428855][18253:18255] CHIP:DIS: UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540: new best score: 7 [1709882125.428922][18253:18255] CHIP:DIS: Checking node lookup status after 5 ms [1709882125.428973][18253:18255] CHIP:DIS: Keeping DNSSD lookup active [1709882125.624778][18253:18255] CHIP:DIS: Checking node lookup status after 201 ms [1709882125.625087][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540 while in state 2 [1709882125.625154][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1709882125.625388][18253:18255] CHIP:IN: SecureSession[0xffff9402abf0]: Allocated Type:2 LSID:63436 [1709882125.625490][18253:18255] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1709882125.627910][18253:18255] CHIP:EM: <<< [E:6658i S:0 M:172137351] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1709882125.628270][18253:18255] CHIP:SC: Sent Sigma1 msg [1709882125.628345][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1709882125.676582][18253:18255] CHIP:EM: >>> [E:6658i S:0 M:113942881 (Ack:172137351)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882125.676649][18253:18255] CHIP:EM: Found matching exchange: 6658i, Delegate: 0xffff9400f918 [1709882125.676710][18253:18255] CHIP:EM: Rxd Ack; Removing MessageCounter:172137351 from Retrans Table on exchange 6658i [1709882125.711424][18253:18255] CHIP:EM: >>> [E:6658i S:0 M:113942882 (Ack:172137351)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) [1709882125.711515][18253:18255] CHIP:EM: Found matching exchange: 6658i, Delegate: 0xffff9400f918 [1709882125.711574][18253:18255] CHIP:EM: CHIP MessageCounter:172137351 not in RetransTable on exchange 6658i [1709882125.711672][18253:18255] CHIP:SC: Received Sigma2Resume msg [1709882125.712059][18253:18255] CHIP:SC: Found MRP parameters in the message [1709882125.712163][18253:18255] CHIP:SC: Peer assigned session session ID 24578 [1709882125.719368][18253:18255] CHIP:SC: Sending status report. Protocol code 0, exchange 6658 [1709882125.719668][18253:18255] CHIP:EM: <<< [E:6658i S:0 M:172137352 (Ack:113942882)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0000:40 (SecureChannel:StatusReport) [1709882125.720237][18253:18255] CHIP:SC: SecureSession[0xffff9402abf0, LSID:63436]: State change 'kEstablishing' --> 'kActive' [1709882125.720326][18253:18255] CHIP:IN: SecureSession[0xffff9402abf0]: Activated - Type:2 LSID:63436 [1709882125.720374][18253:18255] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:63436 PSID:24578! [1709882125.720428][18253:18255] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1709882125.720596][18253:18255] CHIP:TOO: Sending cluster (0x00000060) command (0x00000002) on endpoint 1 [1709882125.720714][18253:18255] CHIP:DMG: ICR moving to [AddingComm] [1709882125.720772][18253:18255] CHIP:DMG: ICR moving to [AddedComma] [1709882125.721143][18253:18255] CHIP:EM: <<< [E:6659i S:63436 M:216947268] (S) Msg TX to 1:0000000000000001 [CBA8] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1709882125.721421][18253:18255] CHIP:DMG: ICR moving to [AwaitingRe] [1709882126.072090][18253:18255] CHIP:EM: Retransmitting MessageCounter:216947268 on exchange 6659i Send Cnt 1 [1709882126.116842][18253:18255] CHIP:EM: Retransmitting MessageCounter:172137352 on exchange 6658i Send Cnt 1 [1709882126.122095][18253:18255] CHIP:EM: >>> [E:6658i S:0 M:113942883 (Ack:172137352)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882126.122168][18253:18255] CHIP:EM: Found matching exchange: 6658i, Delegate: (nil) [1709882126.122241][18253:18255] CHIP:EM: Rxd Ack; Removing MessageCounter:172137352 from Retrans Table on exchange 6658i [1709882126.480876][18253:18255] CHIP:EM: Retransmitting MessageCounter:216947268 on exchange 6659i Send Cnt 2 [1709882127.065043][18253:18255] CHIP:EM: Retransmitting MessageCounter:216947268 on exchange 6659i Send Cnt 3 [1709882127.502299][18253:18255] CHIP:EM: >>> [E:6659i S:63436 M:80305979 (Ack:216947268)] (S) Msg RX from 1:0000000000000001 [CBA8] --- Type 0001:09 (IM:InvokeCommandResponse) [1709882127.502405][18253:18255] CHIP:EM: Found matching exchange: 6659i, Delegate: 0xffff94008628 [1709882127.502491][18253:18255] CHIP:EM: Rxd Ack; Removing MessageCounter:216947268 from Retrans Table on exchange 6659i [1709882127.502577][18253:18255] CHIP:DMG: ICR moving to [ResponseRe] [1709882127.502691][18253:18255] CHIP:DMG: InvokeResponseMessage = [1709882127.502752][18253:18255] CHIP:DMG: { [1709882127.502808][18253:18255] CHIP:DMG: suppressResponse = false, [1709882127.502867][18253:18255] CHIP:DMG: InvokeResponseIBs = [1709882127.502944][18253:18255] CHIP:DMG: [ [1709882127.503002][18253:18255] CHIP:DMG: InvokeResponseIB = [1709882127.503085][18253:18255] CHIP:DMG: { [1709882127.503148][18253:18255] CHIP:DMG: CommandDataIB = [1709882127.503219][18253:18255] CHIP:DMG: { [1709882127.503284][18253:18255] CHIP:DMG: CommandPathIB = [1709882127.503370][18253:18255] CHIP:DMG: { [1709882127.503450][18253:18255] CHIP:DMG: EndpointId = 0x1, [1709882127.503539][18253:18255] CHIP:DMG: ClusterId = 0x60, [1709882127.503620][18253:18255] CHIP:DMG: CommandId = 0x4, [1709882127.503697][18253:18255] CHIP:DMG: }, [1709882127.503775][18253:18255] CHIP:DMG: [1709882127.503843][18253:18255] CHIP:DMG: CommandFields = [1709882127.503919][18253:18255] CHIP:DMG: { [1709882127.503993][18253:18255] CHIP:DMG: 0x0 = [1709882127.504070][18253:18255] CHIP:DMG: { [1709882127.504155][18253:18255] CHIP:DMG: 0x0 = 0, [1709882127.504240][18253:18255] CHIP:DMG: }, [1709882127.504320][18253:18255] CHIP:DMG: }, [1709882127.504391][18253:18255] CHIP:DMG: }, [1709882127.504469][18253:18255] CHIP:DMG: [1709882127.504579][18253:18255] CHIP:DMG: }, [1709882127.504658][18253:18255] CHIP:DMG: [1709882127.504715][18253:18255] CHIP:DMG: ], [1709882127.504790][18253:18255] CHIP:DMG: [1709882127.504847][18253:18255] CHIP:DMG: InteractionModelRevision = 11 [1709882127.504902][18253:18255] CHIP:DMG: }, [1709882127.505065][18253:18255] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0060 Command=0x0000_0004 [1709882127.505131][18253:18255] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0060 Command 0x0000_0004 [1709882127.505232][18253:18255] CHIP:TOO: OperationalCommandResponse: { [1709882127.505295][18253:18255] CHIP:TOO: commandResponseState: { [1709882127.505354][18253:18255] CHIP:TOO: ErrorStateID: 0 [1709882127.505411][18253:18255] CHIP:TOO: } [1709882127.505463][18253:18255] CHIP:TOO: } [1709882127.505574][18253:18255] CHIP:DMG: ICR moving to [AwaitingDe] [1709882127.505998][18253:18255] CHIP:EM: <<< [E:6659i S:63436 M:216947269 (Ack:80305979)] (S) Msg TX to 1:0000000000000001 [CBA8] [UDP:[fe80::604:b8ff:fe00:eb90%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882127.506241][18253:18255] CHIP:EM: Flushed pending ack for MessageCounter:80305979 on exchange 6659i [1709882127.564998][18253:18255] CHIP:EM: >>> [E:6659i S:63436 M:80305980 (Ack:216947268)] (S) Msg RX from 1:0000000000000001 [CBA8] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882127.781160][18253:18255] CHIP:IN: Received unknown unsecure packet for initiator 0x32D8B56240DE0716 [1709882127.834737][18253:18255] CHIP:EM: >>> [E:6659i S:63436 M:80305981 (Ack:216947268)] (S) Msg RX from 1:0000000000000001 [CBA8] --- Type 0000:10 (SecureChannel:StandaloneAck) [1709882127.883538][18253:18255] CHIP:EM: >>> [E:6659i S:63436 M:80305982 (Ack:216947268)] (S) Msg RX from 1:0000000000000001 [CBA8] --- Type 0000:10 (SecureChannel:StandaloneAck)

raul-marquez-csa commented 7 months ago

@ZeddChen, can you provide the ci-pics file? Also, can I use on-network commissioning mode instead of ble-wifi for this?

ZeddChen commented 7 months ago

@raul-marquez-csa Sure, this is the ci-pics. ci-pics.txt

raul-marquez-csa commented 7 months ago

@raul-marquez-csa Sure, this is the ci-pics. ci-pics.txt

Thanks, is ble commissioning specifically required?

cecille commented 7 months ago

Commissioning method won't affect this test.

raju-apple commented 6 months ago

@raul-marquez-csa any update on this issue ?