Rootless podman play kube fails to start a Pod when using custom podman build

[mgoltzsche]

I am maintaining an alternative alpine-based podman container image. When I tried to upgrade it from v4 to v5.1.1 here my e2e test case that runs the podman play kube command as unprivileged user 1000 within a docker container failed. Specifically it fails to mount /tmp/storage-run-1000/containers/networks/rootless-netns/run into the containers at /run because the directory /tmp/storage-run-1000/containers/networks/rootless-netns does not exist. The parent directory does exist, though. The podman play kube test case is the only one failing. All other tests succeed.
I am not reporting this as a podman bug since the test scenario works with the official podman image quay.io/podman/stable:v5.0.3, indicating that the problem is caused by my build.

Here's how to reproduce the problem:

1. Checkout Upgrade v5.1.1 mgoltzsche/podman-static#91.
2. Change into the checked out directory.
3. Build the container image: docker build -t local-podman .
4. Run the play kube command within the container (with a pod.yaml file mounted):

docker run --rm --privileged -u podman:podman --mount="type=bind,src=`pwd`/test/pod.yaml,dst=/pod.yaml" --entrypoint=podman local-podman play kube /pod.yaml

5. Watch the container fail:

Resolving "alpine" using unqualified-search registries (/etc/containers/registries.conf)
Trying to pull docker.io/library/alpine:3.17...
Getting image source signatures
Copying blob sha256:3c854c8cbf469fda815b8f6183300c07cfa2fbb5703859ca79aff93ae934961b
Copying config sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890
Writing manifest to image destination
[starting container 99f3e454cf839ffef97b00d436da3d48b034a96714bd9377d70d46c05ec93099: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory]
[starting container 99f3e454cf839ffef97b00d436da3d48b034a96714bd9377d70d46c05ec93099: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory starting container 416e44b910c1efbcc14737d4ea579b326f437cb1e69111d270387c24c76ab2d6: a dependency of container 416e44b910c1efbcc14737d4ea579b326f437cb1e69111d270387c24c76ab2d6 failed to start: container state improper]
Pod:
f705802d214f032732c2b92ab92c4bb822c822f6c95751f9d77bc24192b97f9c
Container:
416e44b910c1efbcc14737d4ea579b326f437cb1e69111d270387c24c76ab2d6


starting container 99f3e454cf839ffef97b00d436da3d48b034a96714bd9377d70d46c05ec93099: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory
starting container 416e44b910c1efbcc14737d4ea579b326f437cb1e69111d270387c24c76ab2d6: a dependency of container 416e44b910c1efbcc14737d4ea579b326f437cb1e69111d270387c24c76ab2d6 failed to start: container state improper
Error: failed to start 2 containers

I also ran the command with --log-level=debug but it didn't clarify the root cause for me:

Debug log

Debug log

