cloud-init apparently has some service to set the hostname, and apparently this runs on every boot. It's failing (see below) which delays login. I'm not actually providing any hostname metadata or anything about hostname in my userscript; shouldn't it just silently move on? May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Failed to set the hostname to localhost.localdomain (localhost.localdomain) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[WARNING]: Running set_hostname (<module 'cloudinit.config.cc_set_hostname' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_set_hostname.pyc'>) failed May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Running set_hostname (<module 'cloudinit.config.cc_set_hostname' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_set_hostname.pyc'>) failed May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x21945d0>) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Reading from /etc/hosts (quiet=False) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Read 83 bytes from /etc/hosts May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Reading from /etc/hosts (quiet=False) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Read 83 bytes from /etc/hosts May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] cc_update_hostname.py[DEBUG]: Updating hostname to localhost.localdomain (localhost.localdomain) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Running command ['hostname'] with allowed return codes [0] (shell=False, capture=True) May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] __init__.py[DEBUG]: Attempting to update hostname to localhost.localdomain in 1 files May 17 02:40:28 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Running command ['hostnamectl', 'set-hostname', 'localhost.localdomain'] with allowed return codes [0] (shell=False, capture=True) May 17 02:40:53 localhost cloud-init[433]: [CLOUDINIT] util.py[WARNING]: Failed to write hostname localhost.localdomain to /var/lib/cloud/data/previous-hostname May 17 02:40:53 localhost cloud-init[433]: [CLOUDINIT] util.py[DEBUG]: Failed to write hostname localhost.localdomain to /var/lib/cloud/data/previous-hostname May 17 02:40:53 localhost cloud-init[433]: [CLOUDINIT] helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x2194590>) May 17 02:40:53 localhost cloud-init[433]: [CLOUDINIT] cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts
I should add that I am using a fake EC2 metadata service and I haven't actually implemented the hostname bit. I'll fix that... I assume that's the problem, but cloud-init should be robust against that. (Notably, this wasn't a problem with F18.)
This is failing in EC2 as well. I'll attach a log file.
Created attachment 751325 [details] cloud-init log from f19 tc boot This is the log from boot. Consequence is a minute delay at boot; possibly worse.
Excerpt from log file: May 21 16:53:02 localhost [CLOUDINIT] helpers.py[DEBUG]: Running config-set_hostname using lock (<FileLock using file '/var/lib/cloud/instances/i-a8ba4cc4/sem/config_set_hostname'>) May 21 16:53:02 localhost [CLOUDINIT] cc_set_hostname.py[DEBUG]: Setting the hostname to ip-10-147-161-247.ec2.internal (ip-10-147-161-247) May 21 16:53:02 localhost [CLOUDINIT] util.py[DEBUG]: Running command ['hostnamectl', 'set-hostname', 'ip-10-147-161-247.ec2.internal'] with allowed return codes [0] (shell=False, capture=True) May 21 16:53:27 localhost [CLOUDINIT] util.py[WARNING]: Failed to set the hostname to ip-10-147-161-247.ec2.internal (ip-10-147-161-247) May 21 16:53:27 localhost [CLOUDINIT] util.py[DEBUG]: Failed to set the hostname to ip-10-147-161-247.ec2.internal (ip-10-147-161-247) Note the 25-second pause. Running `hostnamectl set-hostname up-10-147-161-247.ec2.internal` as root from the booted system works fine. Next in the log: May 21 16:53:27 localhost [CLOUDINIT] util.py[DEBUG]: Running command ['hostname'] with allowed return codes [0] (shell=False, capture=True) May 21 16:53:27 localhost [CLOUDINIT] __init__.py[DEBUG]: Attempting to update hostname to ip-10-147-161-247.ec2.internal in 1 files May 21 16:53:27 localhost [CLOUDINIT] util.py[DEBUG]: Running command ['hostnamectl', 'set-hostname', 'ip-10-147-161-247.ec2.internal'] with allowed return codes [0] (shell=False, capture=True) May 21 16:53:52 localhost [CLOUDINIT] util.py[WARNING]: Failed to write hostname ip-10-147-161-247.ec2.internal to /var/lib/cloud/data/previous-hostname May 21 16:53:52 localhost [CLOUDINIT] util.py[DEBUG]: Failed to write hostname ip-10-147-161-247.ec2.internal to /var/lib/cloud/data/previous-hostname
Maybe we just need to add "hostnamed.service" to the Wants line in cloud-init.service? It looks from the logs that that service is coming up _after_. (Will try this locally...)
Errr. systemd-hostnamed.service, of course.
Nope. That doesn't seem to help.
Per the documentation, systemd-hostnamed.service should come up by itself when it's needed. You can test that by stopping it and then running 'hostnamectl set-hostname foo' which will automatically start the service again. Looking at the timing of events at boot, this seems to happen, i.e., cloud-init calls hostnamectl which brings up the service but it fails for some reason. I instrumented cloud-init and found the following: May 24 07:09:30 juergh-193-3-019213-001 [CLOUDINIT] __init__.py[DEBUG]: Attempting to update hostname to juergh-193-3-019213-001.localdomain in 1 files May 24 07:09:30 juergh-193-3-019213-001 [CLOUDINIT] util.py[DEBUG]: Running command ['hostnamectl', 'set-hostname', 'juergh-193-3-019213-001.localdomain'] with allowed return codes [0] (shell=False, capture=True) May 24 07:09:55 juergh-193-3-019213-001 [CLOUDINIT] util.py[DEBUG]: stdout = May 24 07:09:55 juergh-193-3-019213-001 [CLOUDINIT] util.py[DEBUG]: stderr = Failed to issue method call: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. May 24 07:09:55 juergh-193-3-019213-001 [CLOUDINIT] util.py[DEBUG]: rc = 1 May 24 07:09:55 juergh-193-3-019213-001 [CLOUDINIT] util.py[WARNING]: Failed to write hostname juergh-193-3-019213-001.localdomain to /var/lib/cloud/data/previous-hostname May 24 07:09:55 juergh-193-3-019213-001 [CLOUDINIT] util.py[DEBUG]: Failed to write hostname juergh-193-3-019213-001.localdomain to /var/lib/cloud/data/previous-hostname
I also hacked cloud-init to explicitly start the hostname service and then wait 10 seconds prior to setting the hostname. Still fails.
Disabling selinux fixes the issue. Could this be related to: https://bugzilla.redhat.com/show_bug.cgi?id=914992
Ahaha! I had ruled that out because I booted with selinux=0 and it didn't work either. But apparently, cloud-init completely fails in that situation too. So, I changed to writing "SELINUX=permissive" to /etc/sysconfig/selinux, and that didn't work either, but on further inspection, on boot SELinux is still in enforcing mode, ignoring that config file. (Changed it to "SELINUX=disabled" doesn't work either.) Sooo, I booted with enforcing=0 on the kernel command line, and now it works. I think maybe I need a vacation. :) (I think probably `Requires systemd-hostnamed.service` in the systemd config is a good idea too.)
Any AVC msgs?
Must be this: /var/log/audit/audit.log:type=USER_AVC msg=audit(1369645724.117:16): pid=199 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: denied { send_msg } for msgtype=method_return dest=:1.2 spid=520 tpid=519 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?' /var/log/audit/audit.log:type=USER_AVC msg=audit(1369645749.524:17): pid=199 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: denied { send_msg } for msgtype=method_return dest=:1.4 spid=520 tpid=522 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'
Yes. # ps -eZ |grep initrc
At what point do you need that? Once the system is actually up, there's no output. But while it's trying, # ps -eZ |grep initrc system_u:system_r:initrc_t:s0 434 ? 00:00:00 cloud-init system_u:system_r:initrc_t:s0 510 ? 00:00:00 hostnamectl
Ok, we need to add a policy for cloud-init and allow systemd_hostnamed_t to dbus chat with this new policy.
Created attachment 754223 [details] Initial cloud-init policy Please download mycloud.te and run # make -f /usr/share/selinux/devel/Makefile mycloud.pp # semodule -i mycloud.pp # chcon -t cloud_init_exec_t /usr/bin/cloud-init # chcon -R -t cloud_var_lib_t /var/lib/cloud # chcon -t cloud_log_t /var/log/cloud* re-test it and # ausearch -m avc -ts recent
---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.192:11): avc: denied { read } for pid=189 comm="cloud-init" name="instance" dev="vda1" ino=2590 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=lnk_file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.192:12): avc: denied { getattr } for pid=189 comm="cloud-init" path="/var/lib/cloud/instances/i-AAAAAAAA/cloud-config.txt" dev="vda1" ino=2603 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.192:13): avc: denied { read } for pid=189 comm="cloud-init" name="cloud-config.txt" dev="vda1" ino=2603 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.192:14): avc: denied { open } for pid=189 comm="cloud-init" path="/var/lib/cloud/instances/i-AAAAAAAA/cloud-config.txt" dev="vda1" ino=2603 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.315:15): avc: denied { setattr } for pid=189 comm="cloud-init" name="cloud" dev="vda1" ino=18992 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=dir ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.316:16): avc: denied { search } for pid=189 comm="cloud-init" name="files" dev="vda1" ino=19240 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=dir ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.316:17): avc: denied { read } for pid=189 comm="cloud-init" name="file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.316:18): avc: denied { open } for pid=189 comm="cloud-init" path="/etc/selinux/targeted/contexts/files/file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.316:19): avc: denied { getattr } for pid=189 comm="cloud-init" path="/etc/selinux/targeted/contexts/files/file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.321:20): avc: denied { write } for pid=189 comm="cloud-init" name="context" dev="selinuxfs" ino=5 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.321:21): avc: denied { check_context } for pid=189 comm="cloud-init" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.328:22): avc: denied { open } for pid=189 comm="cloud-init" path="/var/log/cloud-init.log" dev="vda1" ino=2577 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.328:23): avc: denied { setattr } for pid=189 comm="cloud-init" name="cloud-init.log" dev="vda1" ino=2577 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.330:24): avc: denied { unlink } for pid=189 comm="cloud-init" name="boot-finished" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.330:25): avc: denied { write } for pid=189 comm="cloud-init" name="cloud" dev="vda1" ino=18992 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=dir ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.330:26): avc: denied { remove_name } for pid=189 comm="cloud-init" name="instance" dev="vda1" ino=2590 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=dir ---- time->Wed May 29 13:12:09 2013 type=AVC msg=audit(1369833129.330:27): avc: denied { unlink } for pid=189 comm="cloud-init" name="instance" dev="vda1" ino=2590 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=lnk_file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.215:33): arch=c000003e syscall=2 success=yes exit=4 a0=f01e00 a1=0 a2=1b6 a3=732e736e61656c6f items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.215:33): avc: denied { open } for pid=434 comm="cloud-init" path="/etc/selinux/targeted/contexts/files/file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file type=AVC msg=audit(1369833132.215:33): avc: denied { read } for pid=434 comm="cloud-init" name="file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file type=AVC msg=audit(1369833132.215:33): avc: denied { search } for pid=434 comm="cloud-init" name="files" dev="vda1" ino=19240 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=dir ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.215:34): arch=c000003e syscall=5 success=yes exit=0 a0=4 a1=7fffabac3880 a2=7fffabac3880 a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.215:34): avc: denied { getattr } for pid=434 comm="cloud-init" path="/etc/selinux/targeted/contexts/files/file_contexts.subs_dist" dev="vda1" ino=19245 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:file_context_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.217:35): arch=c000003e syscall=1 success=yes exit=31 a0=4 a1=13b3280 a2=1f a3=fe items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.217:35): avc: denied { check_context } for pid=434 comm="cloud-init" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.223:36): arch=c000003e syscall=2 success=yes exit=4 a0=11a8a60 a1=441 a2=1b6 a3=3 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.223:36): avc: denied { open } for pid=434 comm="cloud-init" path="/var/log/cloud-init.log" dev="vda1" ino=2577 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.224:37): arch=c000003e syscall=90 success=yes exit=0 a0=1140d80 a1=1a4 a2=7ff5ab729fa8 a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.224:37): avc: denied { setattr } for pid=434 comm="cloud-init" name="cloud-init.log" dev="vda1" ino=2577 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.853:38): arch=c000003e syscall=88 success=yes exit=0 a0=14fa680 a1=e41400 a2=7ff5ab729fa8 a3=41414141414141 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.853:38): avc: denied { create } for pid=434 comm="cloud-init" name="instance" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=lnk_file type=AVC msg=audit(1369833132.853:38): avc: denied { add_name } for pid=434 comm="cloud-init" name="instance" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=dir ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.853:39): arch=c000003e syscall=2 success=yes exit=4 a0=7fffabac3eb0 a1=2 a2=7fffabac3ec7 a3=f items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.853:39): avc: denied { write } for pid=434 comm="cloud-init" name="context" dev="selinuxfs" ino=5 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.861:40): arch=c000003e syscall=2 success=yes exit=4 a0=107cc70 a1=0 a2=1b6 a3=1 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.861:40): avc: denied { open } for pid=434 comm="cloud-init" path="/var/lib/cloud/instances/i-AAAAAAAA/datasource" dev="vda1" ino=2595 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file type=AVC msg=audit(1369833132.861:40): avc: denied { read } for pid=434 comm="cloud-init" name="datasource" dev="vda1" ino=2595 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.861:41): arch=c000003e syscall=5 success=yes exit=0 a0=4 a1=7fffabac67e0 a2=7fffabac67e0 a3=1 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.861:41): avc: denied { getattr } for pid=434 comm="cloud-init" path="/var/lib/cloud/instances/i-AAAAAAAA/datasource" dev="vda1" ino=2595 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.862:42): arch=c000003e syscall=2 success=yes exit=4 a0=13f5d10 a1=241 a2=1b6 a3=3 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.862:42): avc: denied { write } for pid=434 comm="cloud-init" name="datasource" dev="vda1" ino=2595 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.863:43): arch=c000003e syscall=90 success=yes exit=0 a0=14023c0 a1=1a4 a2=7ff5ab729fa8 a3=2f41414141414141 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.863:43): avc: denied { setattr } for pid=434 comm="cloud-init" name="datasource" dev="vda1" ino=2595 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.890:44): arch=c000003e syscall=4 success=yes exit=0 a0=14a4250 a1=7fffabac5a20 a2=7fffabac5a20 a3=6769666e6f632d64 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.890:44): avc: denied { read } for pid=434 comm="cloud-init" name="instance" dev="vda1" ino=2590 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=lnk_file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.894:45): arch=c000003e syscall=2 success=yes exit=4 a0=1130890 a1=241 a2=1b6 a3=3 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.894:45): avc: denied { dac_override } for pid=434 comm="cloud-init" capability=1 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:system_r:cloud_init_t:s0 tclass=capability ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.894:46): arch=c000003e syscall=6 success=yes exit=0 a0=14faa30 a1=7fffabac5ee0 a2=7fffabac5ee0 a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.894:46): avc: denied { getattr } for pid=434 comm="cloud-init" path="/var/lib/cloud/instance" dev="vda1" ino=2590 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=lnk_file ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.906:47): arch=c000003e syscall=257 success=yes exit=4 a0=ffffffffffffff9c a1=13f54f0 a2=90800 a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.906:47): avc: denied { read } for pid=434 comm="cloud-init" name="handlers" dev="vda1" ino=2580 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=dir ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.996:48): arch=c000003e syscall=269 success=yes exit=0 a0=ffffffffffffff9c a1=4be22a a2=2 a3=7fff88b09440 items=0 ppid=481 pid=482 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="growpart" exe="/usr/bin/bash" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.996:48): avc: denied { write } for pid=482 comm="growpart" name="tmp" dev="vda1" ino=15654 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.997:49): arch=c000003e syscall=137 success=yes exit=0 a0=4be22a a1=7fff88b09690 a2=fffffffffff47404 a3=7fff88b09500 items=0 ppid=481 pid=482 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="growpart" exe="/usr/bin/bash" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.997:49): avc: denied { getattr } for pid=482 comm="growpart" name="/" dev="vda1" ino=2 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:fs_t:s0 tclass=filesystem ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.997:50): arch=c000003e syscall=2 success=yes exit=3 a0=103dfc0 a1=2c1 a2=180 a3=0 items=0 ppid=481 pid=482 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="growpart" exe="/usr/bin/bash" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.997:50): avc: denied { write open } for pid=482 comm="growpart" path="/tmp/sh-thd-1369822935" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=file type=AVC msg=audit(1369833132.997:50): avc: denied { create } for pid=482 comm="growpart" name="sh-thd-1369822935" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=file type=AVC msg=audit(1369833132.997:50): avc: denied { add_name } for pid=482 comm="growpart" name="sh-thd-1369822935" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:12 2013 type=SYSCALL msg=audit(1369833132.998:51): arch=c000003e syscall=87 success=yes exit=0 a0=103dfc0 a1=0 a2=180 a3=7fff88b09570 items=0 ppid=481 pid=482 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="growpart" exe="/usr/bin/bash" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833132.998:51): avc: denied { unlink } for pid=482 comm="growpart" name="sh-thd-1369822935" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=file type=AVC msg=audit(1369833132.998:51): avc: denied { remove_name } for pid=482 comm="growpart" name="sh-thd-1369822935" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.001:52): arch=c000003e syscall=4 success=yes exit=0 a0=f2d610 a1=7fffabac61c0 a2=7fffabac61c0 a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.001:52): avc: denied { getattr } for pid=434 comm="cloud-init" path="/dev/vda1" dev="devtmpfs" ino=1433 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:fixed_disk_device_t:s0 tclass=blk_file ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.004:53): arch=c000003e syscall=2 success=yes exit=3 a0=14012f0 a1=0 a2=1ff a3=0 items=0 ppid=1 pid=434 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.004:53): avc: denied { open } for pid=434 comm="cloud-init" path="/dev/vda1" dev="devtmpfs" ino=1433 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:fixed_disk_device_t:s0 tclass=blk_file type=AVC msg=audit(1369833133.004:53): avc: denied { read } for pid=434 comm="cloud-init" name="vda1" dev="devtmpfs" ino=1433 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:fixed_disk_device_t:s0 tclass=blk_file ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.038:54): arch=c000003e syscall=83 success=yes exit=0 a0=1ef5050 a1=1c0 a2=b a3=7fffb4d57850 items=0 ppid=488 pid=489 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="mktemp" exe="/usr/bin/mktemp" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.038:54): avc: denied { create } for pid=489 comm="mktemp" name="growpart.lPyXNl" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.073:55): arch=c000003e syscall=257 success=yes exit=3 a0=ffffffffffffff9c a1=7ed0c0 a2=30900 a3=0 items=0 ppid=483 pid=502 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="rm" exe="/usr/bin/rm" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.073:55): avc: denied { read } for pid=502 comm="rm" name="growpart.lPyXNl" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.073:56): arch=c000003e syscall=263 success=yes exit=0 a0=ffffffffffffff9c a1=7ed0c0 a2=200 a3=7fffe0822320 items=0 ppid=483 pid=502 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="rm" exe="/usr/bin/rm" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.073:56): avc: denied { rmdir } for pid=502 comm="rm" name="growpart.lPyXNl" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.101:57): arch=c000003e syscall=59 success=yes exit=0 a0=13d2710 a1=15a5be0 a2=7fffabac76c8 a3=0 items=0 ppid=434 pid=504 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="hostname" exe="/usr/bin/hostname" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.101:57): avc: denied { execute_no_trans } for pid=504 comm="cloud-init" path="/usr/bin/hostname" dev="vda1" ino=7661 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:hostname_exec_t:s0 tclass=file type=AVC msg=audit(1369833133.101:57): avc: denied { read open } for pid=504 comm="cloud-init" path="/usr/bin/hostname" dev="vda1" ino=7661 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:hostname_exec_t:s0 tclass=file type=AVC msg=audit(1369833133.101:57): avc: denied { execute } for pid=504 comm="cloud-init" name="hostname" dev="vda1" ino=7661 scontext=system_u:system_r:cloud_init_t:s0 tcontext=unconfined_u:object_r:hostname_exec_t:s0 tclass=file ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.112:58): arch=c000003e syscall=42 success=yes exit=0 a0=3 a1=7fff0fd2c2f0 a2=21 a3=7fff0fd2c0a0 items=0 ppid=434 pid=505 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="hostnamectl" exe="/usr/bin/hostnamectl" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.112:58): avc: denied { connectto } for pid=505 comm="hostnamectl" path="/run/dbus/system_bus_socket" scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tclass=unix_stream_socket type=AVC msg=audit(1369833133.112:58): avc: denied { write } for pid=505 comm="hostnamectl" name="system_bus_socket" dev="tmpfs" ino=10789 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:system_dbusd_var_run_t:s0 tclass=sock_file type=AVC msg=audit(1369833133.112:58): avc: denied { search } for pid=505 comm="hostnamectl" name="dbus" dev="tmpfs" ino=10788 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:system_dbusd_var_run_t:s0 tclass=dir ---- time->Wed May 29 13:12:13 2013 type=SYSCALL msg=audit(1369833133.567:62): arch=c000003e syscall=189 success=yes exit=0 a0=1bb31b4 a1=7f0a96d3e3be a2=194e4e0 a3=1f items=0 ppid=1 pid=513 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cloud-init" exe="/usr/bin/python2.7" subj=system_u:system_r:cloud_init_t:s0 key=(null) type=AVC msg=audit(1369833133.567:62): avc: denied { relabelto } for pid=513 comm="cloud-init" name="boot-finished" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file type=AVC msg=audit(1369833133.567:62): avc: denied { relabelfrom } for pid=513 comm="cloud-init" name="boot-finished" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:cloud_var_lib_t:s0 tclass=file
type=AVC msg=audit(1369833133.567:62): avc: denied { relabelto } for pid=513 comm="cloud-init" name="boot-finished" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:var_lib_t:s0 tclass=file type=AVC msg=audit(1369833133.567:62): avc: denied { relabelfrom } for pid=513 comm="cloud-init" name="boot-finished" dev="vda1" ino=2641 scontext=system_u:system_r:cloud_init_t:s0 tcontext=system_u:object_r:cloud_var_lib_t:s0 tclass=file Does cloud-init label /var/lib/cloud?
(In reply to Miroslav Grepl from comment #19) > Does cloud-init label /var/lib/cloud? I don't think so? I'm afraid my selinux-fu is beginner-level only.
$ ls -ldZ /var/lib/cloud drwxr-xr-x. root root system_u:object_r:var_lib_t:s0 /var/lib/cloud
cloud-init frequently compares the labels of the files that it writes against the ones matchpathcon expects and runs restorecon on the ones that differ to keep it from breaking other daemons. For instance, SSH host keys. I notice that AVC mentions cloud_init_t and cloud_var_lib_t. If selinux-policy recently gained a module for cloud-init then that module is probably going to need quite a few new file context rules.
(In reply to Garrett Holmstrom from comment #22) > cloud-init frequently compares the labels of the files that it writes > against the ones matchpathcon expects and runs restorecon on the ones that > differ to keep it from breaking other daemons. For instance, SSH host keys. Ok, then it makes sense. > > I notice that AVC mentions cloud_init_t and cloud_var_lib_t. If > selinux-policy recently gained a module for cloud-init then that module is > probably going to need quite a few new file context rules.
Okay, so what else do we need here?
I am going to update the test policy for additional testing. Then we are going to add to Fedora policy.
(In reply to Miroslav Grepl from comment #23) > (In reply to Garrett Holmstrom from comment #22) > > cloud-init frequently compares the labels of the files that it writes > > against the ones matchpathcon expects and runs restorecon on the ones that > > differ to keep it from breaking other daemons. For instance, SSH host keys. > > Ok, then it makes sense. Does it do a script?
Created attachment 754843 [details] Updated rules
Created attachment 754844 [details] file context spec
Ok, again download these files and run steps from the comment #17.
(In reply to Miroslav Grepl from comment #29) > Ok, again download these files and run steps from the comment #17. Sorry, but what do I do with the file context spec? I'm sure that's a key point. :)
Just download mycloud.te and mycloud.fc file and run # make -f /usr/share/selinux/devel/Makefile mycloud.pp # semodule -i mycloud.pp # restorecon -R -v /usr/bin/cloud-init /var/lib/cloud /var/log/cloud* re-test it and # ausearch -m avc -ts recent
Got it. Bugzilla obscures attachment filenames unless you click on "details" so that didn't help. :) Note that /var/log/cloud doesn't exist until cloud-init runs, so I got an initial "restorecon: lstat(/var/log/cloud*) failed: No such file or directory". I assume that's expected in that case, but if necessary we could pre-create that file. With the above modules, on reboot I get # ausearch -m avc -ts recent <no matches> But the problem is still there. I'm going to attach the whole audit.log.
Created attachment 755273 [details] audit.log, after reboot with proposed selinux module
Ok. allow systemd_hostnamed_t initrc_t:dbus send_msg; system_u:system_r:initrc_t:s0 510 ? 00:00:00 hostnamectl How is hostnamectl started in this case?
(In reply to Miroslav Grepl from comment #34) > How is hostnamectl started in this case? Called with subprocess.Popen in python. We could presumably refactor it to use the systemd-hostnamed api directly but it doesn't right now.
What is a path to a script which runs it?
(In reply to Miroslav Grepl from comment #36) > What is a path to a script which runs it? This is convoluted. It's called from /usr/lib/python2.7/site-packages/cloudinit/util.py, from /usr/lib/python2.7/site-packages/cloudinit/distros/rhel.py, which is called from /usr/lib/python2.7/site-packages/cloudinit/config/cc_set_hostname.py. That's a cloud-config module, so it's called from "/usr/bin/cloud-init modules --mode=config", as part of /usr/lib/systemd/system/cloud-config.service
Anything else I should do or try?
Ah, I missed the previous comment. Let me update the local test policy.
Created attachment 756453 [details] mycloude.te
Created attachment 756454 [details] mycloud.fc
Download mycloud.fc and mycloud.te and run # make -f /usr/share/selinux/devel/Makefile mycloud.pp # semodule -i mycloud.pp # restorecon -R -v /usr/bin/cloud-init /var/lib/cloud /var/log/cloud* /usr/lib/systemd/system/cloud* and re-test again.
Same failure with the new policy, and again no matches to `ausearch -m avc -ts recent`. Do you want the whole audit log again?
semodule -DB Will turn off dontaudit rules, see if you get any new avc's about your service.
Also pls make sure you run # ausearch -m avc,user_avc
Created attachment 758252 [details] output of ausearch -m avc,user_avc Here is the log after applying the latest files from above and using "semodule -DB".
Excerpt: time->Fri Jun 7 17:32:32 2013 type=SYSCALL msg=audit(1370626352.438:23): arch=c000003e syscall=59 success=yes exit=0 a0=1a0ba00 a1=1a0f810 a2=19f3430 a3=7fffb2586460 items=0 ppid=337 pid=380 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="hostname" exe="/usr/bin/hostname" subj=system_u:system_r:hostname_t:s0 key=(null) type=AVC msg=audit(1370626352.438:23): avc: denied { noatsecure } for pid=380 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.438:23): avc: denied { siginh } for pid=380 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.438:23): avc: denied { rlimitinh } for pid=380 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.438:23): avc: denied { read write } for pid=380 comm="hostname" path="socket:[11599]" dev="sockfs" ino=11599 scontext=system_u:system_r:hostname_t:s0 tcontext=system_u:system_r:dhcpc_t:s0 tclass=udp_socket type=AVC msg=audit(1370626352.438:23): avc: denied { read write } for pid=380 comm="hostname" path="socket:[11598]" dev="sockfs" ino=11598 scontext=system_u:system_r:hostname_t:s0 tcontext=system_u:system_r:dhcpc_t:s0 tclass=udp_socket ---- time->Fri Jun 7 17:32:32 2013 type=SYSCALL msg=audit(1370626352.443:24): arch=c000003e syscall=59 success=yes exit=0 a0=1a0b860 a1=1a0f810 a2=19f3430 a3=7fffb2586ea0 items=0 ppid=337 pid=381 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="hostname" exe="/usr/bin/hostname" subj=system_u:system_r:hostname_t:s0 key=(null) type=AVC msg=audit(1370626352.443:24): avc: denied { noatsecure } for pid=381 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.443:24): avc: denied { siginh } for pid=381 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.443:24): avc: denied { rlimitinh } for pid=381 comm="hostname" scontext=system_u:system_r:dhcpc_t:s0 tcontext=system_u:system_r:hostname_t:s0 tclass=process type=AVC msg=audit(1370626352.443:24): avc: denied { read write } for pid=381 comm="hostname" path="socket:[11599]" dev="sockfs" ino=11599 scontext=system_u:system_r:hostname_t:s0 tcontext=system_u:system_r:dhcpc_t:s0 tclass=udp_socket type=AVC msg=audit(1370626352.443:24): avc: denied { read write } for pid=381 comm="hostname" path="socket:[11598]" dev="sockfs" ino=11598 scontext=system_u:system_r:hostname_t:s0 tcontext=system_u:system_r:dhcpc_t:s0 tclass=udp_socket ----
allow systemd_hostnamed_t initrc_t:dbus send_msg; Which indicates some service was running as initrc_t and was sent a dbus message.
(In reply to Daniel Walsh from comment #48) > allow systemd_hostnamed_t initrc_t:dbus send_msg; > > > Which indicates some service was running as initrc_t and was sent a dbus > message. Yeah -- see comment #34.
Matthew, how can I reproduce it?
Discussed at 2013-06-10 blocker review meeting: http://meetbot.fedoraproject.org/fedora-blocker-review/2013-06-10/f19final-blocker-review-4.2013-06-10-16.01.log.txt . We had to do quite a lot of interpretation of this bug in the meeting as no clear blocker rationale was given (bad Matthew!), but we read it as something like 'there's an AVC during startup and startup might be a bit slow, but it works'. On that basis it's rejected as a blocker - the system basically works, it doesn't violate criteria - but accepted as a freeze exception - it looks kind of bad and if it slows things down, is inconvenient. If our interpretation was incorrect or you disagree with our reasoning, please re-propose as a blocker _with a clear explanation of why_.
(In reply to Adam Williamson from comment #51) > Discussed at 2013-06-10 blocker review meeting: > http://meetbot.fedoraproject.org/fedora-blocker-review/2013-06-10/f19final- > blocker-review-4.2013-06-10-16.01.log.txt . We had to do quite a lot of > interpretation of this bug in the meeting as no clear blocker rationale was > given (bad Matthew!), but we read it as something like 'there's an AVC > during startup and startup might be a bit slow, but it works'. On that basis > it's rejected as a blocker - the system basically works, it doesn't violate > criteria - but accepted as a freeze exception - it looks kind of bad and if > it slows things down, is inconvenient. > > If our interpretation was incorrect or you disagree with our reasoning, > please re-propose as a blocker _with a clear explanation of why_. Sorry. Re-proposing. The AVC actually completely blocks some of the cloud-init functionality, and being slow is a side-effect. That side-effect is _also_ bad, because it's an entire 60 second delay before login is possible, which basically kills the cloud image as useful for autoscaling services (that's both in EC2 and in OpenStack). Also, since it's an issue with the image, and since we don't yet have a good mechanism for updating the image as a whole, it's not like we can fix this with a zero-day update. I don't know what release criteria this would go under; I hadn't actually anticipated a problem like this in advance or I would have suggested that something to cover it be added. (So, yeah, I'll take that "bad Matthew" for that too.)
(In reply to Miroslav Grepl from comment #50) > Matthew, > how can I reproduce it? Boot ami-6f3b5006 (us east, x86_64) in Amazon EC2. That's the F19 beta. Releng is uploading a test candidate for the final release too, but we're waiting on that. Alternately, look at the images in http://dl.fedoraproject.org/pub/alt/stage/19-TC2/Images/ and boot in OpenStack.
(In reply to Miroslav Grepl from comment #50) > Matthew, > how can I reproduce it? TC images, available globally: │ ami-d7293aa3 : eu-west-1 image for x86_64 │ ami-ff8a19c5 : ap-southeast-2 image for x86_64 │ ami-95951e94 : ap-northeast-1 image for x86_64 │ ami-62b91c7f : sa-east-1 image for x86_64 │ ami-f7c555c7 : us-west-2 image for x86_64 │ ami-377e095e : us-east-1 image for x86_64 │ ami-ebb3fdb9 : ap-southeast-1 image for x86_64
Hmmm -- those TC2 images in EC2 are failing to even get the key after a minute. I'll investigate tomorrow.
Given the impact we can just argue that it's serious enough to constitute a breach of the Xen/EC2 criterion (which I was gonna cite, but the wiki seems to be falling over ATM). We'll consider it at the next blocker meeting. Note, to propose a blocker you set Blocks: (not Depends on:), and to *re-propose* a bug that's been rejected, you have to unset the whiteboard field that indicates the rejection.
Matthew, could you add outputs of # ls -Z /usr/lib/systemd/system/cloud-* and # ps -efZ |grep initrc I am trying to reproduce it.
(In reply to Miroslav Grepl from comment #57) Not sure if you mean before or after applying the new policy. Here's before: # ls -Z /usr/lib/systemd/system/cloud-* -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-config.service -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-config.target -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-final.service -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-init-local.service -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-init.service # ps -efZ |grep initrc system_u:system_r:initrc_t:s0 root 432 1 1 19:30 ? 00:00:00 /usr/bin/python /usr/bin/cloud-init init system_u:system_r:initrc_t:s0 root 504 432 0 19:30 ? 00:00:00 hostnamectl set-hostname localhost After the new policy: # ls -Z /usr/lib/systemd/system/cloud-* -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-config.service -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-config.target -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-final.service -rw-r--r--. root root unconfined_u:object_r:cloud_init_unit_file_t:s0 /usr/lib/systemd/system/cloud-init-local.service -rw-r--r--. root root unconfined_u:object_r:systemd_unit_file_t:s0 /usr/lib/systemd/system/cloud-init.service # ps -efZ |grep initrc system_u:system_r:initrc_t:s0 root 430 1 2 19:36 ? 00:00:00 /usr/bin/python /usr/bin/cloud-init init system_u:system_r:initrc_t:s0 root 501 430 0 19:36 ? 00:00:00 hostnamectl set-hostname localhost Is the "mycloud.fc" file supposed to have cloud-init-.* or is that meant to be cloud-init.*?
Also, in case it isn't clear here: The cloud-init program takes metadata in a variety of formats and performs system-configuration actions based on that. This is up to and including a sort of "rc.local", where a shell script is executed as root and expected to be able to do just about everything to the system. (If we want to try to constrain that further, which wouldn't necessarily be a terrible idea, that'd be a lot of work.)
Yes, we will run it as unconfined domain. But we need to have own domain. We don't want to dbus chat with initrc_t. Ok, there is a bug in .fc file. Try to change to -/usr/lib/systemd/system/cloud-config-.* -- gen_context(system_u:object_r:cloud_init_unit_file_t,s0) /usr/lib/systemd/system/cloud-init-.* -- -gen_context(system_u:object_r:cloud_init_unit_file_t,s0) +/usr/lib/systemd/system/cloud-config.* -- gen_context(system_u:object_r:cloud_init_unit_file_t,s0) +/usr/lib/systemd/system/cloud-init.* -- gen_context(system_u:object_r:cloud_init_unit_file_t,s0) +/usr/lib/systemd/system/cloud-final.* -- gen_context(system_u:object_r:cloud_init_unit_file_t,s0) and # make -f /usr/share/selinux/devel/Makefile mycloud.pp # semodule -i mycloud.pp # restorecon -R -v /usr/lib/systemd/system/cloud*
I'll try that again when I get a chance, although I should note that I tried /usr/lib/systemd/system/cloud-.* -- gen_context(system_u:object_r:cloud_init_unit_file_t,s0) yesterday and it didn't help.
Matthew, is there a test machine where I could log in?
(I sent Miroslav information for an EC2 login host via a private email.) Any progress or further ideas?
I added more fixes for the policy but I am not able to reproduce allow systemd_hostnamed_t initrc_t:dbus send_msg;
Do you have an OpenStack environment you can test in? That would be ideal.
I use the machine which you provide me.
Discussed at the 2013-06-12 blocker review meeting [1]: Accepted as a blocker for F19 final due to violation of the following F19 final release criterion [2] (in the sense that many of the important use cases are effectively blocked): "The release must boot successfully as Xen DomU with releases providing a functional, supported Xen Dom0 and widely used cloud providers utilizing Xen. This does not include any issues limited to the release functioning as Xen Dom0" [1] http://meetbot.fedoraproject.org/fedora-blocker-review/2013-06-12/f19final-blocker-review-5.2013-06-12-16.01.txt [2] http://fedoraproject.org/wiki/Fedora_19_Final_Release_Criteria
Fixes has been added to selinux-policy-3.12.1-53.fc19
Whoops, inadvertently I turned it to ASSIGNED. Moved to MODIFIED. Sorry for the noise.
(In reply to Miroslav Grepl from comment #68) > Fixes has been added to selinux-policy-3.12.1-53.fc19 I've confirmed that this works with manual testing. Hope to see it in the next TC or RC so we can test the image as a whole.
selinux-policy-3.12.1-53.fc19 has been submitted as an update for Fedora 19. https://admin.fedoraproject.org/updates/selinux-policy-3.12.1-53.fc19
The fix should be in the TC6 cloud images
Package selinux-policy-3.12.1-54.fc19: * should fix your issue, * was pushed to the Fedora 19 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing selinux-policy-3.12.1-54.fc19' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-11355/selinux-policy-3.12.1-54.fc19 then log in and leave karma (feedback).
Can cloud folks check this fix with TC6? Thanks!
Fix in TC6 confirmed. Hostname is set, cloud-init is happy and there's no SELinux AVC denials at all.
selinux-policy-3.12.1-54.fc19 has been pushed to the Fedora 19 stable repository. If problems still persist, please make note of it in this bug report.
Hi This is still happening for me Selinux version [root@salt-test6 ~]# rpm -qa selinux* selinux-policy-targeted-3.13.1-60.el7.noarch selinux-policy-3.13.1-60.el7.noarch Red Hat version [root@salt-test6 ~]# cat /etc/redhat-release Red Hat Enterprise Linux Server release 7.2 (Maipo) Note that this is an image from Red Hat rhel-guest-image-7.2-20160302.0.x86_64 [root@salt-test6 log]# tail -n2 cloud-init.log Apr 28 22:03:03 localhost cloud-init: 2016-04-28 22:03:03,718 - util.py[WARNING]: Failed to set the hostname to salt-test6.novalocal (salt-test6) Apr 28 22:03:09 localhost cloud-init: 2016-04-28 22:03:09,961 - util.py[WARNING]: Running module set_hostname (<module 'cloudinit.config.cc_set_hostname' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_set_hostname.pyc'>) failed
Also cloud config version [root@salt-test6 ~]# rpm -qa cloud* cloud-init-0.7.6-6.el7.x86_64 cloud-utils-growpart-0.27-13.el7.noarch