The bug that only showed up because my test was too fast
A couple hundred milliseconds cost me an hour, and the annoying part is I'd written the fix for it before I even had the bug. I was writing a Testcontainers deployment check for a custom Keycloak authenticator - boot a real Keycloak server with the built provider jar dropped into providers/, hit the admin REST API, confirm the provider shows up.
First pass, I picked the wait strategy the way you'd expect:
.waitingFor(Wait.forLogMessage(".*Running the server in development mode.*", 1))
Keycloak prints that line during start-dev, so it felt like a reasonable "the server is up" signal. The test ran, and about one time in three it failed with a plain connection reset trying to hit the admin token endpoint. No stack trace pointing anywhere useful, just "connection refused," which is the least helpful error message a network client can give you.
The instinct is to blame Testcontainers, or Docker networking, or just add a Thread.sleep(2000) and move on. I've done that before and regretted it - a sleep just moves the flake to a slower CI runner instead of fixing it.
What was actually happening: that log line prints the moment Keycloak's startup sequence reaches "development mode," which is before the HTTP listener has finished binding and accepting connections. The gap is small - a couple hundred milliseconds most of the time - which is exactly why it only failed sometimes. Fast enough CI runner, you never see it. Slightly loaded runner, the test wins the race against the listener and gets a reset.
The Fix
The fix was smaller than the investigation:
.waitingFor(Wait.forHttp("/realms/master")
.forStatusCode(200)
.withStartupTimeout(Duration.ofMinutes(3)))
Poll the actual endpoint you're about to call, instead of trusting a log line that tells you what the server is doing, not what it's ready for. Obvious in hindsight. It always is.
What Stuck With Me
A log-message wait strategy will pass code review without question, because it reads as "wait until the server says it's running" - which sounds exactly right. It just isn't the same claim as "wait until the server is accepting connections," and nothing about the code makes that distinction visible. You only find the gap between those two claims by having the test flake on you, ideally in CI where you can't step through it, which is the least convenient possible place to learn it.
Same class of bug, one level up: don't trust a stated intention, wait on the actual side effect you depend on. Applies well past Testcontainers - anywhere something logs "starting" before it's actually ready to be used.
Comments
No comments yet. Start the discussion.