time="2024-06-05T00:54:20Z" level=info msg="podman filtering at log level debug"
time="2024-06-05T00:54:20Z" level=debug msg="Called kube.PersistentPreRunE(podman --log-level=debug play kube /pod.yaml)"
time="2024-06-05T00:54:20Z" level=debug msg="Using conmon: \"/usr/local/lib/podman/conmon\""
time="2024-06-05T00:54:20Z" level=info msg="Using sqlite as database backend"
time="2024-06-05T00:54:20Z" level=debug msg="systemd-logind: dial unix /var/run/dbus/system_bus_socket: connect: no such file or directory"
time="2024-06-05T00:54:20Z" level=debug msg="Using graph driver overlay"
time="2024-06-05T00:54:20Z" level=debug msg="Using graph root /podman/.local/share/containers/storage"
time="2024-06-05T00:54:20Z" level=debug msg="Using run root /tmp/storage-run-1000/containers"
time="2024-06-05T00:54:20Z" level=debug msg="Using static dir /podman/.local/share/containers/storage/libpod"
time="2024-06-05T00:54:20Z" level=debug msg="Using tmp dir /tmp/storage-run-1000/libpod/tmp"
time="2024-06-05T00:54:20Z" level=debug msg="Using volume path /podman/.local/share/containers/storage/volumes"
time="2024-06-05T00:54:20Z" level=debug msg="Using transient store: false"
time="2024-06-05T00:54:20Z" level=debug msg="Not configuring container store"
time="2024-06-05T00:54:20Z" level=debug msg="Initializing event backend file"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime youki initialization failed: no valid executable found for OCI runtime youki: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime krun initialization failed: no valid executable found for OCI runtime krun: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun initialization failed: no valid executable found for OCI runtime crun: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun-vm initialization failed: no valid executable found for OCI runtime crun-vm: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun-wasm initialization failed: no valid executable found for OCI runtime crun-wasm: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime runj initialization failed: no valid executable found for OCI runtime runj: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime ocijail initialization failed: no valid executable found for OCI runtime ocijail: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Using OCI runtime \"/usr/local/bin/runc\""
time="2024-06-05T00:54:20Z" level=info msg="podman filtering at log level debug"
time="2024-06-05T00:54:20Z" level=debug msg="Called kube.PersistentPreRunE(podman --log-level=debug play kube /pod.yaml)"
time="2024-06-05T00:54:20Z" level=debug msg="Using conmon: \"/usr/local/lib/podman/conmon\""
time="2024-06-05T00:54:20Z" level=info msg="Using sqlite as database backend"
time="2024-06-05T00:54:20Z" level=debug msg="systemd-logind: dial unix /var/run/dbus/system_bus_socket: connect: no such file or directory"
time="2024-06-05T00:54:20Z" level=debug msg="Using graph driver overlay"
time="2024-06-05T00:54:20Z" level=debug msg="Using graph root /podman/.local/share/containers/storage"
time="2024-06-05T00:54:20Z" level=debug msg="Using run root /tmp/storage-run-1000/containers"
time="2024-06-05T00:54:20Z" level=debug msg="Using static dir /podman/.local/share/containers/storage/libpod"
time="2024-06-05T00:54:20Z" level=debug msg="Using tmp dir /tmp/storage-run-1000/libpod/tmp"
time="2024-06-05T00:54:20Z" level=debug msg="Using volume path /podman/.local/share/containers/storage/volumes"
time="2024-06-05T00:54:20Z" level=debug msg="Using transient store: false"
time="2024-06-05T00:54:20Z" level=debug msg="[graphdriver] trying provided driver \"overlay\""
time="2024-06-05T00:54:20Z" level=debug msg="overlay: ignore_chown_errors=true"
time="2024-06-05T00:54:20Z" level=debug msg="Unable to create kernel-style whiteout: operation not permitted"
time="2024-06-05T00:54:20Z" level=debug msg="backingFs=overlayfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false"
time="2024-06-05T00:54:20Z" level=debug msg="Initializing event backend file"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime youki initialization failed: no valid executable found for OCI runtime youki: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun initialization failed: no valid executable found for OCI runtime crun: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun-vm initialization failed: no valid executable found for OCI runtime crun-vm: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime runj initialization failed: no valid executable found for OCI runtime runj: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime krun initialization failed: no valid executable found for OCI runtime krun: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime ocijail initialization failed: no valid executable found for OCI runtime ocijail: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Configured OCI runtime crun-wasm initialization failed: no valid executable found for OCI runtime crun-wasm: invalid argument"
time="2024-06-05T00:54:20Z" level=debug msg="Using OCI runtime \"/usr/local/bin/runc\""
time="2024-06-05T00:54:20Z" level=debug msg="Initialized SHM lock manager at path /libpod_rootless_lock_1000"
time="2024-06-05T00:54:20Z" level=debug msg="Podman detected system restart - performing state refresh"
time="2024-06-05T00:54:20Z" level=info msg="Setting parallel job count to 49"
time="2024-06-05T00:54:20Z" level=debug msg="Could not move to subcgroup: mkdir /sys/fs/cgroup/init: permission denied"
time="2024-06-05T00:54:20Z" level=debug msg="Successfully loaded 1 networks"
time="2024-06-05T00:54:20Z" level=debug msg="found free device name podman1"
time="2024-06-05T00:54:20Z" level=debug msg="found free ipv4 network subnet 10.89.0.0/24"
time="2024-06-05T00:54:20Z" level=debug msg="Looking up image \"localhost/podman-pause:5.1.1-0\" in local containers storage"
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/podman-pause:5.1.1-0\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/podman-pause:5.1.1-0\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/podman-pause:5.1.1-0\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="FROM \"scratch\""
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="overlay: mount_data=lowerdir=/podman/.local/share/containers/storage/overlay/a4885a717ffa4342782673a8986868ae52e6e7a79b0d68c8c8c536f448563003/empty,upperdir=/podman/.local/share/containers/storage/overlay/a4885a717ffa4342782673a8986868ae52e6e7a79b0d68c8c8c536f448563003/diff,workdir=/podman/.local/share/containers/storage/overlay/a4885a717ffa4342782673a8986868ae52e6e7a79b0d68c8c8c536f448563003/work,volatile"
time="2024-06-05T00:54:20Z" level=debug msg="Container ID: 1ad509f0ee50404f1f4f7a2a4e35674f5a503727c771ae64a7338c36d2c66358"
time="2024-06-05T00:54:20Z" level=debug msg="Parsed Step: {Env:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] Command:copy Args:[/usr/local/lib/podman/catatonit /catatonit] Flags:[] Attrs:map[] Message:COPY /usr/local/lib/podman/catatonit /catatonit Heredocs:[] Original:COPY /usr/local/lib/podman/catatonit /catatonit}"
time="2024-06-05T00:54:20Z" level=debug msg="COPY []string(nil), imagebuilder.Copy{FromFS:false, From:\"\", Src:[]string{\"/usr/local/lib/podman/catatonit\"}, Dest:\"/catatonit\", Download:false, Chown:\"\", Chmod:\"\", Checksum:\"\", Files:[]imagebuilder.File(nil)}"
time="2024-06-05T00:54:20Z" level=debug msg="added content file:d0cd4e6ac234d396090aa185ba5a7499444c169d3c4bdd4386b2dabe7d866bd8"
time="2024-06-05T00:54:20Z" level=debug msg="Parsed Step: {Env:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] Command:entrypoint Args:[/catatonit -P] Flags:[] Attrs:map[json:true] Message:ENTRYPOINT /catatonit -P Heredocs:[] Original:ENTRYPOINT [\"/catatonit\", \"-P\"]}"
time="2024-06-05T00:54:20Z" level=debug msg="COMMIT localhost/podman-pause:5.1.1-0"
time="2024-06-05T00:54:20Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\""
time="2024-06-05T00:54:20Z" level=debug msg="COMMIT \"containers-storage:[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\""
time="2024-06-05T00:54:20Z" level=debug msg="committing image with reference \"containers-storage:[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\" is allowed by policy"
time="2024-06-05T00:54:20Z" level=debug msg="layer list: [\"a4885a717ffa4342782673a8986868ae52e6e7a79b0d68c8c8c536f448563003\"]"
time="2024-06-05T00:54:20Z" level=debug msg="using \"/var/tmp/buildah2883076953\" to hold temporary data"
time="2024-06-05T00:54:20Z" level=debug msg="layer \"a4885a717ffa4342782673a8986868ae52e6e7a79b0d68c8c8c536f448563003\" size is 373248 bytes, uncompressed digest sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8, possibly-compressed digest sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8"
time="2024-06-05T00:54:20Z" level=debug msg="OCIv1 config = {\"created\":\"2024-06-05T00:54:20.381249519Z\",\"architecture\":\"amd64\",\"os\":\"linux\",\"config\":{\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Entrypoint\":[\"/catatonit\",\"-P\"],\"Labels\":{\"io.buildah.version\":\"1.36.0\"}},\"rootfs\":{\"type\":\"layers\",\"diff_ids\":[\"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\"]},\"history\":[{\"created\":\"2024-06-05T00:54:20.380902598Z\",\"created_by\":\"/bin/sh -c #(nop) COPY file:d0cd4e6ac234d396090aa185ba5a7499444c169d3c4bdd4386b2dabe7d866bd8 in /catatonit \",\"empty_layer\":true},{\"created\":\"2024-06-05T00:54:20.382529687Z\",\"created_by\":\"/bin/sh -c #(nop) ENTRYPOINT [\\\"/catatonit\\\", \\\"-P\\\"]\"}]}"
time="2024-06-05T00:54:20Z" level=debug msg="OCIv1 manifest = {\"schemaVersion\":2,\"mediaType\":\"application/vnd.oci.image.manifest.v1+json\",\"config\":{\"mediaType\":\"application/vnd.oci.image.config.v1+json\",\"digest\":\"sha256:23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\",\"size\":668},\"layers\":[{\"mediaType\":\"application/vnd.oci.image.layer.v1.tar\",\"digest\":\"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\",\"size\":373248}],\"annotations\":{\"org.opencontainers.image.base.digest\":\"\",\"org.opencontainers.image.base.name\":\"\"}}"
time="2024-06-05T00:54:20Z" level=debug msg="Docker v2s2 config = {\"created\":\"2024-06-05T00:54:20.381249519Z\",\"container\":\"1ad509f0ee50404f1f4f7a2a4e35674f5a503727c771ae64a7338c36d2c66358\",\"container_config\":{\"Hostname\":\"\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[],\"Image\":\"\",\"Volumes\":{},\"WorkingDir\":\"\",\"Entrypoint\":[\"/catatonit\",\"-P\"],\"OnBuild\":[],\"Labels\":{\"io.buildah.version\":\"1.36.0\"}},\"config\":{\"Hostname\":\"\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[],\"Image\":\"\",\"Volumes\":{},\"WorkingDir\":\"\",\"Entrypoint\":[\"/catatonit\",\"-P\"],\"OnBuild\":[],\"Labels\":{\"io.buildah.version\":\"1.36.0\"}},\"architecture\":\"amd64\",\"os\":\"linux\",\"rootfs\":{\"type\":\"layers\",\"diff_ids\":[\"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\"]},\"history\":[{\"created\":\"2024-06-05T00:54:20.380902598Z\",\"created_by\":\"/bin/sh -c #(nop) COPY file:d0cd4e6ac234d396090aa185ba5a7499444c169d3c4bdd4386b2dabe7d866bd8 in /catatonit \",\"empty_layer\":true},{\"created\":\"2024-06-05T00:54:20.382529687Z\",\"created_by\":\"/bin/sh -c #(nop) ENTRYPOINT [\\\"/catatonit\\\", \\\"-P\\\"]\"}]}"
time="2024-06-05T00:54:20Z" level=debug msg="Docker v2s2 manifest = {\"schemaVersion\":2,\"mediaType\":\"application/vnd.docker.distribution.manifest.v2+json\",\"config\":{\"mediaType\":\"application/vnd.docker.container.image.v1+json\",\"size\":1342,\"digest\":\"sha256:8f19d6980e9eebede3acf94a355408dbe4bf8deca60476af6df891e339e083de\"},\"layers\":[{\"mediaType\":\"application/vnd.docker.image.rootfs.diff.tar\",\"size\":373248,\"digest\":\"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\"}]}"
time="2024-06-05T00:54:20Z" level=debug msg="Using SQLite blob info cache at /podman/.local/share/containers/cache/blob-info-cache-v1.sqlite"
time="2024-06-05T00:54:20Z" level=debug msg="IsRunningImageAllowed for image containers-storage:"
time="2024-06-05T00:54:20Z" level=debug msg=" Using transport \"containers-storage\" policy section \"\""
time="2024-06-05T00:54:20Z" level=debug msg=" Requirement 0: allowed"
time="2024-06-05T00:54:20Z" level=debug msg="Overall: allowed"
time="2024-06-05T00:54:20Z" level=debug msg="start reading config"
time="2024-06-05T00:54:20Z" level=debug msg="finished reading config"
time="2024-06-05T00:54:20Z" level=debug msg="Manifest has MIME type application/vnd.oci.image.manifest.v1+json, ordered candidate list [application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.docker.distribution.manifest.v1+json]"
time="2024-06-05T00:54:20Z" level=debug msg="... will first try using the original manifest unmodified"
time="2024-06-05T00:54:20Z" level=debug msg="Checking if we can reuse blob sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8: general substitution = true, compression for MIME type \"application/vnd.oci.image.layer.v1.tar\" = true"
time="2024-06-05T00:54:20Z" level=debug msg="reading layer \"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\""
time="2024-06-05T00:54:20Z" level=debug msg="No compression detected"
time="2024-06-05T00:54:20Z" level=debug msg="Using original blob without modification"
time="2024-06-05T00:54:20Z" level=debug msg="Applying tar in /podman/.local/share/containers/storage/overlay/c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8/diff"
time="2024-06-05T00:54:20Z" level=debug msg="finished reading layer \"sha256:c749259dab5e8173e7615277d927e0bc2f9a36de3bf982dd5121098af89f9df8\""
time="2024-06-05T00:54:20Z" level=debug msg="No compression detected"
time="2024-06-05T00:54:20Z" level=debug msg="Compression change for blob sha256:23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958 (\"application/vnd.oci.image.config.v1+json\") not supported"
time="2024-06-05T00:54:20Z" level=debug msg="Using original blob without modification"
time="2024-06-05T00:54:20Z" level=debug msg="setting image creation date to 2024-06-05 00:54:20.381249519 +0000 UTC"
time="2024-06-05T00:54:20Z" level=debug msg="created new image ID \"23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\" with metadata \"{}\""
time="2024-06-05T00:54:20Z" level=debug msg="added name \"localhost/podman-pause:5.1.1-0\" to image \"23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/podman-pause:5.1.1-0\""
time="2024-06-05T00:54:20Z" level=debug msg="printing final image id \"23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="Pod using bridge network mode"
time="2024-06-05T00:54:20Z" level=debug msg="Got pod cgroup as /libpod_parent/3579fb5e07a14738498ef1c5780a16321d8eb81b704b0e0f3878f098ad4187b9"
time="2024-06-05T00:54:20Z" level=debug msg="Looking up image \"localhost/podman-pause:5.1.1-0\" in local containers storage"
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/podman-pause:5.1.1-0\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="Found image \"localhost/podman-pause:5.1.1-0\" as \"localhost/podman-pause:5.1.1-0\" in local containers storage"
time="2024-06-05T00:54:20Z" level=debug msg="Found image \"localhost/podman-pause:5.1.1-0\" as \"localhost/podman-pause:5.1.1-0\" in local containers storage ([overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958)"
time="2024-06-05T00:54:20Z" level=debug msg="exporting opaque data as blob \"sha256:23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="Inspecting image 23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958"
time="2024-06-05T00:54:20Z" level=debug msg="exporting opaque data as blob \"sha256:23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="Inspecting image 23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958"
time="2024-06-05T00:54:20Z" level=debug msg="Inspecting image 23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958"
time="2024-06-05T00:54:20Z" level=debug msg="using systemd mode: false"
time="2024-06-05T00:54:20Z" level=debug msg="setting container name 3579fb5e07a1-infra"
time="2024-06-05T00:54:20Z" level=debug msg="Loading default seccomp profile"
time="2024-06-05T00:54:20Z" level=debug msg="Successfully loaded network podman-default-kube-network: &{podman-default-kube-network fb598caca0ff255c8bc78dc1586de3b78aa63b6b2e11f6132c7b4b0233dd3946 bridge podman1 2024-06-05 00:54:20.30417581 +0000 UTC [{{{10.89.0.0 ffffff00}} 10.89.0.1 <nil>}] [] false false true [] map[] map[] map[driver:host-local]}"
time="2024-06-05T00:54:20Z" level=debug msg="Successfully loaded 2 networks"
time="2024-06-05T00:54:20Z" level=debug msg="Allocated lock 1 for container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1"
time="2024-06-05T00:54:20Z" level=debug msg="exporting opaque data as blob \"sha256:23b22e4066df67f8eef758a70d4e3b5796ae40665ef44cc004ea302bb1a4d958\""
time="2024-06-05T00:54:20Z" level=debug msg="Created container \"00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1\""
time="2024-06-05T00:54:20Z" level=debug msg="Container \"00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1\" has work directory \"/podman/.local/share/containers/storage/overlay-containers/00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1/userdata\""
time="2024-06-05T00:54:20Z" level=debug msg="Container \"00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1\" has run directory \"/tmp/storage-run-1000/containers/overlay-containers/00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1/userdata\""
time="2024-06-05T00:54:20Z" level=debug msg="Looking up image \"alpine:3.17\" in local containers storage"
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf\""
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"docker.io/library/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"registry.fedoraproject.org/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]registry.fedoraproject.org/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"registry.access.redhat.com/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]registry.access.redhat.com/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"docker.io/library/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="Pulling image alpine:3.17 (policy: missing)"
time="2024-06-05T00:54:20Z" level=debug msg="Looking up image \"alpine:3.17\" in local containers storage"
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"localhost/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"docker.io/library/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"registry.fedoraproject.org/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]registry.fedoraproject.org/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"registry.access.redhat.com/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]registry.access.redhat.com/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"docker.io/library/alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:20Z" level=debug msg="Trying \"alpine:3.17\" ..."
time="2024-06-05T00:54:20Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:20Z" level=debug msg="Attempting to pull candidate docker.io/library/alpine:3.17 for alpine:3.17"
time="2024-06-05T00:54:20Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17\""
time="2024-06-05T00:54:20Z" level=debug msg="Resolving \"alpine\" using unqualified-search registries (/etc/containers/registries.conf)"
Resolving "alpine" using unqualified-search registries (/etc/containers/registries.conf)
Trying to pull docker.io/library/alpine:3.17...
time="2024-06-05T00:54:20Z" level=debug msg="Copying source image //alpine:3.17 to destination image [overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]docker.io/library/alpine:3.17"
time="2024-06-05T00:54:20Z" level=debug msg="Using registries.d directory /etc/containers/registries.d"
time="2024-06-05T00:54:20Z" level=debug msg="Trying to access \"docker.io/library/alpine:3.17\""
time="2024-06-05T00:54:20Z" level=debug msg="No credentials matching docker.io/library/alpine found in /tmp/storage-run-1000/containers/auth.json"
time="2024-06-05T00:54:20Z" level=debug msg="No credentials matching docker.io/library/alpine found in /podman/.config/containers/auth.json"
time="2024-06-05T00:54:20Z" level=debug msg="No credentials matching docker.io/library/alpine found in /podman/.docker/config.json"
time="2024-06-05T00:54:20Z" level=debug msg="No credentials matching docker.io/library/alpine found in /podman/.dockercfg"
time="2024-06-05T00:54:20Z" level=debug msg="No credentials for docker.io/library/alpine found"
time="2024-06-05T00:54:20Z" level=debug msg=" No signature storage configuration found for docker.io/library/alpine:3.17, using built-in default file:///podman/.local/share/containers/sigstore"
time="2024-06-05T00:54:20Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io"
time="2024-06-05T00:54:20Z" level=debug msg="GET https://registry-1.docker.io/v2/"
time="2024-06-05T00:54:20Z" level=debug msg="Ping https://registry-1.docker.io/v2/ status 401"
time="2024-06-05T00:54:20Z" level=debug msg="GET https://auth.docker.io/token?scope=repository%3Alibrary%2Falpine%3Apull&service=registry.docker.io"
time="2024-06-05T00:54:21Z" level=debug msg="GET https://registry-1.docker.io/v2/library/alpine/manifests/3.17"
time="2024-06-05T00:54:21Z" level=debug msg="Content-Type from manifest GET is \"application/vnd.docker.distribution.manifest.list.v2+json\""
time="2024-06-05T00:54:21Z" level=debug msg="Using SQLite blob info cache at /podman/.local/share/containers/cache/blob-info-cache-v1.sqlite"
time="2024-06-05T00:54:21Z" level=debug msg="Source is a manifest list; copying (only) instance sha256:f9b3530b7b1ac155e376c9f2952ac3db64d9478c50a0d1af74399618190dd99c for current system"
time="2024-06-05T00:54:21Z" level=debug msg="GET https://registry-1.docker.io/v2/library/alpine/manifests/sha256:f9b3530b7b1ac155e376c9f2952ac3db64d9478c50a0d1af74399618190dd99c"
time="2024-06-05T00:54:21Z" level=debug msg="Content-Type from manifest GET is \"application/vnd.docker.distribution.manifest.v2+json\""
time="2024-06-05T00:54:21Z" level=debug msg="IsRunningImageAllowed for image docker:docker.io/library/alpine:3.17"
time="2024-06-05T00:54:21Z" level=debug msg=" Using default policy section"
time="2024-06-05T00:54:21Z" level=debug msg=" Requirement 0: allowed"
time="2024-06-05T00:54:21Z" level=debug msg="Overall: allowed"
time="2024-06-05T00:54:21Z" level=debug msg="Downloading /v2/library/alpine/blobs/sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
time="2024-06-05T00:54:21Z" level=debug msg="GET https://registry-1.docker.io/v2/library/alpine/blobs/sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
Getting image source signatures
time="2024-06-05T00:54:22Z" level=debug msg="Reading /podman/.local/share/containers/sigstore/library/alpine@sha256=f9b3530b7b1ac155e376c9f2952ac3db64d9478c50a0d1af74399618190dd99c/signature-1"
time="2024-06-05T00:54:22Z" level=debug msg="Not looking for sigstore attachments: disabled by configuration"
time="2024-06-05T00:54:22Z" level=debug msg="Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json]"
time="2024-06-05T00:54:22Z" level=debug msg="... will first try using the original manifest unmodified"
Copying blob sha256:3c854c8cbf469fda815b8f6183300c07cfa2fbb5703859ca79aff93ae934961b
time="2024-06-05T00:54:22Z" level=debug msg="Checking if we can reuse blob sha256:3c854c8cbf469fda815b8f6183300c07cfa2fbb5703859ca79aff93ae934961b: general substitution = true, compression for MIME type \"application/vnd.docker.image.rootfs.diff.tar.gzip\" = true"
time="2024-06-05T00:54:22Z" level=debug msg="Failed to retrieve partial blob: convert_images not configured"
time="2024-06-05T00:54:22Z" level=debug msg="Downloading /v2/library/alpine/blobs/sha256:3c854c8cbf469fda815b8f6183300c07cfa2fbb5703859ca79aff93ae934961b"
time="2024-06-05T00:54:22Z" level=debug msg="GET https://registry-1.docker.io/v2/library/alpine/blobs/sha256:3c854c8cbf469fda815b8f6183300c07cfa2fbb5703859ca79aff93ae934961b"
time="2024-06-05T00:54:22Z" level=debug msg="Detected compression format gzip"
time="2024-06-05T00:54:22Z" level=debug msg="Using original blob without modification"
time="2024-06-05T00:54:22Z" level=debug msg="Applying tar in /podman/.local/share/containers/storage/overlay/f4111324080ce5b633fab04c0f3f21b587f2ac10a289cc9e2760c67e0d26711c/diff"
Copying config sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890
time="2024-06-05T00:54:22Z" level=debug msg="No compression detected"
time="2024-06-05T00:54:22Z" level=debug msg="Compression change for blob sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890 (\"application/vnd.docker.container.image.v1+json\") not supported"
time="2024-06-05T00:54:22Z" level=debug msg="Using original blob without modification"
Writing manifest to image destination
time="2024-06-05T00:54:22Z" level=debug msg="setting image creation date to 2024-01-27 00:31:02.7684662 +0000 UTC"
time="2024-06-05T00:54:22Z" level=debug msg="created new image ID \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" with metadata \"{}\""
time="2024-06-05T00:54:22Z" level=debug msg="added name \"docker.io/library/alpine:3.17\" to image \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Pulled candidate docker.io/library/alpine:3.17 successfully"
time="2024-06-05T00:54:22Z" level=debug msg="Looking up image \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" in local containers storage"
time="2024-06-05T00:54:22Z" level=debug msg="Trying \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" ..."
time="2024-06-05T00:54:22Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Found image \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" as \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" in local containers storage"
time="2024-06-05T00:54:22Z" level=debug msg="Found image \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" as \"eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\" in local containers storage ([overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890)"
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Inspecting image eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Looking up image \"alpine:3.17\" in local containers storage"
time="2024-06-05T00:54:22Z" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2024-06-05T00:54:22Z" level=debug msg="Trying \"localhost/alpine:3.17\" ..."
time="2024-06-05T00:54:22Z" level=debug msg="reference \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]localhost/alpine:3.17\" does not resolve to an image ID"
time="2024-06-05T00:54:22Z" level=debug msg="Trying \"docker.io/library/alpine:3.17\" ..."
time="2024-06-05T00:54:22Z" level=debug msg="parsed reference into \"[overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Found image \"alpine:3.17\" as \"docker.io/library/alpine:3.17\" in local containers storage"
time="2024-06-05T00:54:22Z" level=debug msg="Found image \"alpine:3.17\" as \"docker.io/library/alpine:3.17\" in local containers storage ([overlay@/podman/.local/share/containers/storage+/tmp/storage-run-1000/containers:overlay.ignore_chown_errors=true]@eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890)"
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Inspecting image eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Inspecting image eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
time="2024-06-05T00:54:22Z" level=debug msg="Inspecting image eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890"
time="2024-06-05T00:54:22Z" level=debug msg="using systemd mode: false"
time="2024-06-05T00:54:22Z" level=debug msg="adding container to pod mypod"
time="2024-06-05T00:54:22Z" level=debug msg="setting container name mypod-build"
time="2024-06-05T00:54:22Z" level=debug msg="Loading default seccomp profile"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /proc"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /dev"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /dev/pts"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /dev/mqueue"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /sys"
time="2024-06-05T00:54:22Z" level=debug msg="Adding mount /sys/fs/cgroup"
time="2024-06-05T00:54:22Z" level=debug msg="Allocated lock 2 for container 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34"
time="2024-06-05T00:54:22Z" level=debug msg="exporting opaque data as blob \"sha256:eaba187917ccc6af1386ecfdd95a56858a553d14888387980fb07b326e8ce890\""
time="2024-06-05T00:54:22Z" level=debug msg="Created container \"1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34\""
time="2024-06-05T00:54:22Z" level=debug msg="Container \"1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34\" has work directory \"/podman/.local/share/containers/storage/overlay-containers/1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34/userdata\""
time="2024-06-05T00:54:22Z" level=debug msg="Container \"1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34\" has run directory \"/tmp/storage-run-1000/containers/overlay-containers/1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34/userdata\""
time="2024-06-05T00:54:22Z" level=debug msg="Strongconnecting node 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1"
time="2024-06-05T00:54:22Z" level=debug msg="Pushed 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1 onto stack"
time="2024-06-05T00:54:22Z" level=debug msg="Finishing node 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1. Popped 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1 off stack"
time="2024-06-05T00:54:22Z" level=debug msg="Strongconnecting node 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34"
time="2024-06-05T00:54:22Z" level=debug msg="Pushed 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34 onto stack"
time="2024-06-05T00:54:22Z" level=debug msg="Finishing node 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34. Popped 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34 off stack"
time="2024-06-05T00:54:22Z" level=debug msg="overlay: mount_data=lowerdir=/podman/.local/share/containers/storage/overlay/l/UKMA2EFG57QG3YT4WETB7FXTPD,upperdir=/podman/.local/share/containers/storage/overlay/5351cac92d1782b22203d6f5d006c7332c6907815d304da7ba9d8446ea2db5d6/diff,workdir=/podman/.local/share/containers/storage/overlay/5351cac92d1782b22203d6f5d006c7332c6907815d304da7ba9d8446ea2db5d6/work"
time="2024-06-05T00:54:22Z" level=debug msg="Made network namespace at /tmp/storage-run-1000/netns/netns-dda30f4f-e782-ee8e-91a8-a1db3be0478c for container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1"
time="2024-06-05T00:54:22Z" level=debug msg="Mounted container \"00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1\" at \"/podman/.local/share/containers/storage/overlay/5351cac92d1782b22203d6f5d006c7332c6907815d304da7ba9d8446ea2db5d6/merged\""
time="2024-06-05T00:54:22Z" level=debug msg="Created root filesystem for container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1 at /podman/.local/share/containers/storage/overlay/5351cac92d1782b22203d6f5d006c7332c6907815d304da7ba9d8446ea2db5d6/merged"
time="2024-06-05T00:54:22Z" level=debug msg="Creating rootless network namespace at \"/tmp/storage-run-1000/containers/networks/rootless-netns/rootless-netns\""
time="2024-06-05T00:54:22Z" level=debug msg="pasta arguments: --config-net --pid /tmp/storage-run-1000/containers/networks/rootless-netns/rootless-netns-conn.pid --dns-forward 169.254.0.1 -t none -u none -T none -U none --no-map-gw --quiet --netns /tmp/storage-run-1000/containers/networks/rootless-netns/rootless-netns"
time="2024-06-05T00:54:22Z" level=debug msg="The path of /etc/resolv.conf in the mount ns is \"/etc/resolv.conf\""
time="2024-06-05T00:54:22Z" level=debug msg="Cleaning up rootless network namespace"
time="2024-06-05T00:54:22Z" level=debug msg="Unmounted container \"00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1\""
time="2024-06-05T00:54:22Z" level=debug msg="Network is already cleaned up, skipping..."
time="2024-06-05T00:54:22Z" level=debug msg="Cleaning up container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1"
time="2024-06-05T00:54:22Z" level=debug msg="Network is already cleaned up, skipping..."
time="2024-06-05T00:54:22Z" level=debug msg="Container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1 storage is already unmounted, skipping..."
[starting container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory]
[starting container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory starting container 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34: a dependency of container 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34 failed to start: container state improper]
Pod:
3579fb5e07a14738498ef1c5780a16321d8eb81b704b0e0f3878f098ad4187b9
Container:
1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34


