slow (minutes delay) start when rinning with --userns=keep-id

[dc25]

/kind bug

Description

podman can take a long time to start when running with --userns=keep-id

Take a look at the following transcript. Podman run commands that start
quickly slow down when --userns=keep-id is added to the command. If I run
the same command a second time, it starts quickly.

In this example I use a trivial Docker file that just sets a couple
environment variables to create a new image, "d" . The first time I run "d"
with keep-id, it takes 6 or so seconds. In practice though, if I use a
longer Docker file I have seen it take up to 3 minutes to start with keep-id
(the first time). I thought that podman had frozen but eventually it
started.

This was with version "4.0.0-dev". Version "3.1.0-dev" does not show this
problem.

dave@ubdesktop2004base:/tmp/e$ podman run -it docker.io/library/ubuntu:20.10  bash
Trying to pull docker.io/library/ubuntu:20.10...
Getting image source signatures
Copying blob 32f3531c8415 skipped: already exists  
Copying config e508bd6d69 done  
Writing manifest to image destination
Storing signatures
root@ff8bc2022927:/# echo started prety fast even with pull
started prety fast even with pull
root@ff8bc2022927:/# exit
dave@ubdesktop2004base:/tmp/e$ podman run -it --userns=keep-id docker.io/library/ubuntu:20.10  bash
dave@96f63e862a32:/$ echo took about 5 seconds to start                      
took about 5 seconds to start
dave@96f63e862a32:/$ exit
dave@ubdesktop2004base:/tmp/e$ cat Dockerfile 
FROM docker.io/library/ubuntu:20.10

ENV XXX xxxx
ENV ZZZ zzzz
dave@ubdesktop2004base:/tmp/e$ podman build -t d .
STEP 1/3: FROM docker.io/library/ubuntu:20.10
STEP 2/3: ENV XXX xxxx
--> d60bd506cb5
STEP 3/3: ENV ZZZ zzzz
COMMIT d
--> 43b9c2caf47
Successfully tagged localhost/d:latest
43b9c2caf47c20dfb2d59aa3ec11b9baea2b82e3e71804c583acf39935ad6460
dave@ubdesktop2004base:/tmp/e$ podman run -it d bash
root@164638801cb8:/# echo started almost instantly                            
started almost instantly
root@164638801cb8:/# 
root@164638801cb8:/# 
root@164638801cb8:/# 
root@164638801cb8:/# exit
dave@ubdesktop2004base:/tmp/e$ podman run -it --userns=keep-id d bash
dave@dc5fcdadf894:/$ echo took about 6 seconds
took about 6 seconds
dave@dc5fcdadf894:/$ exit
dave@ubdesktop2004base:/tmp/e$ 
dave@ubdesktop2004base:/tmp/e$ 
dave@ubdesktop2004base:/tmp/e$ podman run -it --userns=keep-id d bash
dave@34d7d2685c82:/$ echo started almost instantly 
started almost instantly
dave@34d7d2685c82:/$ 
dave@34d7d2685c82:/$ exit
dave@ubdesktop2004base:/tmp/e$ podman --version
podman version 4.0.0-dev
dave@ubdesktop2004base:/tmp/e$ 

Additional information you deem important (e.g. issue happens only occasionally):

Running on ubuntu 20.04 desktop.

Output of podman version:

$ podman --version
podman version 4.0.0-dev

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.22.0
  cgroupControllers: []
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: Unknown
    path: /usr/local/libexec/podman/conmon
    version: 'conmon version 2.0.30-dev, commit: 018c40e0f7c66a08548745f458a64ee2508fb0b1'
  cpus: 1
  distribution:
    distribution: ubuntu
    version: "20.04"
  eventLogger: file
  hostname: ubdesktop2004base
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 5.11.0-25-generic
  linkmode: dynamic
  memFree: 1314594816
  memTotal: 4125016064
  ociRuntime:
    name: runc
    package: 'runc: /usr/sbin/runc'
    path: /usr/sbin/runc
    version: |-
      runc version 1.0.0~rc95-0ubuntu1~20.04.2
      spec: 1.0.2-dev
      go: go1.13.8
      libseccomp: 2.5.1
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_AUDIT_WRITE,CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_MKNOD,CAP_NET_BIND_SERVICE,CAP_NET_RAW,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: true
    seccompEnabled: true
    seccompProfilePath: ""
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: 'slirp4netns: /usr/bin/slirp4netns'
    version: |-
      slirp4netns version 0.4.3
      commit: 2244b9b6461afeccad1678fac3d6e478c28b4ad6
  swapFree: 1403224064
  swapTotal: 1516871680
  uptime: 18h 18m 34.75s (Approximately 0.75 days)
registries:
  search:
  - localhost
  - docker.io
  - registry.fedoraproject.org
  - registry.access.redhat.com
store:
  configFile: /home/dave/.config/containers/storage.conf
  containerStore:
    number: 6
    paused: 0
    running: 1
    stopped: 5
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/dave/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 3
  runRoot: /run/user/1000/containers
  volumePath: /home/dave/.local/share/containers/storage/volumes
version:
  APIVersion: 4.0.0-dev
  Built: 1628726281
  BuiltTime: Wed Aug 11 16:58:01 2021
  GitCommit: d594046410ec2f001697c957dc628e401e293ca5
  GoVersion: go1.13.8
  OsArch: linux/amd64
  Version: 4.0.0-dev

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

built yesterday from latest source.

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide? (https://github.com/containers/podman/blob/master/troubleshooting.md)

Yes

Additional environment details (AWS, VirtualBox, physical, etc.):

Running in virtualbox virtual machine`

[rhatdan]

This is because Podman has to chown the undelying storage if you run the same image with and without keep-id

We now have a shifting file system which we should be able to use to fix this problem.
@flouthoc & @giuseppe PTAL

[dc25]

Thank you.

Just to be clear, this does not happen with the ealier, "podman version 3.1.0-dev", version. Is chowning the underllying storage something that needs to be done in "podman version 4.0.0-dev" but not in the earlier version?

If there's a fix on the way it doesn't mater much (to me at least) why it's happening but the "chown the underlying storage" explanation feels incomplete (at least, to me).

[mlegenovic]

@dc25 You can workaround the problem with

[storage.options.overlay]
mount_program = "/usr/bin/fuse-overlayfs"

in your ~/.config/containers/storage.conf file.

[dc25]

Thank you.

I also had to add a "drivers" setting which resulted in the following ~/.config/containers/storage.conf :

[storage]
  driver = "overlay"

[storage.options.overlay]
mount_program = "/usr/bin/fuse-overlayfs"

This took care of the slow start for me.

What, if any, cost is there to running with these config settings? If there's no cost, would it make sense to make them the default? For that matter, is there a way to display the defaults? Maybe that has something to do with why podman version 3.1.0-dev starts fast but podman version 4.0.0-dev does not. Did a quick search to try to answer these questions but nothing jumped out.

[giuseppe]

I think we can close this issue as a duplicate of #10374