testcontainers-node: Cannot connect to Reaper with log wait strategy when using Rancher Desktop

Outline

• Since Version 8.7.0 we seem to encounter race-conditions while starting the container postgres:10.
• Only around 15% of starts of a test container are sucessful.
• The run actual container may not be the issue however, since the logs indicate, that it may not be responsible.

Expected Behaviour

• Container starts normally.

Actual Behaviour

• Test-Containers cannot connect to the “Reaper” container.
• The released package 8.6.1 worked just fine
• Starting with released npm package 8.6.2-beta.0 the problems were introduced.
• The same faulty behaviour can be confirmed with packages 8.7.0 and 8.8.0

Workaround Use version 8.6.1.

Testcontainer Logs FAULTY Version: 8.7.0

  testcontainers DEBUG Found .testcontainers.properties file +0ms
  testcontainers DEBUG Found applicable Docker client strategy: UnixSocketStrategy +15ms
  testcontainers DEBUG Testing Docker client strategy URI: unix:///var/run/docker.sock +166ms
  testcontainers DEBUG No registry auth locator found for registry: "https://index.docker.io/v1/" +19ms
  testcontainers INFO  Using Docker client strategy: UnixSocketStrategy, Docker host: localhost +12ms
  testcontainers DEBUG Not pulling image as it already exists: postgres:10 +16ms
  testcontainers DEBUG Creating new Reaper for session: cdb3787427d99e29d797c56ec048235e +1ms
  testcontainers DEBUG Re-using cached auth for registry https://index.docker.io/v1/ +0ms
  testcontainers DEBUG Not pulling image as it already exists: testcontainers/ryuk:0.3.2 +12ms
  testcontainers INFO  Creating container for image: testcontainers/ryuk:0.3.2 +1ms
  testcontainers WARN  Unable to detect docker-compose version, is it installed? Error: spawn docker-compose ENOENT +57ms
  testcontainers DEBUG System diagnostics: {"node":{"version":"v14.19.0","architecture":"x64","platform":"darwin"},"docker":{"serverVersion":"20.10.11","operatingSystem":"Alpine Linux v3.14","operatingSystemType":"linux","architecture":"x86_64","cpus":2,"memory":4134436864}} +1ms
  testcontainers INFO  Starting container testcontainers/ryuk:0.3.2 with ID: d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665 +49ms
  testcontainers:containers TRACE d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665: 2022/05/03 06:28:34 Pinging Docker... +0ms
  testcontainers:containers TRACE d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665: 2022/05/03 06:28:34 Docker daemon is available! +0ms
  testcontainers:containers TRACE d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665: 2022/05/03 06:28:34 Starting on port 8080... +0ms
  testcontainers:containers TRACE d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665: 2022/05/03 06:28:34 Started! +0ms
  testcontainers DEBUG Waiting for container to be ready: d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665 +383ms
  testcontainers DEBUG Waiting for log message "/.+ Started!/" +1ms
  testcontainers INFO  Container is ready +5ms
  testcontainers DEBUG Connecting to Reaper d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665 on localhost:49434 +0ms
  testcontainers ERROR Reaper d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665 socket error: Error: connect ECONNREFUSED 127.0.0.1:49434 +4ms
  testcontainers ERROR Connection to Reaper d317bc41f51ffaa3ef6b1f38ad8e025d41282e26960b28c5a9a788205084d665 closed with error +1ms

