Fast machine + Fast runtime == Container Timeout

[danielbodart]

On a fast linux machine with a fast runtime (like Bun), starting the reaper RYUK image finishes before you attach the waitStrategy.

You appear to start the container on line 196

But only wait for the container on line 225

Expected Behaviour
For the logs to be read even when the container instantly starts

Actual Behaviour
You look for the logs after they have already been sent

Testcontainer Logs
2025-04-04T11:43:56.998Z testcontainers [DEBUG] [6ccdcca4a1fa] Starting container...
2025-04-04T11:43:57.123Z testcontainers [DEBUG] [6ccdcca4a1fa] Started container
2025-04-04T11:43:57.123Z testcontainers [INFO] [6ccdcca4a1fa] Started container for image "testcontainers/ryuk:0.11.0"
2025-04-04T11:43:57.125Z testcontainers [DEBUG] [6ccdcca4a1fa] Fetching container logs...
2025-04-04T11:43:57.125Z testcontainers [DEBUG] [6ccdcca4a1fa] Demuxing stream...
2025-04-04T11:43:57.125Z testcontainers [DEBUG] [6ccdcca4a1fa] Demuxed stream
2025-04-04T11:43:57.125Z testcontainers [DEBUG] [6ccdcca4a1fa] Fetched container logs
2025-04-04T11:43:57.126Z testcontainers [DEBUG] [6ccdcca4a1fa] Waiting for container to be ready...
2025-04-04T11:43:57.126Z testcontainers [DEBUG] [6ccdcca4a1fa] Waiting for log message "/.Started./"...

Docker Logs
time=2025-04-04T11:43:57.122Z level=INFO msg=starting connection_timeout=1m0s reconnection_timeout=10s request_timeout=10s shutdown_timeout=10m0s remove_retries=10 retry_offset=-1s changes_retry_interval=1s port=8080 verbose=false
time=2025-04-04T11:43:57.123Z level=INFO msg=Started address=[::]:8080
time=2025-04-04T11:43:57.123Z level=INFO msg="client processing started"

Notice testcontainers starts waiting at 2025-04-04T11:43:57.126Z
Docker has already finished 3ms before at 2025-04-04T11:43:57.123Z (Sometime the gap is bigger and sometimes it starts later and so sees the log message.

Steps to Reproduce

1. Have fast linux machine with native docker
2. Use Bun
3. Start any test container (we were trying Postgres but it does not get that far)
4. Test will hang
5. Check logs

Environment Information

• Operating System: Ubuntu 24.04
• Docker Version: 26.1.3
• Bun version: 1.2.3
• Testcontainers version: 10.24.0
• CPU: Intel i9 12900k
• RAM: 32gb
• HD: WD Black SN750
• GPU: 4070

Solution
Either buffer the output or attach before calling start

[cristianrgreco]

Hi @danielbodart, small world!

The delay between the two doesn't matter - when the log stream is requested from Docker we specify to give us logs since the start time of the container.

I'll add that to date I've never heard of/seen of this race condition. I also develop on an OC 13900K and haven't seen it.

If the Ryuk container is failing to start it'll be for some other reason.

I don't use bun and have heard of some incompatibility issues with it and node, same for deno. I'll assume that if you tried to run your test with node instead of bun that it'd work. If not I'd need more info, perhaps some repro.

[kiview]

This reminds me a lot of the race condition on waiting we observed with Bun before:
#807 (comment)

Which seemed to be related to the internal HTTP streaming behavior of Bun:
oven-sh/bun#13696

[cristianrgreco]

Closing as dupe of #807 (comment)

[danielbodart]

Small world indeed! @cristianrgreco

Interesting, thank you for those Bun links @kiview.

Is there a way to make test containers NOT cleanup after itself. As maybe I wasn't clear before but it does work with Bun sometimes but because it cleans up and deletes the test container, I can't get the logs out of the reaper container to compare.

[maxmil]

I'm not sure that this is a dupe of #807 since we are running on a more recent version of test containers and looking at the logs that Dan shared test containers is using the log wait strategy rather than the health check strategy.

Here's another log with DEBUG=testcontainers* set which shows the failure and that "Started" was in the container logs when it was shutdown.

2025-04-04T16:17:05.775Z testcontainers [INFO] [7c0e90e22a4e] Started container for image "testcontainers/ryuk:0.11.0"
2025-04-04T16:17:05.779Z testcontainers [DEBUG] [7c0e90e22a4e] Fetching container logs...
2025-04-04T16:17:05.780Z testcontainers [DEBUG] [7c0e90e22a4e] Waiting for container to be ready...
2025-04-04T16:17:05.780Z testcontainers [DEBUG] [7c0e90e22a4e] Waiting for log message "/.*Started.*/"...
2025-04-04T16:17:05.780Z testcontainers [DEBUG] [7c0e90e22a4e] Fetching container logs...
2025-04-04T16:17:05.782Z testcontainers [DEBUG] [7c0e90e22a4e] Demuxing stream...
2025-04-04T16:17:05.782Z testcontainers [DEBUG] [7c0e90e22a4e] Demuxed stream
2025-04-04T16:17:05.783Z testcontainers [DEBUG] [7c0e90e22a4e] Demuxing stream...
2025-04-04T16:17:05.783Z testcontainers [DEBUG] [7c0e90e22a4e] Demuxed stream
2025-04-04T16:18:05.782Z testcontainers [ERROR] [7c0e90e22a4e] Log message "/.*Started.*/" not received after 60000ms
2025-04-04T16:18:05.782Z testcontainers [ERROR] [7c0e90e22a4e] Container failed to be ready: Error: Log message "/.*Started.*/" not received after 60000ms
2025-04-04T16:18:05.783Z testcontainers [DEBUG] [7c0e90e22a4e] Stopping container...
2025-04-04T16:18:05.794Z testcontainers [DEBUG] [7c0e90e22a4e] Log wait strategy complete
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:17:05.775Z level=INFO msg=starting connection_timeout=1m0s reconnection_timeout=10s request_timeout=10s shutdown_timeout=10m0s remove_retries=10 retry_offset=-1s changes_retry_interval=1s port=8080 verbose=false
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:17:05.775Z level=INFO msg=Started address=[::]:8080
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:17:05.775Z level=INFO msg="client processing started"
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:18:05.792Z level=INFO msg="prune check" clients=0
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:18:05.792Z level=INFO msg="client processing stopped"
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:18:05.792Z level=INFO msg=removed containers=0 networks=0 volumes=0 images=0
2025-04-04T16:18:05.795Z testcontainers:containers [7c0e90e22a4e] time=2025-04-04T16:18:05.792Z level=INFO msg=done

I haven't debugged but reading the code I think that start time is not defined in this case which means it does not download all the container logs.

[cristianrgreco]

Is there a way to make test containers NOT cleanup after itself. As maybe I wasn't clear before but it does work with Bun sometimes but because it cleans up and deletes the test container, I can't get the logs out of the reaper container to compare.

You can disable the resource reaper by setting the env var TESTCONTAINERS_RYUK_DISABLED=true.

You can see all container logs (including the reaper container) by setting the env var DEBUG=testcontainers:containers.

since we are running on a more recent version of test containers and looking at the logs that Dan shared test containers is using the log wait strategy rather than the health check strategy.

There hasn't been any fix in more recent versions of Testcontainers because there's nothing to fix. The reaper container is meant to use the log wait strategy instead of the health check strategy because it supports additional container runtimes like rancher and Colima.

I haven't debugged but reading the code I think that start time is not defined in this case which means it does not download all the container logs.

Indeed it is not defined which defaults to the container start time (0), meaning it does download all the logs. If a start time is defined then we get a subset of the logs. This is used for example for container restarts where we don't want to stream logs from before the container was restarted.

As I said I'm fairly certain this is an issue with bun, as this almost certainly would have come up before over the last few years if it were as you say (CICD must've executed this flow 10,000s of times by now). If you still have doubts then as I said try it with node and if it still fails then share a repro.

