Bug 1956836 - AVC denial when setting hostname on GCP using "set-valid-hostname.sh" script
Summary: AVC denial when setting hostname on GCP using "set-valid-hostname.sh" script
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Machine Config Operator
Version: 4.9
Hardware: All
OS: Linux
low
medium
Target Milestone: ---
: 4.9.0
Assignee: MCO Team
QA Contact: Rio Liu
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-05-04 14:09 UTC by Micah Abbott
Modified: 2021-11-01 01:24 UTC (History)
18 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1945646
Environment:
Last Closed: 2021-10-29 15:17:32 UTC
Target Upstream Version:
miabbott: needinfo-


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift machine-config-operator pull 2618 0 None open Bug 1956836: templates: Rework node-valid-hostname to fix SELinux denial 2021-06-14 21:55:11 UTC
Github openshift os pull 551 0 None open BZ 1956836: overlay: Add rhcos-usrlocal-selinux-fixup.service 2021-05-14 18:23:04 UTC
Red Hat Product Errata RHSA-2021:3759 0 None None None 2021-11-01 01:24:17 UTC

Comment 1 Micah Abbott 2021-05-04 14:55:04 UTC
When digging into the status of a cluster running `4.8.0-0.nightly-2021-04-30-201824`, it looks like the AVC denial originally reported in BZ#1945646 is still present.

```
sh-4.4# chroot /host 
sh-4.4# audit2allow -a


#============= systemd_hostnamed_t ==============
allow systemd_hostnamed_t initrc_t:dbus send_msg;
sh-4.4# cd /var/log/audit/
sh-4.4# grep -R hostnamed *
audit.log.3:type=SERVICE_START msg=audit(1620134026.498:31): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=SERVICE_STOP msg=audit(1620134056.512:46): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=SERVICE_START msg=audit(1620134103.304:32): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=USER_AVC msg=audit(1620134103.493:36): pid=982 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.14 spid=1256 tpid=1352 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
audit.log.3:type=SERVICE_STOP msg=audit(1620134133.524:55): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
```

It looks like PID 982 (`dbus-daemon`) is getting activated by PID 1256 (`systemd-hostname`) and that is generating the AVC denial.

Digging into the logs around the time of the AVC denial, there doesn't appear to be any failure related to setting the hostname.

```
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Network Manager...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.1560] NetworkManager (version 1.30.0-1.el8) is starting... (for the first time)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.1563] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 10-disable-default-plugins.conf, 20-client-id-from-mac.conf) (etc: 99-keyfiles.conf, hostname.conf, sdn.conf)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.1593] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Network Manager.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Reached target Network.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.1676] manager[0x56264d779010]: monitoring kernel firmware directory '/lib/firmware'.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.9' (uid=0 pid=1245 comm="/usr/sbin/NetworkManager --no-daemon " label="system_u:sy>
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Update GCP routes for forwarded IPs..
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting OpenSSH server daemon...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Network Manager Wait Online...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Hostname Service...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c sshd[1252]: Server listening on 0.0.0.0 port 22.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c sshd[1252]: Server listening on :: port 22.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started OpenSSH server daemon.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Successfully activated service 'org.freedesktop.hostname1'
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Hostname Service.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3002] hostname: hostname: using hostnamed
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3003] hostname: hostname changed from (none) to "ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c"
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3010] dns-mgr[0x56264d76c170]: init: dns=default,systemd-resolved rc-manager=symlink
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3105] Loaded device plugin: NMOvsFactory (/usr/lib64/NetworkManager/1.30.0-1.el8/libnm-device-plugin-ovs.so)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c gcp-routes.sh[1249]: done applying vip rules
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3150] Loaded device plugin: NMTeamFactory (/usr/lib64/NetworkManager/1.30.0-1.el8/libnm-device-plugin-team.so)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3151] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3152] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3153] manager: Networking is enabled by state file
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3155] dhcp-init: Using DHCP client 'internal'
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.9' (uid=0 pid=1245 comm="/usr/sbin/NetworkManager --no-daemon " label="sys>
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3166] settings: Loaded settings plugin: keyfile (internal)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Network Manager Script Dispatcher Service...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3200] settings: Loaded settings plugin: ifcfg-rh ("/usr/lib64/NetworkManager/1.30.0-1.el8/libnm-settings-plugin-ifcfg-rh.so")
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3222] device (lo): carrier: link connected
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3226] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3240] manager: (ens4): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3288] settings: (ens4): created default wired connection 'Wired connection 1'
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3294] device (ens4): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Network Manager Script Dispatcher Service.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c kernel: IPv6: ADDRCONF(NETDEV_UP): ens4: link is not ready
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3381] device (ens4): carrier: link connected
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3460] device (ens4): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3494] policy: auto-activating connection 'Wired connection 1' (71988c48-5343-3873-b0a7-b2ea36b42c31)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3501] device (ens4): Activation: starting connection 'Wired connection 1' (71988c48-5343-3873-b0a7-b2ea36b42c31)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3502] device (ens4): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3508] manager: NetworkManager state is now CONNECTING
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3511] device (ens4): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3519] device (ens4): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3527] dhcp4 (ens4): activation: beginning transaction (timeout in 45 seconds)
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3615] dhcp4 (ens4): state changed unknown -> bound, address=10.0.128.3
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3643] device (ens4): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3689] device (ens4): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3692] device (ens4): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3697] manager: NetworkManager state is now CONNECTED_LOCAL
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3709] manager: NetworkManager state is now CONNECTED_SITE
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3710] policy: set 'Wired connection 1' (ens4) as default for IPv4 routing and DNS
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.9' (uid=0 pid=1245 comm="/usr/sbin/NetworkManager --no-daemon " label="system_u:syst>
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c dbus-daemon[982]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3757] device (ens4): Activation: successful, device activated.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3767] manager: NetworkManager state is now CONNECTED_GLOBAL
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c NetworkManager[1245]: <info>  [1620134103.3780] manager: startup complete
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Network Manager Wait Online.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Configures OVS with proper host networking configuration...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Started Network Manager Wait Online.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Configures OVS with proper host networking configuration...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c configure-ovs.sh[1310]: + touch /var/run/ovs-config-executed
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c configure-ovs.sh[1310]: + rpm -qa
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c systemd[1]: Starting Set GCP Transient Hostname...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c configure-ovs.sh[1310]: + grep -q openvswitch
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c afterburn[1314]: May 04 13:15:03.441 INFO Fetching http://metadata.google.internal/computeMetadata/v1/instance/hostname: Attempt #1
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c afterburn[1314]: May 04 13:15:03.447 INFO Fetch successful
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c bash[1347]: ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-ci.internal is longer than 63 characters, using trunacated hostname
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c bash[1351]: setting static hostname to ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd-hostnamed[1256]: Changed static host name to 'ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9'
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 NetworkManager[1245]: <info>  [1620134103.4938] hostname: hostname changed from "ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c" to "ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9"
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: console-login-helper-messages-issuegen.service: Succeeded.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Started Generate console-login-helper-messages issue snippet.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: console-login-helper-messages-issuegen.service: Consumed 22ms CPU time
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Starting Permit User Sessions...
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Started Permit User Sessions.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Started Serial Getty on ttyS0.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Started Getty on tty1.
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Reached target Login Prompts.
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + '[' OpenShiftSDN == OVNKubernetes ']'
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + '[' OpenShiftSDN == OpenShiftSDN ']'
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + iface=
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + nmcli connection show ovs-port-phys0
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + nmcli connection show ovs-if-phys0
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + nmcli connection show ovs-port-br-ex
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + nmcli connection show ovs-if-br-ex
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + nmcli connection show br-ex
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + rm -f /etc/NetworkManager/system-connections/br-ex.nmconnection /etc/NetworkManager/system-connections/ovs-if-br-ex.nmconnection /etc/NetworkManager/system-connections/ovs-port-br-ex.nmconnection /etc/NetworkManager/system-connections/>
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + ovs-vsctl --timeout=30 --if-exists del-br br-int -- --if-exists del-br br-local -- --if-exists del-br br-ex
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 configure-ovs.sh[1310]: + [[ -n '' ]]
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: ovs-configuration.service: Succeeded.
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 ovs-vsctl[1399]: ovs|00001|vsctl|INFO|Called as ovs-vsctl --timeout=30 --if-exists del-br br-int -- --if-exists del-br br-local -- --if-exists del-br br-ex
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: Started Configures OVS with proper host networking configuration.
May 04 13:15:04 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: ovs-configuration.service: Consumed 519ms CPU time
May 04 13:15:07 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 chronyd[988]: Selected source 169.254.169.254
May 04 13:15:13 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: NetworkManager-dispatcher.service: Succeeded.
May 04 13:15:13 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd[1]: NetworkManager-dispatcher.service: Consumed 146ms CPU time
```


