Testcontainers not able to read container logs when using with podman

[sureshgadupu]

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description
I am trying to use Podman (version 4.2) instead of Docker to run the tests with Testcontainers.
I am trying to start the RabbitMQ containers with following code

static {
        rabbitMQContainer = new RabbitMQContainer("rabbitmq:3.10.6-management-alpine")
                .withStartupTimeout(Duration.of(100, SECONDS));
        rabbitMQContainer.start();

    }

Describe the results you received:

Testcontainer is recognizing the Podman as docker environment but failing to recognize the container strartup based on the log messages.
org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*Server startup complete.*'

.testcontainer.properties

docker.client.strategy=org.testcontainers.dockerclient.NpipeSocketClientProviderStrategy
DOCKER_HOST = npipe:////./pipe/podman-machine-default

It seems testcontainers is unable to read the logs from the container with docker compatible API

01:47:18.283 [docker-java-stream--3447464] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "{"cause":"using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported","message":"failed to obtain logs for Container '0f95cf80e0d2030b8d7f4c2d01d3c882ac438b068a13b72e47f14ace05040e71': using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported","response":500}[\n]"

Describe the results you expected:

I am expecting testcontainers should be able to read container logs to identify the successful startup of container.

Additional information you deem important (e.g. issue happens only occasionally):

Output of podman version:

Client:       Podman Engine
Version:      4.2.0
API Version:  4.2.0
Go Version:   go1.16.15
Git Commit:   7fe5a419cfd2880df2028ad3d7fd9378a88a04f4
Built:        Fri Aug 12 02:20:57 2022
OS/Arch:      windows/amd64

Server:       Podman Engine
Version:      4.1.1
API Version:  4.1.1
Go Version:   go1.18.4
Built:        Sat Jul 23 07:05:59 2022
OS/Arch:      linux/amd64

Output of podman info:

