Bug 1737554

Summary:	Cannot run container with systemd
Product:	[Fedora] Fedora	Reporter:	Lukas Slebodnik <lslebodn>
Component:	podman	Assignee:	Giuseppe Scrivano <gscrivan>
Status:	CLOSED RAWHIDE	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	bbaude, dwalsh, frantisek.kluknavsky, jnovy, lsm5, mheon, santiago, yaneti
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	podman-1.4.5-0.84.dev.git66ea32c.fc31	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2019-08-08 11:48:52 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Lukas Slebodnik 2019-08-05 16:06:24 UTC

Description of problem:
The latest version of podman in rawhide broke running containers with systemd.


Version-Release number of selected component (if applicable):
sh# rpm -q podman oci-systemd-hook
podman-1.4.5-0.74.dev.git140e08e.fc31.x86_64
oci-systemd-hook-0.2.0-2.git05e6923.fc31.x86_64

How reproducible:
Deterministic

Steps to Reproduce:
1. dnf install -y podman
2. podman pull registry.access.redhat.com/ubi8-init
3. podman run -d registry.access.redhat.com/ubi8-init

Actual results:
podman run -d registry.access.redhat.com/ubi8-init
Error: time="2019-08-05T18:02:30+02:00" level=warning msg="signal: killed"
time="2019-08-05T18:02:30+02:00" level=error msg="container_linux.go:346: starting container process caused \"process_linux.go:449: container init caused \\\"rootfs_linux.go:58: mounting \\\\\\\"/sys/fs/cgroup/machine.slice/libpod-c9d4193f9069cd00129f41e587adbd03f223f0baa4b6b2097b2470764128e2c6.scope\\\\\\\" to rootfs \\\\\\\"/var/lib/containers/storage/overlay/bd1f26110bb27d0cf87b1f82aa72d2e043bd1f01fcbcaa91aad195c7923b78e2/merged\\\\\\\" at \\\\\\\"/sys/fs/cgroup\\\\\\\" caused \\\\\\\"stat /sys/fs/cgroup/machine.slice/libpod-c9d4193f9069cd00129f41e587adbd03f223f0baa4b6b2097b2470764128e2c6.scope: no such file or directory\\\\\\\"\\\"\"\n"
container_linux.go:346: starting container process caused "process_linux.go:449: container init caused \"rootfs_linux.go:58: mounting \\\"/sys/fs/cgroup/machine.slice/libpod-c9d4193f9069cd00129f41e587adbd03f223f0baa4b6b2097b2470764128e2c6.scope\\\" to rootfs \\\"/var/lib/containers/storage/overlay/bd1f26110bb27d0cf87b1f82aa72d2e043bd1f01fcbcaa91aad195c7923b78e2/merged\\\" at \\\"/sys/fs/cgroup\\\" caused \\\"stat /sys/fs/cgroup/machine.slice/libpod-c9d4193f9069cd00129f41e587adbd03f223f0baa4b6b2097b2470764128e2c6.scope: no such file or directory\\\"\"": OCI runtime error

Expected results:
sh# podman run -d registry.access.redhat.com/ubi8-init
98ad604c4b705ad6a20b749b43c1d5a32cbdce039709dac3350355e7f1687978
sh# podman ps
CONTAINER ID  IMAGE                                        COMMAND     CREATED        STATUS            PORTS  NAMES
98ad604c4b70  registry.access.redhat.com/ubi8-init:latest  /sbin/init  2 seconds ago  Up 2 seconds ago         mystifying_cohen

Additional info:
It works like a magic with podman-1.4.5-0.29.dev.gitd6b41eb.fc31.x86_64.rpm
I wonder whether I should lock version of podman with dnf or switch to moby-engine to have something stable on rawhide.

Please consider add sanity test to rawhide and enable gating there
https://docs.fedoraproject.org/en-US/rawhide-gating/

Comment 1 Lukas Slebodnik 2019-08-05 16:09:27 UTC

And debug output with the latest version from koji (podman-1.4.5-0.81.dev.git3bffe77.fc31.x86_64)

