podman with bind mount leaving cgroup debris and prevents container restart

[aalba6675]

Is this a BUG REPORT or FEATURE REQUEST?:

Uncomment only one, leave it on its own line:

/kind bug

/kind feature

Description

When podman stops a systemd container with bind mounts, it leaves behind a lot of cgroup debris.
This prevents the container from starting the third time.

Steps to reproduce the issue:

1. Workaround: currently to get working bind mounts I have to set mount --make-private /tmp. Otherwise oci-systemd-hook cannot move the mount to the overlay. This on Fedora 28. Cannot move mount from /tmp/ocitmp.XXXX to .../merged/run projectatomic/oci-systemd-hook#92

2. Create a systemd-based fedora:28 container

podman create --name bobby_silver -v /srv/docker/volumes/podman/home:/home:z   --env container=podman  --entrypoint=/sbin/init --stop-signal=RTMIN+3 fedora:28

3. Start container 3 times

podman start bobby_silver
podman stop bobby_silver
podman start bobby_silver
podman stop bobby_silver
podman start bobby_silver
podman stop bobby_silver

Describe the results you received:
After first start/stop cycle there is cgroup debris:

cgroup on /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0 type cgroup (rw,nosuid,nodev,noexec,relatime,seclabel,xattr,name=systemd)
cgroup on /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0 type cgroup (rw,nosuid,nodev,noexec,relatime,seclabel,xattr,name=systemd)
cgroup on /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0 type cgroup (rw,nosuid,nodev,noexec,relatime,seclabel,xattr,name=systemd)

## third time unlucky
unable to start container "bobby_silver": container create failed: container_linux.go:348: starting container process caused "process_linux.go:402: container init caused \"rootfs_linux.go:58: mounting \\\"cgroup\\\" to rootfs \\\"/var/lib/containers/storage/overlay/52f7959a1a8a171b2c8aee587ea81c964e84130681444f0ff03b3202804a91cb/merged\\\" at \\\"/sys/fs/cgroup\\\" caused \\\"stat /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0: no such file or directory\\\"\""

journal

May 06 10:37:05 podman.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
May 06 10:37:05 podman.localdomain audit: ANOM_PROMISCUOUS dev=vethd814e8bb prom=256 old_prom=0 auid=1050 uid=0 gid=0 ses=3
May 06 10:37:05 podman.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): vethd814e8bb: link is not ready
May 06 10:37:05 podman.localdomain kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethd814e8bb: link becomes ready
May 06 10:37:05 podman.localdomain kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
May 06 10:37:05 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered blocking state
May 06 10:37:05 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered disabled state
May 06 10:37:05 podman.localdomain kernel: device vethd814e8bb entered promiscuous mode
May 06 10:37:05 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered blocking state
May 06 10:37:05 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered forwarding state
May 06 10:37:05 podman.localdomain NetworkManager[1159]: <info>  [1525574225.9736] device (vethd814e8bb): carrier: link connected
May 06 10:37:05 podman.localdomain NetworkManager[1159]: <info>  [1525574225.9747] manager: (vethd814e8bb): new Veth device (/org/freedesktop/NetworkManager/Devices/12)
May 06 10:37:05 podman.localdomain systemd-udevd[18311]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
May 06 10:37:05 podman.localdomain systemd-udevd[18311]: Could not generate persistent MAC address for vethd814e8bb: No such file or directory
May 06 10:37:05 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=89
May 06 10:37:05 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=91
May 06 10:37:05 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=92
May 06 10:37:05 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=93
May 06 10:37:05 podman.localdomain audit: NETFILTER_CFG table=filter family=2 entries=155
May 06 10:37:06 podman.localdomain conmon[18363]: conmon cd8be22a52efaed7e279 <ninfo>: about to waitpid: 18364
May 06 10:37:06 podman.localdomain kernel: SELinux: mount invalid.  Same superblock, different security settings for (dev mqueue, type mqueue)
May 06 10:37:06 podman.localdomain oci-systemd-hook[18389]: systemdhook <error>: cd8be22a52ef: pid not found in state: Success
May 06 10:37:06 podman.localdomain conmon[18363]: conmon cd8be22a52efaed7e279 <error>: Failed to create container: exit status 1
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=filter family=2 entries=156
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=94
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=96
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=94
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=96
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=10 entries=78
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=10 entries=80
May 06 10:37:06 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered disabled state
May 06 10:37:06 podman.localdomain audit: ANOM_PROMISCUOUS dev=vethd814e8bb prom=0 old_prom=256 auid=1050 uid=0 gid=0 ses=3
May 06 10:37:06 podman.localdomain kernel: device vethd814e8bb left promiscuous mode
May 06 10:37:06 podman.localdomain kernel: cni0: port 2(vethd814e8bb) entered disabled state
May 06 10:37:06 podman.localdomain NetworkManager[1159]: <info>  [1525574226.1560] device (vethd814e8bb): released from master device cni0
May 06 10:37:06 podman.localdomain gnome-shell[3393]: Removing a network device that was not added
May 06 10:37:06 podman.localdomain gnome-shell[2067]: Removing a network device that was not added
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=94
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=93
May 06 10:37:06 podman.localdomain audit: NETFILTER_CFG table=nat family=2 entries=91

