Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Error, when pulling short-named image via docker api #16400

Closed
fedinskiy opened this issue Nov 3, 2022 · 28 comments
Closed

Error, when pulling short-named image via docker api #16400

fedinskiy opened this issue Nov 3, 2022 · 28 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. stale-issue

Comments

@fedinskiy
Copy link

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

/kind bug

Description
I have an application, which uses podman socket via test-containers library. When I am using this app to run containers, based on images which have non-qualified names (eg postgres:9.6.12) and were not yet pulled to the machine, it fails with an error. When I use fully-qualified names (eg docker.io/postgres:9.6.12), or pull images in advance, it works. When the same app uses Docker API, it works for images with any names.

Steps to reproduce the issue:

  1. Have podman installed and started via systemctl --user enable podman.socket --now
  2. Force testcontainers to use the podman socket export DOCKER_HOST=unix:///run/user/${UID}/podman/podman.sock
  3. Clone the reproducer: git clone [email protected]:fedinskiy/reproducer.git -b reproducer/podman-nopull && cd reproducer
  4. Purge existing images podman rmi --all and docker rmi --force $(docker images -q)
  5. run tests mvn clean verify # fails
  6. pull required images: testcontainers/ryuk:0.3.4, nginx:latest and postgres:9.6.12
  7. run tests again mvn clean verify # succeeds
  8. If p. 2 is omitted, everything works. If fully-qualified names is used instead (eg docker.io/postgres:9.6.10) is also works

Describe the results you received:
See above

