--userns=keep-id storage-chown-by-maps kills machine with large images

[Hi-Angel]

/kind bug

Description

While migrating a CI from Docker to Podman, I'm occasionally stumbling upon freezes of Podman commands. They may take dozens (!!!) of minutes, with Podman not doing anything at all.

The hangs aren't specific to any commands. E.g. right as I'm writing this text, I see two jobs, one with podman run … and another with podman inspect both frozen. So I connected to the server with ssh and trying running a time podman inspect foobar (literally a request for non-existing foobar image), and it hanged as well. podman ps hangs, and podman version even hangs!!

Basically, to be able to create this report I had to kill a podman process. I had 2 podman run processes and 2 podman inspects. I killed one of podman inspect processes, and a little later CI finally proceeded and podman commands started working.

Steps to reproduce the issue:

I'm afraid I couldn't find any. It seems to be happening when multiple podman processes are run, but my attempts simulating that in different ways didn't succeed. It just happens from time to time as part of CI, in which case CI basically breaks completely.

Steps to reproduce were found as part of this duplicate issue and are copied below:

1. This is the "fairly large" image:

   podman pull ghcr.io/martinpitt/swaypod:latest
   time podman create --userns=keep-id ghcr.io/martinpitt/swaypod:latest
   

2. This is the image that adds TeXlive (which makes it a few hundred MB larger):

   podman pull ghcr.io/martinpitt/swaypod:allpkgs
   time podman create --userns=keep-id ghcr.io/martinpitt/swaypod:allpkgs
   

Describe the results you received:

Step 1 takes 4 s on a Fedora 37 cloud VM (2 CPUs, 4 GiB RAM) with the default btrfs. On a standard RHEL 9.2 VM with XFS and on my laptop's Fedora 37 VM with /home being on ext4, it takes about 20 seconds. In top I see a process called "exe" which is taking 100% CPU:

PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
972 admin     20   0 1351936  65172  28028 S  96.0   1.7   0:12.33 exe

That is really this:

admin       1972 95.0  1.3 1351680 49344 pts/0   Sl+  04:04   0:01 storage-chown-by-maps /home/admin/.local/share/containers/storage/overlay/3cc2d72c07248c18a9185b6a5bba0e7932b0ce5c26dbc763e476eb50c2a7ea94/merged

With the larger image in step 2, the Fedora 37 btrfs VM takes merely 6s. However, both on the RHEL 9.2 XFS VM as well as my ext4 real-iron Fedora 37 laptop, the storage-chown-by-maps process never ends. After maybe half a minute it kills the VM (ssh dead, cannot log into the virsh console either), and my laptop becomes really sluggish, I cannot even start top any more. Trying to kill -9 or even sudo kill -9 (!) that storage-chown-by-maps does not work either, it's just unkillable.

Describe the results you expected:

The storage-chown-by-maps process should finish eventually, but ideally reasonably fast. This is more or less a glorified chown -R, no? that shouldn't take more than a few seconds.

Output of podman version:

Client:       Podman Engine
Version:      4.3.1
API Version:  4.3.1
Go Version:   go1.18.1
Built:        Thu Jan  1 00:00:00 1970
OS/Arch:      linux/amd64

Output of podman info:

