podman: podman system service fails to start when run via systemd --user mode

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

/kind bug

Description

podman system service -t 0 fails when run via systemd unit files

Following are the systemd unit files used for testing:

podman.socket

[Unit]
Description=Podman Socket

[Socket]
ListenStream=/tmp/test.sock (or for TCP --> ListenStream=127.0.0.1:<random_available_port>)

[Install]
WantedBy=sockets.target

podman.service

[Unit]
Description=Podman Service
Requires=podman.socket
After=podman.socket
StartLimitIntervalSec=0

[Service]
Type=notify
KillMode=process
Environment=LOGGING="--log-level=debug"
ExecStart=/usr/bin/podman $LOGGING system service -t 0
TimeoutStopSec=30

[Install]
WantedBy=multi-user.target

Steps to reproduce the issue:

1. Create two systemd unit files - one for socket and one for service (like shown above).

2. Load and run the systemd unit files in both user mode and root mode. Of course, use different socket locations/ports for unix/tcp respectively.

3. The root mode runs just fine without any problems. The user mode fails irrespective of unix/tcp socket. Not sure what am I doing wrong.

Describe the results you received:

Results when run as root --> this is the happy path. both podman.service and podman.socket work just fine

[root@localhost ~]# systemctl status podman
● podman.service - Podman Service
   Loaded: loaded (/run/systemd/system/podman.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2021-03-05 08:31:22 EST; 11s ago
 Main PID: 507761 (podman)
    Tasks: 10 (limit: 48707)
   Memory: 50.2M
   CGroup: /system.slice/podman.service
           └─507761 /usr/bin/podman --log-level=debug system service -t 0

Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods:   POST Path: /volumes/create"
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods:    GET Path: /v{version:[0-9][0-9.]*}/volumes/>
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods:    GET Path: /volumes/{name}"
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods: DELETE Path: /v{version:[0-9][0-9.]*}/volumes/>
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods: DELETE Path: /volumes/{name}"
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods:   POST Path: /v{version:[0-9][0-9.]*}/volumes/>
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Methods:   POST Path: /volumes/prune"
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="Notify sent successfully"
Mar 05 08:31:22 localhost.localdomain podman[507761]: time="2021-03-05T08:31:22-05:00" level=debug msg="API Server idle for 0s"

[root@localhost ~]# systemctl status podman.socket
● podman.socket - Podman Socket
   Loaded: loaded (/run/systemd/system/podman.socket; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2021-03-05 08:31:22 EST; 14min ago
   Listen: 127.0.0.1:8081 (Stream)
    Tasks: 0 (limit: 48707)
   Memory: 0B
   CGroup: /system.slice/podman.socket

Mar 05 08:31:22 localhost.localdomain systemd[1]: Listening on Podman Socket.

Results when run as user --> this FAILS for podman.service, but podman.socket works fine

[testuser@localhost ~]$ systemctl --user status podman
● podman.service - Podman Service
   Loaded: loaded (/home/testuser/.config/systemd/user/podman.service; enabled; vendor preset: enabled)
   Active: failed (Result: timeout) since Fri 2021-03-05 08:23:31 EST; 9min ago
  Process: 507054 ExecStart=/usr/bin/podman $LOGGING system service -t 0 (code=exited, status=1/FAILURE)
 Main PID: 507054 (code=exited, status=1/FAILURE)

Mar 05 08:23:31 localhost.localdomain systemd[5841]: podman.service: start operation timed out. Terminating.
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=info msg="Received shutdown signal terminated, terminating!"
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=info msg="Invoking shutdown handler libpod"
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=info msg="Received shutdown signal terminated, terminating!"
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=info msg="Invoking shutdown handler server"
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=debug msg="APIServer.Shutdown ignored as Duration is UnlimitedService"
Mar 05 08:23:31 localhost.localdomain podman[507054]: time="2021-03-05T08:23:31-05:00" level=info msg="Invoking shutdown handler libpod"
Mar 05 08:23:31 localhost.localdomain systemd[5841]: podman.service: Main process exited, code=exited, status=1/FAILURE
Mar 05 08:23:31 localhost.localdomain systemd[5841]: podman.service: Failed with result 'timeout'.
Mar 05 08:23:31 localhost.localdomain systemd[5841]: Failed to start Podman Service.

[testuser@localhost ~]$ systemctl --user status podman.socket
● podman.socket - Podman Socket
   Loaded: loaded (/home/testuser/.config/systemd/user/podman.socket; enabled; vendor preset: enabled)
   Active: active (listening) since Fri 2021-03-05 08:22:01 EST; 11min ago
   Listen: 127.0.0.1:8082 (Stream)
   CGroup: /user.slice/user-1000.slice/user@1000.service/podman.socket

Mar 05 08:22:01 localhost.localdomain systemd[5841]: Listening on Podman Socket.

Describe the results you expected:

Expected the user mode podman.service to run successfully.

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

As mentioned before, this happens only in systemd user mode irrespective of unix/tcp socket. I tested them both.

Output of podman version:

[testuser@localhost ~]$ podman version
Version:      3.0.1
API Version:  3.0.0
Go Version:   go1.14.12
Built:        Mon Feb 22 09:36:53 2021
OS/Arch:      linux/amd64

Output of podman info --debug:

[testuser@localhost ~]$ podman info --debug
host:
  arch: amd64
  buildahVersion: 1.19.4
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: conmon-2.0.26-3.el8.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.0.26, commit: c35ce4989f35168ff023617f1ea36554ae56d952'
  cpus: 4
  distribution:
    distribution: '"centos"'
    version: "8"
  eventLogger: journald
  hostname: localhost.localdomain
  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: 4.18.0-240.10.1.el8_3.x86_64
  linkmode: dynamic
  memFree: 3533475840
  memTotal: 8040083456
  ociRuntime:
    name: crun
    package: crun-0.18-2.el8.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 0.18
      commit: 808420efe3dc2b44d6db9f1a3fac8361dde42a95
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    exists: true
    path: /run/user/1000/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
    selinuxEnabled: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.1.4-2.module_el8.3.0+475+c50ce30b.x86_64
    version: |-
      slirp4netns version 1.1.4
      commit: b66ffa8e262507e37fca689822d23430f3357fe8
      libslirp: 4.3.1
      SLIRP_CONFIG_VERSION_MAX: 3
  swapFree: 1320378368
  swapTotal: 2613047296
  uptime: 214h 52m 27.38s (Approximately 8.92 days)
registries:
  search:
  - registry.gitlab.com
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - registry.centos.org
  - docker.io
store:
  configFile: /home/testuser/.config/containers/storage.conf
  containerStore:
    number: 0
    paused: 0
    running: 0
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: fuse-overlayfs-1.1.2-3.module_el8.3.0+507+aa0970ae.x86_64
      Version: |-
        fuse-overlayfs: version 1.1.0
        FUSE library version 3.2.1
        using FUSE kernel interface version 7.26
  graphRoot: /home/testuser/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 8
  runRoot: /run/user/1000/containers
  volumePath: /home/testuser/.local/share/containers/storage/volumes
version:
  APIVersion: 3.0.0
  Built: 1614004613
  BuiltTime: Mon Feb 22 09:36:53 2021
  GitCommit: ""
  GoVersion: go1.14.12
  OsArch: linux/amd64
  Version: 3.0.1

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

[testuser@localhost ~]$ rpm -q podman
podman-3.0.1-1.el8.x86_64

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide?

Yes

Additional environment details (AWS, VirtualBox, physical, etc.): Cent OS 8 VM