Describe the results you expected:
Podman API should be fully compatible with Docker API (https://podman.io/blogs/2020/07/01/rest-versioning.html)

Additional information you deem important (e.g. issue happens only occasionally):
Initially reported here, for test-containers library: testcontainers/testcontainers-java#5998, according to them it is docker-api error.

Output of podman version:

Client:       Podman Engine
Version:      4.3.0
API Version:  4.3.0
Go Version:   go1.18.7
Built:        Fri Oct 21 10:16:35 2022
OS/Arch:      linux/amd64

Output of podman info:

host:
  arch: amd64
  buildahVersion: 1.28.0
  cgroupControllers:
  - cpu
  - io
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.4-3.fc36.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.4, commit: '
  cpuUtilization:
    idlePercent: 91.21
    systemPercent: 1.59
    userPercent: 7.2
  cpus: 8
  distribution:
    distribution: fedora
    variant: workstation
    version: "36"
  eventLogger: journald
  hostname: localhost.localdomain
  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: 6.0.5-200.fc36.x86_64
  linkmode: dynamic
  logDriver: journald
  memFree: 7868071936
  memTotal: 33395286016
  networkBackend: cni
  ociRuntime:
    name: crun
    package: crun-1.6-2.fc36.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.6
      commit: 18cf2efbb8feb2b2f20e316520e0fd0b6c41ef4d
      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: true
  serviceIsRemote: false
  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: 8589930496
  swapTotal: 8589930496
  uptime: 1h 57m 23.00s (Approximately 0.04 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries:
  registry.access.redhat.com:
    Blocked: false
    Insecure: true
    Location: registry.access.redhat.com
    MirrorByDigestOnly: false
    Mirrors: null
    Prefix: registry.access.redhat.com
    PullFromMirror: ""
  search:
  - docker.io
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - quay.io
store:
  configFile: /home/fedinskiy/.config/containers/storage.conf
  containerStore:
    number: 0
    paused: 0
    running: 0
    stopped: 0
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/fedinskiy/.local/share/containers/storage
  graphRootAllocated: 510965841920
  graphRootUsed: 185257885696
  graphStatus:
    Backing Filesystem: btrfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 4
  runRoot: /run/user/1000/containers
  volumePath: /home/fedinskiy/.local/share/containers/storage/volumes
version:
  APIVersion: 4.3.0
  Built: 1666340195
  BuiltTime: Fri Oct 21 10:16:35 2022
  GitCommit: ""
  GoVersion: go1.18.7
  Os: linux
  OsArch: linux/amd64
  Version: 4.3.

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

podman-4.3.0-2.fc36.x86_64

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.):

$ grep "hub" /usr/share/containers/containers.conf
compat_api_enforce_docker_hub = true
$ grep -v "#"  /etc/containers/registries.conf
unqualified-search-registries = ["docker.io","registry.fedoraproject.org","registry.access.redhat.com","quay.io"]
[[registry]]
location = "registry.access.redhat.com"
insecure = true


short-name-mode="disabled"
@openshift-ci openshift-ci bot added the kind/bug Categorizes issue or PR as related to a bug. label Nov 3, 2022
@vrothberg
Copy link
Member

Thanks for reaching out, @fedinskiy. Any chance you can break it down to a reproducer involving podman only? Digging into the code of the reproducer will slow things down considerably.

@vrothberg
Copy link
Member

My guess is that "short names" is a red herring as short names are resolved as Docker does. There's probably some field in the JSON message that testcontainers expect?

$ grep "hub" /usr/share/containers/containers.conf
compat_api_enforce_docker_hub = true

That's not needed as it's set to true by default. The short-name mode isn't required to be set to disabled either as short names resolve to docker.io only on the compat AP (unless compat_api_enfore_docker_hub is explicitly set to false).

@fedinskiy
Copy link
Author

@vrothberg I saw a comment[1] in this repo, which mentions logging of socket operations. I was not able to find anything about it in the docs, but hoped you know something about this option. In that case, I will be able to make a curl version of the reproducer.

Also, I believe, there are two problems:

  1. The image is not being pulled
  2. There is a Json response with (potential) fields "stream", "status", "progressDetail", "id", "from", "time" and "errorDetail" and this response has empty (or null) field "status", which is not expected by calling code and leads to an error. My debugging (for version 4.2.1) showed, that there is a field "error" with content "initializing source docker://postgres:9.6.12: unable to retrieve auth token: invalid username/password: unauthorized: incorrect username or password"

[1] #15306 (comment)

@vrothberg
Copy link
Member

@vrothberg I saw a comment[1] in this repo, which mentions logging of socket operations. I was not able to find anything about it in the docs, but hoped you know something about this option. In that case, I will be able to make a curl version of the reproducer.

Thanks a lot for your help, @fedinskiy! One way to get the logs is to run podman --log-level=debug system service -t0. This will spin up the server and listen on the usual socket. You can run curl against the socket and then you'll get the debug messages on the server side.

There is a Json response with (potential) fields "stream", "status", "progressDetail", "id", "from", "time" and "errorDetail" and this response has empty (or null) field "status", which is not expected by calling code and leads to an error.

That may be the important part. I am curious to see the reproducer and compare docker's response with the one of podman.

My debugging (for version 4.2.1) showed, that there is a field "error" with content "initializing source docker://postgres:9.6.12: unable to retrieve auth token: invalid username/password: unauthorized: incorrect username or password"

That is surprising. docker://postgres:9.6.12 would resolve to docker://docker.io/library/postgres:9.6.12.

@fedinskiy
Copy link
Author

fedinskiy commented Nov 4, 2022

I used this command for debugging purposes, to decrease the amount of logs:

export TESTCONTAINERS_RYUK_DISABLED=true
mvn clean verify -Dtest=AppTest#testName

This is what I get from podman debug logs(podman --log-level=debug system service -t0):

DEBU[0008] IdleTracker:new 0m+0h/0t connection(s)        X-Reference-Id=0xc00041a018
DEBU[0008] IdleTracker:closed 0m+0h/1t connection(s)     X-Reference-Id=0xc00041a018
WARN[0008] IdleTracker: StateClosed transition by connection marked un-managed  X-Reference-Id=0xc00041a018
DEBU[0008] IdleTracker:new 0m+0h/1t connection(s)        X-Reference-Id=0xc0001a4020
DEBU[0008] IdleTracker:active 0m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
DEBU[0008] Loading registries configuration "/etc/containers/registries.conf" 
DEBU[0008] Failed to decode keys ["registry.short-name-mode"] from "/etc/containers/registries.conf" 
DEBU[0008] Loading registries configuration "/etc/containers/registries.conf.d/000-shortnames.conf" 
@ - - [04/Nov/2022:12:14:56 +0100] "GET /v1.32/info HTTP/1.1" 200 2383 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0008] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc0001a4020
DEBU[0008] IdleTracker:active 1m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
@ - - [04/Nov/2022:12:14:56 +0100] "GET /v1.32/version HTTP/1.1" 200 879 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0008] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc0001a4020
DEBU[0008] IdleTracker:active 1m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
DEBU[0008] parsed reference into "[overlay@/home/fedinskiy/.local/share/containers/storage+/run/user/1000/containers]@027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
DEBU[0008] exporting opaque data as blob "sha256:027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
DEBU[0008] exporting opaque data as blob "sha256:027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
@ - - [04/Nov/2022:12:14:56 +0100] "GET /v1.32/images/json HTTP/1.1" 200 647 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0008] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc0001a4020
DEBU[0008] IdleTracker:active 1m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
DEBU[0008] Looking up image "postgres:9.6.12" in local containers storage 
DEBU[0008] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "localhost/postgres:9.6.12" ...       
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "registry.fedoraproject.org/postgres:9.6.12" ... 
DEBU[0008] Trying "registry.access.redhat.com/postgres:9.6.12" ... 
DEBU[0008] Trying "quay.io/postgres:9.6.12" ...         
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "postgres:9.6.12" ...                 
DEBU[0008] Looking up image "docker.io/library/postgres:9.6.12" in local containers storage 
DEBU[0008] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
INFO[0008] Request Failed(Not Found): failed to find image postgres:9.6.12: docker.io/library/postgres:9.6.12: No such image 
@ - - [04/Nov/2022:12:14:56 +0100] "GET /v1.32/images/postgres:9.6.12/json HTTP/1.1" 404 213 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0008] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc0001a4020
DEBU[0008] IdleTracker:active 1m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
DEBU[0008] Looking up image "postgres:9.6.12" in local containers storage 
DEBU[0008] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "localhost/postgres:9.6.12" ...       
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "registry.fedoraproject.org/postgres:9.6.12" ... 
DEBU[0008] Trying "registry.access.redhat.com/postgres:9.6.12" ... 
DEBU[0008] Trying "quay.io/postgres:9.6.12" ...         
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "postgres:9.6.12" ...                 
DEBU[0008] Pulling image docker.io/library/postgres:9.6.12 (policy: always) 
DEBU[0008] Looking up image "docker.io/library/postgres:9.6.12" in local containers storage 
DEBU[0008] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Trying "docker.io/library/postgres:9.6.12" ... 
DEBU[0008] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0008] Attempting to pull candidate docker.io/library/postgres:9.6.12 for docker.io/library/postgres:9.6.12 
DEBU[0008] parsed reference into "[overlay@/home/fedinskiy/.local/share/containers/storage+/run/user/1000/containers]docker.io/library/postgres:9.6.12" 
Trying to pull docker.io/library/postgres:9.6.12...
DEBU[0008] Copying source image //postgres:9.6.12 to destination image [overlay@/home/fedinskiy/.local/share/containers/storage+/run/user/1000/containers]docker.io/library/postgres:9.6.12 
DEBU[0008] Using registries.d directory /etc/containers/registries.d 
DEBU[0008] Trying to access "docker.io/library/postgres:9.6.12" 
DEBU[0008] Returning credentials for docker.io/library/postgres from DockerAuthConfig 
DEBU[0008]  No signature storage configuration found for docker.io/library/postgres:9.6.12, using built-in default file:///home/fedinskiy/.local/share/containers/sigstore 
DEBU[0008] Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io 
DEBU[0008] GET https://registry-1.docker.io/v2/         
DEBU[0009] Ping https://registry-1.docker.io/v2/ status 401 
DEBU[0009] GET https://auth.docker.io/token?account=developer&scope=repository%3Alibrary%2Fpostgres%3Apull&service=registry.docker.io 
DEBU[0010] Accessing "docker.io/library/postgres:9.6.12" failed: unable to retrieve auth token: invalid username/password: unauthorized: incorrect username or password 
DEBU[0010] Error pulling candidate docker.io/library/postgres:9.6.12: initializing source docker://postgres:9.6.12: unable to retrieve auth token: invalid username/password: unauthorized: incorrect username or password 
@ - - [04/Nov/2022:12:14:56 +0100] "POST /v1.32/images/create?fromImage=postgres&tag=9.6.12 HTTP/1.1" 200 358 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)" # it looks like the failure is here
DEBU[0010] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc0001a4020
DEBU[0010] IdleTracker:closed 1m+0h/2t connection(s)     X-Reference-Id=0xc0001a4020
DEBU[0010] IdleTracker:new 0m+0h/2t connection(s)        X-Reference-Id=0xc0004aa1b0
DEBU[0010] IdleTracker:active 0m+0h/3t connection(s)     X-Reference-Id=0xc0004aa1b0
@ - - [04/Nov/2022:12:14:57 +0100] "GET /v1.32/containers/json?all=true&filters=%7B%22label%22%3A%5B%22org.testcontainers%3Dtrue%22%2C%22org.testcontainers.sessionId%3D9f9f962f-24bd-498d-8af1-0029194d96ef%22%5D%7D HTTP/1.1" 200 3 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0010] IdleTracker:idle 1m+0h/3t connection(s)       X-Reference-Id=0xc0004aa1b0
DEBU[0010] IdleTracker:active 1m+0h/3t connection(s)     X-Reference-Id=0xc0004aa1b0
DEBU[0010] Successfully loaded network # <cut for brewity>
DEBU[0010] Successfully loaded 9 networks               
@ - - [04/Nov/2022:12:14:57 +0100] "POST /v1.32/networks/prune?filters=%7B%22label%22%3A%5B%22org.testcontainers%3Dtrue%22%2C%22org.testcontainers.sessionId%3D9f9f962f-24bd-498d-8af1-0029194d96ef%22%5D%7D HTTP/1.1" 200 23 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0010] IdleTracker:idle 1m+0h/3t connection(s)       X-Reference-Id=0xc0004aa1b0
DEBU[0010] IdleTracker:active 1m+0h/3t connection(s)     X-Reference-Id=0xc0004aa1b0
@ - - [04/Nov/2022:12:14:58 +0100] "POST /v1.32/volumes/prune?filters=%7B%22label%22%3A%5B%22org.testcontainers%3Dtrue%22%2C%22org.testcontainers.sessionId%3D9f9f962f-24bd-498d-8af1-0029194d96ef%22%5D%7D HTTP/1.1" 200 41 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0010] IdleTracker:idle 1m+0h/3t connection(s)       X-Reference-Id=0xc0004aa1b0
DEBU[0010] IdleTracker:active 1m+0h/3t connection(s)     X-Reference-Id=0xc0004aa1b0
DEBU[0010] parsed reference into "[overlay@/home/fedinskiy/.local/share/containers/storage+/run/user/1000/containers]@027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
DEBU[0010] exporting opaque data as blob "sha256:027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
DEBU[0010] parsed reference into "[overlay@/home/fedinskiy/.local/share/containers/storage+/run/user/1000/containers]@027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
DEBU[0010] exporting opaque data as blob "sha256:027eba2e89396946fd63dd69c919844b248c8b591c07545321de3006503cc974" 
@ - - [04/Nov/2022:12:14:58 +0100] "POST /v1.32/images/prune?filters=%7B%22label%22%3A%5B%22org.testcontainers%3Dtrue%22%2C%22org.testcontainers.sessionId%3D9f9f962f-24bd-498d-8af1-0029194d96ef%22%5D%7D HTTP/1.1" 200 40 "" "Apache-HttpClient/5.0.3 (Java/11.0.16)"
DEBU[0010] IdleTracker:idle 1m+0h/3t connection(s)       X-Reference-Id=0xc0004aa1b0
DEBU[0010] IdleTracker:closed 1m+0h/3t connection(s)     X-Reference-Id=0xc0004aa1b0

