Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be available on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1574316 - Non-privileged systemd containers run sluggish with --tty
Summary: Non-privileged systemd containers run sluggish with --tty
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: oci-systemd-hook
Version: 29
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Tom Sweeney
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-03 05:03 UTC by Mikhail Zabaluev
Modified: 2019-11-05 13:35 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-01 18:00:35 UTC
Type: Bug
mikhail.zabaluev: needinfo-


Attachments (Terms of Use)

Description Mikhail Zabaluev 2018-05-03 05:03:37 UTC
Description of problem:
Trying to run a non-privileged container with systemd as PID 1, on Fedora Atomic 28 host testing ostree to verify a fix to bug 1510139. Can't get httpd to work or even systemd output on all runs.

Version-Release number of selected component (if applicable):
oci-systemd-hook-0.1.16-1.git05bd9a0.fc28.x86_64

ostree://fedora-atomic:fedora/28/x86_64/testing/atomic-host
                   Version: 28.20180502.0 (2018-05-02 11:55:33)
                    Commit: b7a88a7de1f17cb556f3295e608919a4a7b4e78b777e14b87c81b4514436afb6

How reproducible:
Uncertain, result varies.

Steps to Reproduce:
1. Create a directory with the following Dockerfile:

FROM registry.fedoraproject.org/fedora:latest

ENV container docker

RUN dnf -y install httpd; dnf clean all; systemctl enable httpd
STOPSIGNAL SIGRTMIN+3
EXPOSE 80
CMD [ "/sbin/init" ]

2. Build a container with `docker build -t systemdtest .` in the directory.
3. Run the container with `docker run --rm -ti -p 80:80 systemdtest`, observe the result, stop the container, repeat.

Actual results:

On different runs across several boots of the host machine, varying between:

1. No output at all.

2. Some progress into the boot sequence, httpd never starts:

systemd 234 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN default-hierarchy=hybrid)
Detected virtualization docker.
Detected architecture x86-64.

Welcome to Fedora 27 (Twenty Seven)!

Set hostname to <9b7290db2249>.
Failed to install release agent, ignoring: Read-only file system
[  OK  ] Reached target Local File Systems.
system.slice: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice, ignoring: Operation not permitted
[  OK  ] Created slice System Slice.
[  OK  ] Listening on Journal Socket.
ldconfig.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/ldconfig.service, ignoring: Operation not permitted
         Starting Rebuild Dynamic Linker Cache...
[  OK  ] Reached target Remote File Systems.
[  OK  ] Listening on Journal Socket (/dev/log).
systemd-journal-catalog-update.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-journal-catalog-update.service, ignoring: Operation not permitted
         Starting Rebuild Journal Catalog...
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Listening on Process Core Dump Socket.
[  OK  ] Reached target Swap.
systemd-sysusers.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-sysusers.service, ignoring: Operation not permitted
         Starting Create System Users...
[  OK  ] Reached target Slices.
[  OK  ] Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Reached target Paths.
systemd-journald.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-journald.service, ignoring: Operation not permitted
         Starting Journal Service...
[  OK  ] Reached target Local Encrypted Volumes.
[  OK  ] Listening on /dev/initctl Compatibility Named Pipe.
[  OK  ] Started Rebuild Dynamic Linker Cache.
[  OK  ] Started Rebuild Journal Catalog.
[  OK  ] Started Create System Users.
systemd-update-done.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-update-done.service, ignoring: Operation not permitted
         Starting Update is Completed...
ldconfig.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/ldconfig.service, ignoring: Operation not permitted
systemd-journal-catalog-update.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-journal-catalog-update.service, ignoring: Operation not permitted
systemd-sysusers.service: Failed to set invocation ID on control group /system.slice/docker-9b7290db22499411a1e0eb92fa2df31ff06f76b607d5955c5c41597185b5c364.scope/system.slice/systemd-sysusers.service, ignoring: Operation not permitted
[  OK  ] Started Journal Service.
         Starting Flush Journal to Persistent Storage...

3. Immediate systemd failure:

systemd 234 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN default-hierarchy=hybrid)
Detected virtualization docker.
Detected architecture x86-64.

Welcome to Fedora 27 (Twenty Seven)!

Set hostname to <3022b9094e4b>.
Failed to install release agent, ignoring: Permission denied
Failed to create /system.slice/docker-3022b9094e4b3d0c49237091cb67572fc1177cabbe7e676516a4bc743d870056.scope/init.scope control group: Permission denied
Failed to allocate manager object: Permission denied
[!!!!!!] Failed to allocate manager object, freezing.
Freezing execution.