I think these messages are related to the AVC denial:

```
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c bash[1347]: ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-ci.internal is longer than 63 characters, using trunacated hostname
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9.c.openshift-gce-devel-c bash[1351]: setting static hostname to ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9
May 04 13:15:03 ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9 systemd-hostnamed[1256]: Changed static host name to 'ci-ln-xw294mb-f76d1-slbkd-worker-b-zn9g9'
```

The use of `systemd-hostnamed` appears to be coming from setting the hostname via `hostnamectl` in the MCO `set-valid-hostnames.sh` script that is used on GCP:

https://github.com/openshift/machine-config-operator/blob/master/templates/common/_base/files/usr-local-sbin-set-valid-hostname.yaml#L64


This is kind of an MCO issue, though the RHCOS team helped with that script.  I think we should probably be the ones to investigate how to avoid the AVC denial when using this script.

Comment 2 Colin Walters 2021-05-04 19:33:15 UTC
I think this is a pure selinux policy bug; that looks like something that should be allowed.

Comment 3 Micah Abbott 2021-05-04 20:15:09 UTC
@Miros @Zydenek could you weigh in on a need for an SELinux policy change here?

Comment 4 Daniel Walsh 2021-05-04 21:32:48 UTC
This looks like you have a service on the system that is running as initrc_t, which is causing the issue, since systemd-hostname is not allowed to communicate with it.

Is there some labeling issue on this service?

ps -eZ | grep initrc_t

Comment 5 Micah Abbott 2021-05-05 14:45:33 UTC
(In reply to Daniel Walsh from comment #4)
> This looks like you have a service on the system that is running as
> initrc_t, which is causing the issue, since systemd-hostname is not allowed
> to communicate with it.
> 
> Is there some labeling issue on this service?
> 
> ps -eZ | grep initrc_t

The systemd service is being installed by the MCO:

https://github.com/openshift/machine-config-operator/blob/master/templates/common/_base/units/node-valid-hostname.service.yaml

...and it looks like the service is sourcing the script via `bash` - https://github.com/openshift/machine-config-operator/blob/master/templates/common/_base/units/node-valid-hostname.service.yaml#L13-L15

The comment in that service says that systemd prevents direct execution of that script in /usr/local/sbin.  But having the MCO write out the script to a more appropriate place probably isn't possible due to where we can write files on RHCOS.

Comment 10 Micah Abbott 2021-05-12 18:35:04 UTC
Adjusting priority to low based on BZ scrub.  While we do want to avoid any AVC denials, the functionality appears unaffected, so it doesn't seem like something we need to rush to fix.

Comment 11 Daniel Walsh 2021-05-12 18:48:59 UTC
BTW:

time->Thu Apr  1 13:19:02 2021
type=PROCTITLE msg=audit(1617283142.102:54): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1617283142.102:54): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7f7a24015680 a2=4 a3=0 items=0 ppid=2553 pid=3473 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1617283142.102:54): avc:  granted  { setsecparam } for  pid=3473 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security


This is not a deniel, Notice the `granted`, This means the SELinux policy wants to tell the system any time a processes does a setsecparam,  So this is expected and is not a bug.

