Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Failed starting podman API using systemctl : Failed to start Podman API Service. #8800

Closed
ruddy32 opened this issue Dec 21, 2020 · 3 comments
Closed

Failed starting podman API using systemctl : Failed to start Podman API Service. #8800

ruddy32 opened this issue Dec 21, 2020 · 3 comments
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.

Comments

@ruddy32
Copy link

ruddy32 commented Dec 21, 2020

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

/kind bug

Description

Failed starting podman API using systemctl : systemd[1205]: Failed to start Podman API Service.

Steps to reproduce the issue:

  1. Archlinux x86/64 system

  2. Run systemctl --user start podman

Describe the results you received:

System journal show :
systemd[1205]: Failed to start Podman API Service.

Describe the results you expected:

systemd[1205]: Podman API Service started.

Additional information you deem important (e.g. issue happens only occasionally):
This happen since version 2.2.0
Running journalctl --user -lxeu podman provides :

déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=info msg="/usr/bin/podman filtering at log level debug"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Called service.PersistentPreRunE(/usr/bin/podman --log-level=debug system service)"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Reading configuration file \"/usr/share/containers/containers.conf\""
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Merged system config \"/usr/share/containers/containers.conf\": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.29.0 Annotati>
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Reading configuration file \"/etc/containers/containers.conf\""
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Merged system config \"/etc/containers/containers.conf\": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.29.0 Annotations:[]>
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Initializing boltdb state at /home/user/.local/share/containers/storage/libpod/bolt_state.db"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using graph driver vfs"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using graph root /home/user/.local/share/containers/storage"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using run root /run/user/1000/containers"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using static dir /home/user/.local/share/containers/storage/libpod"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using tmp dir /run/user/1000/libpod/tmp"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Using volume path /home/user/.local/share/containers/storage/volumes"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Set libpod namespace to \"\""
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Not configuring container store"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="Initializing event backend journald"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=warning msg="Error initializing configured OCI runtime crun: no valid executable found for OCI runtime crun: invalid argument"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=warning msg="Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument"
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=debug msg="using runtime \"/usr/bin/runc\""
déc. 21 23:24:59 lt003 podman[8575]: time="2020-12-21T23:24:59+01:00" level=info msg="Setting parallel job count to 25"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=info msg="/usr/bin/podman filtering at log level debug"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Called service.PersistentPreRunE(/usr/bin/podman --log-level=debug system service)"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Reading configuration file \"/usr/share/containers/containers.conf\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Merged system config \"/usr/share/containers/containers.conf\": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.29.0 Annotati>
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Reading configuration file \"/etc/containers/containers.conf\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Merged system config \"/etc/containers/containers.conf\": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.29.0 Annotations:[]>
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Initializing boltdb state at /home/user/.local/share/containers/storage/libpod/bolt_state.db"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using graph driver vfs"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using graph root /home/user/.local/share/containers/storage"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using run root /run/user/1000/containers"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using static dir /home/user/.local/share/containers/storage/libpod"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using tmp dir /run/user/1000/libpod/tmp"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Using volume path /home/user/.local/share/containers/storage/volumes"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Set libpod namespace to \"\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="[graphdriver] trying provided driver \"vfs\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Initializing event backend journald"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="using runtime \"/usr/bin/runc\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=warning msg="Error initializing configured OCI runtime crun: no valid executable found for OCI runtime crun: invalid argument"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=warning msg="Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=info msg="Setting parallel job count to 25"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=info msg="using API endpoint: 'unix:/run/user/1000/podman/podman.sock'"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="registered SIGHUP watcher for config"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="waiting for SIGHUP to reload configuration"
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=info msg="API server listening on \"/run/user/1000/podman/podman.sock\""
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Methods:  <N/A> Path: /v{version:[0-9][0-9.]*}/auth"

...
déc. 21 23:25:00 lt003 systemd[1205]: podman.service: **Got notification message from PID 8585, but reception only permitted for main PID 8575**
...
déc. 21 23:25:00 lt003 podman[8585]: time="2020-12-21T23:25:00+01:00" level=debug msg="Notify sent successfully"
déc. 21 23:25:05 lt003 podman[8585]: time="2020-12-21T23:25:05+01:00" level=debug msg="API Server idle for 5s"
déc. 21 23:25:05 lt003 podman[8585]: time="2020-12-21T23:25:05+01:00" level=debug msg="APIServer.Shutdown by go/src/sync/once.go:66, 0/0 connection(s)"
déc. 21 23:25:05 lt003 podman[8585]: time="2020-12-21T23:25:05+01:00" level=debug msg="Called service.PersistentPostRunE(/usr/bin/podman --log-level=debug system service)"
déc. 21 23:25:05 lt003 systemd[1205]: podman.service: Failed with result 'protocol'.