@fedinskiy
Copy link
Author

So, I pruned all images and tried to run the request in question:

Podman:

$  curl -v --unix-socket /run/user/1000/podman/podman.sock -X POST http://localhost/v1.32/images/create?fromImage=postgres&tag=9.6.12
[1] 30236
[fedinskiy@localhost tests]$ *   Trying /run/user/1000/podman/podman.sock:0...
* Connected to localhost (/run/user/1000/podman/podman.sock) port 80 (#0)
> POST /v1.32/images/create?fromImage=postgres HTTP/1.1
> Host: localhost
> User-Agent: curl/7.82.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Api-Version: 1.41
< Libpod-Api-Version: 4.3.0
< Server: Libpod/4.3.0 (linux)
< X-Reference-Id: 0xc0006ce008
< Date: Fri, 04 Nov 2022 11:28:46 GMT
< Transfer-Encoding: chunked
<
{"status":"Pulling fs layer","progressDetail":{},"id":"e9995326b091"}
{"status":"Pulling fs layer","progressDetail":{},"id":"55c520fc03c5"}
{"status":"Pulling fs layer","progressDetail":{},"id":"a0cb03f17886"}
{"status":"Pulling fs layer","progressDetail":{},"id":"99b5b1679915"}
{"status":"Pulling fs layer","progressDetail":{},"id":"bb26f7e78134"}
{"status":"Pulling fs layer","progressDetail":{},"id":"c8e073b7ae91"}
{"status":"Download complete","progressDetail":{},"id":"bb26f7e78134"}
{"status":"Download complete","progressDetail":{},"id":"55c520fc03c5"}
{"status":"Pulling fs layer","progressDetail":{},"id":"d0ac84d6672c"}
{"status":"Download complete","progressDetail":{},"id":"d0ac84d6672c"}
{"status":"Downloading","progressDetail":{"current":2709888,"total":31420038},"progress":"[====\u003e                                              ]   2.71MB/31.42MB","id":"e9995326b091"}
<Download progress omitted for brevity>
{"status":"Downloading","progressDetail":{"current":89377109,"total":91838701},"progress":"[================================================\u003e  ]  89.38MB/91.84MB","id":"f4c3677d4414"}
{"status":"Download complete","progressDetail":{},"id":"f4c3677d4414"}
{"status":"Pulling fs layer","progressDetail":{},"id":"027eba2e8939"}
{"status":"Download complete","progressDetail":{},"id":"027eba2e8939"}
{"status":"Download complete","progressDetail":{},"id":"027eba2e8939"}
# hangs afterwards, can be killed by Ctrl+C

Docker

$ curl -v --unix-socket /var/run/docker.sock -X POST http://localhost/v1.32/images/create?fromImage=postgres&tag=9.6.12
[1] 51259
$ *   Trying /var/run/docker.sock:0...

* Connected to localhost (/run/docker.sock) port 80 (#0)
> POST /v1.32/images/create?fromImage=postgres HTTP/1.1
> Host: localhost
> User-Agent: curl/7.82.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Api-Version: 1.41
< Content-Type: application/json
< Docker-Experimental: false
< Ostype: linux
< Server: Docker/20.10.21 (linux)
< Date: Fri, 04 Nov 2022 11:52:38 GMT
< Transfer-Encoding: chunked
< 
{"status":"Pulling from library/postgres","id":"10"}
{"status":"Digest: sha256:b2baf8998630663d21370da06387c950e587071bdd307ee34e661cdcc7442bcc"}
{"status":"Pulling from library/postgres","id":"10-alpine"}
{"status":"Digest: sha256:8ee4d835d1173ebb2ca2a1f45d7fbbb99eecb506b635c35ea7d137d25e0ce28b"}
{"status":"Pulling from library/postgres","id":"10-alpine3.13"}
{"status":"Digest: sha256:b5c858482611b150f2addb8d3df572ccdf706ed90ef2b1e22ad9a849c69bb43e"}
{"status":"Pulling from library/postgres","id":"10-alpine3.14"}
{"status":"Digest: sha256:a976f0ef83856f7388ffa80cc038961b5610160d8ee21f4d14329ba938076c56"}
{"status":"Pulling from library/postgres","id":"10-alpine3.15"}
{"status":"Digest: sha256:2e04791a2d3f1b2496b596bafcac9d95fd5e51db8345cc8aa1c3aa1d57e12764"}
{"status":"Pulling from library/postgres","id":"10-alpine3.16"}
{"status":"Digest: sha256:8ee4d835d1173ebb2ca2a1f45d7fbbb99eecb506b635c35ea7d137d25e0ce28b"}
{"status":"Pulling from library/postgres","id":"10-beta1"}
{"status":"Digest: sha256:92f468785cfbff83fed64d698204746f8dc71e8678fb247f0a55a4f74df6150d"}
{"status":"Pulling from library/postgres","id":"10-beta1-alpine"}
{"status":"Digest: sha256:1d770f3c0718ed824e51c019896d21faf98b58f1764b3d70a784ac43cdceec79"}
{"status":"Pulling from library/postgres","id":"10-beta2"}
{"status":"Digest: sha256:190fa1e057dff4185ab73aeb5d8d2d56811e4bd48106f3a4b6bae54ba6950c5a"}
{"status":"Pulling from library/postgres","id":"10-beta2-alpine"}
{"status":"Digest: sha256:187ac13141a1a3320ff9532ea5e635b96178b838f9637ca675438535bb8c5dce"}
{"status":"Pulling from library/postgres","id":"10-beta3"}
{"status":"Digest: sha256:802521458c79ded89f718d6f0b0a0856b9468b3aaf4ca3ecd6942129a50188c2"}
{"status":"Pulling from library/postgres","id":"10-beta3-alpine"}
{"status":"Digest: sha256:8c9b277d2394e6f54848a40768bc790e1c029e16411aae6e85b37656dc99e3e7"}
{"status":"Pulling from library/postgres","id":"10-beta4"}
{"status":"Digest: sha256:6f077f2c9950462808fddc4d01f58b096a41774af6d8b52ad2e7255c41d5f244"}
{"status":"Pulling from library/postgres","id":"10-beta4-alpine"}
{"status":"Digest: sha256:9ab99815d86e834a96975680af69a9d44833a1bfbcfda6e549ad1db0aca99856"}
# I waited ten minutes for everything to download and finally reached pull rate limit. In other runs,  the process could only be stopped with kill command

@vrothberg
Copy link
Member

@fedinskiy can you point to the test that is failing in testcontainers? I would love to better understand what is being tested. Looking at the source code of the test may help.

@fedinskiy
Copy link
Author

fedinskiy commented Nov 14, 2022

@vrothberg : below is a copy of steps from the testcontainer issue:

  1. Have podman installed
  2. Make podman use dockerhub by default(due to [1] ):
    a. Change line short-name-mode setting inside of /etc/containers/registries.conf into "disabled"
    b. Change order of unqualified-search-registries in the same file, so docker.io would be the first one
    c. In file /usr/share/containers/containers.conf uncomment compat_api_enforce_docker_hub = true
  3. Clone the reproducer: git clone [email protected]:fedinskiy/reproducer.git -b reproducer/podman-nopull
  4. Use podman rmi to purge postgres:9.6.12 and nginx:latest
  5. Force usage of podman socket: export DOCKER_HOST=unix:///run/user/${UID}/podman/podman.sock && export TESTCONTAINERS_RYUK_DISABLED=true
  6. Inside reproducer folder run mvn clean verify. This will fail.
  7. Download the images: podman pull postgress:9.6.12 && podman pull nginx:latest
  8. Repeat step 6 again. Now everything runs as expected

[1] testcontainers/testcontainers-java#5612

@vrothberg
Copy link
Member

@fedinskiy I am entirely unfamiliar with testcontainers. Having a pointer to the code would speed things up considerably. I assume that one test fails that has some source code.

@fedinskiy
Copy link
Author

fedinskiy commented Nov 14, 2022

@vrothberg
NullPointerException is thrown here: https://github.com/docker-java/docker-java/blob/master/docker-java-api/src/main/java/com/github/dockerjava/api/command/PullImageResultCallback.java#L48

That happens, because this field is null (probably due to unmarshalling of non-existing field from json object):
https://github.com/docker-java/docker-java/blob/master/docker-java-api/src/main/java/com/github/dockerjava/api/model/ResponseItem.java#L23

User-facing code of the test looks like that: https://github.com/fedinskiy/reproducer/blob/reproducer/podman-nopull/src/test/java/io/quarkus/qe/AppTest.java#L18

Full java stacktrace is below:

org.testcontainers.containers.ContainerLaunchException: Container startup failed
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:349)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:322)
	at io.quarkus.qe.AppTest.testName(AppTest.java:18)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at junit.framework.TestCase.runTest(TestCase.java:177)
	at junit.framework.TestCase.runBare(TestCase.java:142)
	at junit.framework.TestResult$1.protect(TestResult.java:122)
	at junit.framework.TestResult.runProtected(TestResult.java:142)
	at junit.framework.TestResult.run(TestResult.java:125)
	at junit.framework.TestCase.run(TestCase.java:130)
	at junit.framework.TestSuite.runTest(TestSuite.java:241)
	at junit.framework.TestSuite.run(TestSuite.java:236)
	at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:90)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
	at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)
