|
| 1 | +# Logging |
| 2 | + |
| 3 | +It would be nice to see what Testcontainers is doing while the test is running. You can enable all logs by setting the `DEBUG` environment variable. For example: |
| 4 | + |
| 5 | +```bash |
| 6 | +DEBUG=testcontainers* npm test |
| 7 | +``` |
| 8 | + |
| 9 | +If we run the test again, we'll see a lot of debug output: |
| 10 | + |
| 11 | +``` |
| 12 | +[DEBUG] Checking container runtime strategy "UnixSocketStrategy"... |
| 13 | +[TRACE] Fetching Docker info... |
| 14 | +[TRACE] Fetching remote container runtime socket path... |
| 15 | +[TRACE] Resolving host... |
| 16 | +[TRACE] Fetching Compose info... |
| 17 | +[TRACE] Looking up host IPs... |
| 18 | +[TRACE] Initialising clients... |
| 19 | +[TRACE] Container runtime info: |
| 20 | +{ |
| 21 | + "node": { |
| 22 | + "version": "v22.14.0", |
| 23 | + "architecture": "x64", |
| 24 | + "platform": "linux" |
| 25 | + }, |
| 26 | + "containerRuntime": { |
| 27 | + "host": "localhost", |
| 28 | + "hostIps": [ |
| 29 | + { |
| 30 | + "address": "127.0.0.1", |
| 31 | + "family": 4 |
| 32 | + } |
| 33 | + ], |
| 34 | + "remoteSocketPath": "/var/run/docker.sock", |
| 35 | + "indexServerAddress": "https://index.docker.io/v1/", |
| 36 | + "serverVersion": "28.0.1", |
| 37 | + "operatingSystem": "Docker Desktop", |
| 38 | + "operatingSystemType": "linux", |
| 39 | + "architecture": "x86_64", |
| 40 | + "cpus": 32, |
| 41 | + "memory": 33524871168, |
| 42 | + "runtimes": [ |
| 43 | + "io.containerd.runc.v2", |
| 44 | + "nvidia", |
| 45 | + "runc" |
| 46 | + ], |
| 47 | + "labels": [ |
| 48 | + "com.docker.desktop.address=unix:///var/run/docker-cli.sock" |
| 49 | + ] |
| 50 | + }, |
| 51 | + "compose": { |
| 52 | + "version": "2.33.1-desktop.1", |
| 53 | + "compatability": "v2" |
| 54 | + } |
| 55 | +} |
| 56 | +[DEBUG] Container runtime strategy "UnixSocketStrategy" works |
| 57 | +[DEBUG] Checking if image exists "redis:latest"... |
| 58 | +[DEBUG] Checked if image exists "redis:latest" |
| 59 | +[DEBUG] Pulling image "redis:latest"... |
| 60 | +[DEBUG] Executing Docker credential provider "docker-credential-desktop.exe" |
| 61 | +[DEBUG] Auth config found for registry "https://index.docker.io/v1/": CredsStore |
| 62 | +[redis:latest] {"status":"Pulling from library/redis","id":"latest"} |
| 63 | +[redis:latest] {"status":"Pulling fs layer","progressDetail":{},"id":"6e909acdb790"} |
| 64 | +... |
| 65 | +[redis:latest] {"status":"Status: Downloaded newer image for redis:latest"} |
| 66 | +[DEBUG] Pulled image "redis:latest" |
| 67 | +[DEBUG] Acquiring lock file "/tmp/testcontainers-node.lock"... |
| 68 | +[DEBUG] Acquired lock file "/tmp/testcontainers-node.lock" |
| 69 | +[DEBUG] Listing containers... |
| 70 | +[DEBUG] Listed containers |
| 71 | +[DEBUG] Creating new Reaper for session "4c81d4efc176" with socket path "/var/run/docker.sock"... |
| 72 | +[DEBUG] Checking if image exists "testcontainers/ryuk:0.11.0"... |
| 73 | +[DEBUG] Checked if image exists "testcontainers/ryuk:0.11.0" |
| 74 | +[DEBUG] Image "testcontainers/ryuk:0.11.0" already exists |
| 75 | +[DEBUG] Creating container for image "testcontainers/ryuk:0.11.0"... |
| 76 | +[DEBUG] [11a9d12ea231] Created container for image "testcontainers/ryuk:0.11.0" |
| 77 | +[INFO] [11a9d12ea231] Starting container for image "testcontainers/ryuk:0.11.0"... |
| 78 | +[DEBUG] [11a9d12ea231] Starting container... |
| 79 | +[DEBUG] [11a9d12ea231] Started container |
| 80 | +[INFO] [11a9d12ea231] Started container for image "testcontainers/ryuk:0.11.0" |
| 81 | +[DEBUG] [11a9d12ea231] Fetching container logs... |
| 82 | +[DEBUG] [11a9d12ea231] Demuxing stream... |
| 83 | +[DEBUG] [11a9d12ea231] Demuxed stream |
| 84 | +[DEBUG] [11a9d12ea231] Fetched container logs |
| 85 | +[DEBUG] [11a9d12ea231] Waiting for container to be ready... |
| 86 | +[DEBUG] [11a9d12ea231] Waiting for log message "/.*Started.*/"... |
| 87 | +[DEBUG] [11a9d12ea231] Fetching container logs... |
| 88 | +[11a9d12ea231] time=2025-03-24T12:10:17.130Z 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 |
| 89 | +[11a9d12ea231] time=2025-03-24T12:10:17.130Z level=INFO msg=Started address=[::]:8080 |
| 90 | +[11a9d12ea231] time=2025-03-24T12:10:17.130Z level=INFO msg="client processing started" |
| 91 | +[DEBUG] [11a9d12ea231] Demuxing stream... |
| 92 | +[DEBUG] [11a9d12ea231] Demuxed stream |
| 93 | +[DEBUG] [11a9d12ea231] Fetched container logs |
| 94 | +[DEBUG] [11a9d12ea231] Log wait strategy complete |
| 95 | +[INFO] [11a9d12ea231] Container is ready |
| 96 | +[DEBUG] [11a9d12ea231] Connecting to Reaper (attempt 1) on "localhost:32774"... |
| 97 | +[DEBUG] [11a9d12ea231] Connected to Reaper |
| 98 | +[DEBUG] Releasing lock file "/tmp/testcontainers-node.lock"... |
| 99 | +[DEBUG] Released lock file "/tmp/testcontainers-node.lock" |
| 100 | +[DEBUG] Creating container for image "redis:latest"... |
| 101 | +[11a9d12ea231] time=2025-03-24T12:10:17.145Z level=INFO msg="client connected" address=172.17.0.1:40446 clients=1 |
| 102 | +[11a9d12ea231] time=2025-03-24T12:10:17.145Z level=INFO msg="adding filter" type=label values="[org.testcontainers.session-id=4c81d4efc176]" |
| 103 | +[936d82e9964e] Created container for image "redis:latest" |
| 104 | +[936d82e9964e] Starting container for image "redis:latest"... |
| 105 | +[936d82e9964e] Starting container... |
| 106 | +[936d82e9964e] Started container |
| 107 | +[936d82e9964e] Started container for image "redis:latest" |
| 108 | +[936d82e9964e] Fetching container logs... |
| 109 | +[936d82e9964e] Demuxing stream... |
| 110 | +[936d82e9964e] Demuxed stream |
| 111 | +[936d82e9964e] Fetched container logs |
| 112 | +[936d82e9964e] Waiting for container to be ready... |
| 113 | +[936d82e9964e] Waiting for host port 32775... |
| 114 | +[936d82e9964e] Waiting for internal port 6379... |
| 115 | +[936d82e9964e] 1:C 24 Mar 2025 12:10:17.419 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo |
| 116 | +[936d82e9964e] 1:C 24 Mar 2025 12:10:17.419 * Redis version=7.4.2, bits=64, commit=00000000, modified=0, pid=1, just started |
| 117 | +[936d82e9964e] 1:C 24 Mar 2025 12:10:17.419 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf |
| 118 | +[936d82e9964e] 1:M 24 Mar 2025 12:10:17.419 * monotonic clock: POSIX clock_gettime |
| 119 | +[936d82e9964e] 1:M 24 Mar 2025 12:10:17.419 * Running mode=standalone, port=6379. |
| 120 | +[936d82e9964e] 1:M 24 Mar 2025 12:10:17.420 * Server initialized |
| 121 | +[936d82e9964e] 1:M 24 Mar 2025 12:10:17.420 * Ready to accept connections tcp |
| 122 | +[DEBUG] [936d82e9964e] Host port 32775 ready |
| 123 | +[DEBUG] [936d82e9964e] Host port wait strategy complete |
| 124 | +[DEBUG] [936d82e9964e] Internal port 6379 ready |
| 125 | +[INFO] [936d82e9964e] Container is ready |
| 126 | +[INFO] [936d82e9964e] Stopping container... |
| 127 | +[DEBUG] [936d82e9964e] Stopping container... |
| 128 | +[936d82e9964e] 1:signal-handler (1742818217) Received SIGTERM scheduling shutdown... |
| 129 | +[DEBUG] [936d82e9964e] Stopped container |
| 130 | +[DEBUG] [936d82e9964e] Removing container... |
| 131 | +[DEBUG] [936d82e9964e] Removed container |
| 132 | +[INFO] [936d82e9964e] Stopped container |
| 133 | +``` |
| 134 | + |
| 135 | +These logs are very useful for debugging when a container isn't working as expected. You can see there are logs from the Testcontainers library, as well as logs emitted from all Testcontainers-managed containers. |
0 commit comments