Output of podman version:

Version:      2.2.1
API Version:  2.1.0
Go Version:   go1.15.6
Git Commit:   a0d478edea7f775b7ce32f8eb1a01e75374486cb
Built:        Tue Dec  8 22:48:23 2020
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.18.0
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: Unknown
    path: /usr/bin/conmon
    version: 'conmon version 2.0.22, commit: 9c34a8663b85e479e0c083801e89a2b2835228ed'
  cpus: 8
  distribution:
    distribution: arch
    version: unknown
  eventLogger: journald
  hostname: lt003
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 985
      size: 1
    - container_id: 1
      host_id: 100000
      size: 50001
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 50001
  kernel: 5.9.14-arch1-1
  linkmode: dynamic
  memFree: 169549824
  memTotal: 16636588032
  ociRuntime:
    name: runc
    package: Unknown
    path: /usr/bin/runc
    version: |-
      runc version 1.0.0-rc92
      commit: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
      spec: 1.0.2-dev
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: Unknown
    version: |-
      slirp4netns version 1.1.8
      commit: d361001f495417b880f20329121e3aa431a8f90f
      libslirp: 4.4.0
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.1
  swapFree: 17178816512
  swapTotal: 17179865088
  uptime: 14h 10m 7.94s (Approximately 0.58 days)
registries:
  search:
  - docker.io
  - registry.fedoraproject.org
  - quay.io
  - registry.access.redhat.com
  - registry.centos.org
store:
  configFile: /home/user/.config/containers/storage.conf
  containerStore:
    number: 2
    paused: 0
    running: 0
    stopped: 2
  graphDriverName: vfs
  graphOptions: {}
  graphRoot: /home/user/.local/share/containers/storage
  graphStatus: {}
  imageStore:
    number: 5
  runRoot: /run/user/1000/containers
  volumePath: /home/user/.local/share/containers/storage/volumes
version:
  APIVersion: 2.1.0
  Built: 1607464103
  BuiltTime: Tue Dec  8 22:48:23 2020
  GitCommit: a0d478edea7f775b7ce32f8eb1a01e75374486cb
  GoVersion: go1.15.6
  OsArch: linux/amd64
  Version: 2.2.1

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

warning: podman-2.2.1-1 is up to date -- reinstalling
resolving dependencies...
looking for conflicting packages...

Packages (1) podman-2.2.1-1

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.):
@openshift-ci-robot openshift-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Dec 21, 2020
@mheon
Copy link
Member

mheon commented Dec 22, 2020

Likely fixed by #8753 (merged upstream but not yet in any release)

@giuseppe giuseppe changed the title systemctl Failed starting podman API using systemctl : Failed to start Podman API Service. Dec 22, 2020
@rhatdan rhatdan closed this as completed Dec 22, 2020
@arzarif
Copy link

arzarif commented Apr 13, 2021 •
edited
Loading

I was seeing the same issue with podman version 3.0.1. This appears to be an issue with options passed to the start command in the unit file. The timeout (5s) both the original poster and I experienced are coming from defaults:

# /usr/bin/podman --log-level=debug system service --help
Run API service

Description:
  Run an API service

Enable a listening service for API access to Podman commands.


Usage:
  podman system service [options] [URI]

Examples:
  podman system service --time=0 unix:///tmp/podman.sock

Options:
  -t, --time int   Time until the service session expires in seconds.  Use 0 to disable the timeout (default 5)

Wouldn't the expectation be that the start command in the unit file disables the timeout?

@mheon
Copy link
Member

mheon commented Apr 14, 2021

No - Podman is expected to time out in this case. Systemd will restart it via socket activation when it is needed.

If you do not use socket activation, you will need to manually set the timeout to 0 in the unit file.

@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 22, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Sep 22, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@rhatdan @ruddy32 @arzarif @mheon @openshift-ci-robot