host:
  arch: amd64
  buildahVersion: 1.26.1
  cgroupControllers: []
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: conmon-2.1.0-2.fc36.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.0, commit: '
  cpuUtilization:
    idlePercent: 99.71
    systemPercent: 0.16
    userPercent: 0.13
  cpus: 2
  distribution:
    distribution: fedora
    variant: container
    version: "36"
  eventLogger: file
  hostname: DESKTOP-I2JE5RO
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 5.10.102.1-microsoft-standard-WSL2
  linkmode: dynamic
  logDriver: journald
  memFree: 326529024
  memTotal: 948813824
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun-1.5-1.fc36.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.5
      commit: 54ebb8ca8bf7e6ddae2eb919f5b82d1d96863dea
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    exists: true
    path: /run/user/1000/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: true
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: false
  serviceIsRemote: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.2.0-0.2.beta.0.fc36.x86_64
    version: |-
      slirp4netns version 1.2.0-beta.0
      commit: 477db14a24ff1a3de3a705e51ca2c4c1fe3dda64
      libslirp: 4.6.1
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.3
  swapFree: 1051947008
  swapTotal: 1073741824
  uptime: 24h 47m 49.01s (Approximately 1.00 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - docker.io
  - quay.io
store:
  configFile: /home/user/.config/containers/storage.conf
  containerStore:
    number: 6
    paused: 0
    running: 0
    stopped: 6
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/user/.local/share/containers/storage
  graphRootAllocated: 269490393088
  graphRootUsed: 1740734464
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 5
  runRoot: /run/user/1000/containers
  volumePath: /home/user/.local/share/containers/storage/volumes
version:
  APIVersion: 4.1.1
  Built: 1658516759
  BuiltTime: Sat Jul 23 07:05:59 2022
  GitCommit: ""
  GoVersion: go1.18.4
  Os: linux
  OsArch: linux/amd64
  Version: 4.1.1

Package info (e.g. output of rpm -q podman or apt list podman):

(paste your output here)

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide? (https://github.com/containers/podman/blob/main/troubleshooting.md)

Yes

Additional environment details (AWS, VirtualBox, physical, etc.):

[mheon]

Any details on the HTTP API requests that Testcontainers is making? Running podman system service -t 0 --log-level=trace instead of using the systemd-managed Podman socket ought to print details about the requests being made

[sureshgadupu]

If I run podman system service -t 0 --log-level=trace command , I am getting following error

Error: unknown shorthand flag: 't' in -t
See 'podman.exe system --help'

If I run podman system service --log-level=trace command
I am getting below output

time="2022-08-27T19:43:37+12:00" level=info msg="C:\\Program Files\\RedHat\\Podman\\podman.exe filtering at log level trace"
time="2022-08-27T19:43:37+12:00" level=debug msg="Called system.PersistentPreRunE(C:\\Program Files\\RedHat\\Podman\\podman.exe system service --log-level=trace)"
Error: unrecognized command `podman.exe system service`
Try 'podman.exe system --help' for more information

I posted same issue to Testcontainers team and they replied with below answer

it seems the logging subsystem of your podman installation is not correctly set up. The Docker documentation explains the following constraints for usage of the logs API:

Note: This endpoint works only for containers with the json-file or journald logging driver.

I would suggest asking the podman community how to correctly configure the log driver to allow usage of /containers/{id}/logs, I don't think there is anything Testcontainers can do here and it expects to interact with a Docker-compatible API.

[sureshgadupu]

Please find logs which gives api calls information

19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000E: endpoint lease request (3 MINUTES) [route: {}->npipe://localhost:2375][total available: 1; route allocated: 1 of 2147483647; total allocated: 1 of 2147483647]
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000E: endpoint leased [route: {}->npipe://localhost:2375][total available: 0; route allocated: 1 of 2147483647; total allocated: 1 of 2147483647]
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000E: acquired ep-0000000D
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000E: acquired endpoint ep-0000000D
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.MainClientExec - ex-0000000E: executing GET /v1.32/containers/b37afe5618d407b06699dc4743075547696c16b18b03d6323b9bf5eca68c9529/logs?stdout=true&stderr=true&follow=true&since=0 HTTP/1.1
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-0000000D: start execution ex-0000000E
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-0000000D: executing exchange ex-0000000E over http-outgoing-1
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> GET /v1.32/containers/b37afe5618d407b06699dc4743075547696c16b18b03d6323b9bf5eca68c9529/logs?stdout=true&stderr=true&follow=true&since=0 HTTP/1.1
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> x-tc-sid: fbefaf79-52a3-4569-98f7-aa4added9f05
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> Accept-Encoding: gzip, x-gzip, deflate
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> Host: localhost:2375
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> Connection: keep-alive
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.11)
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "GET /v1.32/containers/b37afe5618d407b06699dc4743075547696c16b18b03d6323b9bf5eca68c9529/logs?stdout=true&stderr=true&follow=true&since=0 HTTP/1.1[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "x-tc-sid: fbefaf79-52a3-4569-98f7-aa4added9f05[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "Host: localhost:2375[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "Connection: keep-alive[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.11)[\r][\n]"
19:49:39.927 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 >> "[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "HTTP/1.1 500 Internal Server Error[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Api-Version: 1.40[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Content-Type: application/json[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Libpod-Api-Version: 4.1.1[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Server: Libpod/4.1.1 (linux)[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "X-Reference-Id: 0xc001024658[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Date: Sat, 27 Aug 2022 07:49:39 GMT[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "Content-Length: 367[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "[\r][\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-1 << "{"cause":"using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported","message":"failed to obtain logs for Container 'b37afe5618d407b06699dc4743075547696c16b18b03d6323b9bf5eca68c9529': using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported","response":500}[\n]"
19:49:39.936 [docker-java-stream--282623829] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-1 << HTTP/1.1 500 Internal Server Error

[sureshgadupu]

I was able to resolve the issue after watching the youtube video .

After setting events-backend to k8s-file in /usr/share/containers/container.conf file in virtual machine my tests are running fine.

If you are using Podman version 4.2, no need to change cgroup-manager option