Repository navigation
fix(rust): Fix flaky reloading producer test and false purge counts after a reload - #601
Draft
mwarkentin wants to merge 3 commits into
Draft
mwarkentin wants to merge 3 commits into
mwarkentin wants to merge 3 commits into
Conversation
test_old_queue_is_empty_when_the_swap_happens and test_ignoring_ordering_still_drains_the_retired_client expect the old client's in_flight_count() to be 0 once it is drained. That count is librdkafka's rd_kafka_outq_len, which also counts stats reports, logs and other events waiting to be served, not just messages. Arroyo's producer config reports stats every second, and the 1 s linger in lingering_blob usually makes the drain end right at the first report. In local runs the old client's first report was served within a few ms of the drain ending in all 15 runs on rdkafka 0.37 and in most runs on 0.39. If that report is still queued when the test reads the count, the assert sees 1. CI has hit this four times since the tests were added, always with left: 1. Turn stats off in lingering_blob so no periodic report can land in the count. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QUYJLCL2crYejXVqdCdBL9
swap() reported the old client's in_flight_count() as the messages purged when it is dropped. That count is librdkafka's rd_kafka_outq_len, which also counts stats reports, logs and delivery reports waiting to be served. A swap that lands next to a stats report, which Arroyo's producer config sends every second, then logs "dropping the old client with messages still queued, they are lost" and bumps arroyo.producer.config_reload_purged_messages although nothing was lost. CI caught this once, in test_ignoring_ordering_still_drains_the_retired_client. A drain that finishes leaves no messages on the client: rd_kafka_flush only succeeds once every message is delivered or failed and its delivery report served. Nothing can reach the old client after that, so report 0 then. Fall back to in_flight_count only when the drain timed out. That fallback can still overcount, but it never undercounts, and a drain that finished can no longer report lost messages. The new tests hold the old client's polling thread in a stats callback so a report waits on its queue during the swap, and check that a timed-out drain still counts what it leaves behind. Against the old count the first one fails every time on rdkafka 0.38 and 0.39. On 0.37 it passes either way: there flush keeps polling until in_flight_count() is 0, stats reports included, so the report is served before the count. From 0.38 on, flush returns as soon as no messages are left. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QUYJLCL2crYejXVqdCdBL9
…am-2030-fix-flaky-reloading-producer-test Brings in #591 (delivery futures) and #600 (QueueFull when the reload buffer is full). The only conflict was drain()'s signature: it keeps this branch's bool return and takes main's Client<C>. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QUYJLCL2crYejXVqdCdBL9
This branch has not been deployed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
test_old_queue_is_empty_when_the_swap_happensfails now and then withleft: 1, right: 0.The test reads
in_flight_count()on the old client at the swap. That is librdkafka'srd_kafka_outq_len. It counts queued messages, but also stats reports, logs and delivery reports that are waiting to be served by poll.Arroyo's producer config sends a stats report every second.
lingering_blobsetslinger.msto 1000, so the drain usually ends about 1 s after the client is built, right when its first stats report comes in. If that report is still waiting on the queue when the test reads the count, the count is 1 and the assert fails.The same miscount hits production code. After the drain,
swap()usedold.in_flight_count()as the number of purged messages. A waiting stats report then logs "dropping the old client with messages still queued, they are lost" and bumpsarroyo.producer.config_reload_purged_messages, though nothing was lost.test_ignoring_ordering_still_drains_the_retired_clientchecks that count, so it can flake the same way.Evidence:
CI failed 4 times on this since the tests landed in Add ReloadingKafkaProducer #573, always with
left: 1, right: 0:test_ignoring_ordering_still_drains_the_retired_client, rdkafka 0.37, onmainat 49c24ec (job)test_old_queue_is_empty_when_the_swap_happens, rdkafka 0.38, 8cb627c (job)test_old_queue_is_empty_when_the_swap_happens, rdkafka 0.37, f99b937 (job)test_old_queue_is_empty_when_the_swap_happens, rdkafka 0.37, first run of fix(rust): Remove duplicate imports in producer tests #599 (job)The other red Rust runs in that time were the build errors fixed by fix(rust): Remove duplicate imports in producer tests #599 and one job that hit the 10 minute limit.
I timed it on a copy of
mainwith extra logging. With rdkafka 0.37, the old client's first stats report was served 1001.3 to 1002.2 ms after the client was built, and the drain ended at 1001.8 to 1002.7 ms (15 of 15 runs). With 0.39 it was the same in 8 of 10 runs. In the other 2, the probe took about 50 ms longer, and so did the drain.I could not make the unmodified test fail on this machine: 0 failures in 530 runs on
main(rdkafka 0.37 and 0.39, idle, next to busy loops, pinned to one CPU, and next to other copies of the tests). It is a narrow race, and CI runners are busier.On a copy of
mainwith a shorter stats interval inlingering_blob(rdkafka 0.39), it fails the same way, withleft: 1. That was 1 of 30 runs at 1 ms, 3 of 130 at 5 ms, and 0 of 30 at 20 ms. With stats off it was 0 of 100. With rdkafka 0.37 it did not fail even at 1 ms.Change
Test fix:
lingering_blobturns stats off ("statistics.interval.ms": "0"). Only the two lingering tests use it. Both assert on messages, not stats.Production fix, in its own commit:
drain()now returns whether the flush finished. If it did,swap()reports 0 purged messages. If the drain timed out,swap()still usesin_flight_count().This is exact after a drain that finished.
rd_kafka_flushonly succeeds once every message is delivered or failed and its delivery report has been served. After that, nothing can reach the old client. After a timed-out drain the count is unchanged. It is an upper bound: it can count too many, never too few.Two new tests:
test_stats_waiting_on_a_drained_client_are_not_counted_as_purgedholds the old client's polling thread in a stats callback, so a report waits on its queue during the swap.test_timed_out_drain_counts_the_messages_it_leaveschecks that a timed-out drain still counts the message it leaves behind.purged_at_drop(test only) is now anOption, so a test can read it before the old client's drop finishes.How tested
Before, on
main: see the numbers above.After, on this branch:
test_old_queue_is_empty_when_the_swap_happenswithcargo test --lib -- --exact: 150 of 150 passed in a row on rdkafka 0.39, 150 of 150 on 0.37, and 100 of 100 on 0.38.reloading_producermodule (30 tests): 5 runs each on rdkafka 0.37, 0.38 and 0.39, all passed. It also passed once with--features pull.test_old_queue_is_empty_when_the_swap_happensfails 5 of 5. With the drain after the install removed (unordered path),test_ignoring_ordering_still_drains_the_retired_clientfails 5 of 5.test_stats_waiting_on_a_drained_client_are_not_counted_as_purgedfails every time withleft: 1: 20 of 20 runs on rdkafka 0.38 and 25 of 25 on 0.39. On 0.37 it passes either way. Thereflushkeeps polling untilin_flight_count()is 0, stats reports included, so the report is served before the count. From 0.38 on,flushreturns as soon as no messages are left.test_timed_out_drain_counts_the_messages_it_leavesfails 5 of 5.cargo fmt --check,cargo checkandcargo check --features pullpass. CI does not run clippy.cargo clippy --all-targets --features pullshows the same warnings as onmain, and none inreloading_producer.rs.Follow-up
test_produce_does_not_wait_for_a_drain_that_never_finishesalso readsin_flight_count()with stats on. It has not flaked in CI, so I left it alone.Generated by Claude Code