starting container 00a770724f38ed07d8fed49eefbb806360132185464a08d9f658f3b2f8b1ecb1: rootless netns: mount "/tmp/storage-run-1000/containers/networks/rootless-netns/run" to "/run": no such file or directory
starting container 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34: a dependency of container 1c510489566bf56f03f1e7efce3f0963bcd2c6182db4af5b9a7e8949ac774a34 failed to start: container state improper
Error: failed to start 2 containers
time="2024-06-05T00:54:22Z" level=debug msg="Shutting down engines"
time="2024-06-05T00:54:22Z" level=debug msg="Failed to add pause process to systemd sandbox cgroup: dbus: couldn't determine address of session bus"

Here's the `podman info` output.

podman info

$ docker run --rm --privileged -u podman:podman --mount="type=bind,src=`pwd`/test/pod.yaml,dst=/pod.yaml" --entrypoint=podman local-podman info
host:
  arch: amd64
  buildahVersion: 1.36.0
  cgroupControllers:
  - cpuset
  - cpu
  - io
  - memory
  - hugetlb
  - pids
  - rdma
  - misc
  cgroupManager: cgroupfs
  cgroupVersion: v2
  conmon:
    package: Unknown
    path: /usr/local/lib/podman/conmon
    version: 'conmon version 2.1.10, commit: e21e7c85b7637e622f21c57675bf1154fc8b1866'
  cpuUtilization:
    idlePercent: 95.05
    systemPercent: 1.17
    userPercent: 3.78
  cpus: 16
  databaseBackend: sqlite
  distribution:
    distribution: alpine
    version: 3.19.1
  eventLogger: file
  freeLocks: 2048
  hostname: af6b5e2ff570
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 1
      size: 999
    - container_id: 1000
      host_id: 1001
      size: 64535
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 1
      size: 999
    - container_id: 1000
      host_id: 1001
      size: 64535
  kernel: 6.5.0-35-generic
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 3124318208
  memTotal: 33532874752
  networkBackend: netavark
  networkBackendInfo:
    backend: netavark
    dns:
      package: Unknown
      path: /usr/local/lib/podman/aardvark-dns
      version: aardvark-dns 1.10.0
    package: Unknown
    path: /usr/local/lib/podman/netavark
    version: netavark 1.10.3
  ociRuntime:
    name: runc
    package: Unknown
    path: /usr/local/bin/runc
    version: |-
      runc version 1.1.12
      commit: v1.1.12-0-g51d5e946
      spec: 1.0.2-dev
      go: go1.20.13
      libseccomp: 2.5.4
  os: linux
  pasta:
    executable: /usr/local/bin/pasta
    package: Unknown
    version: |
      pasta 2024_05_23.765eb0b
      Copyright Red Hat
      GNU General Public License, version 2 or later
        <https://www.gnu.org/licenses/old-licenses/gpl-2.0.html>
      This is free software: you are free to change and redistribute it.
      There is NO WARRANTY, to the extent permitted by law.
  remoteSocket:
    exists: false
    path: /tmp/storage-run-1000/podman/podman.sock
  rootlessNetworkCmd: pasta
  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: ""
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: ""
    package: ""
    version: ""
  swapFree: 41943035904
  swapTotal: 41943035904
  uptime: 3h 51m 15.00s (Approximately 0.12 days)
  variant: ""
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries:
  search:
  - docker.io
  - registry.fedoraproject.org
  - registry.access.redhat.com