[danielbodart]

Here you go, here is a very simple example showing the race condition

https://github.com/danielbodart/bun-test-containers-race-condition.

I don't think you will ever see this in node as I don't think node can execute quick enough to catch this edge case.

In the repo I can make the problem always happen and I can make it always work so it should be a good starting place to work out what is the problem. Maybe it's actually a bug in Bun, maybe testcontainers or maybe even dockerode / Docker. But at least now it's super easy to reproduce and debug

[danielbodart]

I'd done a pull request in this space: #977

[cristianrgreco]

I've had a look and it does seem a dupe of #807.

---

If you ensure that the Ryuk container is not running before a single test run, the test will fail almost 100%_ of the time.

The summary of my findings is that there is some incompatibility between the way Docker streams the logs, and the way Bun handles the log stream. I say this for 2 reasons:

1. The Bun stream API isn't 100% node compatible, and this issue does not occur at all with Node.
2. If you run the test against Podman instead of Docker, the test passes 100% of the time.

It seems then that the fix needs to happen in either Docker or Bun (oven-sh/bun#13696).

I've tried fiddling with the way the stream is created, trying to push additional data through to see if it triggers the previous logs to come through, etc, and had no luck. If there's a way to get it to work it'll probably be some workaround, such as not following the logs, and instead polling them at an interval, but that's not ideal.

If you find a good workaround then I'll happily accept a PR.

[danielbodart]

So I have found a "fix" or at least a way to make the timing issues go away. Firstly I am not suggesting this as a change to your library, more recording this for future posperity!

I was following the rabbit down the whole, and started looking at Dockerode code, which thankfully also links to Dockers API docs.

For the logs method they link to here

And for the follow parameter they then link to the docs for attach

And I noticed that attach has two parameters: logs for historic, and stream for future.

So I though I wonder if the problem goes away if you swtich from using dockerode logs method to using the attach. And sure enough it does!

So instead of this inside DockerContainerClient.logs

    container
      .logs({
        follow: true,
        stdout: true,
        stderr: true,
        tail: opts?.tail ?? -1,
        since: opts?.since ?? 0,
      })

You write this

  container
      .attach({
        logs: true,
        stream: true,
        stdout: true,
        stderr: true,
      })

Then no output is missed.

As I said I am not suggesting you make this change, as this does appear to be a race condition in the Docker API (not even dockerode).

Time to go deeper and look at the Go code for Docker API

This correlates with your statement:

if you run the test against Podman instead of Docker, the test passes 100% of the time.

@cristianrgreco does this mean there is a simple of making testcontainers use podman instead of docker?

[cristianrgreco]

Interesting finding!

@cristianrgreco does this mean there is a simple of making testcontainers use podman instead of docker?

Yep, it's just a case of setting up Podman and exposing an env var. Check out the Podman/Linux section here: https://node.testcontainers.org/supported-container-runtimes/