[Build] Darwin test failed -[MTRXPCListenerSampleTests test900_SubscribeClusterStateCache]

[woody-apple]

Build issue(s)

2023-06-27T05:25:37.9210620Z 2023-06-27 05:25:37.918 xcodebuild[85838:204236] [MT] IDETestOperationsObserverDebug: 151.145 sec, +151.145 sec -- end
2023-06-27T05:25:43.5069200Z Failing tests:
2023-06-27T05:25:43.5069390Z 
2023-06-27T05:25:43.5070160Z 	-[MTRXPCListenerSampleTests test900_SubscribeClusterStateCache]
2023-06-27T05:25:43.5070520Z Test session results, code coverage, and logs:
2023-06-27T05:25:43.5070700Z 
2023-06-27T05:25:43.5078630Z ** TEST FAILED **
2023-06-27T05:25:43.5078830Z 
2023-06-27T05:25:43.5080000Z 	/Users/runner/Library/Developer/Xcode/DerivedData/Matter-fezxjrcgbvmiwkgpcrhtmcinmudo/Logs/Test/Test-Matter Framework Tests-2023.06.27_05-13-40-+0000.xcresult
2023-06-27T05:25:43.5080670Z 
2023-06-27T05:25:43.5139080Z Testing started
2023-06-27T05:25:48.5399760Z ##[error]Process completed with exit code 65.

https://github.com/project-chip/connectedhomeip/actions/runs/5385718043/jobs/9775015395

Platform

No response

Anything else?

No response

[bzbarsky-apple]

Failing bit:

2023-06-27T05:25:19.1145580Z /Users/runner/work/connectedhomeip/connectedhomeip/src/darwin/Framework/CHIPTests/MTRXPCListenerSampleTests.m:1793: error: -[MTRXPCListenerSampleTests test900_SubscribeClusterStateCache] : (([result[@"data"][@"value"] boolValue]) equal to (YES)) failed: ("NO") is not equal to ("YES")
2023-06-27T05:25:19.1249260Z Test Case '-[MTRXPCListenerSampleTests test900_SubscribeClusterStateCache]' failed (9.273 seconds).

This looks like a racy test to me. It sends an "on" command and then once we get the response to that command it fulfills the expectation we are waiting on. Once that happens we try to read the cached data. In this case you can see in the log that this read is happening interleaved with (on a different thread) us getting the actual data report that would update said cached data.

This is actually quite easy to reproduce if I change the min-interval for the subscription to 10.

[bzbarsky-apple]

I guess the test has a sleep(1) to try to make it pass...but that's still racy.

[bzbarsky-apple]

And it looks like the XPC subscribe API does not report attribute bits, so there is no way to wait until we actually get the report.