jgallagher
commented
4 weeks ago I hit this locally and looked into it for a bit. I think this might be a bug / race in Oximeter producer assignment. There are two ways Oximeter decides what its producers are:
- It runs a refresh loop where it periodically asks Nexus for its full set of producers. The default interval for this loop is 10 minutes; we don't change that in tests, so it effectively only runs once, around the time Oximeter starts.
- When a new producer registers with Nexus, Nexus sends a post to Oximeter telling it about the new producer.
Oximeter logs all of these; snipping out just the relevant bits from a failed test:
13:42:53.584Z INFO test_mgs_metrics (oximeter): refreshing list of producers from Nexus
collector_id = 39e6175b-4df2-4730-b11d-cbc1e60a2e78
collector_ip = ::1
file = oximeter/collector/src/agent.rs:761
13:42:53.622Z DEBG test_mgs_metrics (oximeter): registered new metric producer
address = [::1]:44257
collector_id = 39e6175b-4df2-4730-b11d-cbc1e60a2e78
collector_ip = ::1
producer_id = a6458b7d-87c3-4483-be96-854d814c20de
13:42:53.658Z DEBG test_mgs_metrics (oximeter): registered new metric producer
address = [::1]:40449
collector_id = 39e6175b-4df2-4730-b11d-cbc1e60a2e78
collector_ip = ::1
producer_id = 47991ac2-392b-4188-bf19-96e0f0440d14
13:42:53.678Z INFO test_mgs_metrics (oximeter): refreshed list of producers from Nexus
collector_id = 39e6175b-4df2-4730-b11d-cbc1e60a2e78
collector_ip = ::1
file = oximeter/collector/src/agent.rs:809
n_current_tasks = 1
n_pruned_tasks = 1
13:42:54.442Z DEBG test_mgs_metrics (oximeter): registered new metric producer
address = 127.0.0.1:41885
collector_id = 39e6175b-4df2-4730-b11d-cbc1e60a2e78
collector_ip = ::1
producer_id = e559cb0e-f223-4273-a733-d5f31b1be530So I think what happened was:
- Oximeter sent a request to Nexus to list its current producers; this is a series of paginated requests (in practice in this test it's two requests: one that fetches the first page, and a second that gets an empty result, signaling the end of the list).
- Nexus POST'd a new collector (
a6458b7d-87c3-4483-be96-854d814c20de; this isn't MGS). - Nexus POST'd another new collector (
47991ac2-392b-4188-bf19-96e0f0440d14; this one is MGS). - Oximeter finished getting its list of producers. There was only one producer in this list (
n_current_tasks = 1), so it pruned the other one it new about (MGS, because we got unlucky from timing or UUID ordering or something). - Nexus POST'd another new collector (
e559cb0e-f223-4273-a733-d5f31b1be530; also not MGS).
At this point Oximeter is aware of 2 collectors but pruned the third, and the one this test in particular cares about. It would have corrected itself the next time the refresh loop ran, but that's 10 minutes away, and the test times out after 1.
bnaecker
andrewjstone
hawkw
This test failed on a CI run on https://github.com/oxidecomputer/omicron/pull/6881
https://github.com/oxidecomputer/omicron/pull/6881/checks?check_run_id=31702768426
Link here to the specific line of output from the buildomat log showing the failure: https://buildomat.eng.oxide.computer/wg/0/details/01JAE89628KSREHPCPZHC8DVS0/TV1XNO9ztAlr3QY3XQh3zGrYKkUsoCJHt0VvRzVuqCqsj1Ab/01JAE89QQBY3BRXDXDZ6N76977#S6309
Excerpt from the log showing the failure: