Skip to content

/v1.32/networks/create "failed to respond" #17640

New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Closed
k-wall opened this issue Feb 27, 2023 · 22 comments
Closed

/v1.32/networks/create "failed to respond" #17640

k-wall opened this issue Feb 27, 2023 · 22 comments
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. macos MacOS (OSX) related remote Problem is in podman-remote

Comments

@k-wall
Copy link

k-wall commented Feb 27, 2023

Issue Description

I have a suite of integration tests using testcontainers to automate Apache Kafka tests. Each test creates containers for Kafka and Zookeeper and a Podman Network which is torn down after each test. After succession of several passing tests, I see a /v1.32/networks/create call fail. Podman appears to close the socket without sending a HTTP response.

The problem is 100% repeatable for me and always occurs in exactly the same spot in the test suite.

If I fix a bug in testcontainers that allows it to retry the network POST, the problem disappears.

client:       Podman Engine
Version:      4.4.2
API Version:  4.4.2
Go Version:   go1.20.1
Git Commit:   74afe26887f814d1c39925a1624851ef3590e79c
Built:        Thu Feb 23 15:59:21 2023
OS/Arch:      darwin/amd64

Server:       Podman Engine
Version:      4.4.1
API Version:  4.4.1
Go Version:   go1.19.5
Built:        Thu Feb  9 10:58:53 2023
OS/Arch:      linux/amd64
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.MainClientExec:102 - ex-00000011: executing POST /v1.32/networks/create HTTP/1.1
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection:134 - http-outgoing-0: set socket timeout to 44000000000 NANOSECONDS
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient:213 - ep-00000010: start execution ex-00000011
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager:594 - ep-00000010: executing exchange ex-00000011 over http-outgoing-0
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:169 - http-outgoing-0 >> POST /v1.32/networks/create HTTP/1.1
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> accept: application/json
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> content-type: application/json
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> x-tc-sid: 16246381-601c-4abb-8e67-5cb92c70a7f5
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Accept-Encoding: gzip, x-gzip, deflate
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Content-Length: 363
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Host: localhost:2375
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Connection: keep-alive
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "POST /v1.32/networks/create HTTP/1.1[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "accept: application/json[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "content-type: application/json[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "x-tc-sid: 16246381-601c-4abb-8e67-5cb92c70a7f5[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Content-Length: 363[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Host: localhost:2375[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Connection: keep-alive[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "[\r][\n]"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:106 - http-outgoing-0 >> "{"enableIPv6":null,"Name":"1664a022-9886-424a-8028-65c38b953248","Driver":null,"IPAM":null,"Options":{},"CheckDuplicate":true,"Internal":null,"EnableIPv6":null,"Attachable":null,"Labels":{"org.testcontainers":"true","org.testcontainers.lang":"java","org.testcontainers.version":"unspecified","org.testcontainers.sessionId":"16246381-601c-4abb-8e67-5cb92c70a7f5"}}"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:106 - http-outgoing-0 << "end of stream"
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection:125 - http-outgoing-0: Close connection
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient:239 - ep-00000010: endpoint closed
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient:243 - ep-00000010: discarding endpoint
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager:349 - ep-00000010: releasing endpoint
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager:372 - ep-00000010: connection is not kept alive
2023-02-26 19:29:55 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager:381 - ep-00000010: connection released [route: {}->unix://localhost:2375][total available: 1; route allocated: 1 of 2147483647; total allocated: 1 of 2147483647]
2023-02-26 19:29:55 ERROR 🐳 [quay.io/ogunalp/kafka-native:latest-snapshot]:535 - Could not start container
java.lang.RuntimeException: com.github.dockerjava.zerodep.shaded.org.apache.hc.core5.http.NoHttpResponseException: localhost:2375 failed to respond
	at com.github.dockerjava.zerodep.ApacheDockerHttpClientImpl.execute(ApacheDockerHttpClientImpl.java:195) ~[docker-java-transport-zerodep-3.3.0.jar:?]
	at com.github.dockerjava.zerodep.ZerodepDockerHttpClient.execute(ZerodepDockerHttpClient.java:8) ~[docker-java-transport-zerodep-3.3.0.jar:?]
	at org.testcontainers.dockerclient.HeadersAddingDockerHttpClient.execute(HeadersAddingDockerHttpClient.java:23) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.execute(DefaultInvocationBuilder.java:228) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.post(DefaultInvocationBuilder.java:124) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.exec.CreateNetworkCmdExec.execute(CreateNetworkCmdExec.java:27) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.exec.CreateNetworkCmdExec.execute(CreateNetworkCmdExec.java:12) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.exec.AbstrSyncDockerCmdExec.exec(AbstrSyncDockerCmdExec.java:21) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.shaded.com.github.dockerjava.core.command.AbstrDockerCmd.exec(AbstrDockerCmd.java:35) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.Network$NetworkImpl.create(Network.java:100) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.Network$NetworkImpl.getId(Network.java:64) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.GenericContainer.applyConfiguration(GenericContainer.java:874) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:378) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:344) ~[testcontainers-unspecified.jar:unspecified]
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81) ~[duct-tape-1.0.8.jar:?]
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:334) ~[testcontainers-unspecified.jar:unspecified]
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322) ~[testcontainers-unspecified.jar:unspecified]
	at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:783) ~[?:?]
	at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:829) ~[?:?]

