batch_processing_with_kafka.end_to_end wedged CIKafka for 10+ minutes — hang is outside its own 60s tracked timeout

[jeremydmiller]

Caught by the #4108 instrumentation on its first capped job (run 32786336368, CIKafka, 2026-08-24): the job died at the 20-minute cap with 297/302 tests done and one in flight — and this time the log names it:

23:38:12 [INF]  11m46s — 297/302 done, 1 in flight (lane 0), longest running: Wolverine.Kafka.Tests.batch_processing_with_kafka.end_to_end (188s)
23:40:04 [INF]  STALLED: Wolverine.Kafka.Tests.batch_processing_with_kafka.end_to_end has been in flight 300s on lane 0 (pid 3814)
...
23:44:50 [INF]  18m24s — 297/302 done, 1 in flight (lane 0), longest running: Wolverine.Kafka.Tests.batch_processing_with_kafka.end_to_end (586s)

Still climbing at 586s when the cap killed the job. This is the #4083 shape (a batch that wedges reports nothing) finally with a name on it, and very plausibly the same job that produced the earlier unexplained CIKafka cap-kills.

The sharp clue

The test (src/Transports/Kafka/Wolverine.Kafka.Tests/batch_processing_with_kafka.cs) puts a .Timeout(60.Seconds()) on its tracked session — yet it was in flight for 10+ minutes. So the hang is not the message wait, which would have thrown at 60s. The wedge has to be either:

1. AlbaHost.For<Program> startup — e.g. a Kafka admin/consumer connection retrying unboundedly while the broker container is degraded, before the tracked session even starts; or
2. await using host teardown — the tracked session times out (or completes), and disposal then hangs stopping a Kafka listener/producer. This is the CIPulsar wedges in PulsarNativeReliabilityTests — DotPulsar producers stall in Setup, and the test's 1000s timeout outlives the 20-minute job cap #4100 Pulsar shape exactly: an await parked on the GC heap waiting for a broker state change that never comes.

Teardown is the more likely suspect given the test's own assertions never reported a failure — a 60s timeout throwing inside the attempt would surface as a failed test, not a silent wedge (though an exception thrown while the host refuses to dispose would also present this way).

Getting the async stacks next time

The dump that would settle this didn't happen: the runner's SIGTERM never reached the build process's cancellation handler (the bash → build.sh → dotnet run chain forwards nothing). #4115 fixes that with a pid-handshake relay — once merged, the next recurrence should produce dumpasync --coalesce output for pid-in-hand in the job log (grep '\[stall\]'), plus a partial ledger naming the test in the artifact.

Until then it can be chased locally: run CIKafka, and if it wedges, dotnet-dump collect -p <pid from the STALLED line> + dumpasync --coalesce.

Related: #4083 (the shape), #4100 (the Pulsar precedent and the dumpasync method), #4108 (the instrumentation that named it), #4115 (the relay that will capture it).

🤖 Generated with Claude Code

[jeremydmiller]

Hypothesis 1 is mechanically confirmed, with a number. PR #4189.

Measured

PROBE-4116 elapsed=00:21:38.3621011 failure=BrokerInitializationException:
  Unable to initialize the Broker kafka in time

A Wolverine host takes 21 minutes and 38 seconds to fail to start against an unreachable Kafka broker — UseKafka("localhost:9099").AutoProvision() against a closed port, on main. The job cap is 20 minutes.

BrokerTransport.InitializeAsync retries a failed startup twenty times with a five-second pause, and nothing bounds it by a clock. Twenty attempts bounds tries, not time, and one try costs whatever the broker client's own request timeout is — 60s for librdkafka. 20 × (60 + 5) ≈ 21½ minutes.

That lands exactly where this issue said to look: before the tracked session starts, which is precisely why the test's own .Timeout(60.Seconds()) could not fire. The sharp clue in the issue body is explained by the mechanism rather than by the message wait.

It also ignored cancellation outright — await Task.Delay(5.Seconds()), no token — so a host being shut down could not break out. Proven: cancelling on attempt 2 still ran all 20 attempts across 95 seconds.

What #4189 does

WolverineOptions.BrokerInitializationTimeout, default 2 minutes, checked between attempts, plus the cancellation token on the pause. Broker SDKs take no CancellationToken on their provisioning calls, so an in-flight attempt is not interrupted — the honest bound is budget + one client request timeout, ~3 minutes for Kafka instead of ~22. Transport-agnostic, so it covers Rabbit, ASB, Pulsar and SQS too.

What it does not claim

This does not prove it is what happened on 8/24 — that evidence is gone, and #4115's relay has not caught a recurrence since (the only cancelled tests.yml job since is 33168694171, which was CIMarten — #4083). What it removes is the mechanism by which any broker trouble at host startup becomes a twenty-minute wedge with no diagnostics.

On hypothesis 2 (teardown)

Weaker, but not eliminated. Kafka's listener drain is already bounded by an explicit shutdown budget (GH-3434), and InlineKafkaSender.Dispose is a bounded Flush(10s), so the obvious unbounded waits are not there. That makes startup the likelier of the two — an observation from reading, not a proof.

Leaving this open until either a recurrence is captured with async stacks or CIKafka goes a meaningful stretch clean with #4189 in. CIKafka on main currently runs 521–575s against the 1200s cap, so there is no standing pressure.

[jeremydmiller]

Closing. #4189 is merged (4e737afb).

What is established. The mechanism the issue named as hypothesis 1 is confirmed with a number: a Wolverine host took 21m38s to fail to start against an unreachable Kafka broker, because BrokerTransport.InitializeAsync bounded its retries by an attempt count and not by a clock, while one attempt costs librdkafka's 60s request timeout. That is longer than the 20-minute job cap, and it sits before the tracked session starts — which is exactly why this test's own .Timeout(60.Seconds()) could never fire, the sharp clue this issue opened with. The retry pause also ignored cancellation outright.

WolverineOptions.BrokerInitializationTimeout (default 2 minutes, checked between attempts) plus the cancellation token now bound it to roughly three minutes for Kafka — budget plus one uninterruptible client request — instead of twenty-two. It is transport-agnostic, so Rabbit, ASB, Pulsar and SQS get the same bound.

What is not established, and is the reason I had left this open. This does not prove the 8/24 wedge was that loop. That evidence is gone, and #4115's SIGTERM relay has not caught a recurrence since — the only cancelled tests.yml job in the interval was 33168694171, which was CIMarten (#4083), not CIKafka. Hypothesis 2, teardown, was not eliminated either; it is only weaker, because Kafka's listener drain is already bounded by an explicit budget (GH-3434) and InlineKafkaSender.Dispose is a bounded Flush(10s).

CIKafka since, against the 1200s cap:

run	conclusion	CIKafka
33280239021 (with #4189)	success	565s
33266297511	success	551s
33180615133	success	568s
33171286581	success	552s
33119797212	success	561s
33112008437	success	544s

A 24-second spread and no cap-kills, so there is no standing pressure here.

Closing on the fix rather than on a reproduction: the unbounded startup path is gone, and if the wedge recurs it now fails as a readable startup error instead of a job cancellation with discarded logs. Reopen on any recurrence — the instrumentation from #4108/#4115/#4142 should name it next time.