rootless podman issues after user logs out

[slcmpunk]

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description

Steps to reproduce the issue:

1. [root@rhel85 ~]# ssh test2@localhost test2@localhost's password:

   Last login: Tue Feb 15 15:30:02 2022 from ::1

2. [test2@rhel85 ~]$ podman run -d registry.access.redhat.com/rhel7 sleep infinity 3f93bc489b026d7b707599072424017fcf56e4654524cd6b2def1cab853fb5f3

3. [root@rhel85 ~]# sleep 90 ; ll /run/user total 0 drwx------. 3 root root 80 Feb 15 09:40 0 drwx------. 8 test2 test2 180 Feb 15 15:37 1001 drwx------. 6 test3 test3 140 Feb 15 13:49 1002

4. [root@rhel85 ~]# ssh test2@localhost test2@localhost's password:

   Last login: Tue Feb 15 15:35:19 2022 from ::1

5. [test2@rhel85 ~]$ podman --log-level=debug ps -a INFO[0000] podman filtering at log level debug
   DEBU[0000] Called ps.PersistentPreRunE(podman --log-level=debug ps -a) DEBU[0000] Merged system config "/usr/share/containers/containers.conf" DEBU[0000] Using conmon: "/usr/bin/conmon"
   DEBU[0000] Initializing boltdb state at /home/test2/.local/share/containers/storage/libpod/bolt_state.db DEBU[0000] Using graph driver overlay
   DEBU[0000] Using graph root /home/test2/.local/share/containers/storage DEBU[0000] Using run root /run/user/1001/containers
   DEBU[0000] Using static dir /home/test2/.local/share/containers/storage/libpod DEBU[0000] Using tmp dir /run/user/1001/libpod/tmp
   DEBU[0000] Using volume path /home/test2/.local/share/containers/storage/volumes DEBU[0000] Set libpod namespace to ""
   DEBU[0000] Not configuring container store
   DEBU[0000] Initializing event backend file
   DEBU[0000] configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument DEBU[0000] configured OCI runtime crun initialization failed: no valid executable found for OCI runtime crun: invalid argument DEBU[0000] configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument DEBU[0000] Using OCI runtime "/usr/bin/runc"
   INFO[0000] Found CNI network podman (type=bridge) at /home/test2/.config/cni/net.d/87-podman.conflist DEBU[0000] Default CNI network name podman is unchangeable INFO[0000] podman filtering at log level debug
   DEBU[0000] Called ps.PersistentPreRunE(podman --log-level=debug ps -a) DEBU[0000] cached value indicated that overlay is supported DEBU[0000] Merged system config "/usr/share/containers/containers.conf" DEBU[0000] cached value indicated that overlay is supported DEBU[0000] Using conmon: "/usr/bin/conmon"
   DEBU[0000] Initializing boltdb state at /home/test2/.local/share/containers/storage/libpod/bolt_state.db DEBU[0000] Using graph driver overlay
   DEBU[0000] Using graph root /home/test2/.local/share/containers/storage DEBU[0000] Using run root /run/user/1001/containers
   DEBU[0000] Using static dir /home/test2/.local/share/containers/storage/libpod DEBU[0000] Using tmp dir /run/user/1001/libpod/tmp
   DEBU[0000] Using volume path /home/test2/.local/share/containers/storage/volumes DEBU[0000] cached value indicated that overlay is supported DEBU[0000] Set libpod namespace to ""
   DEBU[0000] [graphdriver] trying provided driver "overlay" DEBU[0000] cached value indicated that overlay is supported DEBU[0000] overlay test mount indicated that metacopy is not being used DEBU[0000] backingFs=xfs, projectQuotaSupported=false, useNativeDiff=true, usingMetacopy=false DEBU[0000] Initializing event backend file
   DEBU[0000] configured OCI runtime crun initialization failed: no valid executable found for OCI runtime crun: invalid argument DEBU[0000] configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument DEBU[0000] configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument DEBU[0000] Using OCI runtime "/usr/bin/runc"
   INFO[0000] Found CNI network podman (type=bridge) at /home/test2/.config/cni/net.d/87-podman.conflist DEBU[0000] Default CNI network name podman is unchangeable DEBU[0000] Podman detected system restart - performing state refresh ERRO[0000] Error refreshing container 3f93bc489b026d7b707599072424017fcf56e4654524cd6b2def1cab853fb5f3: error acquiring lock 0 for container 3f93bc489b026d7b707599072424017fcf56e4654524cd6b2def1cab853fb5f3: file exists ERRO[0000] Error refreshing volume c9cccab63362ff8438bbb38f5be7cdd1132a8bde72a69cb32db0bbf9db715f02: error acquiring lock 4 for volume c9cccab63362ff8438bbb38f5be7cdd1132a8bde72a69cb32db0bbf9db715f02: file exists INFO[0000] Setting parallel job count to 7
   DEBU[0000] container 3f93bc489b026d7b707599072424017fcf56e4654524cd6b2def1cab853fb5f3 has no defined healthcheck CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 3f93bc489b02 registry.access.redhat.com/rhel7:latest sleep infinity About a minute ago Created compassionate_hofstadter DEBU[0000] Called ps.PersistentPostRunE(podman --log-level=debug ps -a)

