example/orderstatus: the orderevents tests read back no events when the reader's first Fetch leaves out the events' partition

[Zaba505]

What happens

TestInit_produces_the_order_s_events_keyed_by_its_ID_in_order in example/orderstatus/cmd/orderevents fails intermittently on main, in the merge queue and on PRs, e.g. run 39678387044 on main:

--- FAIL: TestInit_produces_the_order_s_events_keyed_by_its_ID_in_order (0.12s)
    main_test.go:285:
        Error Trace:  example/orderstatus/cmd/orderevents/main_test.go:285
        Error:        "[]" should have 4 item(s), but has 0

The CLI exits 0 and prints the order ID, so the four events were produced. The test's readAll then reads none of them back.

Since the test landed on 2026-10-19 (#1079) it has failed 17 times in about 310 CI runs, roughly 1 run in 18. Sixteen of the failures are this test. One is its sibling, TestInit_without_an_order_ID_makes_a_random_one_and_prints_it, which uses the same readAll and fails with elements differ:

Run	Where	Test
39689285771	main	produces
39678387044	main	produces
39629611323	Renovate PR	produces
39522187395	Renovate PR	produces
39520441591	Renovate PR	produces
39519296072	Renovate PR	produces
39519086159	merge queue (#1233)	without an order ID
39517375682	merge queue (#1233)	produces
39500674562	main	produces
39499707281	main	produces
39497034669	merge queue (#1222)	produces
39491892106	merge queue (#1220)	produces
39472288442	main	produces
39455009396	main	produces
39407108659	merge queue (#1169)	produces
39393295262	main	produces
39365931881	Renovate PR	produces

Why

This hasn't been triaged. What follows comes from the code and a reproduction.

readAll polls with a one-second timeout and stops at the first poll that returns no records. That poll can come back empty while the records are still unread.

The cluster seeds orders.events with 12 partitions, and the four events land on one of them. After kgo lists the start offsets, it makes each partition's cursor usable one at a time (consumer.go#L2284-L2290). The first cursor starts the fetch loop (source.go#L265-L271, source.go#L858-L866), so the first Fetch can go out with only the partitions that were usable by then. If the events' partition isn't one of them, kfake holds the Fetch for kgo's default FetchMaxWait of 5s, and the other partitions wait for the next Fetch. The test runs in a synctest bubble, so the fake clock jumps to readAll's one-second deadline first, and the empty poll ends the read.

Reproduction. On main (6351c86), with no code change, at GOMAXPROCS=4:

go -C example/orderstatus test -c -race -cover -o "$PWD/orderevents.test" ./cmd/orderevents
GOMAXPROCS=4 ./orderevents.test -test.run 'TestInit_produces_the_order_s_events_keyed_by_its_ID_in_order' -test.count=300

This failed 2 of 300 runs. It didn't fail at GOMAXPROCS=1 or 2. Running eight copies at once, TestInit_without_an_order_ID_makes_a_random_one_and_prints_it failed 2 of 3,200 runs the same way.

To see the partial Fetch, I gave readAll's client a debug logger and recorded the size of its first Fetch request. Each partition adds 33 bytes, so 457 bytes is all 12 partitions. Over 3,200 runs:

First Fetch	Partitions	Runs	Read 0 events
457 bytes	12	3,168	0
160 to 424 bytes	3 to 11	25	3
94 to 127 bytes	1 to 2	7	6

Every failure had a partial first Fetch. A partial Fetch that included the events' partition read all four events. In a failing run the log shows the Fetch written, nothing read for one second, then the poll canceled:

19:00:00.010000 [DEBUG] wrote Fetch v18; broker: 0, bytes_written: 127, ...
19:00:01.010000 [DEBUG] read Fetch v18; broker: 0, bytes_read: 0, read_wait: 0s, time_to_read: 1s, err: context canceled

The same readAll loop is also in example/orderstatus/app/app_test.go and queue/kafka/producer_test.go. The app tests only read one-partition topics, and with one partition the first Fetch always includes it. TestProduce_keeps_the_order_of_records_with_one_key reads a three-partition topic. It passed 2,000 of 2,000 runs locally and hasn't failed in CI.

Expected

The orderevents tests read back every event the CLI produced, whichever partitions kgo's first Fetch covers. They fail only when the CLI is broken.

References

• run 39678387044, the run that prompted this
• readAll and the 12-partition cluster
• TestInit_produces_the_order_s_events_keyed_by_its_ID_in_order

[Zaba505]

Triage

Verdict: A reproducible bug in the tests' readAll, not in the orderevents CLI. readAll can stop before kgo has fetched the partition that holds the records. It reaches further than reported: queue/kafka's readAll has the same flaw, and the Kafka page quotes it for end users to copy. #1256 is filed to fix it.

Is this a misuse of humus?

No. No end user's code is involved. readAll is the walkthrough's own test helper, in cmd/orderevents/main_test.go, and the CLI works. In every failing run below, the CLI exited 0. In the runs that log their requests, the cluster held the events on their partition before readAll began. The read is what fails.

queue/kafka's tests have the same helper, in producer_test.go. The Kafka page's What a Producer stored quotes it for end users who test their own Producer. An end user who copies it for a topic with more than one partition gets the same flake, and nothing on the page warns them. The page's own example reads a one-partition topic, which isn't exposed.

Is it a feature request?

No. The behaviour contradicts what the walkthrough and the Kafka page promise:

• story(example): produce an order's events by hand with a small CLI #1014, the story for cmd/orderevents, asks for "Tests against kfake: the events it produces are keyed by the order, in order, and decode as the projector expects." A run that reads none of them checks none of that, and it fails the required Build job while the CLI works.
• Producing to Kafka's Testing section planned the helper: "readAll is a franz-go client that dials h.Dial and polls a topic to its end." It stops at a quiet poll, not at the topic's end.
• readAll's comment, in queue/kafka and on the Kafka page: "readAll returns every record of topic, in each partition's order".

The fix is in test helpers and one docs sample. It changes no API.

Is it reproducible?

Yes. At 6351c86, with Go 1.27.0 (CI runs 1.27.2), franz-go v1.22.2, kmsg v1.15.0 and kfake v0.0.0-20261020001454-39ebb4656165, under -race at GOMAXPROCS=4, as CI's runners have 4 CPUs. Each test ran 4 times on its own. The new tests use the existing CLI, cluster and readAll. Before they assert, they log the partitions that each of readAll's ListOffsets and Fetch requests names, by the bubble's clock, through a kfake control that lets the cluster answer as usual.

Test	Partitions	First Fetch	Failed
TestInit_produces_the_order_s_events_keyed_by_its_ID_in_order, unchanged	12	as kgo sends it	1 of 1,200
the same, logging its requests	12	as kgo sends it	1 of 1,200
TestInit_without_an_order_ID_makes_a_random_one_and_prints_it, unchanged	12	as kgo sends it	1 of 1,200
TestProduce_keeps_the_order_of_records_with_one_key (queue/kafka), unchanged	3	as kgo sends it	0 of 1,200
order-1's four events, forced	12	leaves out the events' partition	100 of 100
two orders' events, forced	12	leaves out one order's partition	100 of 100
ten records with one key (queue/kafka), forced	3	leaves out the records' partition	100 of 100

The forced tests use kfake.Fault to fail the records' partition in readAll's first ListOffsets once, with the retriable OFFSET_NOT_AVAILABLE. kgo makes the other partitions fetchable at once, and only lists the faulted one again a second later (consumer.go#L2176-L2195). So the first Fetch goes out without it, every time.

As kgo sends it: the first Fetch leaves out the events' partition. The CLI produces order-1's four events to partition 10. This is the failing run of the test that logs its requests:

1. +0s ListOffsets names 12 partitions [0 1 2 3 4 5 6 7 8 9 10 11]: readAll's client lists all twelve in one request.
2. +0s Fetch (session epoch 0, max wait 5000ms) names 9 partitions [0 1 2 3 4 7 8 9 11]: the first Fetch leaves out 5, 6 and 10.
3. None of the nine holds a record, so kfake holds the Fetch. No other Fetch is sent.
4. +1s readAll returns 0 records: the poll's deadline comes first, and the empty poll ends the read. "[]" should have 4 item(s), but has 0.

Over its 1,200 runs, the first Fetch named all twelve partitions 1,182 times, 11 partitions 14 times, 10 three times and 9 once. Only the run whose first Fetch left out partition 10 failed. A partial first Fetch that still names the events' partition reads all four. A passing run looks like this:

+0s Fetch (session epoch 0, max wait 5000ms) names 12 partitions [0 1 2 3 4 5 6 7 8 9 10 11]
+0s Fetch (session epoch 1, max wait 5000ms) names 1 partitions [10]
+1s Fetch (session epoch -1, max wait 1ms) names 0 partitions []
+1.001s readAll returns 4 records

Forced: two orders, one of their partitions left out. In one run, the two random IDs land on partitions 5 and 9, and 5 is faulted:

1. +0s Fetch (session epoch 0, max wait 5000ms) names 11 partitions [0 1 2 3 4 6 7 8 9 10 11]
2. The record on partition 9 comes back at once. The next Fetch names only partition 9, whose offset moved: +0s Fetch (session epoch 1, max wait 5000ms) names 1 partitions [9]. kfake holds it.
3. +1.001s readAll returns 1 records, keyed [CIA5DWM5ZB4GPQARAINRVETTK4], and require.ElementsMatch fails with elements differ.

Over 100 runs, it read one order's events in 93, and neither order's in 7. In each of those 7, both orders were on the faulted partition. CI's failing run of this test, 39519086159, read neither order, and so did the unchanged test's failing run here: elements differ, with list B empty. So a partial first Fetch can drop one order or both.

Forced, in queue/kafka: the Producer's records. Ten records with one key land on partition 2 of a three-partition topic. +0s Fetch (session epoch 0, max wait 5000ms) names 2 partitions [0 1], then +1s readAll returns 0 records. The test expects 10.

This corrects the report on one point. TestProduce_keeps_the_order_of_records_with_one_key isn't safe, only rarely hit. It passed 1,200 runs out of 1,200 here, as it passed the report's 2,000. But when its first Fetch is forced to leave out the records' partition, it reads 0 of 10 records in 100 runs out of 100. Its topic has three partitions, so kgo has fewer cursors to make usable after the first one, and the window in step 2 of Why is shorter than with twelve. I got that from kgo's code and didn't measure it.

Why

readAll polls with a one-second deadline and returns at the first poll that finds no records. An empty poll only means the topic has been read if every partition was in the Fetch that the poll waited on.

1. After a ListOffsets response, kgo makes each partition's cursor usable one at a time, in a loop (consumer.go#L2264-L2301). The first allowUsable calls maybeConsume, which starts the fetch loop on a goroutine of its own (source.go#L265-L270, source.go#L858-L866).
2. That goroutine builds the Fetch from the cursors that are usable when it gets there (source.go#L828-L846). With more than one P, it can get there while the loop in step 1 is still going. I got this from kgo's code. The partial first Fetches above, 18 in 1,200 runs, are what it produces.
3. A cursor that becomes usable while a Fetch is in flight doesn't send another. It only marks the fetch loop to go round again once the Fetch in flight returns (atomic_maybe_work.go#L14-L31). Reproduced: in each of the 208 logged runs that read nothing, the first Fetch is the only one sent before readAll returns.
4. kfake holds a Fetch whose partitions have fewer bytes than its MinBytes until its MaxWaitMillis (01_fetch.go#L283-L311). kgo's default is 5s (config.go#L231-L237). Reproduced: the logs show the Fetch sent with max wait 5000ms, and no answer by +1s.
5. readAll's poll deadline is 1s, so the poll ends empty first. The bubble only makes the wait free. Outside one, the poll would still end at 1s, before kfake answers at 5s. I got that from the code and didn't test it.

With one partition, the first Fetch either names it or isn't sent. So the app tests' readAll, whose topics each have one partition, isn't exposed to this. The shared cases read each partition up to its end offset, and queue/kafka's container test reads until it has the number of records it expects, so neither is exposed either. I got these from the code and didn't test them.

#1256 is filed to fix it:

• the orderevents tests read back every event the CLI produced, whichever partitions kgo's first Fetch names;
• queue/kafka's readAll returns every record of a topic with any number of partitions, as its comment says;
• both hold when the first Fetch leaves out the records' partition and kfake holds it for 5s, which the triage's forced tests, merged into main_test.go and producer_test.go, show;
• readAll's comment, and the Kafka page section that quotes it, say how it knows it has read the whole topic.

[Zaba505]

Fixed by #1257 (#1257), merged as 08b44fa, for story #1256.

readAll, in the orderevents tests and in queue/kafka's producer tests, no longer stops at the first poll that comes back empty. It now takes each partition's high watermark from the kfake cluster before it starts, and polls until it has read every partition up to it, under one deadline of a minute. A fetch error fails the test, and so does running out of time. The Kafka page's "What a Producer stored" section quotes the new readAll.

The triage's forced reproductions are now tests: orderevents reads all four of order-1's events and both orders' events, and queue/kafka's readAll reads all ten records, with the first Fetch forced to leave out the records' partition. Each test also asserts that the first Fetch did leave it out.