created pods are not startable

[trusch]

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

/kind bug

Description

If I create a pod, I expect that I can start it. Unfotunately this fails because the create step also already creates the infra container,
but the start step tries to create it. This is very annoying because the systemd files generated using podman generate systemd --new ... rely on this behavior.

Steps to reproduce the issue:

➜  ~ podman pod create --name example
46ef217caf85603e425c3922d542699220e4070b549f0c9b2ca2030c8e45b1a3
➜  ~ podman pod start example        
Error: error starting some containers: container already exists

Describe the results you received:
I can't start the created pod

Describe the results you expected:
I can start the created pod

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

Output of podman version:

Version:      2.0.1
API Version:  1
Go Version:   go1.14.4
Git Commit:   a11c4ead10177a66ef2810a0a92ea8ce2299da07
Built:        Sat Jun 27 22:04:26 2020
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.15.0
  cgroupVersion: v2
  conmon:
    package: Unknown
    path: /usr/bin/conmon
    version: 'conmon version 2.0.18, commit: 7b3e303be8f1aea7e0d4a784c8e64a75c14756a4'
  cpus: 4
  distribution:
    distribution: arch
    version: unknown
  eventLogger: file
  hostname: carbon
  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.7.5-arch1-1
  linkmode: dynamic
  memFree: 1961365504
  memTotal: 8218943488
  ociRuntime:
    name: crun
    package: Unknown
    path: /usr/bin/crun
    version: |-
      crun version 0.13
      commit: e79e4de4ac16da0ce48777afb72c6241de870525
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: Unknown
    version: |-
      slirp4netns version 1.1.1
      commit: bbf27c5acd4356edb97fa639b4e15e0cd56a39d5
      libslirp: 4.3.0
      SLIRP_CONFIG_VERSION_MAX: 3
  swapFree: 0
  swapTotal: 0
  uptime: 42m 38.73s
registries:
  search:
  - docker.io
  - registry.fedoraproject.org
  - quay.io
  - registry.access.redhat.com
  - registry.centos.org
store:
  configFile: /home/tino/.config/containers/storage.conf
  containerStore:
    number: 2
    paused: 0
    running: 0
    stopped: 2
  graphDriverName: overlay
  graphOptions:
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: Unknown
      Version: |-
        fusermount3 version: 3.9.2
        fuse-overlayfs: version 1.1.0
        FUSE library version 3.9.2
        using FUSE kernel interface version 7.31
  graphRoot: /home/tino/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 78
  runRoot: /run/user/1000
  volumePath: /home/tino/.local/share/containers/storage/volumes
version:
  APIVersion: 1
  Built: 1593288266
  BuiltTime: Sat Jun 27 22:04:26 2020
  GitCommit: a11c4ead10177a66ef2810a0a92ea8ce2299da07
  GoVersion: go1.14.4
  OsArch: linux/amd64
  Version: 2.0.1

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

➜  ~ pacman -Q podman
podman 2.0.1-1

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

[mheon]

Any more details here? I can't reproduce, the pod starts without issue.

[trusch]

Perhaps its worth noting that I have cgroupsv2 enabled and use crun, but other than that my setup is just the default install.

[trusch]

I tried to setup an reproducing environment but failed in the end (fresh OS install, same tools, same versions, everything). Is there anything suspicious in my podman info from above?

[goochjj]

Please provide:
podman --log-level debug pod start example

And any log messages from conmon that might be in your journal or syslog

[danopia]

I just ran into this message myself running 2.0.1 rootless on Debian.

Version info

> podman version
Version:      2.0.1
API Version:  1
Go Version:   go1.14.4
Built:        Thu Jan  1 01:00:00 1970
OS/Arch:      linux/amd64

> podman info --debug
host:
  arch: amd64
  buildahVersion: 1.15.0
  cgroupVersion: v1
  conmon:
    package: 'conmon: /usr/libexec/podman/conmon'
    path: /usr/libexec/podman/conmon
    version: 'conmon version 2.0.18, commit: '
  cpus: 2
  distribution:
    distribution: debian
    version: unknown
  eventLogger: file
  hostname: penguin
  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.4.40-04224-g891a6cce2d44
  linkmode: dynamic
  memFree: 15223529472
  memTotal: 15260385280
  ociRuntime:
    name: runc
    package: 'containerd.io: /usr/bin/runc'
    path: /usr/bin/runc
    version: |-
      runc version 1.0.0-rc10
      commit: dc9208a3303feef5b3839f4323d9beb36df0a9dd
      spec: 1.0.1-dev
  os: linux
  remoteSocket:
    exists: true
    path: /run/user/1000/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: 'slirp4netns: /usr/bin/slirp4netns'
    version: |-
      slirp4netns version 1.0.1
      commit: 6a7b16babc95b6a3056b33fb45b74a6f62262dd4
      libslirp: 4.2.0
  swapFree: 0
  swapTotal: 0
  uptime: 38h 34m 49s (Approximately 1.58 days)