Caused by: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=postgres:9.6.12, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@76c7beb3)
	at org.testcontainers.containers.GenericContainer.getDockerImageName(GenericContainer.java:1371)
	at org.testcontainers.containers.GenericContainer.logger(GenericContainer.java:651)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:331)
	... 27 more
Caused by: java.lang.NullPointerException
	at com.github.dockerjava.api.command.PullImageResultCallback.checkForDockerSwarmResponse(PullImageResultCallback.java:48)
	at com.github.dockerjava.api.command.PullImageResultCallback.onNext(PullImageResultCallback.java:35)
	at org.testcontainers.images.LoggedPullImageResultCallback.onNext(LoggedPullImageResultCallback.java:48)
	at org.testcontainers.images.TimeLimitedLoggedPullImageResultCallback.onNext(TimeLimitedLoggedPullImageResultCallback.java:73)
	at org.testcontainers.images.TimeLimitedLoggedPullImageResultCallback.onNext(TimeLimitedLoggedPullImageResultCallback.java:24)
	at org.testcontainers.shaded.com.github.dockerjava.core.exec.AbstrAsyncDockerCmdExec$1.onNext(AbstrAsyncDockerCmdExec.java:41)
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder$JsonSink.accept(DefaultInvocationBuilder.java:315)
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder$JsonSink.accept(DefaultInvocationBuilder.java:298)
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.lambda$executeAndStream$1(DefaultInvocationBuilder.java:275)
	at java.base/java.lang.Thread.run(Thread.java:829)

