Rootless podman with --userns keep-id fails due to no permissions

[maringuu]

/kind bug

Edit:
I just realised that the problem might be that conmon fails to start. But why it fails to start is a miracle to me.

Syslog entrys from conmon

Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <ndebug>: failed to write to /proc/self/oom_score_adj: Permission denied  
Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <ninfo>: socket path: /run/user/1000/libpod/tmp/socket/0b01f11f4998d30c04a771950939184be0390757fbd771dd24f30c177334f763/attach 
Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <ninfo>: addr{sun_family=AF_UNIX, sun_path=0b01f11f4998d30c04a771950939184be0390757fbd771dd24f30c177334f763/attach} 
Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <ninfo>: terminal_ctrl_fd: 15 
Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <ninfo>: winsz read side: 17, winsz write side: 17 
Dec 28 23:22:57 marten-xps user.info : conmon 0b01f11f4998d30c04a7 <nwarn>: Failed to chown stdin

Description
When running podman with --userns keep-id it fails because it cant access files in /run/user/1000/containers/overlay-containers/ContainerID/userdata

Steps to reproduce the issue:

1. Run `podman run --userns keep-id debian id

My logs for this with `--loglevel debug`

time="2020-12-28T20:25:49+01:00" level=info msg="podman filtering at log level debug"
time="2020-12-28T20:25:49+01:00" level=debug msg="Called run.PersistentPreRunE(podman run --log-level=debug --userns keep-id debian id)"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
time="2020-12-28T20:25:49+01:00" level=debug msg="Initializing boltdb state at /home/maringuu/.local/share/containers/storage/libpod/bolt_state.db"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using graph driver overlay"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using graph root /home/maringuu/.local/share/containers/storage"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using run root /run/user/1000/containers"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using static dir /home/maringuu/.local/share/containers/storage/libpod"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using tmp dir /run/user/1000/libpod/tmp"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using volume path /home/maringuu/.local/share/containers/storage/volumes"
time="2020-12-28T20:25:49+01:00" level=debug msg="Set libpod namespace to \"\""
time="2020-12-28T20:25:49+01:00" level=debug msg="Not configuring container store"
time="2020-12-28T20:25:49+01:00" level=debug msg="Initializing event backend file"
time="2020-12-28T20:25:49+01:00" level=debug msg="using runtime \"/usr/bin/crun\""
time="2020-12-28T20:25:49+01:00" level=warning msg="Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument"
time="2020-12-28T20:25:49+01:00" level=debug msg="using runtime \"/usr/bin/runc\""
time="2020-12-28T20:25:49+01:00" level=info msg="Setting parallel job count to 25"
time="2020-12-28T20:25:49+01:00" level=info msg="podman filtering at log level debug"
time="2020-12-28T20:25:49+01:00" level=debug msg="Called run.PersistentPreRunE(podman run --log-level=debug --userns keep-id debian id)"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
time="2020-12-28T20:25:49+01:00" level=debug msg="Initializing boltdb state at /home/maringuu/.local/share/containers/storage/libpod/bolt_state.db"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using graph driver overlay"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using graph root /home/maringuu/.local/share/containers/storage"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using run root /run/user/1000/containers"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using static dir /home/maringuu/.local/share/containers/storage/libpod"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using tmp dir /run/user/1000/libpod/tmp"
time="2020-12-28T20:25:49+01:00" level=debug msg="Using volume path /home/maringuu/.local/share/containers/storage/volumes"
time="2020-12-28T20:25:49+01:00" level=debug msg="Set libpod namespace to \"\""
time="2020-12-28T20:25:49+01:00" level=debug msg="[graphdriver] trying provided driver \"overlay\""
time="2020-12-28T20:25:49+01:00" level=debug msg="overlay: mount_program=/usr/bin/fuse-overlayfs"
time="2020-12-28T20:25:49+01:00" level=debug msg="backingFs=btrfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false"
time="2020-12-28T20:25:49+01:00" level=debug msg="Initializing event backend file"
time="2020-12-28T20:25:49+01:00" level=debug msg="using runtime \"/usr/bin/runc\""
time="2020-12-28T20:25:49+01:00" level=debug msg="using runtime \"/usr/bin/crun\""
time="2020-12-28T20:25:49+01:00" level=warning msg="Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument"
time="2020-12-28T20:25:49+01:00" level=info msg="Setting parallel job count to 25"
time="2020-12-28T20:25:49+01:00" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf\""
time="2020-12-28T20:25:49+01:00" level=debug msg="parsed reference into \"[overlay@/home/maringuu/.local/share/containers/storage+/run/user/1000/containers:overlay.mount_program=/usr/bin/fuse-overlayfs]@6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="exporting opaque data as blob \"sha256:6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="parsed reference into \"[overlay@/home/maringuu/.local/share/containers/storage+/run/user/1000/containers:overlay.mount_program=/usr/bin/fuse-overlayfs]@6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="exporting opaque data as blob \"sha256:6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="using systemd mode: false"
time="2020-12-28T20:25:49+01:00" level=debug msg="No hostname set; container's hostname will default to runtime default"
time="2020-12-28T20:25:49+01:00" level=debug msg="Loading default seccomp profile"
time="2020-12-28T20:25:49+01:00" level=debug msg="Allocated lock 5 for container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d"
time="2020-12-28T20:25:49+01:00" level=debug msg="parsed reference into \"[overlay@/home/maringuu/.local/share/containers/storage+/run/user/1000/containers:overlay.mount_program=/usr/bin/fuse-overlayfs]@6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="exporting opaque data as blob \"sha256:6d6b00c22231693c9b87e79986d562874446bf10182206e4621e23ca8dfa8e1c\""
time="2020-12-28T20:25:49+01:00" level=debug msg="created container \"29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d\""
time="2020-12-28T20:25:49+01:00" level=debug msg="container \"29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d\" has work directory \"/home/maringuu/.local/share/containers/storage/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata\""
time="2020-12-28T20:25:49+01:00" level=debug msg="container \"29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d\" has run directory \"/run/user/1000/containers/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata\""
time="2020-12-28T20:25:49+01:00" level=debug msg="Not attaching to stdin"
time="2020-12-28T20:25:49+01:00" level=debug msg="overlay: mount_data=lowerdir=/home/maringuu/.local/share/containers/storage/overlay/l/FXMXYN2YJJX6MPUYY35DXIU5U7,upperdir=/home/maringuu/.local/share/containers/storage/overlay/e960ceeadc1e86b10ca29f4afeb93e69926be18768554c0492f30685abd411d5/diff,workdir=/home/maringuu/.local/share/containers/storage/overlay/e960ceeadc1e86b10ca29f4afeb93e69926be18768554c0492f30685abd411d5/work"
time="2020-12-28T20:25:49+01:00" level=debug msg="mounted container \"29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d\" at \"/home/maringuu/.local/share/containers/storage/overlay/e960ceeadc1e86b10ca29f4afeb93e69926be18768554c0492f30685abd411d5/merged\""
time="2020-12-28T20:25:49+01:00" level=debug msg="Created root filesystem for container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d at /home/maringuu/.local/share/containers/storage/overlay/e960ceeadc1e86b10ca29f4afeb93e69926be18768554c0492f30685abd411d5/merged"
time="2020-12-28T20:25:50+01:00" level=debug msg="Modifying container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d /etc/passwd"
time="2020-12-28T20:25:50+01:00" level=debug msg="Modifying container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d /etc/group"
time="2020-12-28T20:25:50+01:00" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode secret"
time="2020-12-28T20:25:50+01:00" level=debug msg="Setting CGroup path for container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d to /libpod_parent/libpod-29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d"
time="2020-12-28T20:25:50+01:00" level=debug msg="reading hooks from /usr/share/containers/oci/hooks.d"
time="2020-12-28T20:25:50+01:00" level=debug msg="Created OCI spec for container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d at /home/maringuu/.local/share/containers/storage/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/config.json"
time="2020-12-28T20:25:50+01:00" level=debug msg="/usr/bin/conmon messages will be logged to syslog"
time="2020-12-28T20:25:50+01:00" level=debug msg="running conmon: /usr/bin/conmon" args="[--api-version 1 -c 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d -u 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d -r /usr/bin/crun -b /home/maringuu/.local/share/containers/storage/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata -p /run/user/1000/containers/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/pidfile -n practical_bartik --exit-dir /run/user/1000/libpod/tmp/exits --socket-dir-path /run/user/1000/libpod/tmp/socket -l k8s-file:/home/maringuu/.local/share/containers/storage/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/ctr.log --log-level debug --syslog --conmon-pidfile /run/user/1000/containers/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /home/maringuu/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg cgroupfs --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --storage-opt --exit-command-arg overlay.mount_program=/usr/bin/fuse-overlayfs --exit-command-arg --events-backend --exit-command-arg file --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d]"
time="2020-12-28T20:25:50+01:00" level=warning msg="Failed to add conmon to cgroupfs sandbox cgroup: error creating cgroup path /libpod_parent/conmon: open /sys/fs/cgroup/cgroup.subtree_control: permission denied"
[conmon:d]: failed to write to /proc/self/oom_score_adj: Permission denied

time="2020-12-28T20:25:50+01:00" level=debug msg="Received: -1"
time="2020-12-28T20:25:50+01:00" level=debug msg="Cleaning up container 29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d"
time="2020-12-28T20:25:50+01:00" level=debug msg="Network is already cleaned up, skipping..."
time="2020-12-28T20:25:50+01:00" level=debug msg="unmounted container \"29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d\""
time="2020-12-28T20:25:50+01:00" level=debug msg="ExitCode msg: \"unknown seccomp syscall `faccessat2` ignored\\nunknown seccomp syscall `openat2` ignored\\nunknown seccomp syscall `pidfd_getfd` ignored\\nerror stat'ing file `/run/user/1000/containers/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/resolv.conf`: permission denied: oci permission denied\""
Error: unknown seccomp syscall `faccessat2` ignored
unknown seccomp syscall `openat2` ignored
unknown seccomp syscall `pidfd_getfd` ignored
error stat'ing file `/run/user/1000/containers/overlay-containers/29db8caaa404382d274ec56bca7b53c520318338778a1295ed6c741ba9373d2d/userdata/resolv.conf`: Permission denied: OCI permission denied

Describe the results you received:

Error: error stat'ing file `/run/user/1000/containers/overlay-containers/7c17726b47cdd7779a37ac8b0f020e008d131242c9d74f7302a3dc42a0f650c8/userdata/hostname`: Permission denied: OCI permission denied

Describe the results you expected:
I expected to not see this error and see the output of id.

Additional information you deem important:
When running with --userns keep-id the owner and group of /run/user/1000/containers/overlay-containers/ContainerID/userdata is the first id made avaiable in /etc/subuid and /etc/subgid.

I didn't experience this a week ago. Then --userns keep-id worked as expected. Maybe it has something todo with the 2.2.1 release.

Output of podman version:

Version:      2.2.1
API Version:  2.1.0
Go Version:   go1.15.6
Git Commit:   8ba5862e81df9b59c365d10740e89d4cca6f9f15
Built:        Tue Dec 22 16:17:44 2020
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.18.0
  cgroupManager: cgroupfs
  cgroupVersion: v2
  conmon:
    package: Unknown
    path: /usr/bin/conmon
    version: 'conmon version 2.0.22, commit: b1345f5b23c757ae9e242f59e4c75f63de4b27e6'
  cpus: 8
  distribution:
    distribution: alpine
    version: 3.13.0_alpha20201218
  eventLogger: file
  hostname: marten-xps
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 10001
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 10001
      size: 65536
  kernel: 5.10.2-0-lts
  linkmode: dynamic
  memFree: 14449778688
  memTotal: 16473690112
  ociRuntime:
    name: crun
    package: Unknown
    path: /usr/bin/crun
    version: |-
      crun version 0.13
      commit: e79e4de4ac16da0ce48777afb72c6241de870525
      spec: 1.0.0
      +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: Unknown
    version: |-
      slirp4netns version 1.1.7
      commit: e62caa08b78f3e662422bd7bfbcd2df3d12dcab1
      libslirp: 4.4.0
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.4.3
  swapFree: 0
  swapTotal: 0
  uptime: 17m 9.66s
registries:
  search:
  - docker.io
store:
  configFile: /home/maringuu/.config/containers/storage.conf
  containerStore:
    number: 4
    paused: 0
    running: 0
    stopped: 4
  graphDriverName: overlay
  graphOptions:
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: Unknown
      Version: |-
        fuse-overlayfs: version 1.3
        fusermount3 version: 3.9.1
        FUSE library version 3.9.1
        using FUSE kernel interface version 7.31
  graphRoot: /home/maringuu/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: btrfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 22
  runRoot: /run/user/1000/containers
  volumePath: /home/maringuu/.local/share/containers/storage/volumes
version:
  APIVersion: 2.1.0
  Built: 1608650264
  BuiltTime: Tue Dec 22 16:17:44 2020
  GitCommit: 8ba5862e81df9b59c365d10740e89d4cca6f9f15
  GoVersion: go1.15.6
  OsArch: linux/amd64
  Version: 2.2.1

Any ideas how I can further debug/fix the problem?
Thank you!

[rhatdan]

This looks like you have some bad data there.
Could you stop all containers and then
$ rm -rf /run/user/3267/containers/overlay-containers/*
$ podman system migrate

And then try again?

[maringuu]

I ran rm -rf ~/.local/share/containers and your two commands. Sadly it made no difference.

The directorys are now empty:

$ tree /run/user/1000

/run/user/1000/containers
├── overlay
├── overlay-containers
├── overlay-layers
│   └── mountpoints.lock
└── overlay-locks

Then I did:

$ podman pull docker.io/alpine
$  podman run --userns keep-id alpine true
Error: error stat'ing file `/run/user/1000/containers/overlay-containers/71eaabd23a4e9f4444c1da9207d37391e8d36f6984bae50f1e030702d7c3f948/userdata/hostname`: Permission denied: OCI permission denied

[rhatdan]

Did you do the migrate to make sure you did not have a version of podman already running?

@giuseppe thoughts?

[maringuu]

Did you do the migrate to make sure you did not have a version of podman already running?

Yes. Sorry I forgot to mention this.

Do you have steps I can do to further debug this?

[maringuu]

I tried

podman run \
	--uidmap=0:10000:1000 \
	--uidmap=1000:1000:1 \
	--uidmap=1001:11000:54537 \
	--gidmap=0:10000:1000 \
	--gidmap=1000:1000:1 \
	--gidmap=1001:11000:54537 \
	alpine id

Where 1000 is my user id. So this should be equivalent do --userns keep-id.
This worked and gave the result I expected from --userns keep-idwith the difference that id does not output my username but that is expected to my understanding.

55537 is the maximum count of uids and gids that I can map without getting an error.
This might be related the problem since my /etc/sub{uid,gid} have maringuu:10000:65536 in them which should make 65536 uids avaiable and not just 55537.

Maybe conmon requests a mapping of 65537 id's and then failes. But tbh I don't know what exactly conmon does so this is just a speculation.

[maringuu]

Turns out I fucked up my alpine install. I had most of the pacakges installed from the edge repo. Now that it is fixed I cant reproduce anymore. It might be related to musl 1.2.2. so probably sometime in the future the problem might come up again.

Thank you for you help!

Edit: I found a workaround. After executing

podman run \
	--uidmap=0:10000:1000 \
	--uidmap=1000:1000:1 \
	--uidmap=1001:11000:54537 \
	--gidmap=0:10000:1000 \
	--gidmap=1000:1000:1 \
	--gidmap=1001:11000:54537 \
	alpine id

the --userns keep-id flag works.

[giuseppe]

@maringuu is this still an issue?

[maringuu]

@maringuu is this still an issue?

Yes it is.

I didn't find a way to get more debug output from conmon. If there is a way I'd be happy to post/analyse more debug logs.

[giuseppe]

we had a similar issue reported, could you give a try to #8869?

If it still doesn't work, could you stat each component in the path that fails and report here the result?

e.g. given a path like /run/user/1000/containers/overlay-containers/71eaabd23a4e9f4444c1da9207d37391e8d36f6984bae50f1e030702d7c3f948/userdata/hostname:

$ stat /run
$ stat /run/user
$ stat /run/user/1000
$ stat /run/user/1000/containers
$ stat /run/user/1000/containers/overlay-containers
$ stat /run/user/1000/containers/overlay-containers/71eaabd23a4e9f4444c1da9207d37391e8d36f6984bae50f1e030702d7c3f948
$ stat /run/user/1000/containers/overlay-containers/71eaabd23a4e9f4444c1da9207d37391e8d36f6984bae50f1e030702d7c3f948/userdata
$ stat /run/user/1000/containers/overlay-containers/71eaabd23a4e9f4444c1da9207d37391e8d36f6984bae50f1e030702d7c3f948/userdata/hostname

[maringuu]

I cant reproduce anymore. I don't know what changed but it suddenly works again.

Thanks for your help.