Comment 12 Micah Abbott 2021-05-13 14:13:05 UTC
(In reply to Daniel Walsh from comment #11)
> BTW:
> 
> time->Thu Apr  1 13:19:02 2021
> type=PROCTITLE msg=audit(1617283142.102:54):
> proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002
> F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
> type=SYSCALL msg=audit(1617283142.102:54): arch=c000003e syscall=1
> success=yes exit=4 a0=7 a1=7f7a24015680 a2=4 a3=0 items=0 ppid=2553 pid=3473
> auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
> tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6"
> subj=system_u:system_r:spc_t:s0 key=(null)
> type=AVC msg=audit(1617283142.102:54): avc:  granted  { setsecparam } for 
> pid=3473 comm="tuned" scontext=system_u:system_r:spc_t:s0
> tcontext=system_u:object_r:security_t:s0 tclass=security
> 
> 
> This is not a deniel, Notice the `granted`, This means the SELinux policy
> wants to tell the system any time a processes does a setsecparam,  So this
> is expected and is not a bug.

Agreed, but what about this message?


```
audit.log.3:type=USER_AVC msg=audit(1620134103.493:36): pid=982 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.14 spid=1256 tpid=1352 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
```

audit2allow is proposing the following:

```
sh-4.4# audit2allow -a


#============= systemd_hostnamed_t ==============
allow systemd_hostnamed_t initrc_t:dbus send_msg;
```

Comment 13 Zdenek Pytela 2021-05-13 15:04:34 UTC
Both the problems were already discussed in bz#1945646. Executing the script directly, without a reference to bash, will make it run in unconfined_service_t.

Frankly, I don't understand this:
> The comment in that service says that systemd prevents direct execution of that script in /usr/local/sbin. 
Why would systemd block it?

Long term solution would probably be confining the service.

Comment 14 Micah Abbott 2021-05-13 15:30:36 UTC
(In reply to Zdenek Pytela from comment #13)
> Both the problems were already discussed in bz#1945646. Executing the script
> directly, without a reference to bash, will make it run in
> unconfined_service_t.
> 
> Frankly, I don't understand this:
> > The comment in that service says that systemd prevents direct execution of that script in /usr/local/sbin. 
> Why would systemd block it?

Yeah, that seems to be misguided.  On a local RHCOS 4.8 node, I was able to successfully run a script in /usr/local/sbin from a systemd service.

Maybe we can just change the service to call out the script directly and solve this issue.

> Long term solution would probably be confining the service.

Comment 15 Micah Abbott 2021-05-13 15:50:01 UTC
(In reply to Micah Abbott from comment #14)
> (In reply to Zdenek Pytela from comment #13)
> > Both the problems were already discussed in bz#1945646. Executing the script
> > directly, without a reference to bash, will make it run in
> > unconfined_service_t.
> > 
> > Frankly, I don't understand this:
> > > The comment in that service says that systemd prevents direct execution of that script in /usr/local/sbin. 
> > Why would systemd block it?
> 
> Yeah, that seems to be misguided.  On a local RHCOS 4.8 node, I was able to
> successfully run a script in /usr/local/sbin from a systemd service.

Looks like my testing was somewhat flawed; newly created files in /usr/local/sbin are getting the `var_t` label:

```
$ ls -lZ /usr/local/sbin/
total 8
-rwxr-xr-x. 1 root root unconfined_u:object_r:var_t:s0 2784 May 13 15:38 set-valid-hostname.sh
```

SELinux is denying the execution of the script in /usr/local/sbin

```
type=AVC msg=audit(1620920257.749:300): avc:  denied  { execute } for  pid=2163 comm="(tname.sh)" name="set-valid-hostname.sh" dev="vda4" ino=23068808 scontext=system_u:system_r:init_t:s0 tcontext=unconfined_u:object_r:var_t:s0 tclass=file permissive=0
```

So this looks like it is rubbing against https://bugzilla.redhat.com/show_bug.cgi?id=1943381


There's no easy mechanism to relabel a file written out by the MCO, so we would have to consider moving the script to /usr/local/bin in the meantime.  Or just wait for the updated SELinux policy as part of the RHEL 8.4.z release.

Comment 16 Daniel Walsh 2021-05-13 18:03:58 UTC
If you move an executable into /usr, you should run restorecon on it, before executing.

The SELinux team decided a few years ago to not have init_t be an unconfined type, which I disagreed with.
And that is causing the AVCs. (Personally init can do anything it wants, so no reason to confine it. But 
I don't control SELinux policy any longer).

Comment 17 Zdenek Pytela 2021-05-13 18:19:58 UTC
(In reply to Micah Abbott from comment #15)
> Looks like my testing was somewhat flawed; newly created files in
> /usr/local/sbin are getting the `var_t` label:
> 
> ```
> $ ls -lZ /usr/local/sbin/
> total 8
> -rwxr-xr-x. 1 root root unconfined_u:object_r:var_t:s0 2784 May 13 15:38
> set-valid-hostname.sh
Such a thing should not happen provided the directory has correct label:

# ls -Zd /usr/local/sbin/
system_u:object_r:bin_t:s0 /usr/local/sbin/
# echo echo > /usr/local/sbin/file
beaker-rhel8# ls -Z /usr/local/sbin/file
unconfined_u:object_r:bin_t:s0 /usr/local/sbin/file

Note if you move a file, it keeps extended attributes; the same for "cp -a".

What would be the output of this command?

# restorecon -Rvn /usr/local/sbin

Comment 18 Micah Abbott 2021-05-13 19:56:26 UTC
(In reply to Zdenek Pytela from comment #17)
> (In reply to Micah Abbott from comment #15)
> > Looks like my testing was somewhat flawed; newly created files in
> > /usr/local/sbin are getting the `var_t` label:
> > 
> > ```
> > $ ls -lZ /usr/local/sbin/
> > total 8
> > -rwxr-xr-x. 1 root root unconfined_u:object_r:var_t:s0 2784 May 13 15:38
> > set-valid-hostname.sh
> Such a thing should not happen provided the directory has correct label:
> 
> # ls -Zd /usr/local/sbin/
> system_u:object_r:bin_t:s0 /usr/local/sbin/
> # echo echo > /usr/local/sbin/file
> beaker-rhel8# ls -Z /usr/local/sbin/file
> unconfined_u:object_r:bin_t:s0 /usr/local/sbin/file
> 
> Note if you move a file, it keeps extended attributes; the same for "cp -a".
> 
> What would be the output of this command?
> 
> # restorecon -Rvn /usr/local/sbin

```
[core@cosa-devsh ~]$ ls -Zd /usr/local/sbin 
system_u:object_r:var_t:s0 /usr/local/sbin
[core@cosa-devsh ~]$ sudo touch /usr/local/sbin/file
[core@cosa-devsh ~]$ ls -Z /usr/local/sbin/file
unconfined_u:object_r:var_t:s0 /usr/local/sbin/file
[core@cosa-devsh ~]$ sudo restorecon -Rvn /usr/local/sbin     
[core@cosa-devsh ~]$ 
```

I think this is https://bugzilla.redhat.com/show_bug.cgi?id=1943381

Comment 19 Colin Walters 2021-05-14 12:59:43 UTC
Ah, yes.  So we can fix this by moving the script to `/usr/local/bin`, or we can add a systemd unit which does a restorecon.  In fact, we need the systemd unit fixup to make in-place updates work.  (ostree does not touch `/var`, it's managed by `systemd-tmpfiles`).

Comment 20 Colin Walters 2021-05-14 18:23:04 UTC
PR in https://github.com/openshift/os/pull/551

Comment 22 Michael Nguyen 2021-06-09 21:04:37 UTC
I'm still seeing the denial.

$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.8.0-0.nightly-2021-06-09-023740   True        False         13m     Cluster version is 4.8.0-0.nightly-2021-06-09-023740
$ oc get nodes
NAME                                         STATUS   ROLES    AGE   VERSION
mnguyen48longnametest-cbjhs-master-0         Ready    master   32m   v1.21.0-rc.0+7f76571
mnguyen48longnametest-cbjhs-master-1         Ready    master   32m   v1.21.0-rc.0+7f76571
mnguyen48longnametest-cbjhs-master-2         Ready    master   32m   v1.21.0-rc.0+7f76571
mnguyen48longnametest-cbjhs-worker-a-d4kpt   Ready    worker   25m   v1.21.0-rc.0+7f76571
mnguyen48longnametest-cbjhs-worker-b-hckbc   Ready    worker   25m   v1.21.0-rc.0+7f76571
mnguyen48longnametest-cbjhs-worker-c-zsv8f   Ready    worker   25m   v1.21.0-rc.0+7f76571
$ oc debug node/mnguyen48longnametest-cbjhs-worker-c-zsv8f
Starting pod/mnguyen48longnametest-cbjhs-worker-c-zsv8f-debug ...
To use host binaries, run `chroot /host`
If you don't see a command prompt, try pressing enter.
sh-4.2# chroot /host
sh-4.4# date           
Wed Jun  9 13:46:18 UTC 2021
sh-4.4# ausearch -m avc
----
time->Wed Jun  9 13:14:40 2021
type=PROCTITLE msg=audit(1623244480.602:213): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1623244480.602:213): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7f3a10016320 a2=4 a3=0 items=0 ppid=2630 pid=3465 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1623244480.602:213): avc:  granted  { setsecparam } for  pid=3465 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
sh-4.4# 
sh-4.4# audit2allow -a


#============= systemd_hostnamed_t ==============
allow systemd_hostnamed_t initrc_t:dbus send_msg;
sh-4.4# 
sh-4.4# cd /var/log/audit/
sh-4.4# grep -R hostnamed *
audit.log.3:type=SERVICE_START msg=audit(1623244358.576:37): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=SERVICE_STOP msg=audit(1623244388.610:54): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=SERVICE_START msg=audit(1623244424.002:33): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.3:type=USER_AVC msg=audit(1623244424.177:37): pid=1033 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.15 spid=1228 tpid=1331 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
audit.log.3:type=SERVICE_STOP msg=audit(1623244454.202:54): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
sh-4.4# 
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel dbus-daemon[1033]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedeskto>
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel dbus-daemon[1033]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus>
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel NetworkManager[1214]: <info>  [1623244424.0628] device (ens4): Activation: successful, device activated.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel NetworkManager[1214]: <info>  [1623244424.0636] manager: NetworkManager state is now CONNECTED_GLOBAL
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel NetworkManager[1214]: <info>  [1623244424.0645] manager: startup complete
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel systemd[1]: Started Network Manager Wait Online.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel systemd[1]: Starting Configures OVS with proper host networking configuration...
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel configure-ovs.sh[1276]: + touch /var/run/ovs-config-executed
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel configure-ovs.sh[1276]: + rpm -qa
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel nm-dispatcher[1259]: Error: Device '' not found.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel systemd[1]: Starting Set GCP Transient Hostname...
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel configure-ovs.sh[1276]: + grep -q openvswitch
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel nm-dispatcher[1259]: Error: Device '' not found.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel afterburn[1283]: Jun 09 13:13:44.127 INFO Fetching http://metadata.google.internal/computeMetadata/v1/instance/hostna>
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel afterburn[1283]: Jun 09 13:13:44.131 INFO Fetch successful
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel bash[1321]: mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel.internal is longer than 63 characters, u>
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce-devel bash[1328]: setting static hostname to mnguyen48longnametest-cbjhs-worker-c-zsv8f
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + '[' OpenShiftSDN == OVNKubernetes ']'
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + '[' OpenShiftSDN == OpenShiftSDN ']'
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + iface=
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + nmcli connection show ovs-port-phys0
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + nmcli connection show ovs-if-phys0
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f systemd-hostnamed[1228]: Changed static host name to 'mnguyen48longnametest-cbjhs-worker-c-zsv8f'
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + nmcli connection show ovs-port-br-ex
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f NetworkManager[1214]: <info>  [1623244424.1781] hostname: hostname changed from "mnguyen48longnametest-cbjhs-worker-c-zsv8f.c.openshift-gce>
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f nm-dispatcher[1259]: Error: Device '' not found.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + nmcli connection show ovs-if-br-ex
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f configure-ovs.sh[1276]: + nmcli connection show br-ex
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8f nm-dispatcher[1259]: Error: Device '' not found.
Jun 09 13:13:44 mnguyen48longnametest-cbjhs-worker-c-zsv8sh-4.4# systemctl status systemd-hostnamed

Comment 23 Colin Walters 2021-06-09 21:19:23 UTC
Now that I think about it more, I think the change (new systemd service) also needs to land in the boot image to achieve "no denials after install".

So that would block on https://github.com/openshift/installer/pull/4977 I think.

However - what this should still fix is that you shouldn't see the same denial on *subsequent* boots.  If you still have that cluster up, can you test that?

Comment 24 Daniel Walsh 2021-06-10 00:19:05 UTC
type=PROCTITLE msg=audit(1623244480.602:213): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1623244480.602:213): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7f3a10016320 a2=4 a3=0 items=0 ppid=2630 pid=3465 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1623244480.602:213): avc:  granted  { setsecparam } for  pid=3465 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security


This is not a DENIAL.  Notice the `avc:  granted  { setsecparam }`.  This is just the audit.log telling you that a process did a security related change to the kernel.

Comment 25 Colin Walters 2021-06-10 12:44:48 UTC
Dan, the log still has the
> audit.log.3:type=USER_AVC msg=audit(1623244424.177:37): pid=1033 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.15 spid=1228 tpid=1331 scontext=system_u:system_r:systemd_hostnamed_t:s0 
message right?

Comment 26 Daniel Walsh 2021-06-10 15:51:57 UTC
Yes that is an AVC and should be fixed in the selinux-policy package.  I see no reason not to allow it.

Comment 27 Michael Nguyen 2021-06-10 15:57:52 UTC
(In reply to Colin Walters from comment #23)
> Now that I think about it more, I think the change (new systemd service)
> also needs to land in the boot image to achieve "no denials after install".
> 
> So that would block on https://github.com/openshift/installer/pull/4977 I
> think.
> 
> However - what this should still fix is that you shouldn't see the same
> denial on *subsequent* boots.  If you still have that cluster up, can you
> test that?

I stood up another cluster and see it in subsequent boots also.

$ oc get nodes
NAME                                       STATUS   ROLES    AGE   VERSION
ci-ln-xx37n7t-f76d1-qtbdl-master-0         Ready    master   30m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-master-1         Ready    master   30m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-master-2         Ready    master   30m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6   Ready    worker   20m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-c-p7p5q   Ready    worker   21m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-d-627hm   Ready    worker   20m   v1.21.0-rc.0+c5e3b15
$ oc debug node/ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6
Starting pod/ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6-debug ...
To use host binaries, run `chroot /host`
If you don't see a command prompt, try pressing enter.
sh-4.2# chroot /host
sh-4.4# ausearch -m avc
----
time->Thu Jun 10 14:24:48 2021
type=PROCTITLE msg=audit(1623335088.965:165): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1623335088.965:165): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7efdb80157a0 a2=4 a3=0 items=0 ppid=2541 pid=3404 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1623335088.965:165): avc:  granted  { setsecparam } for  pid=3404 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
sh-4.4# audit2allow -a


#============= systemd_hostnamed_t ==============
allow systemd_hostnamed_t initrc_t:dbus send_msg;
sh-4.4# 
sh-4.4# 
sh-4.4# 
sh-4.4# cd /var/log/audit     
sh-4.4# ls
audit.log  audit.log.1	audit.log.2
sh-4.4# grep -R hostanmed
sh-4.4# grep -R hostnamed
audit.log.2:type=SERVICE_START msg=audit(1623334945.800:39): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=SERVICE_STOP msg=audit(1623334975.837:55): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=SERVICE_START msg=audit(1623335012.400:32): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=USER_AVC msg=audit(1623335012.570:37): pid=1032 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.15 spid=1220 tpid=1318 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
audit.log.2:type=SERVICE_STOP msg=audit(1623335042.610:54): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
sh-4.4# vi audit.log.2 
sh-4.4# vi audit.log.2
sh-4.4# systemctl reboot
sh-4.4# exit
sh-4.2# 
Removing debug pod ...
$ oc get nodes
NAME                                       STATUS   ROLES    AGE   VERSION
ci-ln-xx37n7t-f76d1-qtbdl-master-0         Ready    master   32m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-master-1         Ready    master   32m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-master-2         Ready    master   32m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6   Ready    worker   23m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-c-p7p5q   Ready    worker   23m   v1.21.0-rc.0+c5e3b15
ci-ln-xx37n7t-f76d1-qtbdl-worker-d-627hm   Ready    worker   23m   v1.21.0-rc.0+c5e3b15
$ watch oc get nodes
$ oc debug node/ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6
Starting pod/ci-ln-xx37n7t-f76d1-qtbdl-worker-b-rwlb6-debug ...
To use host binaries, run `chroot /host`
If you don't see a command prompt, try pressing enter.
sh-4.2# chroot /host
sh-4.4# cd /var/log/audit/
sh-4.4# ls
audit.log  audit.log.1	audit.log.2
sh-4.4# grep -R hostnamed
audit.log.2:type=SERVICE_START msg=audit(1623334945.800:39): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=SERVICE_STOP msg=audit(1623334975.837:55): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=SERVICE_START msg=audit(1623335012.400:32): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log.2:type=USER_AVC msg=audit(1623335012.570:37): pid=1032 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.15 spid=1220 tpid=1318 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
audit.log.2:type=SERVICE_STOP msg=audit(1623335042.610:54): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log:type=SERVICE_START msg=audit(1623336532.399:34): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
audit.log:type=USER_AVC msg=audit(1623336532.608:39): pid=991 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.15 spid=1257 tpid=1382 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
audit.log:type=SERVICE_STOP msg=audit(1623336562.624:56): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"

Comment 28 Colin Walters 2021-06-10 20:29:32 UTC
Hmm, OK next time can you try to gather a bit more information, e.g.:

ls -alZ /usr/local/sbin
systemctl status rhcos-usrlocal-selinux-fixup
rpm-ostree status


I'm not reproducing this on a just launched 
$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.8.0-0.nightly-2021-06-10-071057   True        False         119m    Cluster version is 4.8.0-0.nightly-2021-06-10-071057
$

in GCP, with e.g.:
[root@ci-ln-n489rxt-f76d1-26fmh-master-2 /]# rpm-ostree status
State: idle
Deployments:
* pivot://quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:b73ff400ace82a6c28b7d6524d91811f4f4ec871de91bdd0ad2a0f607e86ffca
              CustomOrigin: Managed by machine-config-operator
                   Version: 48.84.202106092250-0 (2021-06-09T22:54:08Z)

  ostree://92ede04b462bc884de5562062fb45e06d803754cbaa466e3a2d34b4ee5e9634b
                   Version: 48.84.202105190318-0 (2021-05-19T03:22:10Z)

Comment 29 Colin Walters 2021-06-11 14:19:50 UTC
OK digging more, for sure this comment is correct: https://bugzilla.redhat.com/show_bug.cgi?id=1956836#c23
IOW we need the bootimage bump to get to *zero* denials.

What I am uncertain about is whether my assertion that *subsequent* boots are fixed.  In this cluster I just
launched, I see two denials in three reboots.

Timestamps:

# journalctl --list-boots
-2 a3e5562d355449d990866cf60a5caa1b Fri 2021-06-11 13:04:24 UTC—Fri 2021-06-11 13:07:15 UTC
-1 8dc0a08f06674423936a45fe5a41acbb Fri 2021-06-11 13:07:29 UTC—Fri 2021-06-11 13:53:37 UTC
 0 f853376ba96c479d9a9df0c3fb8e22c4 Fri 2021-06-11 13:54:01 UTC—Fri 2021-06-11 14:09:42 UTC

# journalctl -u rhcos-usrlocal-selinux-fixup
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c systemd[1]: Starting RHCOS Fix SELinux Labeling For /usr/local/sbin...
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c chcon[973]: changing security context of '/usr/local/sbin'
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c sh[981]: changing security context of '/var/usrlocal/sbin'
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c sh[981]: changing security context of '/var/usrlocal/sbin/dynamic-system-reserved-calc.sh'
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c sh[981]: changing security context of '/var/usrlocal/sbin/set-valid-hostname.sh'
Jun 11 13:07:36 ci-ln-9xwvsh2-f76d1-7jvjl-worker-b-4tk9d.c.openshift-gce-devel-c systemd[1]: Started RHCOS Fix SELinux Labeling For /usr/local/sbin.

# ausearch -m USER_AVC
----
time->Fri Jun 11 13:07:37 2021
type=USER_AVC msg=audit(1623416857.846:37): pid=1019 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.15 spid=1224 tpid=1322 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'
----
time->Fri Jun 11 13:54:09 2021
type=USER_AVC msg=audit(1623419649.704:39): pid=1000 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.15 spid=1249 tpid=1382 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'


Chronologically ordering these together...hmm actually, it looks like the fixup script *did* run a second before the dispatcher, but it's not clear to me right now if they raced or not.

Comment 30 Colin Walters 2021-06-14 13:12:00 UTC
OK yeah, rebooting multiple times, I only see those two denials.  (Though, I guess we should cross-verify we're seeing denials on all boots on 4.7)

But it's not clear to me yet why we get those denials even once, because we should be relabeling before that script executes, and it seems we are.  Will dig at this more.

Comment 31 Colin Walters 2021-06-14 19:36:27 UTC
Launching a cluster from https://github.com/openshift/installer/pull/4977 I see exactly *one* denial.  Which...okay, so that proves it helps at provisioning time, but I'm still confused where the initial denial comes from, since we're still seemingly relabeling before the script runs.

Comment 32 Colin Walters 2021-06-14 19:36:56 UTC
[root@ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n ~]# journalctl --list-boots
-1 c1595247ddb245d28f1d0d4bd3e10be6 Mon 2021-06-14 18:21:20 UTC—Mon 2021-06-14 18:22:27 UTC
 0 067bbf0aa84f47c5ae908a494e8dcf58 Mon 2021-06-14 18:22:40 UTC—Mon 2021-06-14 19:34:49 UTC
[root@ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n ~]# ausearch -m USER_AVC -i | more
----
type=USER_AVC msg=audit(06/14/21 18:22:48.083:37) : pid=998 uid=dbus auid=unset ses=unset subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=method_return dest=:1.15 spid=1206 tpid=1299 scontext=system_u:sy
stem_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0  exe=/usr/bin/dbus-daemon sauid=dbus hostname=? addr=? terminal=?' 
[root@ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n ~]# journalctl -u rhcos-usrlocal-selinux-fixup
-- Logs begin at Mon 2021-06-14 18:21:20 UTC, end at Mon 2021-06-14 19:36:39 UTC. --
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c systemd[1]: Starting RHCOS Fix SELinux Labeling For /usr/local/sbin...
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c chcon[1320]: changing security context of '/usr/local/sbin'
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c sh[1326]: changing security context of '/var/usrlocal/sbin'
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c sh[1326]: changing security context of '/var/usrlocal/sbin/dynamic-system-reserved-calc.sh'
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c sh[1326]: changing security context of '/var/usrlocal/sbin/set-valid-hostname.sh'
Jun 14 18:21:41 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c systemd[1]: Started RHCOS Fix SELinux Labeling For /usr/local/sbin.
-- Reboot --
Jun 14 18:22:46 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c systemd[1]: Starting RHCOS Fix SELinux Labeling For /usr/local/sbin...
Jun 14 18:22:46 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c chcon[956]: changing security context of '/usr/local/sbin'
Jun 14 18:22:46 ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n.c.openshift-gce-devel-c systemd[1]: Started RHCOS Fix SELinux Labeling For /usr/local/sbin.
[root@ci-ln-tnj95tt-f76d1-t88wd-worker-b-thw4n ~]#

Comment 33 Colin Walters 2021-06-14 20:43:30 UTC
OK one thing I only just fully put together is that the `/usr/local/sbin/set-valid-hostname.sh` is run on all platforms, but the key behavior here (invoking dbus) actually only runs on GCP.  I got confused because there's a now-outdated comment in the code that says:

```
    # Finally, this script is invoked via:
    #  - /etc/NetworkManager/dispatcher.d/90-long-hostnames
    #  - on boot via node-valid-hostname.service
```

but that became a lie after https://github.com/openshift/machine-config-operator/pull/2217
Since then, actually the main thing we care about is `gcp-hostname.service`.

Comment 34 Colin Walters 2021-06-14 20:50:13 UTC
And now that I put that together, it's easy to reproduce the denial with this Ignition:

```
variant: fcos
version: 1.1.0
systemd:
  units:
    - name: gcp-hostname.service
      enabled: true
      contents: |
        [Unit]
        Description=Ensure the node hostname is valid for the cluster
        Before=network-online.target
      
        [Service]
        Type=oneshot
        RemainAfterExit=yes
        User=root
      
        # SystemD prevents direct execution of the script in /usr/local/sbin,
        # so it is sourced. See the script for functionality.
        ExecStart=/bin/bash -c "source /usr/local/sbin/set-valid-hostname.sh; set_valid_hostname coolhost"
      
        [Install]
        WantedBy=multi-user.target
        # Ensure that network-online.target will not complete until the node has a real hostname.
        RequiredBy=network-online.target

storage:
  files:
    - path: /var/usrlocal/sbin/set-valid-hostname.sh
      mode: 0755
      contents:
        inline: |
          #!/bin/bash
          # On some platforms the hostname may be too long (>63 chars).
          #  - On firstboot the hostname is set in the initramfs before NetworkManager
          #    And it may be truncated at 64 characters (too long)
          #  - On reboot affect nodes use 'localhost'.
          #
          # This script is a simple workaround for hostname woes, including
          #  - NOT a localhost name
          #  - NOT longer than 63 characters. Names will be truncated at the
          #    first dot, and then capped at 63 char (which ever is less).
          #  - Race conditions between truncated hostnames by the dhclient
          #    and NetworkManager.
          #
          # Finally, this script is invoked via:
          #  - /etc/NetworkManager/dispatcher.d/90-long-hostnames
          #  - on boot via node-valid-hostname.service
      
          id

          export PATH="/usr/bin:/usr/local/bin:/sbin:/usr/local/sbin:/bin:${PATH}"
          log() { logger --tag "$(basename $0)" "${@}"; }
      
          # wait_localhost waits until the host gets a real hostname.
          # This will wait indefinately. node-valid-hostname.service will terminate
          # this after 5m.
          wait_localhost() {
              log "waiting for non-localhost hostname to be assigned"
              while [[ "$(< /proc/sys/kernel/hostname)" =~ (localhost|localhost.localdomain) ]];
              do
                  sleep 1
              done
              log "node identified as $(</proc/sys/kernel/hostname)"
              exit 0
          }
      
          set_valid_hostname() {
              local host_name=${1}
              local type_arg="transient"
      
              # /etc/hostname is used for static hostnames and is authorative.
              # This will check to make sure that the static hostname is the
              # less than or equal to 63 characters in length.
              if [ -f /etc/hostname ] && [ "$(cat /etc/hostname | wc -m)" -gt 0 ]; then
                  etc_name="$(< /etc/hostname)"
                  type_arg="static"
                  if [ "${etc_name}" != "${host_name}" ]; then
                      log "/etc/hostname is set to ${etc_name} but does not match ${host_name}"
                      log "using /etc/hostname as the authorative name"
                      host_name="${etc_name}"
                  fi
              fi
      
              # Only mutate the hostname if the length is longer than 63 characters. The
              # hostname will be the lesser of 63 characters after the first dot in the
              # FQDN.
              if [ "${#host_name}" -gt 63 ]; then
                  alt_name=$(printf "${host_name}" | cut -f1 -d'.' | cut -c -63)
                  log "${host_name} is longer than 63 characters, using trunacated hostname"
                  host_name="${alt_name}"
              fi
              log "setting ${type_arg} hostname to ${host_name}"
              /bin/hostnamectl "--${type_arg}" set-hostname "${host_name}"
              exit 0
          }
      
          cli_run() {
              mode="${1:?mode must be the first argument}"; shift;
              case "${mode}" in
                      wait_localhost) wait_localhost;;
                  set_valid_hostname) hname="${1:?hostname is a required last argument}";
                                      set_valid_hostname "${hname}";;
                                  *) log "unknown mode ${mode}"; exit 1;;
              esac
          }
      
          # Allow the functions to be sourced. This can be run either as a
          # standalone command or in systemd or part of NetworkManager.
          if [[ "${BASH_SOURCE[0]}" == "${0}" ]]; then
              cli_run ${@}
          fi
      
```

which is bits of the code extracted from the MCO and slightly tweaked to just always set the hostname to `coolhost`, then I reproduce
the denial with e.g.:

$ cosa run -i /path/to/bz1956836-repro.ign rhcos-48.84.202106091622-0-qemu.x86_64.qcow2

outside of a cluster, etc.

Comment 35 Colin Walters 2021-06-14 21:13:06 UTC
And now that I do that, there's another more fundamental thing going on which is distinct from the label of the binaries, because *they aren't executed directly*.
Notice the:

ExecStart=/bin/bash -c "source /usr/local/sbin/set-valid-hostname.sh; set_valid_hostname coolhost"

And digging into that, notice further:

[root@cosa-devsh ~]# cat /etc/systemd/system/bash-id.service 
[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/bin/bash -c 'id'
[root@cosa-devsh ~]# cat /etc/systemd/system/direct-id.service
[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=id
[root@cosa-devsh ~]# journalctl -u bash-id -u direct-id
-- Logs begin at Mon 2021-06-14 21:00:52 UTC, end at Mon 2021-06-14 21:10:02 UTC. --
Jun 14 21:09:53 cosa-devsh systemd[1]: Starting bash-id.service...
Jun 14 21:09:53 cosa-devsh bash[4569]: uid=0(root) gid=0(root) groups=0(root) context=system_u:system_r:initrc_t:s0
Jun 14 21:09:53 cosa-devsh systemd[1]: Finished bash-id.service.
Jun 14 21:10:02 cosa-devsh systemd[1]: Starting direct-id.service...
Jun 14 21:10:02 cosa-devsh id[4575]: uid=0(root) gid=0(root) groups=0(root) context=system_u:system_r:unconfined_service_t:s0
Jun 14 21:10:02 cosa-devsh systemd[1]: Finished direct-id.service.
[root@cosa-devsh ~]# 

And this is true on FCOS too, it has nothing to do with the label of /usr/local/sbin.

Invoking things via `bash` is suppressing the domain transition.  This seems like a general selinux-policy issue, though I am
not sure if it's an intentional design decision or not.  I find this *very* surprising and it's going to be a recurring source of bugs.  

Anyways...now that we *have* fixed the label of /usr/local/sbin on the RHCOS side, we can fix this by changing the MCO code
to execute the binary directly.

Comment 37 Colin Walters 2021-06-14 21:21:36 UTC
Reassigning to MCO since that's the thing that needs to change to most easily work around this, but I'm going to keep the bug and work on a PR.

Comment 39 Michael Nguyen 2021-06-30 16:59:19 UTC
Verified on 4.9.0-0.nightly-2021-06-30-034414

$ oc get clusterversion
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.9.0-0.nightly-2021-06-30-034414   True        False         8m55s   Cluster version is 4.9.0-0.nightly-2021-06-30-034414

$ oc get nodes
NAME                                                             STATUS   ROLES    AGE   VERSION
mnguyen499-7dpfx-master-0.c.openshift-gce-devel.internal         Ready    master   19m   v1.21.0-rc.0+120883f
mnguyen499-7dpfx-master-1.c.openshift-gce-devel.internal         Ready    master   19m   v1.21.0-rc.0+120883f
mnguyen499-7dpfx-master-2.c.openshift-gce-devel.internal         Ready    master   19m   v1.21.0-rc.0+120883f
mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal   Ready    worker   13m   v1.21.0-rc.0+120883f
mnguyen499-7dpfx-worker-b-nnh78.c.openshift-gce-devel.internal   Ready    worker   13m   v1.21.0-rc.0+120883f
mnguyen499-7dpfx-worker-c-lwqxr.c.openshift-gce-devel.internal   Ready    worker   13m   v1.21.0-rc.0+120883f
$ oc debug node/mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal
Starting pod/mnguyen499-7dpfx-worker-a-2g4n5copenshift-gce-develinternal-debug ...
To use host binaries, run `chroot /host`
If you don't see a command prompt, try pressing enter.
sh-4.2# chroot /host
sh-4.4# audit2allow -a


sh-4.4# ausearch -m AVC
----
time->Wed Jun 30 16:39:09 2021
type=PROCTITLE msg=audit(1625071149.889:58): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1625071149.889:58): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7fa274017930 a2=4 a3=0 items=0 ppid=2533 pid=3243 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1625071149.889:58): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
----
time->Wed Jun 30 16:39:11 2021
type=PROCTITLE msg=audit(1625071151.494:59): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1625071151.494:59): arch=c000003e syscall=1 success=yes exit=3 a0=5 a1=7fa274018c80 a2=3 a3=0 items=0 ppid=2533 pid=3243 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1625071151.494:59): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
----
time->Wed Jun 30 16:39:11 2021
type=PROCTITLE msg=audit(1625071151.555:60): proctitle=2F7573722F6C6962657865632F706C6174666F726D2D707974686F6E002D4573002F7573722F7362696E2F74756E6564002D2D6E6F2D64627573
type=SYSCALL msg=audit(1625071151.555:60): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7fa27401a520 a2=4 a3=0 items=0 ppid=2533 pid=3243 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="tuned" exe="/usr/libexec/platform-python3.6" subj=system_u:system_r:spc_t:s0 key=(null)
type=AVC msg=audit(1625071151.555:60): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
sh-4.4# cd /var/log/audit
sh-4.4# cat audit.log  | grep AVC
type=AVC msg=audit(1625071149.889:58): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
type=AVC msg=audit(1625071151.494:59): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
type=AVC msg=audit(1625071151.555:60): avc:  granted  { setsecparam } for  pid=3243 comm="tuned" scontext=system_u:system_r:spc_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
sh-4.4# cat /usr/local/bin/
configure-ovs.sh  mco-hostname      
sh-4.4# cat /usr/local/bin/mco-hostname 
#!/bin/bash
# First, we need to wait until DHCP finishes and the node has a non-`localhost`
# hostname before `kubelet.service` starts.
# That's the `--wait` argument as used by `node-valid-hostname.service`.
#
# Second, on GCP specifically we truncate the hostname if it's >63 characters.
# That's `gcp-hostname.service`.

# Block indefinitely until the host gets a non-localhost name.
# Note node-valid-hostname.service uses systemd to abort if this takes too long.
wait_localhost() {
    echo "waiting for non-localhost hostname to be assigned"
    while [[ "$(< /proc/sys/kernel/hostname)" =~ (localhost|localhost.localdomain) ]];
    do
        sleep 1
    done
    echo "node identified as $(</proc/sys/kernel/hostname)"
    exit 0
}

set_aws_hostname() {
    /usr/bin/afterburn --provider aws --hostname=/run/afterburn.hostname

    local host_name=$(cat /run/afterburn.hostname)

    echo "setting transient hostname to ${host_name}"
    /bin/hostnamectl --transient set-hostname "${host_name}"
    exit 0
}

set_gcp_hostname() {
    /usr/bin/afterburn --provider gcp --hostname=/run/afterburn.hostname

    local host_name=$(cat /run/afterburn.hostname)
    local type_arg="transient"

    # /etc/hostname is used for static hostnames and is authoritative.
    # This will check to make sure that the static hostname is the
    # less than or equal to 63 characters in length.
    if [ -f /etc/hostname ] && [ "$(cat /etc/hostname | wc -m)" -gt 0 ]; then
        etc_name="$(< /etc/hostname)"
        type_arg="static"
        if [ "${etc_name}" != "${host_name}" ]; then
            echo "/etc/hostname is set to ${etc_name} but does not match ${host_name}"
            echo "using /etc/hostname as the authoritative name"
            host_name="${etc_name}"
        fi
    fi

    # Only mutate the hostname if the length is longer than 63 characters. The
    # hostname will be the lesser of 63 characters after the first dot in the
    # FQDN.  This algorithm is only known to work in GCP, and hence is only
    # executed in GCP.
    if [ "${#host_name}" -gt 63 ]; then
        alt_name=$(printf "${host_name}" | cut -f1 -d'.' | cut -c -63)
        echo "${host_name} is longer than 63 characters, using truncated hostname"
        host_name="${alt_name}"
    fi
    echo "setting ${type_arg} hostname to ${host_name}"
    /bin/hostnamectl "--${type_arg}" set-hostname "${host_name}"
    exit 0
}

arg=${1}; shift;
case "${arg}" in
    --wait) wait_localhost;;
    --gcp) set_gcp_hostname;;
    --aws) set_aws_hostname;;
    *) echo "Unhandled arg $arg"; exit 1