store:
  configFile: /podman/.config/containers/storage.conf
  containerStore:
    number: 0
    paused: 0
    running: 0
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.ignore_chown_errors: "true"
  graphRoot: /podman/.local/share/containers/storage
  graphRootAllocated: 102610972672
  graphRootUsed: 71358771200
  graphStatus:
    Backing Filesystem: overlayfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Supports shifting: "true"
    Supports volatile: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 0
  runRoot: /tmp/storage-run-1000/containers
  transientStore: false
  volumePath: /podman/.local/share/containers/storage/volumes
version:
  APIVersion: 5.1.1
  Built: 0
  BuiltTime: Thu Jan  1 00:00:00 1970
  GitCommit: ""
  GoVersion: go1.22.4
  Os: linux
  OsArch: linux/amd64
  Version: 5.1.1

Running the test using the minimal version of the image that uses crun instead of runc and that has the same containers.conf as the official podman container results in the same problem.

Since this works with the official podman container I wonder what am I missing within my custom container image?
Any hint would be appreciated!

[Luap99]

Likely a bug in podman, I cannot see where we actually create the .../rootless-netns/run dir explicitly.
It only works implicitly because .../rootless-netns/run/systemd will be created before that but if there is not happen if there is no /run/systemd so a bug

so I guess you could just run mkdir /run/systemd for now as workaround.

[Luap99]

containers/common#2042 should fix it so feel free to patch your podman build with it or use the mentioned workaround in the image.

[trentapple]

Thanks @Luap99 — makes sense why it would break in Alpine Linux when non systemd since it was implicitly depending on (user) systemd for that path to exist. The relative path (…) also would explain why the path from the test output does not contain systemd in it (/tmp/storage-run-1000/containers/networks/rootless-netns/run in this scenario).

[mgoltzsche]

ah, thanks @Luap99!

[mgoltzsche]

With a workaround (mkdir -pm700 /tmp/storage-run-1000/containers/networks/rootless-netns/run) the test passed, indeed.
Looking forward to the release of the fix.