4. Boots up and starts httpd, no journald logs, does not seem to shut down gracefully (long pause on `docker stop`):

systemd 234 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN default-hierarchy=hybrid)
Detected virtualization docker.
Detected architecture x86-64.

Welcome to Fedora 27 (Twenty Seven)!

Set hostname to <343ad2a4ee5b>.
Failed to install release agent, ignoring: Read-only file system
[  OK  ] Reached target Remote File Systems.
system.slice: Failed to set invocation ID on control group /system.slice/docker-343ad2a4ee5bb7201d429b566174ce73d1dce3b44c7ab73bfee68575585e9d47.scope/system.slice, ignoring: Operation not permitted
[  OK  ] Created slice System Slice.
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Listening on Journal Socket (/dev/log).
[  OK  ] Listening on Process Core Dump Socket.
[  OK  ] Reached target Local File Systems.
[  OK  ] Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Reached target Paths.
[  OK  ] Reached target Local Encrypted Volumes.
[  OK  ] Reached target Swap.
[  OK  ] Reached target Slices.
[  OK  ] Listening on Journal Socket.
systemd-journald.service: Failed to set invocation ID on control group /system.slice/docker-343ad2a4ee5bb7201d429b566174ce73d1dce3b44c7ab73bfee68575585e9d47.scope/system.slice/systemd-journald.service, ignoring: Operation not permitted
         Starting Journal Service...
systemd-journal-catalog-update.service: Failed to set invocation ID on control group /system.slice/docker-343ad2a4ee5bb7201d429b566174ce73d1dce3b44c7ab73bfee68575585e9d47.scope/system.slice/systemd-journal-catalog-update.service, ignoring: Operation not permitted
         Starting Rebuild Journal Catalog...
systemd-sysusers.service: Failed to set invocation ID on control group /system.slice/docker-343ad2a4ee5bb7201d429b566174ce73d1dce3b44c7ab73bfee68575585e9d47.scope/system.slice/systemd-sysusers.service, ignoring: Operation not permitted
         Starting Create System Users...
ldconfig.service: Failed to set invocation ID on control group /system.slice/docker-343ad2a4ee5bb7201d429b566174ce73d1dce3b44c7ab73bfee68575585e9d47.scope/system.slice/ldconfig.service, ignoring: Operation not permitted
         Starting Rebuild Dynamic Linker Cache...
[  OK  ] Listening on /dev/initctl Compatibility Named Pipe.
[  OK  ] Started Journal Service.


Expected results:

The container boots up to working httpd, robustly produces log output.

Comment 1 Daniel Walsh 2018-05-03 13:52:50 UTC
Did you

setsebool -P container_manage_cgroup 1