esac
sh-4.4# systemctl cat gcp-hostname
# /etc/systemd/system/gcp-hostname.service
[Unit]
Description=Set GCP Transient Hostname
# Removal of this file signals firstboot completion
ConditionPathExists=!/etc/ignition-machine-config-encapsulated.json
# Block services relying on networking being up.
Before=network-online.target
# Wait for NetworkManager to report it's online
After=NetworkManager-wait-online.service
# Run before hostname checks
Before=node-valid-hostname.service

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/usr/local/bin/mco-hostname --gcp

[Install]
WantedBy=multi-user.target
WantedBy=network-online.target
sh-4.4# systemctl status gcp-hostname
● gcp-hostname.service - Set GCP Transient Hostname
   Loaded: loaded (/etc/systemd/system/gcp-hostname.service; enabled; vendor preset: disabled)
   Active: active (exited) since Wed 2021-06-30 16:38:36 UTC; 18min ago
  Process: 1279 ExecStart=/usr/local/bin/mco-hostname --gcp (code=exited, status=0/SUCCESS)
 Main PID: 1279 (code=exited, status=0/SUCCESS)
    Tasks: 0 (limit: 95513)
   Memory: 0B
      CPU: 0
   CGroup: /system.slice/gcp-hostname.service

Jun 30 16:38:36 mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal systemd[1]: Starting Set GCP Transient Hostname...
Jun 30 16:38:36 mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal systemd[1]: Started Set GCP Transient Hostname.
Jun 30 16:38:36 mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal mco-hostname[1279]: Jun 30 16:38:36.243 INFO Fetching h>
Jun 30 16:38:36 mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal mco-hostname[1279]: Jun 30 16:38:36.250 INFO Fetch succ>
Jun 30 16:38:36 mnguyen499-7dpfx-worker-a-2g4n5.c.openshift-gce-devel.internal mco-hostname[1279]: setting static hostname to mnguyen4>
sh-4.4# exit
exit
sh-4.2# exit
exit

Removing debug pod ...

Comment 41 errata-xmlrpc 2021-11-01 01:24:16 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.9.0 bug fix and security update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2021:3759


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