podman-restart.service doesn't like x-systemd.automount

[urbenlegend]

Issue Description

Some of my containers aren’t getting started up by podman-restart.service on system reboot. After looking through the logs, I realized they were the ones that depended on my slow USB external BTRFS drive, which is mounted with x-systemd.automount,x-systemd.device-timeout=10 so that it doesn’t hang up the boot if I disconnect it.

It seems like Podman doesn’t like this however:

Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?
Aug 27 22:00:15 systemd[1]: libpod-dbffff4bc5c47e554f3591bc7f5d90f8777b8bb87815b75b670b8c70e585f5b3.scope: Deactivated successfully.
Aug 27 22:00:15 conmon[3507]: conmon dbffff4bc5c47e554f35 <nwarn>: runtime stderr: error stat'ing file `/external/share`: Too many levels of symbolic links
Aug 27 22:00:15 conmon[3507]: conmon dbffff4bc5c47e554f35 <error>: Failed to create container: exit status 1

This eventually causes the container to not start up, which then causes podman-restart.service to fail:

Aug 27 22:01:45 systemd[1]: podman-restart.service: State 'stop-sigterm' timed out. Killing.
Aug 27 22:01:45 systemd[1]: podman-restart.service: Killing process 1966 (conmon) with signal SIGKILL.
Aug 27 22:01:45 systemd[1]: podman-restart.service: Failed with result 'exit-code'.
Aug 27 22:01:45 systemd[1]: Failed to start Podman Start All Containers With Restart Policy Set To Always.

Once the system gets into this state, shutting down the system then leads to a delayed shutdown with the exact same logs seen in this bug that's supposedly fixed: #14434

Temporary workaround: I've been mounting with nofail,x-systemd.before=podman-restart.service instead which seems to work okay, except that if the drive isn't connected, ALL of my containers do not start up, instead of just the ones that depend on the external mount.

Steps to reproduce the issue

Steps to reproduce the issue

1. Add a slow mounting drive to /etc/fstab using systemd automount. In my case it was a slow USB BTRFS drive:

UUID=<uuid>  /external  btrfs  compress-force=zstd:2,x-systemd.automount,x-systemd.device-timeout=10  0 0

2. Start a container that mounts a folder from that slow drive. In my case it was /external/share.
3. Set restart policy to always and enable podman-restart.service
4. Reboot machine. Notice that the container does not start up
5. Shutdown machine. Notice that podman services cause the shutdown to be delayed by 90 seconds.

Describe the results you received

Container fails to wait for systemd automount to complete and instead refuses to start. Shutdown also becomes delayed due to some lingering podman services

Describe the results you expected

Container waits for systemd automount to complete before starting up.

podman info output

host:
  arch: amd64
  buildahVersion: 1.31.2
  cgroupControllers:
  - cpuset
  - cpu
  - io
  - memory
  - hugetlb
  - pids
  - rdma
  - misc
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: /usr/bin/conmon is owned by conmon 1:2.1.8-1
    path: /usr/bin/conmon
    version: 'conmon version 2.1.8, commit: 00e08f4a9ca5420de733bf542b930ad58e1a7e7d'
  cpuUtilization:
    idlePercent: 99.55
    systemPercent: 0.24
    userPercent: 0.21
  cpus: 12
  databaseBackend: boltdb
  distribution:
    distribution: arch
    version: unknown
  eventLogger: journald
  freeLocks: 2034
  hostname: arch-nas
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 6.4.12-arch1-1
  linkmode: dynamic
  logDriver: journald
  memFree: 27661901824
  memTotal: 32991268864
  networkBackend: netavark
  networkBackendInfo:
    backend: netavark
    dns:
      package: /usr/lib/podman/aardvark-dns is owned by aardvark-dns 1.7.0-1
      path: /usr/lib/podman/aardvark-dns
      version: aardvark-dns 1.7.0
    package: /usr/lib/podman/netavark is owned by netavark 1.7.0-1
    path: /usr/lib/podman/netavark
    version: netavark 1.7.0
  ociRuntime:
    name: crun
    package: /usr/bin/crun is owned by crun 1.8.7-1
    path: /usr/bin/crun
    version: |-
      crun version 1.8.7
      commit: 53a9996ce82d1ee818349bdcc64797a1fa0433c4
      rundir: /run/crun
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  pasta:
    executable: ""
    package: ""
    version: ""
  remoteSocket:
    exists: true
    path: /run/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: false
    seccompEnabled: true
    seccompProfilePath: /etc/containers/seccomp.json
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: /usr/bin/slirp4netns is owned by slirp4netns 1.2.1-1
    version: |-
      slirp4netns version 1.2.1
      commit: 09e31e92fa3d2a1d3ca261adaeb012c8d75a8194
      libslirp: 4.7.0
      SLIRP_CONFIG_VERSION_MAX: 4
      libseccomp: 2.5.4
  swapFree: 17179865088
  swapTotal: 17179865088
  uptime: 0h 22m 3.00s
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries: {}
store:
  configFile: /etc/containers/storage.conf
  containerStore:
    number: 7
    paused: 0
    running: 7
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.mountopt: nodev
  graphRoot: /var/lib/containers/storage
  graphRootAllocated: 238342373376
  graphRootUsed: 21833162752
  graphStatus:
    Backing Filesystem: btrfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "true"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 5
  runRoot: /run/containers/storage
  transientStore: false
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 4.6.1
  Built: 1691780613
  BuiltTime: Fri Aug 11 12:03:33 2023
  GitCommit: f3069b3ff48e30373c33b3f5976f15abf8cfee20-dirty
  GoVersion: go1.21.0
  Os: linux
  OsArch: linux/amd64
  Version: 4.6.1