Comment 2 Mikhail Zabaluev 2018-05-04 17:58:52 UTC
(In reply to Daniel Walsh from comment #1)
> Did you
> 
> setsebool -P container_manage_cgroup 1

It was on. With the boolean off, I got this in the host journal:

May 04 17:25:50 audit[897]: VIRT_CONTROL pid=897 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='reason=api vm=? vm-pid=? user=vagrant auid=1000 hostname=? op=_ping exe=? ctr_id_short=?  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 04 17:25:50 audit[897]: VIRT_CONTROL pid=897 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='op=create auid=1000 hostname=? ctr_id_short=? reason=api vm=? vm-pid=? user=vagrant exe=?  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 04 17:25:50 audit[897]: VIRT_CONTROL pid=897 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='op=attach vm=fortochka/radius:no-config ctr_id_short=e8322b53dc84 reason=api vm-pid=0 user=vagrant auid=1000 exe=/sbin/init hostname=e8322b53dc84  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 04 17:25:50 audit[897]: VIRT_CONTROL pid=897 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='vm=fortochka/radius:no-config vm-pid=0 auid=1000 exe=/sbin/init reason=api op=start user=vagrant hostname=e8322b53dc84 ctr_id_short=e8322b53dc84  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 04 17:25:50 NetworkManager[721]: <info>  [1525454750.7945] manager: (vethc25aeea): new Veth device (/org/freedesktop/NetworkManager/Devices/7)
May 04 17:25:50 systemd-udevd[2106]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
May 04 17:25:50 systemd-udevd[2106]: Could not generate persistent MAC address for vethc25aeea: No such file or directory
May 04 17:25:50 NetworkManager[721]: <info>  [1525454750.7958] manager: (veth62f6569): new Veth device (/org/freedesktop/NetworkManager/Devices/8)
May 04 17:25:50 systemd-udevd[2107]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
May 04 17:25:50 systemd-udevd[2107]: Could not generate persistent MAC address for veth62f6569: No such file or directory
May 04 17:25:50 kernel: docker0: port 1(veth62f6569) entered blocking state
May 04 17:25:50 kernel: docker0: port 1(veth62f6569) entered disabled state
May 04 17:25:50 audit: ANOM_PROMISCUOUS dev=veth62f6569 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
May 04 17:25:50 kernel: device veth62f6569 entered promiscuous mode
May 04 17:25:50 audit[897]: SYSCALL arch=c000003e syscall=44 success=yes exit=40 a0=9 a1=c42097def0 a2=28 a3=0 items=0 ppid=1 pid=897 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd-current" exe="/usr/bin/dockerd-current" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 04 17:25:50 audit: PROCTITLE proctitle=2F7573722F62696E2F646F636B6572642D63757272656E74002D2D6164642D72756E74696D65006F63693D2F7573722F6C6962657865632F646F636B65722F646F636B65722D72756E632D63757272656E74002D2D64656661756C742D72756E74696D653D6F6369002D2D617574686F72697A6174696F6E2D706C7567696E3D
May 04 17:25:50 kernel: IPv6: ADDRCONF(NETDEV_UP): veth62f6569: link is not ready
May 04 17:25:50 systemd[1]: Started libcontainer container e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.
May 04 17:25:50 kernel: SELinux: mount invalid.  Same superblock, different security settings for (dev mqueue, type mqueue)
May 04 17:25:50 kernel: eth0: renamed from vethc25aeea
May 04 17:25:50 kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
May 04 17:25:50 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
May 04 17:25:50 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth62f6569: link becomes ready
May 04 17:25:50 kernel: docker0: port 1(veth62f6569) entered blocking state
May 04 17:25:50 kernel: docker0: port 1(veth62f6569) entered forwarding state
May 04 17:25:50 NetworkManager[721]: <info>  [1525454750.9214] device (veth62f6569): carrier: link connected
May 04 17:25:50 NetworkManager[721]: <info>  [1525454750.9219] device (docker0): carrier: link connected
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: rootfs=/var/lib/docker/overlay2/20a0c292b2c604db8f10c4124ec0cfcb0d82d0b1a2a15c9e4e11aa7b24af6811/merged
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: gidMappings not found in config
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: GID: 0
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: uidMappings not found in config
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: UID: 0
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 11:freezer:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :freezer:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 10:blkio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :blkio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 9:memory:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :memory:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: Found cgroup
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: PATH: /system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: SUBSYSTEM_PATH: /sys/fs/cgroup/memory/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: memory path: /sys/fs/cgroup/memory/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope/memory.limit_in_bytes
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: LIMIT: 9223372036854771712
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: Limit in bytes: 9223372036854771712
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: /sys/fs/cgroup already present as a mount point in container configuration, skipping
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 11:freezer:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :freezer:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 10:blkio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :blkio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 9:memory:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :memory:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 8:devices:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :devices:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 7:perf_event:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :perf_event:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 6:hugetlb:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :hugetlb:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 5:net_cls,net_prio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :net_cls,net_prio:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 4:cpuset:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :cpuset:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 3:cpu,cpuacct:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :cpu,cpuacct:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 2:pids:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :pids:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: 1:name=systemd:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
                                        : e8322b53dc84
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: :name=systemd:/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: Found cgroup
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: PATH: /system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <debug>: e8322b53dc84: SUBSYSTEM_PATH: /sys/fs/cgroup/systemd/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope
May 04 17:25:50 oci-systemd-hook[2148]: systemdhook <error>: e8322b53dc84: Failed to set context system_u:object_r:container_file_t:s0:c438,c992 on /var/lib/docker/overlay2/20a0c292b2c604db8f10c4124ec0cfcb0d82d0b1a2a15c9e4e11aa7b24af6811/merged//sys/fs/cgroup/systemd/system.slice/docker-e8322b53dc84f36ea7298a9afe684068c00f4a6051905f5520fe6dbab1140c77.scope/..: Read-only file system
May 04 17:25:50 oci-umount[2149]: umounthook <debug>: prestart container_id:e8322b53dc84 rootfs:/var/lib/docker/overlay2/20a0c292b2c604db8f10c4124ec0cfcb0d82d0b1a2a15c9e4e11aa7b24af6811/merged
May 04 17:25:50 audit[897]: VIRT_CONTROL pid=897 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='reason=api exe=/sbin/init ctr_id_short=e8322b53dc84 hostname=e8322b53dc84 op=resize vm=fortochka/radius:no-config vm-pid=2129 user=vagrant auid=1000  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 04 17:25:52 audit[2129]: AVC avc:  denied  { write } for  pid=2129 comm="systemd" name="release_agent" dev="cgroup" ino=7 scontext=system_u:system_r:container_t:s0:c438,c992 tcontext=system_u:object_r:cgroup_t:s0 tclass=file permissive=0
May 04 17:25:52 audit[2129]: SYSCALL arch=c000003e syscall=257 success=no exit=-13 a0=ffffff9c a1=564a0712e160 a2=80101 a3=0 items=0 ppid=2111 pid=2129 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:container_t:s0:c438,c992 key=(null)
May 04 17:25:52 audit: PROCTITLE proctitle="/sbin/init"
May 04 17:25:52 audit[2129]: AVC avc:  denied  { write } for  pid=2129 comm="systemd" name="cgroup.procs" dev="cgroup" ino=514 scontext=system_u:system_r:container_t:s0:c438,c992 tcontext=system_u:object_r:cgroup_t:s0 tclass=file permissive=0
May 04 17:25:52 audit[2129]: SYSCALL arch=c000003e syscall=257 success=no exit=-13 a0=ffffff9c a1=564a0712f5e0 a2=80101 a3=0 items=0 ppid=2111 pid=2129 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:container_t:s0:c438,c992 key=(null)
May 04 17:25:52 audit: PROCTITLE proctitle="/sbin/init"

With the container_manage_cgroup boolean on, docker run -d ... generates some blob data until, presumably, journald in the container starts up:

dockerd-current[897]: [172B blob data]

Comment 3 Daniel Walsh 2018-05-06 11:53:04 UTC
What AVC's were you seeing with the boolean turned on?

Comment 4 Mikhail Zabaluev 2018-05-07 06:37:31 UTC
(In reply to Daniel Walsh from comment #3)
> What AVC's were you seeing with the boolean turned on?

No denials, only this:

May 07 06:22:58 audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  received policyload notice (seqno=2)
                           exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
May 07 06:22:58 audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  received policyload notice (seqno=3)
                           exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'

Comment 5 Daniel Walsh 2018-05-07 11:42:08 UTC
Tom can you try this out?

Comment 6 Daniel Walsh 2018-05-07 11:43:00 UTC
Mikhail, could you try in permissive mode to see if this is an SELinux issue.  Or it could be an issue with systemd attempting to do something that is not allowed in a container.

Comment 7 Daniel Walsh 2018-05-07 11:43:48 UTC
Systemd guys any idea what operation is being blocked above?

Comment 8 Mikhail Zabaluev 2018-05-08 06:16:11 UTC
(In reply to Daniel Walsh from comment #6)
> Mikhail, could you try in permissive mode to see if this is an SELinux
> issue.

Re-tested in ostree://fedora-atomic:fedora/28/x86_64/testing/atomic-host
Version: 28.20180507.2 (2018-05-07 14:37:37)
Commit: 0f797b1e3da6213a598467acfc8150e1ff51f9a75ca43f81e42caa61f5441c2d

In permissive and enforcing mode alike, the result I get is the same: the container starts and the HTTP server is working, there are no journal logs from inside the container, and the last output on the attached terminal is:

[  OK  ] Started Journal Service.

The container does not stop gracefully, meaning that SIGRTMIN+3 does not have the desired effect.

The journal log gets one error message among less severe messages:

oci-systemd-hook[2412]: systemdhook <error>: f20f15048603: Failed to set context system_u:object_r:container_file_t:s0:c364,c365 on /var/lib/docker/overlay2/89e96e0931b767d8d3e7b9dd272a1c15a08c8b2f638830726a59ead86b26c898/merged//sys/fs/cgroup/systemd/system.slice/docker-f20f15048603c20121c1d94ed786ee6a154fe29abbe59420ffc8a34540676e4a.scope/..: Read-only file system

Comment 9 Mikhail Zabaluev 2018-05-08 06:19:58 UTC
Interestingly, running with --privileged produces a bunch AVC denials and error messages, the container becoming functional nonetheless:


May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad70c50 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged/var/log/journal/86b7348c9b5f42625414bb713e3b5b7a/.: Invalid argument
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad70c50 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged/var/log/journal/86b7348c9b5f42625414bb713e3b5b7a/..: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: /sys/fs/cgroup already present as a mount point in container configuration, skipping
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 11:cpu,cpuacct:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :cpu,cpuacct:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 10:blkio:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :blkio:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9ab00 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9ad20 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9c6a0 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9c940 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9cbf0 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9b7e0 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9b7e0 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad5e480 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad9b7e0 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad5e480 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 audit[2972]: AVC avc:  denied  { mac_admin } for  pid=2972 comm="oci-systemd-hoo" capability=33  scontext=system_u:system_r:container_runtime_t:s0 tcontext=system_u:system_r:container_runtime_t:s0 tclass=capability2 permissive=0
May 07 21:39:02 audit: SELINUX_ERR op=setxattr invalid_context=""
May 07 21:39:02 audit[2972]: SYSCALL arch=c000003e syscall=188 success=no exit=-22 a0=55850ad5e480 a1=7f8d38cb2efe a2=55850ad6c160 a3=1 items=0 ppid=2944 pid=2972 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="oci-systemd-hoo" exe="/usr/libexec/oci/hooks.d/oci-systemd-hook" subj=system_u:system_r:container_runtime_t:s0 key=(null)
May 07 21:39:02 audit: PROCTITLE proctitle=2F7573722F6C6962657865632F6F63692F686F6F6B732E642F6F63692D73797374656D642D686F6F6B007072657374617274002F7661722F6C69622F646F636B65722F636F6E7461696E6572732F3836623733343863396235663432363235343134626237313365336235623761343664623962383036623064333934313633
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 9:perf_event:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :perf_event:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 8:freezer:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :freezer:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 7:pids:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :pids:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 6:cpuset:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :cpuset:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 5:memory:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :memory:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 4:net_cls,net_prio:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :net_cls,net_prio:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 3:hugetlb:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :hugetlb:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 2:devices:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :devices:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 1:name=systemd:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
                                        : 86b7348c9b5f
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: :name=systemd:/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: Found cgroup
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: PATH: /system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <debug>: 86b7348c9b5f: SUBSYSTEM_PATH: /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/.: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/..: Read-only file system
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/cgroup.clone_children: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/tasks: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/notify_on_release: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /var/lib/docker/overlay2/aa70f014641ebbeedc6a540c828370409c39d0538655c1ea7b455352f60a63d9/merged//sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/cgroup.procs: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/.: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/..: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/cgroup.clone_children: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/tasks: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/notify_on_release: Invalid argument
May 07 21:39:02 oci-systemd-hook[2972]: systemdhook <error>: 86b7348c9b5f: Failed to set context  on /sys/fs/cgroup/systemd/system.slice/docker-86b7348c9b5f42625414bb713e3b5b7a46db9b806b0d394163f7c8244f679a6d.scope/cgroup.procs: Invalid argument

Comment 10 Daniel Walsh 2018-05-08 12:38:11 UTC
These avc's are generated with Fedora 28 image?

Comment 11 Mikhail Zabaluev 2018-05-08 13:05:54 UTC
(In reply to Daniel Walsh from comment #10)
> These avc's are generated with Fedora 28 image?

Yes; it's built from registry.fedoraproject.org/fedora:latest as described in comment #0 (that tag might have pointed at F27 at the time the bug was filed).

Comment 12 Mikhail Zabaluev 2018-05-08 19:24:40 UTC
With non-privileged docker run and SELinux boolean container_manage_cgroups set to false, the container fails to start the HTTP service and there are AVC denials as follows:

type=AVC msg=audit(1525806975.186:449): avc:  denied  { write } for  pid=2004 comm="systemd" name="release_agent" dev="cgroup" ino=7 scontext=system_u:system_r:container_t:s0:c15,c631 tcontext=system_u:object_r:cgroup_t:s0 tclass=file permissive=0
type=SYSCALL msg=audit(1525806975.186:449): arch=c000003e syscall=257 success=no exit=-13 a0=ffffff9c a1=559189727120 a2=80101 a3=0 items=0 ppid=1986 pid=2004 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:container_t:s0:c15,c631 key=(null)
type=PROCTITLE msg=audit(1525806975.186:449): proctitle="/sbin/init"
type=AVC msg=audit(1525806975.186:450): avc:  denied  { write } for  pid=2004 comm="systemd" name="cgroup.procs" dev="cgroup" ino=504 scontext=system_u:system_r:container_t:s0:c15,c631 tcontext=system_u:object_r:cgroup_t:s0 tclass=file permissive=0
type=SYSCALL msg=audit(1525806975.186:450): arch=c000003e syscall=257 success=no exit=-13 a0=ffffff9c a1=559189728700 a2=80101 a3=0 items=0 ppid=1986 pid=2004 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:container_t:s0:c15,c631 key=(null)
type=PROCTITLE msg=audit(1525806975.186:450): proctitle="/sbin/init"

Comment 13 Tom Sweeney 2018-05-08 20:21:08 UTC
(I'm not sure the following got through, apologies if it's a repeat.)

I just setup a test system with Fedora 28 (didn't notice the Atomic Host bit until after I set it up) and noted the hang.  However after using 


setsebool -P container_manage_cgroup 1

before doing the 'docker run ...' command everything worked fine.  Can you try this on a non-Atomic host and see if you can still replicate there?

I tried an Atomic host this morning but was only able to use this version of oci-systemd-hook there:

oci-systemd-hook-0.1.15-1.git2d0b8a3.fc28.x86_64

I've not used Atomic Hosts much, can you tell me how you upgraded to 0.1.16?  I tried 'rpm-ostree install oci-systemd-hook' but that return a "you're up to date" type of message.  A GitHub clone/install failed as I couldn't get libselinux-devel installed on the host either.

With the older oci-systemd-hook in play on the Atomic Host, I too saw a hang without output when doing docker run with the flag set to 1.  journalctl had:

May 08 14:26:57 localhost.localdomain audit[2647]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55c6c6811060 items=0 ppid=895 pid=2647 auid=4294967295 uid=0
 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" subj=system_u:system_r:iptables_t:s0 key=(null)
May 08 14:26:57 localhost.localdomain audit: PROCTITLE proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4100504F5354524F5554494E47002D7000746370002D73003
137322E31372E302E32002D64003137322E31372E302E32002D2D64706F7274003830002D6A004D415351554552414445
May 08 14:26:57 localhost.localdomain audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  received policyload notice (seqno=2)
                                                 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
May 08 14:26:57 localhost.localdomain audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  received policyload notice (seqno=3)
                                                 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
May 08 14:26:57 localhost.localdomain systemd[1]: Started libcontainer container 1062144780e2e978a66e636f74dada39f592ae10eaf5901903cf377821f0dc6e.
May 08 14:26:57 localhost.localdomain kernel: SELinux: mount invalid.  Same superblock, different security settings for (dev mqueue, type mqueue)

Then later:

May 08 14:26:57 localhost.localdomain oci-systemd-hook[2686]: systemdhook <debug>: 1062144780e2: SUBSYSTEM_PATH: /sys/fs/cgroup/systemd/system.slice/docker-1062144780e2e978a66e636f74dada39f592ae10eaf5901903cf377821f0dc6e.scope
May 08 14:26:57 localhost.localdomain oci-systemd-hook[2686]: systemdhook <error>: 1062144780e2: Failed to set context system_u:object_r:container_file_t:s0:c353,c990 on /var/lib/docker/overlay2/0d45d19cf38001df01391d98aa4d31722b18f571a4cf129703c2bec10968907b/merged//sys/fs/cgroup/systemd/system.slice/docker-1062144780e2e978a66e636f74dada39f592ae10eaf5901903cf377821f0dc6e.scope/..: Read-only file system
May 08 14:26:57 localhost.localdomain oci-umount[2687]: umounthook <debug>: prestart container_id:1062144780e2 rootfs:/var/lib/docker/overlay2/0d45d19cf38001df01391d98aa4d31722b18f571a4cf129703c2bec10968907b/merged

Comment 14 Mikhail Zabaluev 2018-05-09 04:28:00 UTC
(In reply to Tom Sweeney from comment #13)
> I've not used Atomic Hosts much, can you tell me how you upgraded to 0.1.16?

I switched to the testing branch:

rpm-ostree rebase fedora/28/x86_64/testing/atomic-host

Comment 15 Tom Sweeney 2018-05-09 17:43:20 UTC
I think we'll need the systemd folks to chime in on this.  First off thanks Mikhail for the AH upgrade tip, that worked well.  With the system updated and the boolean in play, I'm still seeing the hang and the AVC's/errors from my previous reply.

I've confirmed that the container is up and running and was able to look at the journalctl there and saw these entries:

May 09 17:02:14 11bc3119f2ca systemd[1]: Reached target Timers.
May 09 17:02:15 11bc3119f2ca systemd[1]: Starting The Apache HTTP Server...
May 09 17:02:16 11bc3119f2ca httpd[24]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 172.17.0.2. Set the 'ServerName' directive global
ly to suppress this message
May 09 17:02:16 11bc3119f2ca systemd[1]: Starting Permit User Sessions...
May 09 17:02:17 11bc3119f2ca systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 09 17:02:17 11bc3119f2ca systemd[1]: Started The Apache HTTP Server.
May 09 17:02:18 11bc3119f2ca systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 09 17:02:18 11bc3119f2ca systemd[1]: Started Permit User Sessions.
May 09 17:02:19 11bc3119f2ca systemd[1]: Reached target Multi-User System.
May 09 17:02:20 11bc3119f2ca systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 09 17:02:21 11bc3119f2ca systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 09 17:02:21 11bc3119f2ca systemd[1]: Started Update UTMP about System Runlevel Changes.
May 09 17:02:23 11bc3119f2ca systemd[1]: Startup finished in 1min 24.886s.
M


systemd folks thoughts on what might be causing the "Failed to add fd to store issues" or the issue in general?  I'm not able to reproduce this on a "regular" Fedora 28 system.

Comment 16 Mikhail Zabaluev 2018-05-10 21:19:26 UTC
Please ignore my earlier reports about missing logs from the container: I have not been using the --merge option with host journalctl, and the logs were always present.

I have narrowed the problem down to using the --tty option with docker run. With the terminal attached, systemd in the container is very slow to start, may fail to produce output on stdout/stderr, and systemd action step messages appear at regular intervals of 1 second. The same problem affects shutdown: systemd receives SIGRTMIN+3 and starts shutting down, but takes about 90 seconds to complete all the steps.
Here's the log of an ultimately successful bootup:

May 10 20:42:21 localhost.localdomain oci-systemd-hook[2674]: systemdhook <error>: 523776831ea3: Failed to set context system_u:object_r:container_file_t:s0:c512,c642 on /var/lib/docker/overlay2/5b8f9574102f5967246b015fa5233ba1f6e48fa7060f668324dc6961e6b1a77b/merged//sys/fs/cgroup/systemd/system.slice/docker-523776831ea3630ce88527530a1a1060973cf2a876416c79386e570d04019440.scope/..: Read-only file system
May 10 20:42:21 localhost.localdomain oci-umount[2675]: umounthook <debug>: prestart container_id:523776831ea3 rootfs:/var/lib/docker/overlay2/5b8f9574102f5967246b015fa5233ba1f6e48fa7060f668324dc6961e6b1a77b/merged
May 10 20:42:21 localhost.localdomain audit[981]: VIRT_CONTROL pid=981 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_runtime_t:s0 msg='vm-pid=2656 user=vagrant auid=1000 exe=/sbin/init ctr_id_short=523776831ea3 reason=api op=resize vm=systemdtest hostname=523776831ea3  exe="/usr/bin/dockerd-current" hostname=? addr=? terminal=? res=success'
May 10 20:43:11 523776831ea3 systemd-journald[18]: Journal started
May 10 20:43:11 523776831ea3 systemd-journald[18]: Runtime journal (/run/log/journal/523776831ea3630ce88527530a1a1060) is 820.0K, max 6.4M, 5.6M free.
May 10 20:43:19 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:19 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:19 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:19 523776831ea3 systemd[1]: Started Create System Users.
May 10 20:43:20 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-sysusers comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:20 523776831ea3 systemd[1]: Started Rebuild Journal Catalog.
May 10 20:43:21 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-journal-catalog-update comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:21 523776831ea3 systemd[1]: Started Rebuild Dynamic Linker Cache.
May 10 20:43:22 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=ldconfig comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:22 523776831ea3 systemd[1]: Starting Update is Completed...
May 10 20:43:23 523776831ea3 systemd[1]: Starting Flush Journal to Persistent Storage...
May 10 20:43:24 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:24 523776831ea3 systemd[1]: Started Update is Completed.
May 10 20:43:25 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-update-done comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:25 523776831ea3 systemd-journald[18]: Time spent on flushing to /var is 1.179ms for 11 entries.
May 10 20:43:25 523776831ea3 systemd-journald[18]: System journal (/var/log/journal/523776831ea3630ce88527530a1a1060) is 8.0M, max 3.9G, 3.9G free.
May 10 20:43:26 523776831ea3 systemd[1]: Started Flush Journal to Persistent Storage.
May 10 20:43:27 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:27 523776831ea3 systemd[1]: Starting Create Volatile Files and Directories...
May 10 20:43:28 523776831ea3 systemd[1]: Started Create Volatile Files and Directories.
May 10 20:43:29 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:29 523776831ea3 systemd[1]: Starting Update UTMP about System Boot/Shutdown...
May 10 20:43:29 localhost.localdomain audit[2699]: SYSTEM_BOOT pid=2699 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 10 20:43:30 523776831ea3 systemd[1]: Started Update UTMP about System Boot/Shutdown.
May 10 20:43:31 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:31 523776831ea3 systemd[1]: Reached target System Initialization.
May 10 20:43:32 523776831ea3 systemd[1]: Started dnf makecache timer.
May 10 20:43:33 523776831ea3 systemd[1]: Listening on D-Bus System Message Bus Socket.
May 10 20:43:34 523776831ea3 systemd[1]: Reached target Sockets.
May 10 20:43:35 523776831ea3 systemd[1]: Reached target Basic System.
May 10 20:43:36 523776831ea3 systemd[1]: Starting The Apache HTTP Server...
May 10 20:43:36 523776831ea3 httpd[24]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 172.17.0.2. Set the 'ServerName' directive globally to suppress this message
May 10 20:43:37 523776831ea3 systemd[1]: Starting Permit User Sessions...
May 10 20:43:38 523776831ea3 systemd[1]: Started Daily Cleanup of Temporary Directories.
May 10 20:43:39 523776831ea3 systemd[1]: Reached target Timers.
May 10 20:43:40 523776831ea3 systemd[1]: Started D-Bus System Message Bus.
May 10 20:43:41 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=dbus comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:41 523776831ea3 systemd[1]: Started The Apache HTTP Server.
May 10 20:43:42 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=httpd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:42 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:42 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:42 523776831ea3 systemd[1]: Started Permit User Sessions.
May 10 20:43:43 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-user-sessions comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:43 523776831ea3 systemd[1]: Reached target Multi-User System.
May 10 20:43:44 523776831ea3 systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 10 20:43:45 523776831ea3 systemd[1]: systemd-journald.service: Failed to add fd to store: Operation not permitted
May 10 20:43:45 localhost.localdomain audit[2918]: SYSTEM_RUNLEVEL pid=2918 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='old-level=N new-level=3 comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 10 20:43:45 523776831ea3 systemd[1]: Started Update UTMP about System Runlevel Changes.
May 10 20:43:46 523776831ea3 systemd[1]: Startup finished in 1min 24.703s.
May 10 20:43:46 localhost.localdomain audit[2656]: SERVICE_START pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-update-utmp-runlevel comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 10 20:43:46 localhost.localdomain audit[2656]: SERVICE_STOP pid=2656 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:container_t:s0:c512,c642 msg='unit=systemd-update-utmp-runlevel comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

When run in the daemon mode, systemd in the container starts up in sub-second time. I observe the same behavior in both Fedora Atomic host and Fedora Workstation.

Comment 17 Mikhail Zabaluev 2018-05-10 21:24:22 UTC
Please bump down the bug severity, it's no longer an impediment to actually running services.

Comment 18 Jan Kurik 2018-08-14 11:10:57 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 29 development cycle.
Changing version to '29'.

Comment 19 Daniel Walsh 2019-01-10 18:11:41 UTC
Is this still an issue?

Comment 20 Ben Cotton 2019-10-31 20:11:36 UTC
This message is a reminder that Fedora 29 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 29 on 2019-11-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '29'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 29 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 21 Daniel Walsh 2019-11-01 18:00:35 UTC
We are no longer supporting Docker, and Podman has built in support. oci-systemd-hook is going away.


Note You need to log in before you can comment on or make changes to this bug.