Describe the results you received: Upon the first podman command ran, we get an error about acquiring locks

Describe the results you expected: No error, containers don't exit upon logout

Additional information you deem important (e.g. issue happens only occasionally): The workaround for this is to run 'loginctl enable-linger', but perhaps we need to reevaluate how podman performs these checks for reboot?

Error output only happens the first time you run a podman command, this is because podman determines a reboot has happened because the runtimeAliveFile is no longer present.

libpod/runtime.go

 498         // We now need to see if the system has restarted
 499         // We check for the presence of a file in our tmp directory to verify this
 500         // This check must be locked to prevent races
 501         runtimeAliveLock := filepath.Join(runtime.config.Engine.TmpDir, "alive.lck")
 502         runtimeAliveFile := filepath.Join(runtime.config.Engine.TmpDir, "alive")
 503         aliveLock, err := storage.GetLockfile(runtimeAliveLock)
 504         if err != nil {
 505                 return errors.Wrapf(err, "error acquiring runtime init lock")
 506         }
 507         // Acquire the lock and hold it until we return
 508         // This ensures that no two processes will be in runtime.refresh at once
 509         // TODO: we can't close the FD in this lock, so we should keep it around
 510         // and use it to lock important operations
 511         aliveLock.Lock()
 512         doRefresh := false
 513         defer func() {
 514                 if aliveLock.Locked() {
 515                         aliveLock.Unlock()
 516                 }
 517         }()
 518 
 519         _, err = os.Stat(runtimeAliveFile)
 520         if err != nil {
 521                 // If we need to refresh, then it is safe to assume there are
 522                 // no containers running.  Create immediately a namespace, as
 523                 // we will need to access the storage.

 550                 // If the file doesn't exist, we need to refresh the state
 551                 // This will trigger on first use as well, but refreshing an
 552                 // empty state only creates a single file
 553                 // As such, it's not really a performance concern
 554                 if os.IsNotExist(err) {
 555                         doRefresh = true

 843 // Reconfigures the runtime after a reboot
 844 // Refreshes the state, recreating temporary files
 845 // Does not check validity as the runtime is not valid until after this has run
 846 func (r *Runtime) refresh(alivePath string) error {
 847         logrus.Debugf("Podman detected system restart - performing state refresh")
 848 
 849         // Clear state of database if not running in container
 850         if !graphRootMounted() {
 851                 // First clear the state in the database
 852                 if err := r.state.Refresh(); err != nil {
 853                         return err
 854                 }
 855         }
 856 
 857         // Next refresh the state of all containers to recreate dirs and
 858         // namespaces, and all the pods to recreate cgroups.
 859         // Containers, pods, and volumes must also reacquire their locks.
 860         ctrs, err := r.state.AllContainers()
 861         if err != nil {
 862                 return errors.Wrapf(err, "error retrieving all containers from state")
 863         }
 864         pods, err := r.state.AllPods()
 865         if err != nil {
 866                 return errors.Wrapf(err, "error retrieving all pods from state")
 867         }
 868         vols, err := r.state.AllVolumes()
 869         if err != nil {
 870                 return errors.Wrapf(err, "error retrieving all volumes from state")
 871         }
 872         // No locks are taken during pod, volume, and container refresh.
 873         // Furthermore, the pod/volume/container refresh() functions are not
 874         // allowed to take locks themselves.
 875         // We cannot assume that any pod/volume/container has a valid lock until
 876         // after this function has returned.
 877         // The runtime alive lock should suffice to provide mutual exclusion
 878         // until this has run.
 879         for _, ctr := range ctrs {
 880                 if err := ctr.refresh(); err != nil {
 881                         logrus.Errorf("Error refreshing container %s: %v", ctr.ID(), err)
 882                 }
 883         }
 884         for _, pod := range pods {
 885                 if err := pod.refresh(); err != nil {
 886                         logrus.Errorf("Error refreshing pod %s: %v", pod.ID(), err)
 887                 }
 888         }
 889         for _, vol := range vols {
 890                 if err := vol.refresh(); err != nil {
 891                         logrus.Errorf("Error refreshing volume %s: %v", vol.Name(), err)
 892                 }
 893         }
 894 
 895         // Create a file indicating the runtime is alive and ready
 896         file, err := os.OpenFile(alivePath, os.O_RDONLY|os.O_CREATE, 0644)
 897         if err != nil {
 898                 return errors.Wrap(err, "error creating runtime status file")
 899         }
 900         defer file.Close()
 901 
 902         r.newSystemEvent(events.Refresh)
 903 
 904         return nil
 905 }

libpod/container_internal.go

 617 // Refresh refreshes the container's state after a restart.
 618 // Refresh cannot perform any operations that would lock another container.
 619 // We cannot guarantee any other container has a valid lock at the time it is
 620 // running.
 621 func (c *Container) refresh() error {

 657         // We need to pick up a new lock
 658         lock, err := c.runtime.lockManager.AllocateAndRetrieveLock(c.config.LockID)
 659         if err != nil {
 660                 return errors.Wrapf(err, "error acquiring lock %d for container %s", c.config.LockID, c.ID())
 661         }
 662         c.lock = lock

Output of podman version:

[test2@rhel85 ~]$ podman version
Version:      3.4.2
API Version:  3.4.2
Go Version:   go1.16.7
Built:        Thu Jan 13 05:15:49 2022
OS/Arch:      linux/amd64

Output of podman info --debug:

[test2@rhel85 ~]$ podman --log-level=debug info
INFO[0000] podman filtering at log level debug          
DEBU[0000] Called info.PersistentPreRunE(podman --log-level=debug info) 
DEBU[0000] cached value indicated that overlay is supported 
DEBU[0000] Merged system config "/usr/share/containers/containers.conf" 
DEBU[0000] cached value indicated that overlay is supported 
DEBU[0000] Using conmon: "/usr/bin/conmon"              
DEBU[0000] Initializing boltdb state at /home/test2/.local/share/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver overlay                   
DEBU[0000] Using graph root /home/test2/.local/share/containers/storage 
DEBU[0000] Using run root /run/user/1001/containers     
DEBU[0000] Using static dir /home/test2/.local/share/containers/storage/libpod 
DEBU[0000] Using tmp dir /run/user/1001/libpod/tmp      
DEBU[0000] Using volume path /home/test2/.local/share/containers/storage/volumes 
DEBU[0000] cached value indicated that overlay is supported 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "overlay" 
DEBU[0000] cached value indicated that overlay is supported 
DEBU[0000] cached value indicated that metacopy is not being used 
DEBU[0000] cached value indicated that native-diff is usable 
DEBU[0000] backingFs=xfs, projectQuotaSupported=false, useNativeDiff=true, usingMetacopy=false 
DEBU[0000] Initializing event backend file              
DEBU[0000] configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument 
DEBU[0000] configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument 
DEBU[0000] configured OCI runtime crun initialization failed: no valid executable found for OCI runtime crun: invalid argument 
DEBU[0000] Using OCI runtime "/usr/bin/runc"            
INFO[0000] Found CNI network podman (type=bridge) at /home/test2/.config/cni/net.d/87-podman.conflist 
DEBU[0000] Default CNI network name podman is unchangeable 
INFO[0000] Setting parallel job count to 7              
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf" 
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf.d/000-shortnames.conf" 
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf.d/001-rhel-shortnames.conf" 
DEBU[0000] Loading registries configuration "/etc/containers/registries.conf.d/002-rhel-shortnames-overrides.conf" 
host:
  arch: amd64
  buildahVersion: 1.23.1
  cgroupControllers: []
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: conmon-2.0.32-1.module+el8.5.0+13852+150547f7.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.0.32, commit: 4b12bce835c3f8acc006a43620dd955a6a73bae0'
  cpus: 2
  distribution:
    distribution: '"rhel"'
    version: "8.5"
  eventLogger: file
  hostname: rhel85
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1001
      size: 1
    - container_id: 1
      host_id: 10000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1001
      size: 1
    - container_id: 1
      host_id: 10000
      size: 65536
  kernel: 4.18.0-348.12.2.el8_5.x86_64
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 329740288
  memTotal: 2819096576
  ociRuntime:
    name: runc
    package: runc-1.0.3-1.module+el8.5.0+13556+7f055e70.x86_64
    path: /usr/bin/runc
    version: |-
      runc version 1.0.3
      spec: 1.0.2-dev
      go: go1.16.7
      libseccomp: 2.5.1
  os: linux
  remoteSocket:
    path: /run/user/1001/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_NET_RAW,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: true
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.1.8-1.module+el8.5.0+12582+56d94c81.x86_64
    version: |-
      slirp4netns version 1.1.8
      commit: d361001f495417b880f20329121e3aa431a8f90f
      libslirp: 4.4.0
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.1
  swapFree: 3123691520
  swapTotal: 3124752384
  uptime: 6h 2m 43.82s (Approximately 0.25 days)
plugins:
  log:
  - k8s-file
  - none
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - registry.centos.org
  - docker.io
store:
  configFile: /home/test2/.config/containers/storage.conf
  containerStore:
    number: 1
    paused: 0
    running: 0
    stopped: 1
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/test2/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 2
  runRoot: /run/user/1001/containers
  volumePath: /home/test2/.local/share/containers/storage/volumes
version:
  APIVersion: 3.4.2
  Built: 1642068949
  BuiltTime: Thu Jan 13 05:15:49 2022
  GitCommit: ""
  GoVersion: go1.16.7
  OsArch: linux/amd64
  Version: 3.4.2

DEBU[0000] Called info.PersistentPostRunE(podman --log-level=debug info) 

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

[test2@rhel85 ~]$ rpm -q podman
podman-3.4.2-9.module+el8.5.0+13852+150547f7.x86_64

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)

No, but podman still performs same checks in the latest podman version, so this would still be an issue.

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

[mheon]

The core issue is that systemd is clearing Podman's temporary files directory. We cannot be expected to continue functioning sanely after files were deleted; simultaneously, the directory we're using, /run/user/$UID, is the only tmpfs guaranteed to be writable by non-root users (assuming it exists). We've evaluated other options, but at present this is the best way we have of doing things. I'm open to suggestions if folks have a better idea, but substantial thought has been put into this already, and this is the best solution we've found.

[giuseppe]

Describe the results you expected: No error, containers don't exit upon logout

this is not possible without using the lingering mode though. systemd will kill all the user processes and there is nothing Podman can do to prevent it

[rhatdan]

Since this is not an Issue Podman can deal with and we have given you a solution, I am closing. Please feel free to continue the discussion here.

[jhollowayj]

For future travelers who stumble into this issue, this was the command I ran to enable "lingering mode" giuseppe mentioned: loginctl enable-linger.

It has also been added to the troubleshooting guide here.

[mohd-akram]

Is this not the same issue as this?

[mheon]

It's really the inverse. In that issue, the Podman temporary files directory was not being cleared at all; in this issue, it's being cleared too much. Both are problematic to successful function.

[mohd-akram]

Is it possible to add a tmpfile rule to handle this issue as well?

[mheon]

Potentially? Removing the Podman SHM locks (/dev/shm/libpod_rootless_lock_$UID) for the user that logged out, when they log out, could work.

[rptaylor]

It might just be a peculiar coincidence, but I have only had this problem on a server which never had lingering enabled and was missing the /var/lib/systemd/linger directory. On a server that once had lingering enabled, then disabled (hence creating /var/lib/systemd/linger), but is otherwise identical to the first server, I never had this problem.