--userns=auto broken after upgrading to kernel 5.19

[klausenbusk]

Hi

Linux 5.19 added support for mounting overlay on top of idmapped layers and support was added with this PR: #1180.

After upgrading to 5.19 starting two containers with --userns=auto using the same image isn't working anymore (ex: 2x podman run --rm -t -i --userns=auto archlinux:latest as root).

When trying to start the second container it fails with:

ERRO[0000] Unmounting /var/lib/containers/storage/overlay/1847fe34a852f9f501b2f4a7dc9fc9f0b23d16edef89eb63c85da5dc15d9e7c0/merged: invalid argument 
Error: error mounting storage for container d0e00f9bd717a33f6f0f0841c98c3fa2f1338595789209f294d76a5fad6b93cc: create mapped mount for "/var/lib/containers/storage/overlay" on "/var/lib/containers/storage/overlay/1847fe34a852f9f501b2f4a7dc9fc9f0b23d16edef89eb63c85da5dc15d9e7c0/mapped/0": invalid argument

Full debug log for starting the second container:

time="2022-08-20T18:14:56+02:00" level=info msg="podman filtering at log level debug"
time="2022-08-20T18:14:56+02:00" level=debug msg="Called run.PersistentPreRunE(podman --log-level=debug run --rm -t -i --userns=auto archlinux:latest)"
time="2022-08-20T18:14:56+02:00" level=debug msg="Merged system config \"/usr/share/containers/containers.conf\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Merged system config \"/etc/containers/containers.conf\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using graph driver overlay"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using graph root /var/lib/containers/storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using run root /run/containers/storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using static dir /var/lib/containers/storage/libpod"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using tmp dir /run/libpod"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using volume path /var/lib/containers/storage/volumes"
time="2022-08-20T18:14:56+02:00" level=debug msg="Set libpod namespace to \"\""
time="2022-08-20T18:14:56+02:00" level=debug msg="[graphdriver] trying provided driver \"overlay\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that overlay is supported"
time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that overlay is supported"
time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that metacopy is being used"
time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that native-diff is not being used"
time="2022-08-20T18:14:56+02:00" level=info msg="Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled"
time="2022-08-20T18:14:56+02:00" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true"
time="2022-08-20T18:14:56+02:00" level=debug msg="Initializing event backend journald"
time="2022-08-20T18:14:56+02:00" level=debug msg="Configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"
time="2022-08-20T18:14:56+02:00" level=debug msg="Configured OCI runtime krun initialization failed: no valid executable found for OCI runtime krun: invalid argument"
time="2022-08-20T18:14:56+02:00" level=debug msg="Configured OCI runtime runc initialization failed: no valid executable found for OCI runtime runc: invalid argument"
time="2022-08-20T18:14:56+02:00" level=debug msg="Configured OCI runtime runj initialization failed: no valid executable found for OCI runtime runj: invalid argument"
time="2022-08-20T18:14:56+02:00" level=debug msg="Configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"
time="2022-08-20T18:14:56+02:00" level=debug msg="Using OCI runtime \"/usr/bin/crun\""
time="2022-08-20T18:14:56+02:00" level=info msg="Setting parallel job count to 25"
time="2022-08-20T18:14:56+02:00" level=debug msg="Pulling image archlinux:latest (policy: missing)"
time="2022-08-20T18:14:56+02:00" level=debug msg="Looking up image \"archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2022-08-20T18:14:56+02:00" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf.d/00-shortnames.conf\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Trying \"docker.io/archlinux/archlinux:latest\" ..."
time="2022-08-20T18:14:56+02:00" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage ([overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe)"
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Looking up image \"docker.io/archlinux/archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2022-08-20T18:14:56+02:00" level=debug msg="Trying \"docker.io/archlinux/archlinux:latest\" ..."
time="2022-08-20T18:14:56+02:00" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"docker.io/archlinux/archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"docker.io/archlinux/archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage ([overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe)"
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Looking up image \"archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux  [] }"
time="2022-08-20T18:14:56+02:00" level=debug msg="Trying \"docker.io/archlinux/archlinux:latest\" ..."
time="2022-08-20T18:14:56+02:00" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage"
time="2022-08-20T18:14:56+02:00" level=debug msg="Found image \"archlinux:latest\" as \"docker.io/archlinux/archlinux:latest\" in local containers storage ([overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe)"
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Inspecting image 88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe"
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Inspecting image 88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe"
time="2022-08-20T18:14:56+02:00" level=debug msg="Inspecting image 88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe"
time="2022-08-20T18:14:56+02:00" level=debug msg="Inspecting image 88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe"
time="2022-08-20T18:14:56+02:00" level=debug msg="using systemd mode: false"
time="2022-08-20T18:14:56+02:00" level=debug msg="No hostname set; container's hostname will default to runtime default"
time="2022-08-20T18:14:56+02:00" level=debug msg="Loading seccomp profile from \"/etc/containers/seccomp.json\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Successfully loaded network podman: &{podman 2f259bab93aaaaa2542ba43ef33eb990d0999ee1b9924b557b7be53c0b7a1bb9 bridge cni-podman0 2021-10-03 17:36:10.867291191 +0200 CEST [{{{10.88.0.0 ffff0000}} 10.88.0.1 <nil>}] false false false map[] map[] map[driver:host-local]}"
time="2022-08-20T18:14:56+02:00" level=debug msg="Successfully loaded 1 networks"
time="2022-08-20T18:14:56+02:00" level=debug msg="Allocated lock 5 for container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75"
time="2022-08-20T18:14:56+02:00" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/run/containers/storage:overlay.mountopt=nodev]@88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="exporting opaque data as blob \"sha256:88d9beaad92efd914ee5a5dd0300cff2ca8984f345ce1281b27fefd7cecee0fe\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that idmapped mounts for overlay are supported"
time="2022-08-20T18:14:56+02:00" level=debug msg="overlay: mount_data=lowerdir=/var/lib/containers/storage/overlay/l/LDZGOEIJ754GWWO52RQGX2VM5P:/var/lib/containers/storage/overlay/l/LEGU6SL74H2BCV4UKUHJ33AKAS,upperdir=/var/lib/containers/storage/overlay/b80641a241f2e64e46116a7e3baa1d9e4a4da1a19fa844f30e43c761a9e6a912/diff,workdir=/var/lib/containers/storage/overlay/b80641a241f2e64e46116a7e3baa1d9e4a4da1a19fa844f30e43c761a9e6a912/work,nodev"
time="2022-08-20T18:14:56+02:00" level=debug msg="Created container \"b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Container \"b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75\" has work directory \"/var/lib/containers/storage/overlay-containers/b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75/userdata\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Container \"b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75\" has run directory \"/run/containers/storage/overlay-containers/b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75/userdata\""
time="2022-08-20T18:14:56+02:00" level=debug msg="Handling terminal attach"
time="2022-08-20T18:14:56+02:00" level=debug msg="[graphdriver] trying provided driver \"overlay\""

time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that overlay is supported"

time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that overlay is supported"

time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that metacopy is being used"

time="2022-08-20T18:14:56+02:00" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true"

time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that idmapped mounts for overlay are supported"

time="2022-08-20T18:14:56+02:00" level=debug msg="Cached value indicated that volatile is being used"

time="2022-08-20T18:14:56+02:00" level=error msg="Unmounting /var/lib/containers/storage/overlay/09aebf7419c4ac9d1ef2368b71b9c3f081bdefd32f82837acf053fced252a428/merged: invalid argument"

time="2022-08-20T18:14:56+02:00" level=debug msg="Failed to mount container \"b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75\": create mapped mount for \"/var/lib/containers/storage/overlay\" on \"/var/lib/containers/storage/overlay/09aebf7419c4ac9d1ef2368b71b9c3f081bdefd32f82837acf053fced252a428/mapped/0\": invalid argument"

time="2022-08-20T18:14:56+02:00" level=debug msg="Network is already cleaned up, skipping..."

time="2022-08-20T18:14:56+02:00" level=debug msg="Cleaning up container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75"

time="2022-08-20T18:14:56+02:00" level=debug msg="Network is already cleaned up, skipping..."

time="2022-08-20T18:14:56+02:00" level=debug msg="Container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75 storage is already unmounted, skipping..."

time="2022-08-20T18:14:56+02:00" level=debug msg="Removing container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75"
time="2022-08-20T18:14:56+02:00" level=debug msg="Cleaning up container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75"
time="2022-08-20T18:14:56+02:00" level=debug msg="Network is already cleaned up, skipping..."
time="2022-08-20T18:14:56+02:00" level=debug msg="Container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75 storage is already unmounted, skipping..."
time="2022-08-20T18:14:56+02:00" level=debug msg="Removing all exec sessions for container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75"
time="2022-08-20T18:14:56+02:00" level=debug msg="Container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75 storage is already unmounted, skipping..."
time="2022-08-20T18:14:56+02:00" level=debug msg="ExitCode msg: \"error mounting storage for container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75: create mapped mount for \\\"/var/lib/containers/storage/overlay\\\" on \\\"/var/lib/containers/storage/overlay/09aebf7419c4ac9d1ef2368b71b9c3f081bdefd32f82837acf053fced252a428/mapped/0\\\": invalid argument\""
Error: error mounting storage for container b37b4eaccfbf9bbd142f3e31fb3915959be986a8390e444e06344d00eaec5e75: create mapped mount for "/var/lib/containers/storage/overlay" on "/var/lib/containers/storage/overlay/09aebf7419c4ac9d1ef2368b71b9c3f081bdefd32f82837acf053fced252a428/mapped/0": invalid argument

The same use-case was working without issues on 5.18. I see a DisableShifting option in the code, but I'm not sure how to set it, but it could help ruling out #1180 or confirming it is the issue.

Tested with both podman 4.1.1 and 4.2.0 on Arch Linux. Kernel 5.18.3-arch1-1 and 5.19.2-arch1-1.

[brauner]

If this is literally extfs then Idmapped mounts aren't supported on top of it. We only supported ext4 from the ext* family currently.

So when using idmapped mounts with overlayfs you first want to check that the filesystem used for the lower or upper layers which are supposed to be Idmapped support Idmapped mounts and then whether overlayfs supports being mounted on top of Idmapped layers. Not sure if both checks are currently performed.

[klausenbusk]

If this is literally extfs then Idmapped mounts aren't supported on top of it. We only supported ext4 from the ext* family currently.

I tested this on a host with ext4 as the rootfs and another host with btrfs as the rootfs. I get the same error in both cases. Could it be something missing in the kernel configuration?

[giuseppe]

I've fixed a similar issue some days ago #1309

basically I was using MS_REC causing existing overlay mounts on top of the storage directory also to be idmapped.

Does the issue you're seeing happen with the first container you create, or do you need at least two? Any chance you could try the patch I've linked above?

If that is not enough, there is something else going on when we test for idmapped mounts support. We already have a test in place to verify that idmapped mounts work on top of overlay before using them.

[klausenbusk]

Does the issue you're seeing happen with the first container you create, or do you need at least two?

It happens when I try to start the second container.

Any chance you could try the patch I've linked above?

Sure, I just built containers/podman@9a83fe3 and bumped github.com/containers/storage to 9ba108e (same error), afterwards I bumped it to d3f1078 and now I can start the second container.

#1308 sounds identical to my issue (not sure how I missed it). Thanks for the pointer :)