@vrothberg
Copy link
Member

Awesome, thank you very much for the pointers!

I'll be traveling this week, but will go back to the issue ASAP.

@TheHaf
Copy link

TheHaf commented Nov 14, 2022

@fedinskiy @vrothberg FYI, I have also recently discovered that NullPointerException in docker-java-api and I have already filed a report there: docker-java/docker-java#1998

In my case the NPE was triggered when I tried to download from a secured repository to which I had no credentials using podman.

I could also provide a PR there, but they haven't responded yet to the issue and I don't want to act prematurely.

@fedinskiy
Copy link
Author

It looks like this issue only affects rootless podman.

If I use rootlfull podmam[1] everything works as expected

[1]
sudo systemctl start podman.socket --now
export DOCKER_HOST=unix:///run/podman/podman.sock
sudo chmod a+rx /run/podman/
sudo chmod a+rw /run/podman/podman.sock

@rhatdan
Copy link
Member

rhatdan commented Nov 21, 2022

We can not prompt over the protocol so when using podman-remote you either need to set on one entry in the registry, which is what we do for podman-machine (docker.io) or you need to use fully qualified names.

@vrothberg
Copy link
Member

@fedinskiy, can you check whether there's a containers.conf or registries.conf file in your $HOME/.config/containers that may override the setting?