Describe the results you expected:
start/stop without any issue

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

Output of podman version:

# podman version
Version:       0.5.2-dev
Go Version:    go1.10.1
OS/Arch:       linux/amd64

Output of podman info:

``
host:
MemFree: 17688948736
MemTotal: 33667493888
SwapFree: 0
SwapTotal: 0
arch: amd64
cpus: 8
hostname: podman.localdomain
kernel: 4.16.5-300.fc28.x86_64
os: linux
uptime: 10h 3m 7.91s (Approximately 0.42 days)
insecure registries:
registries: []
registries:
registries:

• docker.io
• registry.fedoraproject.org
• quay.io
• registry.access.redhat.com
  store:
  ContainerStore:
  number: 4
  GraphDriverName: overlay
  GraphOptions:
• overlay.override_kernel_check=true
  GraphRoot: /var/lib/containers/storage
  GraphStatus:
  Backing Filesystem: xfs
  Native Overlay Diff: "true"
  Supports d_type: "true"
  ImageStore:
  number: 2
  RunRoot: /var/run/containers/storage

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

[aalba6675]

After getting into this situation, I can't start even non-bind mounted containers.
alice_gold is a Fedora:28 container without any bind mounts

unable to start container "alice_gold": container create failed: container_linux.go:348: starting container process caused "process_linux.go:402: container init caused \"rootfs_linux.go:58: mounting \\\"cgroup\\\" to rootfs \\\"/var/lib/containers/storage/overlay/bc6d5e48c36118d012e5996158e5f7de7c0bd386b63cda3be40686a90203c019/merged\\\" at \\\"/sys/fs/cgroup\\\" caused \\\"stat /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5/2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5: no such file or directory\\\"\""
: internal libpod error

[aalba6675]

If I don't use bind mounts at all and leave /tmp as mount --make-shared, then all non-bind mount containers work: they can be start/stop without any cgroup debris.

[rhatdan]

@mrunalp I think this might be runc not running posthook oci-systemd-hook.

@aalba6675 Could you see if the journal reports that oci-systemd-hook ran in the posthook?

[aalba6675]

@rhatdan The posthook doesn't seem to be run. This is the journal when the container is stopped. Leaving behind a lot of cgroup mounted on impossibly long paths like

/sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
libpod_parent/libpod-
conmon-
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0 type cgroup 
(rw,nosuid,nodev,noexec,relatime,seclabel,xattr,name=systemd)```

Journal:

May 06 20:58:29 podman.localdomain audit[5949]: SERVICE_STOP pid=5949 uid=0 auid=1050 ses=3 subj=system_u:system_r:container_t:s0:c124,c228 msg='unit=dbus comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 06 20:58:29 podman.localdomain audit[5949]: SERVICE_STOP pid=5949 uid=0 auid=1050 ses=3 subj=system_u:system_r:container_t:s0:c124,c228 msg='unit=systemd-user-sessions comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 06 20:58:29 podman.localdomain audit[6133]: SYSTEM_SHUTDOWN pid=6133 uid=0 auid=1050 ses=3 subj=system_u:system_r:container_t:s0:c124,c228 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 06 20:58:29 podman.localdomain audit[5949]: SERVICE_STOP pid=5949 uid=0 auid=1050 ses=3 subj=system_u:system_r:container_t:s0:c124,c228 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 06 20:58:29 podman.localdomain audit[5949]: SERVICE_STOP pid=5949 uid=0 auid=1050 ses=3 subj=system_u:system_r:container_t:s0:c124,c228 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 06 20:58:29 podman.localdomain conmon[5938]: conmon cd8be22a52efaed7e279 <ninfo>: container 5949 exited with status 0

Old school (after the container is stopped):

lscgroup | grep pod
cpu,cpuacct:/libpod_parent
cpu,cpuacct:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
cpu,cpuacct:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
pids:/libpod_parent
pids:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
pids:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
cpuset:/libpod_parent
cpuset:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
cpuset:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
hugetlb:/libpod_parent
hugetlb:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
hugetlb:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
memory:/libpod_parent
memory:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
memory:/
libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
blkio:/libpod_parent
blkio:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
blkio:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
freezer:/libpod_parent
freezer:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
freezer:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
net_cls,net_prio:/libpod_parent
net_cls,net_prio:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
net_cls,net_prio:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
devices:/libpod_parent
devices:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
devices:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
perf_event:/libpod_parent
perf_event:/libpod_parent/libpod-conmon-2a5aee03fd0d0c99666543c00c5943a507aee7a6c6cbf932a714e3d090a85ea5
perf_event:/libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0

[aalba6675]

Is there a way to manually clear these cgroups/mounts? Once I get into this state I can't start simple containers (i.e. those without bind mounts).

[rhatdan]

Can't you just umount them?

[aalba6675]

Trying:

umount -t cgroup $(mount | grep ^cgroup.*libpod | gawk '{print $3}')

I get either

umount: /sys/fs/cgroup/systemd/
libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
: not mounted.

or

umount: /sys/fs/cgroup/systemd/libpod_parent/
libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
libpod_parent/libpod-conmon-cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0/
cd8be22a52efaed7e2790d2eb3421c00542c3eb9763bfe715c3ad23647c419e0
: no mount point specified.

[aalba6675]

Another observation: notify_on_release is 0 in the /sys/fs/cgroup/systemd/libpod_parent hierarchy.

[mheon]

CGroups issue could be related to #496
#507 may fix it, but has serious issues with Systemd-managed CGroups that still need to be solved.

[aalba6675]

@mheon - any idea why this would be triggered by a kludgy bind mount (mount --make-private /tmp)?

Non-bind mount containers are functioning without leaving group debris .

Once this situation is triggered (lots of cgroup mounted on /sys/fs/cgroup/systemd/libpod_parent/<long non existent path with uuid repeated>), then even non-bind mount containers could no longer be started.

[mheon]

@aalba6675 The mounts situation makes it sound like it could be oci-umount-hook firing, and less like our other CGroup issues (though it's wierd you're not seeing CGroups left over even in cases where mounts aren't involved, we should still be leaking one or two). I'm not familiar enough with that hook to know for sure what the cause might be, though.

[aalba6675]

@mheon you are right, I spoke too soon. The cgroups are only visible in the legacy tools libcgroup-tools.

lscgroup | grep libpod_parent
cpu,cpuacct:/libpod_parent
cpu,cpuacct:/libpod_parent/libpod-conmon-9a3f523c5c1055be951b2635c9371372f0de0ead65129da8bbab9c21a63f82e6
cpu,cpuacct:/libpod_parent/libpod-conmon-85b047f7598912928dd50ae435e932d8f6d36340bd29d94378cd76c04c1b9d3a
cpu,cpuacct:/libpod_parent/libpod-conmon-85b047f7598912928dd50ae435e932d8f6d36340bd29d94378cd76c04c1b9d3a/85b047f7598912928dd50ae435e932d8f6d36340bd29d94378cd76c04c1b9d3a
cpu,cpuacct:/libpod_parent/libpod-conmon-f31ddb42076b6f92fa4e3528aa69e3835657bac718a15fa1f21eded28d33df6d
cpu,cpuacct:/libpod_parent/libpod-conmon-9616fc8f2a42ad9276f4b65bf20aa48f1d921a3b56433b7b0c17799c7d48f5df
cpu,cpuacct:/libpod_parent/libpod-conmon-9616fc8f2a42ad9276f4b65bf20aa48f1d921a3b56433b7b0c17799c7d48f5df/9616fc8f2a42ad9276f4b65bf20aa48f1d921a3b56433b7b0c17799c7d48f5df
devices:/libpod_parent
devices:/libpod_parent/libpod-conmon-9a3f523c5c1055be951b2635c9371372f0de0ead65129da8bbab9c21a63f82e6
devices:/libpod_parent/libpod-conmon-85b047f7598912928dd50ae435e932d8f6d36340bd29d94378cd76c04c1b9d3a

There is leaking in /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-* as well. However there are no mounts of type cgroup on /sys/fs/cgroup/systemd/libpod_parent/libpod-conmon-*, so this doesn't prevent these stateless containers from start/stop multiple times.

In the case of bind mounts, there seems to be a recursive loop as the directory libpod-conmon-<uuid>/<uuid> gets repeated libpod-conmon-<uuid>/<uuid>/libpod-conmon-<uuid>/<uuid> etc until the container won't start.

[mheon]

The recursive CGroup path seems like a separate bug - our current CGroup issues are mainly a lack of cleanup, whereas this seems to actually be duplicating the Conmon scope repeatedly. Interesting - I'll look at this more tomorrow.