sh# podman --log-level=debug run -d registry.access.redhat.com/ubi8-init
DEBU[0000] using conmon: "/usr/libexec/podman/conmon"   
DEBU[0000] Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver overlay                   
DEBU[0000] Using graph root /var/lib/containers/storage 
DEBU[0000] Using run root /var/run/containers/storage   
DEBU[0000] Using static dir /var/lib/containers/storage/libpod 
DEBU[0000] Using tmp dir /var/run/libpod                
DEBU[0000] Using volume path /var/lib/containers/storage/volumes 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "overlay" 
DEBU[0000] cached value indicated that overlay is supported 
DEBU[0000] cached value indicated that metacopy is being used 
DEBU[0000] cached value indicated that native-diff is not being used 
WARN[0000] Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled 
DEBU[0000] backingFs=xfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true 
DEBU[0000] Initializing event backend journald          
DEBU[0000] using runtime "/usr/bin/runc"                
WARN[0000] Error initializing configured OCI runtime crun: no valid executable found for OCI runtime crun: invalid argument 
INFO[0000] Found CNI network podman (type=bridge) at /etc/cni/net.d/87-podman-bridge.conflist 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,metacopy=on]registry.access.redhat.com/ubi8-init:latest" 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,metacopy=on]@0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] exporting opaque data as blob "sha256:0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,metacopy=on]@0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] exporting opaque data as blob "sha256:0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,metacopy=on]@0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] Got mounts: []                               
DEBU[0000] Got volumes: []
DEBU[0000] Using bridge netmode                         
DEBU[0000] created OCI spec and options for new container 
DEBU[0000] Allocated lock 9 for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 
DEBU[0000] parsed reference into "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.mountopt=nodev,metacopy=on]@0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] exporting opaque data as blob "sha256:0d0a19ef4ca462acbf41e2efa3c34be283eb991551e5b019e48c5090a49d8d3f" 
DEBU[0000] created container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" 
DEBU[0000] container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" has work directory "/var/lib/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata" 
DEBU[0000] container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" has run directory "/var/run/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata" 
DEBU[0000] New container created "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" 
DEBU[0000] container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" has CgroupParent "machine.slice/libpod-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope" 
DEBU[0000] overlay: mount_data=nodev,metacopy=on,lowerdir=/var/lib/containers/storage/overlay/l/YKM53Q7ZDXRXUF2JYN5MP3BIYK:/var/lib/containers/storage/overlay/l/KQV3SN5SHBTOAZWZPBHJDQ3OPT:/var/lib/containers/storage/overlay/l/6ADNY3ASHDLZTBHIPONAURC7SJ,upperdir=/var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/diff,workdir=/var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/work,context="system_u:object_r:container_file_t:s0:c6,c928" 
DEBU[0000] Made network namespace at /var/run/netns/cni-eaec3155-afa4-ac4e-be3d-fdc718105580 for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 
INFO[0000] Got pod network &{Name:reverent_bell Namespace:reverent_bell ID:7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 NetNS:/var/run/netns/cni-eaec3155-afa4-ac4e-be3d-fdc718105580 Networks:[] RuntimeConfig:map[podman:{IP: PortMappings:[] Bandwidth:<nil> IpRanges:[]}]} 
INFO[0000] About to add CNI network cni-loopback (type=loopback) 
DEBU[0000] mounted container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" at "/var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/merged" 
DEBU[0000] Created root filesystem for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 at /var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/merged 
INFO[0000] Got pod network &{Name:reverent_bell Namespace:reverent_bell ID:7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 NetNS:/var/run/netns/cni-eaec3155-afa4-ac4e-be3d-fdc718105580 Networks:[] RuntimeConfig:map[podman:{IP: PortMappings:[] Bandwidth:<nil> IpRanges:[]}]} 
INFO[0000] About to add CNI network podman (type=bridge) 
DEBU[0000] [0] CNI result: Interfaces:[{Name:cni0 Mac:1a:3c:c2:96:12:1c Sandbox:} {Name:vethfaac1434 Mac:de:72:10:5e:d0:22 Sandbox:} {Name:eth0 Mac:a2:ff:9c:5c:7f:c9 Sandbox:/var/run/netns/cni-eaec3155-afa4-ac4e-be3d-fdc718105580}], IP:[{Version:4 Interface:0xc0004dbdf0 Address:{IP:10.88.0.18 Mask:ffff0000} Gateway:10.88.0.1}], Routes:[{Dst:{IP:0.0.0.0 Mask:00000000} GW:<nil>}], DNS:{Nameservers:[] Domain: Search:[] Options:[]} 
DEBU[0000] /etc/system-fips does not exist on host, not mounting FIPS mode secret 
DEBU[0000] Setting CGroups for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 to machine.slice:libpod:7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 
DEBU[0000] reading hooks from /usr/share/containers/oci/hooks.d 
DEBU[0000] added hook /usr/share/containers/oci/hooks.d/oci-systemd-hook.json 
DEBU[0000] hook oci-systemd-hook.json matched; adding to stages [prestart poststop] 
WARN[0000] implicit hook directories are deprecated; set --ociHooks-dir="/usr/share/containers/oci/hooks.d" explicitly to continue to load ociHooks from this directory 
DEBU[0000] reading hooks from /etc/containers/oci/hooks.d 
WARN[0000] implicit hook directories are deprecated; set --ociHooks-dir="/etc/containers/oci/hooks.d" explicitly to continue to load ociHooks from this directory 
DEBU[0000] Created OCI spec for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 at /var/lib/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/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 -s -c 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 -u 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 -r /usr/bin/runc -b /var/lib/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata -p /var/run/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata/pidfile -l k8s-file:/var/lib/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata/ctr.log --exit-dir /var/run/libpod/exits --socket-dir-path /var/run/libpod/socket --log-level debug --syslog --conmon-pidfile /var/run/containers/storage/overlay-containers/7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /var/lib/containers/storage --exit-command-arg --runroot --exit-command-arg /var/run/containers/storage --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /var/run/libpod --exit-command-arg --runtime --exit-command-arg runc --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --storage-opt --exit-command-arg overlay.mountopt=nodev,metacopy=on --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg container --exit-command-arg cleanup --exit-command-arg 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352]"
INFO[0000] Running conmon under slice machine.slice and unitName libpod-conmon-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope 
DEBU[0000] Received: -1                                 
DEBU[0000] Cleaning up container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 
DEBU[0000] Tearing down network namespace for container 7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 
INFO[0000] Got pod network &{Name:reverent_bell Namespace:reverent_bell ID:7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352 NetNS:/var/run/netns/cni-eaec3155-afa4-ac4e-be3d-fdc718105580 Networks:[] RuntimeConfig:map[podman:{IP: PortMappings:[] Bandwidth:<nil> IpRanges:[]}]} 
INFO[0000] About to del CNI network podman (type=bridge) 
DEBU[0000] unmounted container "7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352" 
ERRO[0000] time="2019-08-05T18:07:56+02:00" level=warning msg="signal: killed"
time="2019-08-05T18:07:56+02:00" level=error msg="container_linux.go:346: starting container process caused \"process_linux.go:449: container init caused \\\"rootfs_linux.go:58: mounting \\\\\\\"/sys/fs/cgroup/machine.slice/libpod-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope\\\\\\\" to rootfs \\\\\\\"/var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/merged\\\\\\\" at \\\\\\\"/sys/fs/cgroup\\\\\\\" caused \\\\\\\"stat /sys/fs/cgroup/machine.slice/libpod-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope: no such file or directory\\\\\\\"\\\"\"\n"
container_linux.go:346: starting container process caused "process_linux.go:449: container init caused \"rootfs_linux.go:58: mounting \\\"/sys/fs/cgroup/machine.slice/libpod-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope\\\" to rootfs \\\"/var/lib/containers/storage/overlay/1b73a427a3d8faad4f18295d308d8b87cdab853874817e140923418116437940/merged\\\" at \\\"/sys/fs/cgroup\\\" caused \\\"stat /sys/fs/cgroup/machine.slice/libpod-7bef7a20d554bdbfa97f8c5d37f96779f6ccc7100696929974946da8eb077352.scope: no such file or directory\\\"\"": OCI runtime error

Comment 2 Ed Santiago 2019-08-05 17:52:38 UTC

Confirmed on kernel-5.1.0-0.rc1.git2.1.fc31 and 5.3.0-0.rc2.git4.1.fc31.x86_64

Comment 3 Matthew Heon 2019-08-05 18:15:29 UTC

Reproduces on F30 with master branch.

Comment 4 Ed Santiago 2019-08-05 18:31:10 UTC

Evidence points to #3677 https://github.com/containers/libpod/pull/3677

Comment 5 Giuseppe Scrivano 2019-08-06 07:14:38 UTC

opened a PR here: https://github.com/containers/libpod/pull/3731

Comment 6 Lukas Slebodnik 2019-08-07 08:34:25 UTC

I can confirm that podman-1.4.5-0.84.dev.git66ea32c.fc31.x86_64 fixed the problem.