@fedinskiy
Copy link
Author

@vrothberg all my config entries are in the initial message (the last section).

@rhatdan I had an impression, that option compat_api_enforce_docker_hub = true should enforce docker hub for short names when using socket. Isn't that so?

@rhatdan
Copy link
Member

rhatdan commented Nov 22, 2022

Looks like it is supposed to.

@vrothberg
Copy link
Member

@vrothberg all my config entries are in the initial message (the last section).

The fact that it doesn't work rootless strongly suggests there's a config in your $HOME directory. Is that the case?

@vrothberg
Copy link
Member

The reproducer fails for me both rootless and rootful. But I have no idea what the tests do.

@fedinskiy
Copy link
Author

@vrothberg it is pretty straightforwardm, and you can see it in my repo[1]. The tests just start and stop containers. Under the hood, there is also image pulling by testcontainers library.

[1 ]https://github.com/fedinskiy/reproducer/blob/reproducer/podman-nopull/src/test/java/io/quarkus/qe/AppTest.java

@vrothberg
Copy link
Member

Sorry, I need a working reproducer. I am no Java developer and the provided steps in the issue don't work on Fedora 37 :(

@fedinskiy
Copy link
Author

@vrothberg I am on Fedora 36, maybe that is the reason of differences. Do you receive the same error on rootless and rootfull? What kind of error? Does it go away when you pull the images?

@vrothberg
Copy link
Member

I get the following results (with and without the images):

Tests in error: 
  testNginx(io.quarkus.qe.AppTest): Container startup failed
  testName(io.quarkus.qe.AppTest): Container startup failed
  testFullName(io.quarkus.qe.AppTest): Container startup failed

Tests run: 3, Failures: 0, Errors: 3, Skipped: 0

@github-actions
Copy link

A friendly reminder that this issue had no activity for 30 days.

@mrwilby
Copy link

mrwilby commented Jan 13, 2023

I also reproduce this (testcontainers, exact same java exception callstack) on Apple Silicon. Podman 4.3.1.

@vrothberg
Copy link
Member

I'd love to help but I need an easier reproducer or logs. For instance, how do the REST API calls look like?

@github-actions
Copy link

github-actions bot commented Mar 4, 2023

A friendly reminder that this issue had no activity for 30 days.

@rhatdan
Copy link
Member

rhatdan commented Mar 8, 2023

Since we never heard back, closing this issue, reopen if you have more feedback.

@rhatdan rhatdan closed this as completed Mar 8, 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 Aug 30, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Aug 30, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
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. stale-issue
Projects
None yet
Development

No branches or pull requests

5 participants