host:
  arch: amd64
  buildahVersion: 1.28.0
  cgroupControllers:
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon_2:2.1.5-0ubuntu22.04+obs14.3_amd64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.5, commit: '
  cpuUtilization:
    idlePercent: 96.22
    systemPercent: 0.76
    userPercent: 3.03
  cpus: 4
  distribution:
    codename: jammy
    distribution: ubuntu
    version: "22.04"
  eventLogger: file
  hostname: node29
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 998
      size: 1
    - container_id: 1
      host_id: 10000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 998
      size: 1
    - container_id: 1
      host_id: 10000
      size: 65536
  kernel: 5.15.0-52-generic
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 1288302592
  memTotal: 67404197888
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun_1.7-0ubuntu22.04+obs47.1_amd64
    path: /usr/bin/crun
    version: |-
      crun version 1.7
      commit: 40d996ea8a827981895ce22886a9bac367f87264
      rundir: /run/user/998/crun
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    path: /run/user/998/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: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns_1.2.0-0ubuntu22.04+obs10.15_amd64
    version: |-
      slirp4netns version 1.2.0
      commit: 656041d45cfca7a4176f6b7eed9e4fe6c11e8383
      libslirp: 4.6.1
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.3
  swapFree: 8575172608
  swapTotal: 8589930496
  uptime: 223h 19m 11.00s (Approximately 9.29 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - docker.io
  - quay.io
store:
  configFile: /home/gitlab-runner/.config/containers/storage.conf
  containerStore:
    number: 1
    paused: 0
    running: 1
    stopped: 0
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/gitlab-runner/.local/share/containers/storage
  graphRootAllocated: 983350071296
  graphRootUsed: 645746360320
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 202
  runRoot: /tmp/podman-run-998/containers
  volumePath: /home/gitlab-runner/.local/share/containers/storage/volumes
version:
  APIVersion: 4.3.1
  Built: 0
  BuiltTime: Thu Jan  1 00:00:00 1970
  GitCommit: ""
  GoVersion: go1.18.1
  Os: linux
  OsArch: linux/amd64
  Version: 4.3.1

Package info:

$ apt list podman
Listing... Done
podman/unknown,now 4:4.3.1-0ubuntu22.04+obs64.3 amd64 [installed]
podman/unknown 4:4.3.1-0ubuntu22.04+obs64.3 arm64
podman/unknown 4:4.3.1-0ubuntu22.04+obs64.3 armhf
podman/unknown 4:4.3.1-0ubuntu22.04+obs64.3 s390x

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

[mheon]

More details on the commands being run (particularly the podman run commands) would help. This sounds like a potential deadlock.

[Hi-Angel]

More details on the commands being run (particularly the podman run commands) would help. This sounds like a potential deadlock.

Looking at scrollback when I had the hang, the 4 podman commands that were running are below (I edited out some paths and IDs). I am not sure why are there identical pairs… Looking at paths, both podman run are being run from a single job, and I don't have anything that makes two identical podman runs to run as part of one job 🤷‍♂️ Either way, here they are.

gitlab-+  288652  0.0  0.0 1409668 34596 ?       Sl   14:27   0:00 podman run --rm --userns=keep-id -v /home/user1/.ccache:/home/my_builder/.ccache -v /home/user1/.web_modules/v4/node_modules/:/home/my_builder/.web_modules/v4/node_modules/ -v /home/user1/builds/path_to_project/project/:/home/my_builder/project --user my_builder -t my-builder-ba7f7b1bf09c880df52be235960424ff8e5987a5f2bba341d0947a5004e41e6b:1 /bin/sh -c cd /home/my_builder/project && ./full_build.sh
gitlab-+  288662  0.1  0.0 1410180 39944 ?       Sl   14:27   0:03 podman run --rm --userns=keep-id -v /home/user1/.ccache:/home/my_builder/.ccache -v /home/user1/.web_modules/v4/node_modules/:/home/my_builder/.web_modules/v4/node_modules/ -v /home/user1/builds/path_to_project/project/:/home/my_builder/project --user my_builder -t my-builder-ba7f7b1bf09c880df52be235960424ff8e5987a5f2bba341d0947a5004e41e6b:1 /bin/sh -c cd /home/my_builder/project && ./full_build.sh
gitlab-+  288995  0.0  0.0 1409668 34084 ?       Sl   14:27   0:00 podman inspect base-iso-5cf95cc968e717578e97eb82b422534a6539a7c77718f7079d5344235978bcb8:1
gitlab-+  289004  0.0  0.0 1409584 33944 ?       Sl   14:27   0:00 podman inspect base-iso-5cf95cc968e717578e97eb82b422534a6539a7c77718f7079d5344235978bcb8:1

[Hi-Angel]

I am not sure why are there identical pairs…

Oh, apparently that's just how it works. Running a mere podman run --rm -it test creates two identical processes as well.

[Hi-Angel]

FTR: running the same podman run and podman inspect commands from the same directory manually doesn't hang. So, as I said, it's sporadical.

[Surfrdan]

I'm experiencing the same hanging behaviour when I run a tomcat container. I know the container is doing a LOT of processing on startup (indexing 14TB of JSON files to a postgres DB) and I expect it to un-hang in the future (possibly days from now) as I have run the same container with smaller datasets and it releases in time (maybe minutes or hours). While this is happening I can get nothing from podman ps, podman top, podman logs and probably others. They all hang.

podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z  -it fcrepo_tomcat

iotop on the host OS does show disk IO for the container in question so It's doing something

 337148 be/4 root      127.79 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337150 be/4 root       40.36 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337151 be/4 root       26.90 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337158 be/4 root       13.45 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337159 be/4 root       40.36 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337161 be/4 root       13.45 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337175 be/4 root       13.45 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat
 337176 be/4 root       40.36 K/s    0.00 B/s podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat

[mheon]

Podman should not hang because a container is processing IO. A Podman hang is almost certainly because something is holding a lock; we don't hold locks during steady-state, only during certain setup operations.

[mheon]

Are the containers running (as in, do you see Tomcat in ps? Or just podman?)

[Surfrdan]

On closer inspection @mheon I can not actually see a tomcat process running yet.

Is there anything else I can do to help debug the situation?

From the host:

$ ps aux | grep fcrepo_tomcat_migration
root      337148 15.7  0.1 6582404 76264 pts/0   Sl+  Nov17 227:00 podman run -d --name fcrepo_tomcat_migration --pod fcrepo_migration -v /fedora-storage/delivery/migrated/data/ocfl-root:/usr/local/fedora/data/ocfl-root:z -it fcrepo_tomcat

Obviously I can't run podman top as its still hanging from hours ago:

$ ps aux | grep 'podman top'
root      347816  0.0  0.0 413772 10608 pts/3    S+   09:06   0:00 sudo podman top fcrepo_tomcat_migration
root      347817  0.2  0.0 2819320 64512 pts/3   Sl+  09:06   1:19 podman top fcrepo_tomcat_migration

[mheon]

How big is the volume (/fedora-storage/delivery/migrated/data/ocfl-root)? Does it have a lot of small files? I'm wondering if we aren't trying to chattr millions of files in there because of the :z on the volume mount... Omitting the :z and using --security-opt label=disable instead would be interesting, to see if the container starts faster.

[Hi-Angel]

The hang I got right now is ridiculous. There is only one command running:

gitlab-+ 1197025  0.0  0.0 1409660 34788 pts/0   Sl+  06:44   0:00 podman run --rm --userns=keep-id -v /home/user1/.ccache:/home/my_builder/.ccache -v /home/user1/.web_modules/v4/node_modules/:/home/my_builder/.web_modules/v4/node_modules/ -v /home/user1/builds/J1a__jgb/0/developers/project/:/home/my_builder/project --user my_builder -t project-builder-db12a84caddb49eb7219b2256a64a8a5eb07feef7fb1c5c9c16641d547139b66:1 /bin/echo hello
gitlab-+ 1197035  0.3  0.0 1336184 43964 pts/0   Sl+  06:44   0:00 podman run --rm --userns=keep-id -v /home/user1/.ccache:/home/my_builder/.ccache -v /home/user1/.web_modules/v4/node_modules/:/home/my_builder/.web_modules/v4/node_modules/ -v /home/user1/builds/J1a__jgb/0/developers/project/:/home/my_builder/project --user my_builder -t project-builder-db12a84caddb49eb7219b2256a64a8a5eb07feef7fb1c5c9c16641d547139b66:1 /bin/echo hello

(as we found out earlier, podman commands duplicate itself in process list, so this is just one command).

And somehow managed to hang 😄 🤷‍♂️ Running podman version with these won't return, for example.

[Hi-Angel]

Oh, I don't know if that points to something, but after I Ctrl+ced the command above (I had ran it manually), some seconds later I got this message:

Error: creating container storage: creating an ID-mapped copy of layer "b42cb22c5974757a983a1d4e635f7ff1eba06eb691fd1a4d1a2842a551827958": signal: interrupt

[Hi-Angel]

It hanged again as part of CI, and sending a kill so other processes would continue does nothing, the process won't quit.

[Hi-Angel]

Got stacktrace from the process that hanged first and now doesn't react to kill:

#0  runtime.futex () at /usr/lib/go-1.18/src/runtime/sys_linux_amd64.s:553
#1  0x0000556e9d7419d6 in runtime.futexsleep (addr=0xfffffffffffffe00, val=0, ns=93933576630435) at /usr/lib/go-1.18/src/runtime/os_linux.go:66
#2  0x0000556e9d71b3c7 in runtime.notesleep (n=0xfffffffffffffe00) at /usr/lib/go-1.18/src/runtime/lock_futex.go:159
#3  0x0000556e9d74aac5 in runtime.mPark () at /usr/lib/go-1.18/src/runtime/proc.go:1449
#4  0x0000556e9d74c645 in runtime.stoplockedm () at /usr/lib/go-1.18/src/runtime/proc.go:2422
#5  0x0000556e9d74e11d in runtime.schedule () at /usr/lib/go-1.18/src/runtime/proc.go:3119
#6  0x0000556e9d74e86d in runtime.park_m (gp=0xc000015a00) at /usr/lib/go-1.18/src/runtime/proc.go:3336
#7  0x0000556e9d776f05 in runtime.mcall () at /usr/lib/go-1.18/src/runtime/asm_amd64.s:425
#8  0x0000556e9d77b8a7 in runtime.newproc (fn=0x11) at <autogenerated>:1
#9  0x0000556e9f834d40 in ?? ()
#10 0x0000000000000011 in ?? ()
#11 0x0000556e9d776e85 in runtime.mstart () at /usr/lib/go-1.18/src/runtime/asm_amd64.s:367
#12 0x0000556e9d776e13 in runtime.rt0_go () at /usr/lib/go-1.18/src/runtime/asm_amd64.s:331
#13 0x0000000000000011 in ?? ()
#14 0x00007ffd9e018b78 in ?? ()
#15 0x0000000000000000 in ?? ()

[Surfrdan]

How big is the volume (/fedora-storage/delivery/migrated/data/ocfl-root)? Does it have a lot of small files? I'm wondering if we aren't trying to chattr millions of files in there because of the :z on the volume mount... Omitting the :z and using --security-opt label=disable instead would be interesting, to see if the container starts faster.

It's a 13TB volume with at least 50 million small json and text files and maybe 10million larger bninary files. I let the process run all weekend but it was still hung this morning. I CTRL+Cd the podman run command the other hanging podman ps podman top etc commands completed instandly as soon as I'd killed the podman run.

I followed your advice and replaced the :z with the --security-opt label=disable args and the container came up in an instant! Thanks for identifying the cause of the hang!