Podman in a container

No

Privileged Or Rootless

Privileged

Upstream Latest Release

Yes

Additional environment details

No response

Additional information

No response

[flouthoc]

@vrothberg PTAL

[vrothberg]

This needs triaging which can be done by anyone, so please don´t wait/block on me to work on it.

[rhatdan]

Seems like podman-restart.service should probably wait for all file systems to be mounted before firing off.

[vrothberg]

Temporary workaround: I've been mounting with nofail,x-systemd.before=podman-restart.service instead which seems to work okay,

That is what I would recommend as well. For --restart=always Podman depends on this systemd service, so there is no way Podman could figure out such dependencies on external services. Mounting the drive before the podman-restart.service is the right approach IMO.

except that if the drive isn't connected, ALL of my containers do not start up, instead of just the ones that depend on the external mount.

Now that is interesting. I will investigate.

[vrothberg]

Shutdown also becomes delayed due to some lingering podman services

That is likely a separate issue. If it persists, please open a new issue for this symptom.

[vrothberg]

Now that is interesting. I will investigate.

I am an unable to reproduce this symptom. I suspected that there may be issues when starting one container failed to start but the other containers happily continue running.

[vrothberg]

@urbenlegend any chance you can break it down into another reproducer?

[urbenlegend]

except that if the drive isn't connected, ALL of my containers do not start up, instead of just the ones that depend on the external mount.

Now that is interesting. I will investigate.

Actually, I think that's expected behavior with the nofail,x-systemd.before=podman-restart.service workaround. It causes podman-restart to not even attempt to start up before that drive is mounted, which means none of the containers are started up. This is normal in my opinion and not a cause for concern.

The beauty of using x-systemd.automount,x-systemd.device-timeout=10 instead of nofail,x-systemd.before=podman-restart.service is that it allows podman-restart to be booted up in parallel. Ideally, it should start up, and start all of the containers with --restart=always and any containers that depend on that specific slow-mounting drive will wait until its mounted before resuming happily. The problem is that it doesn't do this. It just bails without waiting. Regular Docker was happy to wait until it was mounted before starting the containers. Podman does not.

That is likely a separate issue. If it persists, please open a new issue for this symptom.

Filed #19815

[vrothberg]

Actually, I think that's expected behavior with the nofail,x-systemd.before=podman-restart.service workaround. It causes podman-restart to not even attempt to start up before that drive is mounted, which means none of the containers are started up. This is normal in my opinion and not a cause for concern.

Ah, thank you. I misinterpreted the statement 👍

and any containers that depend on that specific slow-mounting drive will wait until its mounted before resuming happily. The problem is that it doesn't do this. It just bails without waiting. Regular Docker was happy to wait until it was mounted before starting the containers. Podman does not.

That is interesting. So Docker is capable of starting a container whos mounts are not yet there?

[urbenlegend]

That is interesting. So Docker is capable of starting a container whos mounts are not yet there?

It will just wait due to x-systemd.automount. I am assuming it just simply attempts to access the filesystem, but systemd-automount will make anything that does so pause until the filesystem is actually mounted.

[rhatdan]

I would expect podman to do the same thing. systemd is just making the file system seem like it is mounted and then mounting the file system on first access. Nothing in Docker or Podman should be required that I know of to use this type of service. If Podman is complaining about this, it would be nice to see the logs.

[vrothberg]

@rhatdan I share this impression. Couldn't find anything in Docker that would suggest a custom logic.

[urbenlegend]

@rhatdan, I've already uploaded the relevant logs in the original bug report. A bunch of

Aug 27 22:00:15 systemd[1]: external.automount: Got automount request for /external, triggered by 3512 (3)
Aug 27 22:00:15 systemd[1]: external.automount: Automount point already active?

gets spit out and then it finally fails to start the container.

[rhatdan]

Is /external/share a symbolic link?
@giuseppe any idea?

[urbenlegend]

It isn't, just a regular BTRFS external USB drive with the following mount options:

/dev/sda1 /external btrfs rw,relatime,compress-force=zstd:2,space_cache=v2,subvolid=5,subvol=/ 0 0

EDIT: whoops thats the workaround options, heres the original systemd.automount

/dev/sda1 /external  btrfs  compress-force=zstd:2,x-systemd.automount,x-systemd.device-timeout=10  0 0

[vrothberg]

I see absolutely no evidence in the Docker code that Docker would wait for such mounts, so I am pretty sure Docker errors out as well. It's probably just lucky timing on boot.

I don't think there is much Podman can do, and believe that the mentioned solutions to use systemd's dependency management is the right thing to do. Hence, I will close the issue. Please speak up if you feel different.