registries:
  search:
  - docker.io
  - quay.io
store:
  configFile: /home/dan/.config/containers/storage.conf
  containerStore:
    number: 3
    paused: 0
    running: 0
    stopped: 3
  graphDriverName: vfs
  graphOptions: {}
  graphRoot: /home/dan/.local/share/containers/storage
  graphStatus: {}
  imageStore:
    number: 3
  runRoot: /run/user/1000
  volumePath: /home/dan/.local/share/containers/storage/volumes
version:
  APIVersion: 1
  Built: 0
  BuiltTime: Thu Jan  1 01:00:00 1970
  GitCommit: ""
  GoVersion: go1.14.4
  OsArch: linux/amd64
  Version: 2.0.1

Creating an empty pod:

> podman pod create --name example
ffc7b82466fb3c11aa76f22462110694113f5d4d1bf960ec78c61e27098f5caa
> podman ps -a
CONTAINER ID  IMAGE                            COMMAND    CREATED        STATUS   PORTS   NAMES
55577e7d453d  k8s.gcr.io/pause:3.2                        7 seconds ago  Created          ffc7b82466fb-infra

Trying to start it in debug mode:

> podman --log-level debug pod start example
INFO[0000] podman filtering at log level debug          
DEBU[0000] Called start.PersistentPreRunE(podman --log-level debug pod start example) 
DEBU[0000] Ignoring libpod.conf EventsLogger setting "/home/dan/.config/containers/containers.conf". Use "journald" if you want to change this setting and remove libpod.conf files. 
DEBU[0000] Reading configuration file "/usr/share/containers/containers.conf" 
DEBU[0000] Merged system config "/usr/share/containers/containers.conf": &{{[] [] containers-default-0.14.3 [] host enabled [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] [] [nproc=32768:32768]  [] [] [] false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] false false false  private k8s-file -1 slirp4netns false 2048 private /usr/share/containers/seccomp.json 65536k private host 65536} {false systemd [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] [/usr/libexec/podman/conmon /usr/local/libexec/podman/conmon /usr/local/lib/podman/conmon /usr/bin/conmon /usr/sbin/conmon /usr/local/bin/conmon /usr/local/sbin/conmon /run/current-system/sw/bin/conmon] ctrl-p,ctrl-q true /run/user/1000/libpod/tmp/events/events.log file [/usr/share/containers/oci/hooks.d] docker:// /pause k8s.gcr.io/pause:3.2 /usr/libexec/podman/catatonit shm   false 2048 runc map[crun:[/usr/bin/crun /usr/sbin/crun /usr/local/bin/crun /usr/local/sbin/crun /sbin/crun /bin/crun /run/current-system/sw/bin/crun] kata:[/usr/bin/kata-runtime /usr/sbin/kata-runtime /usr/local/bin/kata-runtime /usr/local/sbin/kata-runtime /sbin/kata-runtime /bin/kata-runtime /usr/bin/kata-qemu /usr/bin/kata-fc] runc:[/usr/bin/runc /usr/sbin/runc /usr/local/bin/runc /usr/local/sbin/runc /sbin/runc /bin/runc /usr/lib/cri-o-runc/sbin/runc /run/current-system/sw/bin/runc]] missing false   [] [crun runc] [crun] [kata kata-runtime kata-qemu kata-fc] {false false false false false false} /etc/containers/policy.json false 3 /home/dan/.local/share/containers/storage/libpod 10 /run/user/1000/libpod/tmp /home/dan/.local/share/containers/storage/volumes} {[/usr/libexec/cni /usr/lib/cni /usr/local/lib/cni /opt/cni/bin] podman /etc/cni/net.d/}} 
DEBU[0000] Reading configuration file "/etc/containers/containers.conf" 
DEBU[0000] Merged system config "/etc/containers/containers.conf": &{{[] [] containers-default-0.14.3 [] host enabled [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] [] [nproc=32768:32768]  [] [] [] false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] false false false  private k8s-file -1 slirp4netns false 2048 private /usr/share/containers/seccomp.json 65536k private host 65536} {false systemd [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] [/usr/libexec/podman/conmon /usr/local/libexec/podman/conmon /usr/local/lib/podman/conmon /usr/bin/conmon /usr/sbin/conmon /usr/local/bin/conmon /usr/local/sbin/conmon /run/current-system/sw/bin/conmon] ctrl-p,ctrl-q true /run/user/1000/libpod/tmp/events/events.log file [/usr/share/containers/oci/hooks.d] docker:// /pause k8s.gcr.io/pause:3.2 /usr/libexec/podman/catatonit shm   false 2048 runc map[crun:[/usr/bin/crun /usr/sbin/crun /usr/local/bin/crun /usr/local/sbin/crun /sbin/crun /bin/crun /run/current-system/sw/bin/crun] kata:[/usr/bin/kata-runtime /usr/sbin/kata-runtime /usr/local/bin/kata-runtime /usr/local/sbin/kata-runtime /sbin/kata-runtime /bin/kata-runtime /usr/bin/kata-qemu /usr/bin/kata-fc] runc:[/usr/bin/runc /usr/sbin/runc /usr/local/bin/runc /usr/local/sbin/runc /sbin/runc /bin/runc /usr/lib/cri-o-runc/sbin/runc /run/current-system/sw/bin/runc]] missing false   [] [crun runc] [crun] [kata kata-runtime kata-qemu kata-fc] {false false false false false false} /etc/containers/policy.json false 3 /home/dan/.local/share/containers/storage/libpod 10 /run/user/1000/libpod/tmp /home/dan/.local/share/containers/storage/volumes} {[/usr/libexec/cni /usr/lib/cni /usr/local/lib/cni /opt/cni/bin] podman /etc/cni/net.d/}} 
DEBU[0000] Using conmon: "/usr/libexec/podman/conmon"   
DEBU[0000] Initializing boltdb state at /home/dan/.local/share/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver vfs                       
DEBU[0000] Using graph root /home/dan/.local/share/containers/storage 
DEBU[0000] Using run root /run/user/1000                
DEBU[0000] Using static dir /home/dan/.local/share/containers/storage/libpod 
DEBU[0000] Using tmp dir /run/user/1000/libpod/tmp      
DEBU[0000] Using volume path /home/dan/.local/share/containers/storage/volumes 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "vfs"   
DEBU[0000] Initializing event backend file              
DEBU[0000] using runtime "/usr/bin/runc"                
DEBU[0000] using runtime "/usr/bin/crun"                
WARN[0000] Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument 
INFO[0000] Setting parallel job count to 7              
DEBU[0000] Strongconnecting node 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 
DEBU[0000] Pushed 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 onto stack 
DEBU[0000] Finishing node 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6. Popped 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 off stack 
DEBU[0000] Made network namespace at /run/user/1000/netns/cni-a57bd98c-d15d-d06e-9ae3-058d17051e13 for container 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 
DEBU[0000] mounted container "55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6" at "/home/dan/.local/share/containers/storage/vfs/dir/2c41e11b57c5135a4524d6dda23535351fd2c0b44547a2de06d027ed956ac148" 
DEBU[0000] slirp4netns command: /usr/bin/slirp4netns --disable-host-loopback --mtu 65520 --enable-sandbox --enable-seccomp -c -e 3 -r 4 --netns-type=path /run/user/1000/netns/cni-a57bd98c-d15d-d06e-9ae3-058d17051e13 tap0 
DEBU[0000] Created root filesystem for container 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 at /home/dan/.local/share/containers/storage/vfs/dir/2c41e11b57c5135a4524d6dda23535351fd2c0b44547a2de06d027ed956ac148 
DEBU[0000] skipping loading default AppArmor profile (rootless mode) 
DEBU[0000] /etc/system-fips does not exist on host, not mounting FIPS mode secret 
WARN[0000] User mount overriding libpod mount at "/dev/shm" 
DEBU[0000] reading hooks from /usr/share/containers/oci/hooks.d 
DEBU[0000] Created OCI spec for container 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 at /home/dan/.local/share/containers/storage/vfs-containers/55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6/userdata/config.json 
DEBU[0000] /usr/libexec/podman/conmon messages will be logged to syslog 
DEBU[0000] running conmon: /usr/libexec/podman/conmon    args="[--api-version 1 -c 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 -u 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 -r /usr/bin/runc -b /home/dan/.local/share/containers/storage/vfs-containers/55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6/userdata -p /run/user/1000/vfs-containers/55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6/userdata/pidfile -n ffc7b82466fb-infra --exit-dir /run/user/1000/libpod/tmp/exits --socket-dir-path /run/user/1000/libpod/tmp/socket -l k8s-file:/home/dan/.local/share/containers/storage/vfs-containers/55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6/userdata/ctr.log --log-level debug --syslog --conmon-pidfile /run/user/1000/vfs-containers/55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6/userdata/conmon.pid]"
[conmon:d]: failed to write to /proc/self/oom_score_adj: Permission denied

DEBU[0000] Received: -1                                 
DEBU[0000] Cleaning up container 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 
DEBU[0000] Tearing down network namespace at /run/user/1000/netns/cni-a57bd98c-d15d-d06e-9ae3-058d17051e13 for container 55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6 
DEBU[0000] unmounted container "55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6" 
Error: error starting some containers: container already exists

There's a couple different interesting bits in the debug log, but without debug podman just prints Error: error starting some containers: container already exists and exits.

Possibly also interesting is the message when I try starting the infra container directly:

> podman start ffc7b82466fb-infra
Error: unable to start container "55577e7d453d54da8595ab5731366905639c19bb3a3a243c2a91d5ce2261aab6": container_linux.go:349: starting container process caused "process_linux.go:449: container init caused \"rootfs_linux.go:58: mounting \\\"proc\\\" to rootfs \\\"/home/dan/.local/share/containers/storage/vfs/dir/2c41e11b57c5135a4524d6dda23535351fd2c0b44547a2de06d027ed956ac148\\\" at \\\"/proc\\\" caused \\\"operation not permitted\\\"\"": OCI runtime permission denied error

It's hard to tell if my issue has the same root cause as OP's but maybe trying to start the infra container has a better error reporting route.

[mheon]

It looks like we do return the errors in question - they must be dropped somewhere.

Also, that error message is truly spectacularly bad - "container already exists" means absolutely nothing here. I think I was the one that wrote that bit, so... oops?

[mheon]

Fix for the error reporting part of this in #6846

[mheon]

Also, any chance you can try using the crun OCI runtime, to see if it gives a different error?

[danopia]

Now that we know the ambiguous error message just means containers couldn't start, it's a bit easier to check stuff!

Here's what I have on my setup:

> podman --runtime crun run --rm -it alpine echo hello
Error: create keyring `2ac4fa3863b92620ef7db3ea62cafd7ed30fb5ea263297822ca935138a346fe5`: Function not implemented: OCI runtime error

> podman --runtime runc run --rm -it alpine echo hello
Error: container_linux.go:349: starting container process caused "process_linux.go:449: container init caused \"rootfs_linux.go:58: mounting \\\"proc\\\" to rootfs \\\"/home/dan/.local/share/containers/storage/btrfs/subvolumes/ca4171554bed1d38736f3660150ac0bd5db2b279674858f35edff7b0f0dfae2f\\\" at \\\"/proc\\\" caused \\\"operation not permitted\\\"\"": OCI runtime permission denied error

(I switched to btrfs since last post as my / is btrfs)

I'm using the "Linux Apps - beta" feature on a Chromebook, so the env is pretty nonstandard. Not sure if this is the same issue trusch had, or if there's hope to get podman working here at all... (Docker works fine)

[mheon]

@giuseppe Does the keyring issue look like a kernel issue to you? I think I recall that.

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[rhatdan]

@giuseppe Did you ever review this?

[giuseppe]

sorry I've missed it. Looks like the kernel is too old and have no support for keyrings.

Both runc and crun have an option --no-new-keyring to skip creating a new one

[rhatdan]

@giuseppe Do we need a way to pass this down through podman to the OCI runtimes?

[danopia]

Hello,

I just performed a full reformat of my Chromebook for unrelated reasons, & installed podman from the kubic debian repo. Rootful podman works great now which is excellent :) and unblocks me building stuff with podman.

Rootless, I had to set up subuid/subgid files, then had a new error message about slirp4netns failed mentioning seccomp, unless passing --net=host, at which point I got back to the previously pasted keyring or /proc messages depending on runtime. Chromebook's Linux env is implemented as an LXC container so I'm wondering if something like #4131 is at play. The kernel isn't too old: Linux penguin 5.4.40-04224-g891a6cce2d44 #1 SMP PREEMPT Tue Jun 23 20:21:29 PDT 2020 x86_64 GNU/Linux but surely has some Google patches on top too.

---

In any case, the messaging that started this whole ticket appears to be fixed:

dan@penguin ~> podman pod create --name example
ad424b900dde4be34723597f7bef0d2ca2f297c3c5162a0eb0c4a9841aaba613
dan@penguin ~> podman pod start example
Error: error starting container e7485cb0a86685add495dcbaae866c673975088363f0ebdbbdc108d6e5e693d7: /usr/bin/slirp4netns failed: "sent tapfd=7 for tap0\nWARNING: Support for seccomp is experimental\nreceived tapfd=7\nenable_seccomp failed\ndo_slirp is exiting\ndo_slirp failed\nparent failed\nWARNING: Support for seccomp is experimental\nStarting slirp\n* MTU:             65520\n* Network:         10.0.2.0\n* Netmask:         255.255.255.0\n* Gateway:         10.0.2.2\n* DNS:             10.0.2.3\n* Recommended IP:  10.0.2.100\nseccomp: The following syscalls will be blocked by seccomp:"

That's a real error message now! so it seems reasonable to me to close this ticket.