[CERT-TEST-FAILURE] [TC-PAVST-2.14] False failure: wildcard subscription cache goes stale after manual DUT reboot
Feature Area
Other
Test Case
TC-PAVST-2.14
Reproduction steps
TC-PAVST-2.14 fails at Step 10 even though the DUT responds correctly at every step. After the manual reboot in Step 6, the framework's wildcard subscription is torn down and never re-established, so verify_attribute_subscription_value() compares a fresh (correct) read against an attribute cache that stopped updating before the reboot.
[MatterTest] 09-15 12:13:39.363 INFO ***** Test Step 10 : TH Reads CurrentConnections attribute from PushAV Stream Transport Cluster on DUT [MatterTest] 09-15 12:13:39.363 INFO ***** Test Step 10 : TH Reads CurrentConnections attribute from PushAV Stream Transport Cluster on DUT [MatterTest] 09-15 12:13:39.363 INFO <<< [E:17632i S:18726 M:90748492 (Ack:89914993)] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [C77C] [UDP:[fe80::f431:b4ff:fe0b:ceea%veth91cde5a]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [MatterTest] 09-15 12:13:39.364 ERROR Data received on an unknown session (LSID=18720). Dropping it! [MatterTest] 09-15 12:13:39.364 INFO Found an existing secure session to [1:0000000012344321]! [MatterTest] 09-15 12:13:39.365 INFO 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space [MatterTest] 09-15 12:13:39.366 INFO <<< [E:17633i S:18726 M:90748493] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [C77C] [UDP:[fe80::f431:b4ff:fe0b:ceea%veth91cde5a]:5540] --- Type 0001:02 (IM:ReadRequest) (B:52) [MatterTest] 09-15 12:13:39.366 INFO ??1 [E:17633i S:18726 M:90748493] (S) Msg Retransmission to 1:0000000012344321 scheduled for 380ms from now [State:Active II:500 AI:300 AT:4000] [MatterTest] 09-15 12:13:39.367 INFO >>> [E:17633i S:18726 M:89914994 (Ack:90748493)] (S) Msg RX from 1:0000000012344321 [C77C] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:71) [MatterTest] 09-15 12:13:39.371 INFO <<< [E:17633i S:18726 M:90748494 (Ack:89914994)] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [C77C] [UDP:[fe80::f431:b4ff:fe0b:ceea%veth91cde5a]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [MatterTest] 09-15 12:13:39.371 INFO [verify_subscription] Mismatch on first check for CurrentConnections on endpoint 1: read=[], cache=[PushAvStreamTransport.Structs.TransportConfigurationStruct(connectionID=1, transportStatus=<TransportStatusEnum.kInactive: 1>, transportOptions=PushAvStreamTransport.Structs.TransportOptionsStruct(streamUsage=<StreamUsageEnum.kLiveView: 3>, videoStreamID=3, audioStreamID=3, TLSEndpointID=0, url='https://localhost:1234/streams/1/', triggerOptions=PushAvStreamTransport.Structs.TransportTriggerOptionsStruct(triggerType=<TransportTriggerTypeEnum.kContinuous: 2>, motionZones=None, motionSensitivity=None, motionTimeControl=None, maxPreRollLen=None), ingestMethod=<IngestMethodsEnum.kCMAFIngest: 0>, containerOptions=PushAvStreamTransport.Structs.ContainerOptionsStruct(containerType=<ContainerFormatEnum.kCmaf: 0>, CMAFContainerOptions=PushAvStreamTransport.Structs.CMAFContainerOptionsStruct(CMAFInterface=<CMAFInterfaceEnum.kInterface1: 0>, segmentDuration=4000, chunkDuration=4, sessionGroup=3, trackName='media', metadataEnabled=None)), expiryTime=3600, videoStreams=[PushAvStreamTransport.Structs.VideoStreamStruct(videoStreamName='video', videoStreamID=3)], audioStreams=[PushAvStreamTransport.Structs.AudioStreamStruct(audioStreamName='audio', audioStreamID=3)]), fabricIndex=1)]. Retrying after delay... [MatterTest] 09-15 12:13:40.004 ERROR Data received on an unknown session (LSID=18720). Dropping it! [MatterTest] 09-15 12:13:40.373 INFO [verify_subscription] Retry 1/3: still mismatched, cache=[PushAvStreamTransport.Structs.TransportConfigurationStruct(connectionID=1, transportStatus=<TransportStatusEnum.kInactive: 1>, transportOptions=PushAvStreamTransport.Structs.TransportOptionsStruct(streamUsage=<StreamUsageEnum.kLiveView: 3>, videoStreamID=3, audioStreamID=3, TLSEndpointID=0, url='https://localhost:1234/streams/1/', triggerOptions=PushAvStreamTransport.Structs.TransportTriggerOptionsStruct(triggerType=<TransportTriggerTypeEnum.kContinuous: 2>, motionZones=None, motionSensitivity=None, motionTimeControl=None, maxPreRollLen=None), ingestMethod=<IngestMethodsEnum.kCMAFIngest: 0>, containerOptions=PushAvStreamTransport.Structs.ContainerOptionsStruct(containerType=<ContainerFormatEnum.kCmaf: 0>, CMAFContainerOptions=PushAvStreamTransport.Structs.CMAFContainerOptionsStruct(CMAFInterface=<CMAFInterfaceEnum.kInterface1: 0>, segmentDuration=4000, chunkDuration=4, sessionGroup=3, trackName='media', metadataEnabled=None)), expiryTime=3600, videoStreams=[PushAvStreamTransport.Structs.VideoStreamStruct(videoStreamName='video', videoStreamID=3)], audioStreams=[PushAvStreamTransport.Structs.AudioStreamStruct(audioStreamName='audio', audioStreamID=3)]), fabricIndex=1)] [MatterTest] 09-15 12:13:40.678 ERROR Data received on an unknown session (LSID=18720). Dropping it! [MatterTest] 09-15 12:13:41.374 INFO [verify_subscription] Retry 2/3: still mismatched, cache=[PushAvStreamTransport.Structs.TransportConfigurationStruct(connectionID=1, transportStatus=<TransportStatusEnum.kInactive: 1>, transportOptions=PushAvStreamTransport.Structs.TransportOptionsStruct(streamUsage=<StreamUsageEnum.kLiveView: 3>, videoStreamID=3, audioStreamID=3, TLSEndpointID=0, url='https://localhost:1234/streams/1/', triggerOptions=PushAvStreamTransport.Structs.TransportTriggerOptionsStruct(triggerType=<TransportTriggerTypeEnum.kContinuous: 2>, motionZones=None, motionSensitivity=None, motionTimeControl=None, maxPreRollLen=None), ingestMethod=<IngestMethodsEnum.kCMAFIngest: 0>, containerOptions=PushAvStreamTransport.Structs.ContainerOptionsStruct(containerType=<ContainerFormatEnum.kCmaf: 0>, CMAFContainerOptions=PushAvStreamTransport.Structs.CMAFContainerOptionsStruct(CMAFInterface=<CMAFInterfaceEnum.kInterface1: 0>, segmentDuration=4000, chunkDuration=4, sessionGroup=3, trackName='media', metadataEnabled=None)), expiryTime=3600, videoStreams=[PushAvStreamTransport.Structs.VideoStreamStruct(videoStreamName='video', videoStreamID=3)], audioStreams=[PushAvStreamTransport.Structs.AudioStreamStruct(audioStreamName='audio', audioStreamID=3)]), fabricIndex=1)] [MatterTest] 09-15 12:13:41.651 ERROR Data received on an unknown session (LSID=18720). Dropping it! [MatterTest] 09-15 12:13:42.376 INFO [verify_subscription] Retry 3/3: still mismatched, cache=[PushAvStreamTransport.Structs.TransportConfigurationStruct(connectionID=1, transportStatus=<TransportStatusEnum.kInactive: 1>, transportOptions=PushAvStreamTransport.Structs.TransportOptionsStruct(streamUsage=<StreamUsageEnum.kLiveView: 3>, videoStreamID=3, audioStreamID=3, TLSEndpointID=0, url='https://localhost:1234/streams/1/', triggerOptions=PushAvStreamTransport.Structs.TransportTriggerOptionsStruct(triggerType=<TransportTriggerTypeEnum.kContinuous: 2>, motionZones=None, motionSensitivity=None, motionTimeControl=None, maxPreRollLen=None), ingestMethod=<IngestMethodsEnum.kCMAFIngest: 0>, containerOptions=PushAvStreamTransport.Structs.ContainerOptionsStruct(containerType=<ContainerFormatEnum.kCmaf: 0>, CMAFContainerOptions=PushAvStreamTransport.Structs.CMAFContainerOptionsStruct(CMAFInterface=<CMAFInterfaceEnum.kInterface1: 0>, segmentDuration=4000, chunkDuration=4, sessionGroup=3, trackName='media', metadataEnabled=None)), expiryTime=3600, videoStreams=[PushAvStreamTransport.Structs.VideoStreamStruct(videoStreamName='video', videoStreamID=3)], audioStreams=[PushAvStreamTransport.Structs.AudioStreamStruct(audioStreamName='audio', audioStreamID=3)]), fabricIndex=1)] [MatterTest] 09-15 12:13:42.377 INFO Found an existing secure session to [1:0000000012344321]! [MatterTest] 09-15 12:13:42.378 INFO 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space [MatterTest] 09-15 12:13:42.378 INFO <<< [E:17634i S:18726 M:90748495] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [C77C] [UDP:[fe80::f431:b4ff:fe0b:ceea%veth91cde5a]:5540] --- Type 0001:02 (IM:ReadRequest) (B:51) [MatterTest] 09-15 12:13:42.378 INFO ??1 [E:17634i S:18726 M:90748495] (S) Msg Retransmission to 1:0000000012344321 scheduled for 355ms from now [State:Active II:500 AI:300 AT:4000] [MatterTest] 09-15 12:13:42.380 INFO >>> [E:17634i S:18726 M:89914995 (Ack:90748495)] (S) Msg RX from 1:0000000012344321 [C77C] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:112) [MatterTest] 09-15 12:13:42.386 INFO <<< [E:17634i S:18726 M:90748496 (Ack:89914995)] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [C77C] [UDP:[fe80::f431:b4ff:fe0b:ceea%veth91cde5a]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [MatterTest] 09-15 12:13:42.387 ERROR Exception occurred in test_TC_PAVST_2_14. Traceback (most recent call last): File "/home/ubuntu/matter-sdk-master-700b2b999-arm64/chip_env/lib/python3.12/site-packages/mobly/base_test.py", line 801, in exec_one_test test_method() File "/home/ubuntu/matter-sdk-master-700b2b999-arm64/chip_env/lib/python3.12/site-packages/matter/testing/decorators.py", line 376, in per_endpoint_runner test_instance.event_loop.run_until_complete(asyncio.wait_for( File "/usr/lib/python3.12/asyncio/base_events.py", line 687, in run_until_complete return future.result() ^^^^^^^^^^^^^^^ File "/usr/lib/python3.12/asyncio/tasks.py", line 520, in wait_for return await fut ^^^^^^^^^ File "/home/ubuntu/Aug/connectedhomeip/src/python_testing/TC_PAVST_2_14.py", line 249, in test_TC_PAVST_2_14 transport_configs = await self.read_single_attribute_check_success( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/ubuntu/matter-sdk-master-700b2b999-arm64/chip_env/lib/python3.12/site-packages/matter/testing/matter_testing.py", line 2633, in read_single_attribute_check_success await self.verify_attribute_subscription_value( File "/home/ubuntu/matter-sdk-master-700b2b999-arm64/chip_env/lib/python3.12/site-packages/matter/testing/matter_testing.py", line 2794, in verify_attribute_subscription_value asserts.fail(problem) File "/home/ubuntu/matter-sdk-master-700b2b999-arm64/chip_env/lib/python3.12/site-packages/mobly/asserts.py", line 441, in fail raise signals.TestFailure(msg, extras) mobly.signals.TestFailure: Details=Subscription cache mismatch for CurrentConnections (cluster 0x0555, attr 0x0001) on endpoint 1: read returned [], subscription cache has [PushAvStreamTransport.Structs.TransportConfigurationStruct(connectionID=1, transportStatus=<TransportStatusEnum.kInactive: 1>, transportOptions=PushAvStreamTransport.Structs.TransportOptionsStruct(streamUsage=<StreamUsageEnum.kLiveView: 3>, videoStreamID=3, audioStreamID=3, TLSEndpointID=0, url='https://localhost:1234/streams/1/', triggerOptions=PushAvStreamTransport.Structs.TransportTriggerOptionsStruct(triggerType=<TransportTriggerTypeEnum.kContinuous: 2>, motionZones=None, motionSensitivity=None, motionTimeControl=None, maxPreRollLen=None), ingestMethod=<IngestMethodsEnum.kCMAFIngest: 0>, containerOptions=PushAvStreamTransport.Structs.ContainerOptionsStruct(containerType=<ContainerFormatEnum.kCmaf: 0>, CMAFContainerOptions=PushAvStreamTransport.Structs.CMAFContainerOptionsStruct(CMAFInterface=<CMAFInterfaceEnum.kInterface1: 0>, segmentDuration=4000, chunkDuration=4, sessionGroup=3, trackName='media', metadataEnabled=None)), expiryTime=3600, videoStreams=[PushAvStreamTransport.Structs.VideoStreamStruct(videoStreamName='video', videoStreamID=3)], audioStreams=[PushAvStreamTransport.Structs.AudioStreamStruct(audioStreamName='audio', audioStreamID=3)]), fabricIndex=1)] (after 3s retry), Extras=None
Root cause: the reboot kills the wildcard-subscription session, and the session the DUT re-establishes afterwards is evicted by the framework's own StopPairing / "Expiring sessions on all active controllers" cleanup. Every later report is dropped as "Data received on an unknown session", freezing the cache at its pre-reboot value while the actual attribute read is correct.
Running the same test with --no-wildcard-subscription passes.
Steps to Reproduce
- Run the test against a camera DUT with PushAV Stream Transport on endpoint 1
python3 TC_PAVST_2_14.py
--commissioning-method on-network
--discriminator 3840
--passcode 20202021
--storage-path admin_storage.json
--endpoint 1
--string-arg th_server_app_path:../tools/push_av_server/src/server.py host_ip:localhost
- At Step 6, reboot the DUT when prompted and press Enter.
- Test proceeds through Steps 7–9 and fails at Step 10.
Expected Behavior
After a reboot step, the wildcard subscription is either re-established (and the cache re-primed) or marked invalid, so attribute verification uses the live read value.
Bug prevalence
Whenever I do this
GitHub hash of the SDK that was being used
700b2b99928f1095c6d37489c89be7e87557b65d
Platform
raspi
Anything else?
Python script: https://github.com/project-chip/connectedhomeip/blob/master/src/python_testing/TC_PAVST_2_14.py
Failure logs: TC-PAVST-2.14.txt
Passing logs:
Source: project-chip/connectedhomeip