Steps to reproduce the issue

I haven't yet been able to reproduce the issue outside test suite. There's something about the workload of the test that appears to trip the defect.

Steps to reproduce the issue

  1. git clone https://github.com/k-wall/kroxylicious-junit5-extension/tree/minimal
  2. TESTCONTAINERS_RYUK_DISABLED=true mvn clean verify -Dmaven.javadoc.skip=true #Use OpenJDK 11
  3. StaticFieldSubclassExtensionTest will fail with the failed network creation call.
  4. Commenting out any test from TemplateTest will allow the test to succeed

Describe the results you received

No response to network creation HTTP request.

Describe the results you expected

Network created successfully.

podman info output

podman info
host:
  arch: amd64
  buildahVersion: 1.29.0
  cgroupControllers:
  - cpu
  - io
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.5-1.fc37.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.5, commit: '
  cpuUtilization:
    idlePercent: 95.76
    systemPercent: 2.6
    userPercent: 1.64
  cpus: 1
  distribution:
    distribution: fedora
    variant: coreos
    version: "37"
  eventLogger: journald
  hostname: localhost.localdomain
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 1000000
    uidmap:
    - container_id: 0
      host_id: 501
      size: 1
    - container_id: 1
      host_id: 100000
      size: 1000000
  kernel: 6.1.11-200.fc37.x86_64
  linkmode: dynamic
  logDriver: journald
  memFree: 74768384
  memTotal: 2065817600
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun-1.8-1.fc37.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.8
      commit: 0356bf4aff9a133d655dc13b1d9ac9424706cac4
      rundir: /run/user/501/crun
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +LIBKRUN +WASM:wasmedge +YAJL
  os: linux
  remoteSocket:
    exists: true
    path: /run/user/501/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
    rootless: true
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: true
  serviceIsRemote: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.2.0-8.fc37.x86_64
    version: |-
      slirp4netns version 1.2.0
      commit: 656041d45cfca7a4176f6b7eed9e4fe6c11e8383
      libslirp: 4.7.0
      SLIRP_CONFIG_VERSION_MAX: 4
      libseccomp: 2.5.3
  swapFree: 0
  swapTotal: 0
  uptime: 22h 9m 22.00s (Approximately 0.92 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - docker.io
store:
  configFile: /var/home/core/.config/containers/storage.conf
  containerStore:
    number: 1
    paused: 0
    running: 0
    stopped: 1
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /var/home/core/.local/share/containers/storage
  graphRootAllocated: 106769133568
  graphRootUsed: 4927156224
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 3
  runRoot: /run/user/501/containers
  transientStore: false
  volumePath: /var/home/core/.local/share/containers/storage/volumes
version:
  APIVersion: 4.4.1
  Built: 1675940333
  BuiltTime: Thu Feb  9 10:58:53 2023
  GitCommit: ""
  GoVersion: go1.19.5
  Os: linux
  OsArch: linux/amd64
  Version: 4.4.1

Podman in a container

No

Privileged Or Rootless

Rootless

Upstream Latest Release

No

Additional environment details

Additional environment details

Additional information

Additional information like issue happens only occasionally or issue happens with a particular architecture or on a particular setting

I checked the podman machine's journalctl, I see nothing suspicious in that log.

podman-machine-journalctl.txt

@k-wall k-wall added the kind/bug Categorizes issue or PR as related to a bug. label Feb 27, 2023
@github-actions github-actions bot added macos MacOS (OSX) related remote Problem is in podman-remote labels Feb 27, 2023
@Luap99
Copy link
Member

Luap99 commented Feb 27, 2023

If you make a single network create call from that java library does it work?

Your jounald output seems incomplete (at least it did not log the API calls from your testsuite), You can filter the podman output with journalctl --user -u podman.service, there might be clue hidden there why the connection was closed.

@k-wall
Copy link
Author

k-wall commented Mar 1, 2023

If you make a single network create call from that java library does it work?

Yes, ordinarily it works without issue. Earlier in the tests I see client side output like this:

2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.MainClientExec:102 - ex-00000004: executing POST /v1.32/networks/create HTTP/1.1
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient:213 - ep-00000003: start execution ex-00000004
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager:594 - ep-00000003: executing exchange ex-00000004 over http-outgoing-0
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:169 - http-outgoing-0 >> POST /v1.32/networks/create HTTP/1.1
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> accept: application/json
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> content-type: application/json
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> x-tc-sid: e7ba0cb9-b301-430e-9adf-8267e11f6737
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Accept-Encoding: gzip, x-gzip, deflate
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Content-Length: 358
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Host: localhost:2375
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> Connection: keep-alive
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-0 >> User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "POST /v1.32/networks/create HTTP/1.1[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "accept: application/json[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "content-type: application/json[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "x-tc-sid: e7ba0cb9-b301-430e-9adf-8267e11f6737[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Content-Length: 358[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Host: localhost:2375[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "Connection: keep-alive[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 >> "[\r][\n]"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:106 - http-outgoing-0 >> "{"enableIPv6":null,"Name":"9bc472c9-291c-44a7-ad7c-162d49f5d616","Driver":null,"IPAM":null,"Options":{},"CheckDuplicate":true,"Internal":null,"EnableIPv6":null,"Attachable":null,"Labels":{"org.testcontainers":"true","org.testcontainers.lang":"java","org.testcontainers.version":"1.17.6","org.testcontainers.sessionId":"e7ba0cb9-b301-430e-9adf-8267e11f6737"}}"
2023-03-01 12:05:13 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-0 << "HTTP/1.1 201 Created[\r][\n]"

but then later I see a failure like this.

2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:169 - http-outgoing-2 >> POST /v1.32/networks/create HTTP/1.1
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> accept: application/json
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> content-type: application/json
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> x-tc-sid: e7ba0cb9-b301-430e-9adf-8267e11f6737
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> Accept-Encoding: gzip, x-gzip, deflate
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> Content-Length: 358
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> Host: localhost:2375
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> Connection: keep-alive
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers:172 - http-outgoing-2 >> User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "POST /v1.32/networks/create HTTP/1.1[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "accept: application/json[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "content-type: application/json[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "x-tc-sid: e7ba0cb9-b301-430e-9adf-8267e11f6737[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "Content-Length: 358[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "Host: localhost:2375[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "Connection: keep-alive[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "User-Agent: Apache-HttpClient/5.0.3 (Java/11.0.16.1)[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:92 - http-outgoing-2 >> "[\r][\n]"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:106 - http-outgoing-2 >> "{"enableIPv6":null,"Name":"535d0ae8-0afc-4f1b-bbcd-f11ad9ce5139","Driver":null,"IPAM":null,"Options":{},"CheckDuplicate":true,"Internal":null,"EnableIPv6":null,"Attachable":null,"Labels":{"org.testcontainers":"true","org.testcontainers.lang":"java","org.testcontainers.version":"1.17.6","org.testcontainers.sessionId":"e7ba0cb9-b301-430e-9adf-8267e11f6737"}}"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire:106 - http-outgoing-2 << "end of stream"
2023-03-01 12:05:27 DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection:125 - http-outgoing-2: Close connection

And like say above, I I fix testcontainers to that it is capable of retrying a failed network create, it works.

journalctl --user -u podman.service

I'm not seeing any output when the tests are run. The tests using testcontainers create containers and networks via the Docker API.

% podman machine ssh
Connecting to vm podman-machine-default. To close connection, use `~.` or `exit`
Fedora CoreOS 37.20230218.2.0
Tracker: https://github.com/coreos/fedora-coreos-tracker
Discuss: https://discussion.fedoraproject.org/tag/coreos

Last login: Wed Mar  1 11:47:44 2023 from 192.168.127.1
[core@localhost ~]$ journalctl -f --user -u podman.socket
No journal files were found.

journalctl --user -u podman.service

@miensol
Copy link

miensol commented Mar 8, 2023

I think I'm being hit by the same or similar issue.
In our setup, the docker host is on a remote machine. We're opening the tunnel to it via SSH. We've configured env variables like so:

dockerHost=unix:///tmp/podman.sock
    2023-03-08T12:44:09.990+01:00 DEBUG 472 --- [    Test worker] o.t.d.DockerClientProviderStrategy       : Transport type: 'httpclient5', Docker host: 'unix:///tmp/podman.sock'
    2023-03-08T12:44:09.990+01:00 DEBUG 472 --- [    Test worker] o.t.d.DockerClientProviderStrategy       : Checking Docker OS type for Environment variables, system properties and defaults. Resolved dockerHost=unix:///tmp/podman.sock
    2023-03-08T12:44:09.991+01:00  INFO 472 --- [    Test worker] org.testcontainers.DockerClientFactory   : Docker host IP address is **********
    2023-03-08T12:44:09.991+01:00 DEBUG 472 --- [    Test worker] org.testcontainers.DockerClientFactory   : Docker info: {NGoroutines=11, BuildahVersion=1.27.1, Name=**********, Swarm={NodeID=, NodeAddr=, LocalNodeState=inactive, ControlAvailable=false, Error=, RemoteManagers=null}, RuncCommit={ID=, Expected=}, OSVersion=8.6, Runtimes={crun={path=/usr/bin/crun}, kata={path=/usr/bin/kata-runtime}, krun={path=/usr/bin/krun}, runc={path=/usr/bin/runc}, runj={path=/usr/local/bin/runj}, runsc={path=/usr/bin/runsc}}, ID=b1008a2c-4f7a-47c0-80ee-7e6c375b4a21, DriverStatus=[[Backing Filesystem, xfs], [Supports d_type, true], [Native Overlay Diff, true], [Using metacopy, false]], BridgeNfIptables=false, LiveRestoreEnabled=false, SystemTime=2023-03-08T12:44:10.742535754+01:00, NoProxy=, Architecture=amd64, NEventsListener=0, HttpsProxy=, Images=253, ContainersRunning=0, Labels=null, InitCommit={ID=, Expected=}, NFd=11, KernelVersion=4.18.0-372.19.1.el8_6.x86_64, CPURealtimeRuntime=true, LoggingDriver=, OSType=linux, SecurityOptions=[name=seccomp,profile=default], ContainerdCommit={ID=, Expected=}, GenericResources=null, KernelMemory=false, OperatingSystem="rocky", RegistryConfig={AllowNondistributableArtifactsCIDRs=[], AllowNondistributableArtifactsHostnames=[], InsecureRegistryCIDRs=[], IndexConfigs={}, Mirrors=[]}, ServerVersion=4.2.0, OomKillDisable=true, CpuCfsQuota=true, Containers=0, Driver=overlay, KernelMemoryTCP=false, IPv4Forwarding=false, ExperimentalBuild=true, ProductLicense=Apache-2.0, DockerRootDir=/home/jenkins/.local/share/containers/storage, CPUSet=true, CpuCfsPeriod=true, DefaultRuntime=crun, SwapTotal=0, CPUShares=true, Debug=false, NCPU=12, Plugins={Volume=[local], Network=[bridge, macvlan, ipvlan], Authorization=null, Log=[k8s-file, none, passthrough, journald]}, SwapLimit=true, CgroupDriver=cgroupfs, Uptime=21h 16m 45.00s (Approximately 0.88 days), SwapFree=0, Rootless=true, ContainersPaused=0, MemTotal=67260190720, IndexServerAddress=, MemoryLimit=true, HttpProxy=, InitBinary=, CPURealtimePeriod=true, CgroupVersion=1, PidsLimit=true, Isolation=, BridgeNfIp6tables=false, Warnings=[], ContainersStopped=0}
    2023-03-08T12:44:09.993+01:00 DEBUG 472 --- [    Test worker] o.t.s.c.g.d.core.command.AbstrDockerCmd  : Cmd: 
    2023-03-08T12:44:10.075+01:00 DEBUG 472 --- [    Test worker] org.testcontainers.DockerClientFactory   : Docker version: {Components=[{Name=Podman Engine, Version=4.2.0, Details={APIVersion=4.2.0, Arch=amd64, BuildTime=2022-11-08T19:34:11+01:00, Experimental=false, GitCommit=, GoVersion=go1.18.4, KernelVersion=4.18.0-372.19.1.el8_6.x86_64, MinAPIVersion=4.0.0, Os=linux}}, {Name=Conmon, Version=conmon version 2.1.2, commit: 98e028a5804809ccb49bc099c0d53adc43ef8cc4, Details={Package=conmon-2.1.2-2.module+el8.6.0+997+05c9d812.x86_64}}, {Name=OCI Runtime (crun), Version=crun version 1.5
    commit: 54ebb8ca8bf7e6ddae2eb919f5b82d1d96863dea

The tests run fine for the first use of test containers.

However, on the second attempt to start a Kafka container, we're getting the following failure:

    2023-03-08T12:24:56.604+01:00 ERROR 498 --- [    Test worker] 🐳 [confluentinc/cp-kafka:7.3.1]         : Could not start container

    java.lang.RuntimeException: com.github.dockerjava.zerodep.shaded.org.apache.hc.core5.http.NoHttpResponseException: localhost:2375 failed to respond
    	at com.github.dockerjava.zerodep.ApacheDockerHttpClientImpl.execute(ApacheDockerHttpClientImpl.java:195)
    	at com.github.dockerjava.zerodep.ZerodepDockerHttpClient.execute(ZerodepDockerHttpClient.java:8)
    	at org.testcontainers.dockerclient.HeadersAddingDockerHttpClient.execute(HeadersAddingDockerHttpClient.java:23)
    	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.execute(DefaultInvocationBuilder.java:228)
    	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.post(DefaultInvocationBuilder.java:124)
    	at org.testcontainers.shaded.com.github.dockerjava.core.exec.CreateContainerCmdExec.execute(CreateContainerCmdExec.java:37)

@abentele
Copy link

same issue for me, with testcontainers

@k-wall
Copy link
Author

k-wall commented Apr 26, 2023

Still seeing this issue on newer podman:

podman --version
podman version 4.5.0

@Luap99
Copy link
Member

Luap99 commented Apr 26, 2023

Do you all use podman machine on macos? Or does this also happen on linux?

@k-wall
Copy link
Author

k-wall commented Apr 26, 2023

@Luap99 Amongst our team (both Mac and Linux developer environments), we are only seeing this problem on the Mac (and the problem is seen by >1 developers.)

I reiterate my offer above to help get the problem tracked down. If I can run with extra logging turned up to help I will. Just let us know what you need.

@abentele
Copy link

updating to testcontainers 1.18.0 fixed it for me

@Luap99
Copy link
Member

Luap99 commented Apr 26, 2023

The gvproxy process is used to proxy all the traffic between VM and host on macos. So I assume you would hit a bug in gvproxy if you do not see it on linux.
It would help if you could come up with a reproducer outside of testcontianers.
Just a guess but I think the problem here is related to load, if the library is constantly making request the gvproxy process may not be able to keep up?

@k-wall
Copy link
Author

k-wall commented Apr 26, 2023

updating to testcontainers 1.18.0 fixed it for me

@abentele - you are probably benefiting from testcontainers/testcontainers-java#6667 which was part of 1.18.0. That fix allows testcontainers to retry the network creation if it fails. Previously network creation was not subjected to the retry.

We are running 1.18.0 and confirm we still see the issue in podman/mac. We are working around by setting org.testcontainers.containers.GenericContainer#withStartupAttempts on our containers.

@xRomZak
Copy link

xRomZak commented Jun 15, 2023

Facing the same issue on Mac (Intel) trying to start container:

  • podman 4.5.1 (rootful/rootless mode - does't matter)
  • testcontainers 1.18.3 (RYUK disabled)

@k-wall
Copy link
Author

k-wall commented Jul 5, 2023

We new use cases in our software, we are seeing this problem more frequently and affecting other Docker API calls. Unfortunately a simple retry is not a viable workaround in all cases.

I'm confirming that I'm still seeing this, even on 4.5.1.

I've been unsuccessful in reproducing the problem outside of Testcontainers.

The gvproxy process is used to proxy all the traffic between VM and host on macos. So I assume you would hit a bug in gvproxy if you do not see it on linux.

Are there instructions on how to turn how to turn up logging in gvproxy?

@SamBarker
Copy link

SamBarker commented Jul 17, 2023

I suspect testcontainers/testcontainers-java#7310 is related if not the root cause of the issues with Network creation.

@robobario
Copy link

robobario commented Jul 19, 2023

To summarise that ticket ^ we think it's a bad interaction between the podman api server HTTP idle timeout and the default connection keepalive timeout in the apache HTTP client that is used by testcontainers. Connections are pooled in the client with a default keepalive of 3 minutes. Idle connections are closed on the podman side after idling 10 seconds, which is only discovered by the HTTP client when it tries to use the connection again. By default there is 1 retry in the HTTP client, so if that retry also picks another pooled connection in this state, then the exception is thrown.

This server side 10 second idle timeout on the connections by default is quite different from Docker where connections look to be very long lived (no idle timeout?). Is there any appetite for increasing or removing the idle timeout in the podman api server so it behaves more like the docker one?

@Luap99
Copy link
Member

Luap99 commented Jul 19, 2023

Thanks for the investigation.

If you want to increase the timeout you need to increase the inactivity timeout of the service, i.e. -t 180 or just disable the service timeout with -t 0. There is also a service_timeout field in containers.conf that can be set so you do not have to modify the systemd service.
Podman is daemonless so the service is designed to go away when it is not used and it will be activated on demand via systemd socket activation.

@robobario
Copy link

Thanks @Luap99, there's also a non-standard response header Keep-Alive that could be added to give a hint to clients about how long the connection can be kept alive, so adding something like Keep-Alive: timeout=10 to responses if idle timeout is 10 seconds.

FYI: We are also exploring client-side fixes as it's perhaps better to make the client resilient, just wondering if there's any improvements on the server.

@k-wall
Copy link
Author

k-wall commented Jul 19, 2023

Podman adding Keep-Alive headers to the response sounds like a good idea to me. It would help Podman will play nicely with existing tooling such as docker-java and things built on top, such as https://github.com/testcontainers/testcontainers-java. That can only help Podman adoption.

I do agree, of course, that the client side should be made resilient too.

@k-wall
Copy link
Author

k-wall commented Jul 19, 2023

If you want to increase the timeout you need to increase the inactivity timeout of the service, i.e. -t 180 or just disable the service timeout with -t 0.

@Luap99 separately, feeding back on the suggestion to try -t 0 as a workaround. That does indeed seen to work. Thank you.

What's the simplest way to tell podman (on the Mac) that you want a machine in that configuration? I don't see any podman machine (start|init) command line switches. A recipe that didn't involve ssh'ing into the VM would be nice. For the record, my steps:

podman machine ssh
sudo su
systemctl disable podman.socket
socat - UNIX-CONNECT:/run/podman/podman.sock.  # expecting No such file or directory
/usr/bin/podman --log-level=info system service -t 0

I couldn't get a containers.conf approach to work. On the host, I tried adding server_timeout = 0 to the [engine] section ~/.config/containers/containers.conf but podman machine init reverted the setting (regenerates the file, I think). Adding it after podman machine init but before podman machine start seemingly did nothing.

I found a couple of files within the VM of that name. I wasn't sure which I was to modify or exactly how.

@Luap99
Copy link
Member

Luap99 commented Jul 19, 2023

add this to /etc/containers/containers.conf.d/service-timeout.conf. We will read all drop in files so you do not have to modify existing ones.

[engine]
service_timeout=0

There is no way to do that by default with podman machine commands. Copying existing config files from the host to the VM on creating time is worth a separate RFE.

As far as setting the Keep-Alive header goes I am not sure we can really mange it in out code. We use the go std lib for the http server which also handles the keep-alive logic and they don't seem to set this. I don't know the reason but it would need to be figured out if we can set the header in our code or if this requires std lib changes.

@k-wall
Copy link
Author

k-wall commented Jul 19, 2023

add this to /etc/containers/containers.conf.d/service-timeout.conf. We will read all drop in files so you do not have to modify existing ones.

[engine]
service_timeout=0

I confirm that works. Thank you.

There is no way to do that by default with podman machine commands. Copying existing config files from the host to the VM on creating time is worth a separate RFE.

I can open a separate GitHub issue if that helps. Let me know.

As far as setting the Keep-Alive header goes I am not sure we can really mange it in out code. We use the go std lib for the http server which also handles the keep-alive logic and they don't seem to set this. I don't know the reason but it would need to be figured out if we can set the header in our code or if this requires std lib changes.

I've been learning more about the Keep-Alive header since I made my comments.

I see now that it is prohibited from HTTP2/3 and looking around, I actually see few open implementations actually using it (https://issues.apache.org/jira/browse/HTTPCLIENT-781 seems to be an outlier). As far as I can see, there's no replacement for the Keep-Alive header - I suspect that's because even if the client is made aware of a server's intentions, the client still needs to handle the corner cases to be robust. Keep-Alive doesn't really help it. In light of this, I've changed my opinion, and see the root cause as with docker-java and test-containers.

@Luap99
Copy link
Member

Luap99 commented Jul 19, 2023

There is no way to do that by default with podman machine commands. Copying existing config files from the host to the VM on creating time is worth a separate RFE.

I can open a separate GitHub issue if that helps. Let me know.

Up to you, if you want this as a feature then it is worth to discus it.

@Luap99
Copy link
Member

Luap99 commented Oct 19, 2023

I am going to close this given this seems to be mostly a client issue. I don't think we should mess with the keep-alive headers in podman as this is managed by go.

@Luap99 Luap99 closed this as completed Oct 19, 2023
@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Jan 18, 2024
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jan 18, 2024
# for free to subscribe to this conversation on GitHub. Already have an account? #.
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. macos MacOS (OSX) related remote Problem is in podman-remote
Projects
None yet
Development

No branches or pull requests

7 participants