WORKING Version 8.6.1

  testcontainers DEBUG Found .testcontainers.properties file +0ms
  testcontainers DEBUG Found applicable Docker client strategy: UnixSocketStrategy +16ms
  testcontainers DEBUG Testing Docker client strategy URI: unix:///var/run/docker.sock +164ms
  testcontainers DEBUG No registry auth locator found for registry: "https://index.docker.io/v1/" +15ms
  testcontainers INFO  Using Docker client strategy: UnixSocketStrategy, Docker host: localhost +7ms
  testcontainers DEBUG Not pulling image as it already exists: postgres:10 +12ms
  testcontainers DEBUG Creating new Reaper for session: 2fdb355e7be4df7f1806f39601b46016 +0ms
  testcontainers DEBUG Re-using cached auth for registry https://index.docker.io/v1/ +0ms
  testcontainers DEBUG Not pulling image as it already exists: testcontainers/ryuk:0.3.2 +8ms
  testcontainers INFO  Creating container for image: testcontainers/ryuk:0.3.2 +0ms
  testcontainers WARN  Unable to detect docker-compose version, is it installed? Error: spawn docker-compose ENOENT +56ms
  testcontainers DEBUG System diagnostics: {"node":{"version":"v14.19.0","architecture":"x64","platform":"darwin"},"docker":{"serverVersion":"20.10.11","operatingSystem":"Alpine Linux v3.14","operatingSystemType":"linux","architecture":"x86_64","cpus":2,"memory":4134436864}} +0ms
  testcontainers INFO  Starting container testcontainers/ryuk:0.3.2 with ID: 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +2ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Pinging Docker... +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Docker daemon is available! +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Starting on port 8080... +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Started! +1ms
  testcontainers DEBUG Waiting for container to be ready: 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +423ms
  testcontainers DEBUG Waiting for host port 49435 for 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +1ms
  testcontainers DEBUG Waiting for internal port 8080 for 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +1ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 New client connected: 127.0.0.1:43461 +216ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Received the first connection +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 EOF +3ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:09 Client disconnected: 127.0.0.1:43461 +1ms
  testcontainers DEBUG Internal port 8080 ready for 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +438ms
  testcontainers DEBUG Host port 49435 ready for 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +717ms
  testcontainers INFO  Container is ready +0ms
  testcontainers DEBUG Connecting to Reaper 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d on localhost:49435 +0ms
  testcontainers DEBUG Connected to Reaper 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d +1ms
  testcontainers INFO  Creating container for image: postgres:10 +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:10 New client connected: 172.17.0.1:55396 +945ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:10 EOF +1ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:10 Client disconnected: 172.17.0.1:55396 +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:10 New client connected: 172.17.0.1:55400 +0ms
  testcontainers:containers TRACE 36cdb67891722f762f59138c031d4181d47b1ba84e3294a3f7d9a5e03d953b7d: 2022/05/03 06:32:10 Adding {"label":{"org.testcontainers.session-id=2fdb355e7be4df7f1806f39601b46016":true}} +0ms
  testcontainers INFO  Starting container postgres:10 with ID: 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +95ms
  testcontainers DEBUG Waiting for container to be ready: 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +508ms
  testcontainers DEBUG Waiting for host port 49436 for 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +0ms
  testcontainers DEBUG Waiting for internal port 5432 for 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: The files belonging to this database system will be owned by user "postgres". +636ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: This user must also own the server process. +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: The database cluster will be initialized with locale "en_US.utf8". +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: The default database encoding has accordingly been set to "UTF8". +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: The default text search configuration will be set to "english". +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: Data page checksums are disabled. +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: fixing permissions on existing directory /var/lib/postgresql/data ... ok +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: creating subdirectories ... ok +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: selecting default max_connections ... 100 +14ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: selecting default shared_buffers ... 128MB +34ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: selecting default timezone ... Etc/UTC +20ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: selecting dynamic shared memory implementation ... posix +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: creating configuration files ... ok +15ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: running bootstrap script ... ok +357ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: performing post-bootstrap initialization ... ok +2s
  testcontainers DEBUG Host port 49436 ready for 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +2s
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: syncing data to disk ... ok +968ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: Success. You can now start the database server using: +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: pg_ctl -D /var/lib/postgresql/data -l logfile start +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +6ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: WARNING: enabling "trust" authentication for local connections +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: You can change this by editing pg_hba.conf or using the option -A, or +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: --auth-local and --auth-host, the next time you run initdb. +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: waiting for server to start....2022-05-03 06:32:14.165 UTC [118] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" +57ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:14.187 UTC [119] LOG:  database system was shut down at 2022-05-03 06:32:13 UTC +23ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:14.193 UTC [118] LOG:  database system is ready to accept connections +9ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: done +44ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: server started +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: CREATE DATABASE +780ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +4ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/* +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.026 UTC [118] LOG:  received fast shutdown request +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: waiting for server to shut down....2022-05-03 06:32:15.029 UTC [118] LOG:  aborting any active transactions +3ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.032 UTC [118] LOG:  worker process: logical replication launcher (PID 125) exited with exit code 1 +3ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.033 UTC [120] LOG:  shutting down +1ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.053 UTC [118] LOG:  database system is shut down +21ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: done +77ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: server stopped +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: PostgreSQL init process complete; ready for start up. +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876:  +0ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.144 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432 +14ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.144 UTC [1] LOG:  listening on IPv6 address "::", port 5432 +0ms
  2022-05-03 08:32:21.644 testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.148 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" +3ms
  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.166 UTC [184] LOG:  database system was shut down at 2022-05-03 06:32:15 UTC +20ms

TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.172 UTC [1] LOG:  database system is ready to accept connections +4ms {"parameters":null}

  testcontainers:containers TRACE 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876: 2022-05-03 06:32:15.552 UTC [213] LOG:  incomplete startup packet +382ms
  testcontainers DEBUG Internal port 5432 ready for 94a2f3b77cef743499996483cae06ee593dde68d46b0b1466b2e7e83f322d876 +2s
  testcontainers INFO  Container is ready +0ms

Steps to Reproduce

1. The problems only appear on our developer machines, running MacOS BigSur. Build systems running on an EC-Instanz using amzn2-ami-hvm-2.0.20210427.0-x86_64-gp2 does not seem to be effected though, since executions never failed so far.
2. Run ‘…’

   const container = await new GenericContainer("postgres:10")
   .withExposedPorts(5432)
   .withEnv("POSTGRES_USER", "root-test-container")
   .withEnv("POSTGRES_PASSWORD", "abcdefg")
   .start();
   

3. Error logs appears rather quickly.

Environment Information

• Operating System: MacOS 11.6.5 BigSur
• Docker Version: Rancher Desktop v2.6.3.beta.12
• Node version: 14.19.0
• Testcontainers version: 8.7.0