integration_tests: bound two timing cases on what they can actually prove

[bburda]

Pull Request

Summary

test_peer_recovery case 7 reads the peer-owned topic through the merged Function after the peer gateway comes back, and it polls until that read answers 200. A 200 is not the answer here. When the peer returns, the member re-subscribes, and until its first sample arrives the read is a well-formed body with "status": "metadata_only" and no payload. The case checked the payload after the poll had already stopped, so the first 200 had to carry data or the case failed.

That is a race with the publisher, and it lost on a sanitizer build: AssertionError: 'metadata_only' != 'data', with subscriber_count: 0 in the reported body.

Case 1 in the same file already waits for the payload, and says why in its own comment. Case 7 now does the same. A read that never carries the sample within the recovery budget still fails the case, with a message that says the sample never came.

Waiting for the payload would on its own accept a gateway whose reads go back to empty between samples, because the poll stops at the first read that carries data. One more read after the poll pins that a read which follows a successful one carries the sample too: once the member's subscription is warm the gateway holds the latest sample and answers from it. This read does not measure how long a cold read waits for its first sample; the test controls no publisher, so it cannot pin that. The failure message of the poll used to make one more read while it was built, on success as well, so the read after the poll was the second one. It now reads the last answer only on the failure path, the way case 4 does.

---

Issue

• none: a test-side timing fix, no change to the gateway

---

Type

• Bug fix
• New feature or tests
• Breaking change
• Documentation only

---

Testing

The demo publisher on the peer-owned topic runs at 500 ms, which is fast enough that the first read after recovery usually already carries a sample. To make the window real, the publisher period was raised locally and the case was run in four configurations:

test version	publisher period	result
before	500 ms	passes, case 7 takes 0.41 s
before	15 s	fails, 'metadata_only' != 'data', same body as CI
after	15 s	passes, case 7 takes 10.0 s
after, expected value mutated to one the gateway never reports	500 ms	fails after the full 90 s budget, only case 7, on the new message

The last row is the check that the new poll can still fail: with the expectation mutated, case 7 spends its whole budget and reports that the sample never came, while the other eight cases stay green.

Full package run with all three changes: colcon test --packages-select ros2_medkit_integration_tests, 1244 tests, 0 errors, 0 failures.

Second case: the graph-event spawn bound

The same package had a second case measuring a quantity it did not control. test_graph_event_discovery timed spawn detection from subprocess.Popen and required it under 2.0 s. The gateway coalesces graph events behind discovery.refresh_debounce_ms, 1000 ms by default and not set by that test. The first event after a quiet period is serviced at the next 100 ms tick, and every event inside the window that follows waits for the window to end. A node coming up raises several events in a row, so its detection typically lands one window after its first event.

Measured by setting the bound to 0 so every run prints its time, eight runs with the default settings:

3.616  3.619  3.415  3.634  3.523  1.148  1.043  3.623  [s]

Two clusters, and the 2.0 s bound sits in the empty gap between them, so the case passed on which side of the debounce the spawn happened to land. Locally that was 2 passes in 8. With the debounce lowered to 50 ms, six runs gave 1.247 1.244 1.244 1.248 0.210 3.005, which is what identifies the debounce as the cause.

For reference, spawn to node-visible-in-the-ROS-graph, measured by an independent rclpy node with no gateway involved and a fresh domain per iteration, is 0.43 s to 0.59 s over eight samples. So most of the old 2.0 s budget was never the gateway's to spend.

A bound on elapsed time cannot separate the two mechanisms on its own, whatever value it takes. The backstop timer is created during gateway initialisation, so its phase relative to a mid-run spawn is arbitrary: a sweep landing inside the bound serves the detection even when the graph-event path is dead. At a 30 s backstop that is a 10/30 chance for a 10 s bound and 2/30 for the old 2 s one, so raising the bound alone would have made the case weaker.

So the case now establishes what it measured before bounding it. The backstop runs at 60 s, the longest interval the gateway accepts. Both cases check that the detection they observed landed within 50 s of a time taken in generate_test_description(). launch_testing calls that function in the test process and only then starts the launch service that forks the gateway, and the gateway arms the backstop timer during its own initialisation. The timer is therefore armed after that point, and a wall timer fires late, never early, so no sweep can have run inside the window. The gateway's own startup only widens it. The spawn bound is 10 s, above the measured spread, and the poll gives up at 15 s so a late detection reports the time it took. The startup case needs the same check because its poll budget outlives the backstop in the sanitizer jobs.

The three poll and latency budgets multiply by get_time_scale(), as the other tests in this directory do, so the ASan and TSan jobs get 30 s, 45 s and 90 s. The 50 s window does not scale: it is bounded by the gateway's backstop interval, which the scale factor does not stretch.

Verified: three runs at scale 1 and three at scale 3 pass with the default settings, spawn detection landing 4.3 s to 4.7 s after the launch was described. Falsification, with the graph-event path disabled by a 60 s debounce:

scale	startup case	spawn case
1	fails at its 30 s poll	fails at its 15 s poll
3	served by the backstop at 60.1 s, fails the 50 s window check	fails at its 45 s poll

The scale 3 row is the reason the startup case checks the window: with a 90 s poll and no check, the backstop would have served it and the case would have passed with the graph-event path dead.

Not identified: with the debounce at 50 ms four runs clustered at 1.244-1.248 s, too tight to be chance, so there is a second quantisation in there; and one run still took 3.005 s. Neither is explained, and neither changes what the bound can prove.

---

Checklist

• Breaking changes are clearly described (and announced in docs / changelog if needed)
• Tests were added or updated if needed
• Docs were updated if behavior or public API changed