Okd: 4.6.0-0.okd-2020-11-27-200126: NetworkManager is not checking reverse lookups when setting a hostname

[JaimeMagiera]

Describe the bug
On installation, the bootstrap process begins, but fails after the masters have restarted. I'm noticing that despite the "core" user being created on initial boot of each master, after the reboots, the "fedora" user is listed at the prompt. Attempts to ssh into the master nodes also fails, despite using the same key for creation which works to get into the bootstrap as expected. Is the Core OS install getting hosed on reboot? Since I can't get into the masters, I'm unable to get their logs.

The process I'm following is the same scripted process that has worked previously. In fact, I built a 4.5 two days ago using the process. Nothing has changed on this end that I can see.

Version

OKD: 4.6.0-0.okd-2020-11-27-200126
FCOS: fedora-coreos-32.20201104.3.0-vmware.x86_64.ova

How reproducible
Every time.

Log bundle
4.6.0-0.okd-2020-11-27-200126-Magiera.tar.gz

[vrutkovs]

Are you sure its "fedora" user, not hostname? Do you have DHCP in the setup?

[JaimeMagiera]

Ahh, yeah. You're right. It was the hostname. Sorry, I have "teething baby lack of sleep brain" at the moment. Yes, there is DHCP. It is working, as the first boot always have the correct hostname. A quick ping test shows all the nodes have the expected forward and reverse. Here's some quick logging on another install attempt...

==================== Before Installer ============================

[jmagiera@lsa-linux-dev bin]$ ./pingMasters.sh -c spiritus -w 5 -m 4
Pinging nodes for cluster: spiritus
PING master-0.spiritus.my.company.edu (10.103.2.100) 56(84) bytes of data.
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=1 ttl=63 time=0.329 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=2 ttl=63 time=0.458 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=3 ttl=63 time=0.485 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=4 ttl=63 time=0.444 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=5 ttl=63 time=0.472 ms

--- master-0.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 103ms
rtt min/avg/max/mdev = 0.329/0.437/0.485/0.060 ms
PING master-1.spiritus.my.company.edu (10.103.2.101) 56(84) bytes of data.
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=1 ttl=63 time=0.365 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=2 ttl=63 time=0.461 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=3 ttl=63 time=0.396 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=4 ttl=63 time=0.430 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=5 ttl=63 time=0.556 ms

--- master-1.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 91ms
rtt min/avg/max/mdev = 0.365/0.441/0.556/0.069 ms
PING master-2.spiritus.my.company.edu (10.103.2.102) 56(84) bytes of data.
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=1 ttl=63 time=0.357 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=2 ttl=63 time=0.552 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=3 ttl=63 time=0.469 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=4 ttl=63 time=0.452 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=5 ttl=63 time=0.508 ms

--- master-2.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 91ms
rtt min/avg/max/mdev = 0.357/0.467/0.552/0.069 ms
PING master-3.spiritus.my.company.edu (10.103.2.103) 56(84) bytes of data.
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=1 ttl=63 time=0.413 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=2 ttl=63 time=0.491 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=3 ttl=63 time=0.530 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=4 ttl=63 time=0.909 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=5 ttl=63 time=0.455 ms

--- master-3.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 68ms
rtt min/avg/max/mdev = 0.413/0.559/0.909/0.180 ms

======================================================================

Oddly, after the reboot, their hostnames are wrong, but the nodes are still ping-able at the correct address. (I can check the DHCP server logs if need be but this looks legit)

============================== During Installer ==============================

[jmagiera@lsa-linux-dev bin]$ ./pingMasters.sh -c spiritus -w 5 -m 4
Pinging nodes for cluster: spiritus
PING master-0.spiritus.my.company.edu (10.103.2.100) 56(84) bytes of data.
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=1 ttl=63 time=0.391 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=2 ttl=63 time=0.432 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=3 ttl=63 time=0.474 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=4 ttl=63 time=0.327 ms
64 bytes from master-0.spiritus.my.company.edu (10.103.2.100): icmp_seq=5 ttl=63 time=0.455 ms

--- master-0.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 113ms
rtt min/avg/max/mdev = 0.327/0.415/0.474/0.058 ms
PING master-1.spiritus.my.company.edu (10.103.2.101) 56(84) bytes of data.
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=1 ttl=63 time=0.554 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=2 ttl=63 time=0.385 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=3 ttl=63 time=0.366 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=4 ttl=63 time=0.382 ms
64 bytes from master-1.spiritus.my.company.edu (10.103.2.101): icmp_seq=5 ttl=63 time=0.377 ms

--- master-1.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 91ms
rtt min/avg/max/mdev = 0.366/0.412/0.554/0.075 ms
PING master-2.spiritus.my.company.edu (10.103.2.102) 56(84) bytes of data.
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=1 ttl=63 time=0.411 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=2 ttl=63 time=0.470 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=3 ttl=63 time=0.491 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=4 ttl=63 time=0.434 ms
64 bytes from master-2.spiritus.my.company.edu (10.103.2.102): icmp_seq=5 ttl=63 time=0.404 ms

--- master-2.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 92ms
rtt min/avg/max/mdev = 0.404/0.442/0.491/0.033 ms
PING master-3.spiritus.my.company.edu (10.103.2.103) 56(84) bytes of data.
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=1 ttl=63 time=0.406 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=2 ttl=63 time=0.424 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=3 ttl=63 time=0.459 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=4 ttl=63 time=0.475 ms
64 bytes from master-3.spiritus.my.company.edu (10.103.2.103): icmp_seq=5 ttl=63 time=0.446 ms

--- master-3.spiritus.my.company.edu ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 90ms
rtt min/avg/max/mdev = 0.406/0.442/0.475/0.024 ms

==========================

Install fails with...

ERROR Cluster operator network Degraded is True with BootstrapError: Internal error while reconciling platform networking resources: Unable to bootstrap OVN, expected amount of control plane nodes (4) do not match found (1): timed out waiting for the condition
INFO Use the following commands to gather logs from the cluster
INFO openshift-install gather bootstrap --help
FATAL failed to wait for bootstrapping to complete: timed out waiting for the condition

=========================

So, hostname is changed on reboot and nodes become unavailable to the installer. I've had limited time this morning but can dig into the logs deeper if nothing stands out to you in what I shared earlier.

[vrutkovs]

hostname changes are not rendered in the log bundle. Check NetworkManager logs

[JaimeMagiera]

After a period, I'm able to log into the nodes. Immediately after sudo'ing, I'm presented with...

[core@fedora ~]$ sudo -s
[systemd]
Failed Units: 1
gcp-hostname.service

Digging deeper...

[root@fedora core]# systemctl status gcp-hostname.service > gcp-hostname.service.log
[root@fedora core]# cat gcp-hostname.service.log
● gcp-hostname.service - Set GCP Transient Hostname
Loaded: loaded (/etc/systemd/system/gcp-hostname.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since Sat 2020-11-28 17:29:00 UTC; 6h ago
Process: 972 ExecStartPre=/usr/bin/afterburn --provider gcp --hostname=/run/afterburn.hostname (code=exited, status=1/FAILURE)
CPU: 55ms

Nov 28 17:29:00 fedora afterburn[972]: Caused by: writing hostname
Nov 28 17:29:00 fedora afterburn[972]: Caused by: maximum number of retries (10) reached
Nov 28 17:29:00 fedora afterburn[972]: Caused by: failed to fetch
Nov 28 17:29:00 fedora afterburn[972]: Caused by: error sending request for url (http://metadata.google.internal/computeMetadata/v1/instance/hostname): error trying to connect: dns error: failed to lookup address information: Name or service not known
Nov 28 17:29:00 fedora afterburn[972]: Caused by: error trying to connect: dns error: failed to lookup address information: Name or service not known
Nov 28 17:29:00 fedora afterburn[972]: Caused by: dns error: failed to lookup address information: Name or service not known
Nov 28 17:29:00 fedora afterburn[972]: Caused by: failed to lookup address information: Name or service not known
Nov 28 17:29:00 fedora systemd[1]: gcp-hostname.service: Control process exited, code=exited, status=1/FAILURE
Nov 28 17:29:00 fedora systemd[1]: gcp-hostname.service: Failed with result 'exit-code'.
Nov 28 17:29:00 fedora systemd[1]: Failed to start Set GCP Transient Hostname.

============

It's as if the installer or FCOS thinks this is a GCP node. I'll keep poking around.

[JaimeMagiera]

Perhaps a red herring, but #393 looks awfully similar to what I'm seeing.

[vrutkovs]

After a period, I'm able to log into the nodes. Immediately after sudo'ing, I'm presented with...
[core@fedora ~]$ sudo -s
[systemd]
Failed Units: 1
gcp-hostname.service

That's a minor issue - https://github.com/openshift/okd/issues/396

[rajinator]

I am seeing the same. I commented on another issue, but i think this is more relevant.

https://github.com/openshift/okd/issues/153#issuecomment-735314786
```I have a similar thing happening @vrutkovs

Release - 4.6.0-0.okd-2020-11-27-200126

FCOS image - 32.20201104.3.0 stable

I have a dhcp server setup to give out hostnames. Bootstrap as well as the 3 node-cluster nodes
lose hostname after reboot. Bootkube service goes into restart loop on bootstrap after a while,
workers kubelet error message says node "fedora" not found.
```

This also happens after installing a 4.5 cluster, and then upgrading to 4.6, as a result of which the nodes hostnames changed to fedora after reboot. So I had to manually set hostnames, even though DHCP was handing them out

[vrutkovs]

I have a dhcp server setup to give out hostnames
...
kubelet error message says node "fedora" not found

kubelet is using hostname as identifier. Did the node receive an expected hostname?

[JaimeMagiera]

Looking at the NetworkManager log, I don't see anything out of the ordinary, just typical DORA with the DHCP server. I'm curious why the nodes were not immediately accessible after reboot. It seemed to take some time. Edit: And even after requesting and accepting the IP and the hostname, it doesn't update the hostname.

OKD-ISSUE394-NetworkManager.log

[vrutkovs]

On one of my nodes I also have

Nov 29 11:01:23 neptr.vrutkovs.eu NetworkManager[900]: <info>  [1606647683.4489] hostname: hostname: using hostnamed
Nov 29 11:01:23 neptr.vrutkovs.eu NetworkManager[900]: <info>  [1606647683.4490] hostname: hostname changed from (none) to "neptr.vrutkovs.eu"

[rajinator]

@vrutkovs nope, only stuck with fedora, and the likely red herring failed gcp-hostname.service which i disabled. The IP was correct on all of them, so the only thing they didn't accept from DHCP was the hostname

[rajinator]

As an added note, it only happens after the part where the nodes' FCOS version is updated

[JaimeMagiera]

Indeed. Looking at the systemd-hostnamed logs, the first call to it on the initial boot sets the hostname as expected. However, on subsequent launches it's not reset. This would leave me to believe that either systemd-hostnamed is not getting a pertinent piece of information to trigger a reset and/or another service is changing the hostname. I think that depends on if FCOS hosts are expected to maintain hostname after an update-triggered reboot, or if they default to "fedora" again unless/until DHCP provides a hostname again or static IP/hostname were implemented.

[root@fedora core]# journalctl -u systemd-hostnamed
-- Logs begin at Sat 2020-11-28 17:14:37 UTC, end at Mon 2020-11-30 01:48:48 UTC. --
Nov 28 17:21:01 localhost systemd[1]: Starting Hostname Service...
Nov 28 17:21:01 localhost systemd[1]: Started Hostname Service.
Nov 28 17:21:02 master-1.spiritus.my.company.edu systemd-hostnamed[2528]: Changed host name to 'master-1.spiritus.my.company.edu'
Nov 28 17:21:32 master-1.spiritus.my.company.edu systemd[1]: systemd-hostnamed.service: Succeeded.
-- Reboot --
Nov 28 17:28:16 fedora systemd[1]: Starting Hostname Service...
Nov 28 17:28:17 fedora systemd[1]: Started Hostname Service.
Nov 28 17:28:47 fedora systemd[1]: systemd-hostnamed.service: Succeeded.
Nov 28 23:57:18 fedora systemd[1]: Starting Hostname Service...
Nov 28 23:57:18 fedora systemd[1]: Started Hostname Service.
Nov 28 23:57:48 fedora systemd[1]: systemd-hostnamed.service: Succeeded.
Nov 30 01:44:46 fedora systemd[1]: Starting Hostname Service...
Nov 30 01:44:46 fedora systemd[1]: Started Hostname Service.
Nov 30 01:45:16 fedora systemd[1]: systemd-hostnamed.service: Succeeded.

[klzsysy]

same here

4.5 upgrade to 4.6, it only happens after the part where the nodes' FCOS version is updated

❯ oc get node
NAME                                   STATUS                        ROLES    AGE     VERSION
manage-dev-gzrpk-master-0              Ready                         master   6d21h   v1.19.0-rc.2+9f84db3-1075
manage-dev-gzrpk-master-1              Ready                         master   6d21h   v1.18.3
manage-dev-gzrpk-master-2              Ready                         master   6d21h   v1.18.3
manage-dev-gzrpk-worker-9vhmd          Ready                         worker   6d21h   v1.18.3
manage-dev-gzrpk-worker-n59h2          Ready                         worker   6d21h   v1.18.3
manage-dev-gzrpk-worker-t8b6m          Ready                         worker   6d21h   v1.19.0-rc.2+9f84db3-1075
master01.manage-dev.oc4.forchange.cn   NotReady,SchedulingDisabled   master   6d22h   v1.18.3
master02.manage-dev.oc4.forchange.cn   Ready                         master   6d22h   v1.18.3
master03.manage-dev.oc4.forchange.cn   Ready                         master   6d22h   v1.18.3
worker01.manage-dev.oc4.forchange.cn   Ready                         worker   6d21h   v1.18.3
worker02.manage-dev.oc4.forchange.cn   Ready                         worker   6d21h   v1.18.3
worker03.manage-dev.oc4.forchange.cn   Ready                         worker   6d21h   v1.18.3
worker04.manage-dev.oc4.forchange.cn   Ready                         worker   6d21h   v1.18.3
worker05.manage-dev.oc4.forchange.cn   NotReady,SchedulingDisabled   worker   6d21h   v1.18.3
worker06.manage-dev.oc4.forchange.cn   Ready                         worker   6d21h   v1.18.3

[root@fedora ~]# hostname
fedora
[root@fedora ~]#  journalctl -u systemd-hostnamed
-- Logs begin at Mon 2020-11-23 07:26:03 UTC, end at Mon 2020-11-30 06:13:29 UTC. --
11月 23 07:50:13 localhost systemd[1]: Starting Hostname Service...
11月 23 07:50:13 localhost systemd[1]: Started Hostname Service.
11月 23 07:50:13 worker05.manage-dev.oc4.forchange.cn systemd-hostnamed[1042]: Changed host name to 'worker05.manage-dev.oc4.forchange.cn'
11月 23 07:50:36 worker05.manage-dev.oc4.forchange.cn systemd[1]: systemd-hostnamed.service: Succeeded.
-- Reboot --
11月 23 08:00:09 localhost systemd[1]: Starting Hostname Service...
11月 23 08:00:09 localhost systemd[1]: Started Hostname Service.
11月 23 08:00:09 worker05.manage-dev.oc4.forchange.cn systemd-hostnamed[742]: Changed host name to 'worker05.manage-dev.oc4.forchange.cn'
11月 23 08:00:40 worker05.manage-dev.oc4.forchange.cn systemd[1]: systemd-hostnamed.service: Succeeded.
-- Reboot --
11月 30 04:35:29 fedora systemd[1]: Starting Hostname Service...
11月 30 04:35:29 fedora systemd[1]: Started Hostname Service.
11月 30 04:35:52 fedora systemd[1]: systemd-hostnamed.service: Succeeded.
11月 30 06:04:19 fedora systemd[1]: Starting Hostname Service...
11月 30 06:04:19 fedora systemd[1]: Started Hostname Service.
11月 30 06:04:52 fedora systemd[1]: systemd-hostnamed.service: Succeeded.

[klzsysy]

Resume normal work after manually set the hostname

[klzsysy]

Seems to be failed are FQDN host...

[dustymabe]

Looking at the NetworkManager log, I don't see anything out of the ordinary, just typical DORA with the DHCP server. I'm curious why the nodes were not immediately accessible after reboot. It seemed to take some time. Edit: And even after requesting and accepting the IP and the hostname, it doesn't update the hostname.

OKD-ISSUE394-NetworkManager.log

In your NetworkManager logs I don't see where the DHCP response included the host name. I would have expected something like:

NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option dhcp_lease_time      => '3600'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option domain_name          => 'ec2.internal'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option domain_name_servers  => '10.0.0.2'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option expiry               => '1606176868'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option host_name            => 'ip-10-0-1-155'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option interface_mtu        => '9001'
NetworkManager[629]: <info>  [1606173268.0436] dhcp4 (eth0): option ip_address           => '10.0.1.155'

I imagine you're relying on reverse DNS lookups. I just did some digging and yeah, this used to work. See https://github.com/coreos/fedora-coreos-tracker/issues/649#issuecomment-736104003

[JaimeMagiera]

For folks following along in their hymnals, Dusty asked me to try bringing up a straight FCOS 33 (no OKD) node with DHCP. Sure enough, the failure remained.

====================================

[jaimelm1@lsa-linux-dev fcos]$ host fcos-33-test.my.company.edu
fcos-33-test.my.company.edu has address xxx.xxx.xxx.xxx
[jaimelm1@lsa-linux-dev fcos]$ ssh -i ~/.ssh/coreadmin_rsa [email protected]
Tracker: https://github.com/coreos/fedora-coreos-tracker
Discuss: https://discussion.fedoraproject.org/c/server/coreos/

Last login: Mon Nov 30 22:53:36 2020 from xxx.xxx.xxx.xxx
[core@fedora ~]$ hostname
fedora

===========================================================

Following all the threads, it's an issue of Network Manager not falling back onto the reverse lookup due to the ordering of precedence. "Is it something other than localhost?" comes before reverse look-ups – and since the Fedora desktop folks in their infinite wisdom wanted to brand workstations by setting hostname to "fedora" when the hostname wasn't explicitly defined, here we are.

I hope the re-order makes it into Network Manager. There are a lot of services, both internal and external, that rely on proper reverse lookups. It seems to me that reverse should be higher up in the precedence.

Thanks for all the legwork on this Dusty.

[JaimeMagiera]

As an aside, I wrote a quick script to reset hostnames on nodes that were changed to "fedora". Nothing fancy, but it simplifies the process if you have a lot of nodes to fix.

https://github.com/JaimeMagiera/oct/blob/master/repairClusterHostnames.sh

[vrutkovs]

Following all the threads, it's an issue of Network Manager not falling back onto the reverse lookup due to the ordering of precedence. "Is it something other than localhost?" comes before reverse look-ups – and since the Fedora desktop folks in their infinite wisdom wanted to brand workstations by setting hostname to "fedora" when the hostname wasn't explicitly defined, here we are.

Seems NetworkManager expects localhost to be transient and doesn't fall back to reverse lookup? Do we have Fedora bug filed?

[JaimeMagiera]

Update: I've successfully gotten past the installation stage by adding hostname entries into my DHCP configuration (DHCP client option code 12). We use BlueCat here. So, it involved a lot of clicks and was quite tedious. This isn't really a way forward for production environments. It could mean incongruity and breakage if, when needing to change hostnames, the DNS is updated but DHCP is not or vice-verse.

Vadim, there is this...

https://bugzilla.redhat.com/show_bug.cgi?id=1892235#c9

There is a patch pending that reorders the precedence of hostname checks, putting reverse DNS higher up. If we could get that moved along somehow. Another bug report would just be marked as duplicate, maybe?

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/09c8387

[vrutkovs]

Gotcha, so we need NM 1.29.2+ to test the commit

[dustymabe]

@JaimeMagiera - I got a build of FCOS with an updated NM (based off of the CI builds done in copr). Do you mind trying it by itself similar to how you did in https://github.com/openshift/okd/issues/394#issuecomment-736170526 and see if the reverse DNS bits work now?

https://dustymabe.fedorapeople.org/fedora-coreos-33.20201201.dev.1-vmware.x86_64.ova

[JaimeMagiera]

@dustymabe You sir, are a scholar and a gentleman. Thank you.

[jaimelm1@lsa-linux-dev fcos]$ ssh -t [email protected] "sudo hostnamectl status"
Static hostname: n/a
Transient hostname: fcos-33-test.my.company.edu
Icon name: computer-vm
Chassis: vm
Machine ID: 228cab6cf9d34ad6afb405a6c14abaa9
Boot ID: 9645fbc52fce4b988d7c6d9bd81f4e67
Virtualization: vmware
Operating System: Fedora CoreOS 33.20201201.dev.1
CPE OS Name: cpe:/o:fedoraproject:fedora:33
Kernel: Linux 5.9.11-200.fc33.x86_64
Architecture: x86-64

[dustymabe]

@JaimeMagiera - just checking, was that system getting the hostname from DHCP too, or did you revert those changes on the DHCP server so we could verify the reverse DNS lookups were working?

[JaimeMagiera]

The DHCP server changes that I mentioned above have to be implemented on a per-host basis (which is why its so tedious). I did not implement that change on this testing host, only on my OKD cluster nodes. So, indeed, the success of this testing VM is due to your inclusion of the updated NM.

[dustymabe]

Do you mind sharing the NM logs from that boot? Something like journalctl -b 0 ?

Also the output of:

• grep hosts /etc/nsswitch.conf
• systemctl is-active systemd-resolved
• systemctl is-enabled systemd-resolved

[fortinj66]

This is maybe unrelated, but when I install 4.6 IPI on VMWare I also have the hostname set to fedora. I am using DHCP but not assigning hostnames. the hostnames are (should) being assigned via the vmware vm name via vsphere-hostname.service
which calls /usr/local/bin/vsphere-hostname.sh which only exists after vmtools is installed.

#!/usr/bin/env bash
set -e
if [ $(hostname -s) = "localhost" ]; then
  if hostname=$(/bin/vmtoolsd --cmd 'info-get guestinfo.hostname'); then
      /usr/bin/hostnamectl --transient --static set-hostname ${hostname}
  fi
fi 

Note that it only gets changed if the current hostname is localhost

Here is the result after the node comes up and reboots:

journalctl -u vsphere-hostname.service
-- Logs begin at Wed 2020-12-02 20:30:44 UTC, end at Wed 2020-12-02 20:44:52 UTC. --
Dec 02 20:33:51 localhost systemd[1]: Started vSphere hostname.
Dec 02 20:33:51 localhost vsphere-hostname.sh[1717]: /usr/local/bin/vsphere-hostname.sh: line 5: /bin/vmtoolsd: No such file or directory
Dec 02 20:33:51 localhost systemd[1]: vsphere-hostname.service: Succeeded.
-- Reboot --
Dec 02 20:41:19 fedora systemd[1]: Started vSphere hostname.
Dec 02 20:41:19 fedora systemd[1]: vsphere-hostname.service: Succeeded.

When /usr/local/bin/vsphere-hostname.sh runs after the reboot, the hostname has already been changed to fedora and so the test fails and the hostname does not get changed...

[dustymabe]

Thanks for the info. I added that datapoint to the existing bug: https://bugzilla.redhat.com/show_bug.cgi?id=1892235#c11

So in your journalctl output, the first run is from before FCOS was upgraded to F33 where the hostname was localhost. In that case it did pass the if statement conditional logic but failed to set the hostname because there is no file at /bin/vmtoolsd. You might want to fix the script because it won't work even if the localhost versus fedora issue didn't exist.

[fortinj66]

You might want to fix the script because it won't work even if the localhost versus fedora issue didn't exist.

I'm not sure who owns the vsphere-hostname.service and /usr/local/bin/vsphere-hostname.sh. As far as I can tell it comes with FCOS

Looks like /bin/vmtoolsd comes with vmtools (?) package

[dustymabe]

not part of FCOS, maybe OKD is layering it in. A good indicator is the fact that the file is in /usr/local/bin/.

[fortinj66]

not part of FCOS, maybe OKD is layering it in. A good indicator is the fact that the file is in /usr/local/bin/.

That could be true... I'm not sure... I'll check the service file and see what it says

[fortinj66]

Yes, It's added during ignition:

[root@fedora etc]# journalctl  -u ignition-files.service  | grep vsphere-hostname
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: createFilesystemsFiles: createFiles: op(1f): [started]  writing file "/sysroot/var/usrlocal/bin/vsphere-hostname.sh"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: createFilesystemsFiles: createFiles: op(1f): [finished] writing file "/sysroot/var/usrlocal/bin/vsphere-hostname.sh"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(4b): [started]  processing unit "vsphere-hostname.service"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(4b): op(4c): [started]  writing unit "vsphere-hostname.service" at "/sysroot/etc/systemd/system/vsphere-hostname.service"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(4b): op(4c): [finished] writing unit "vsphere-hostname.service" at "/sysroot/etc/systemd/system/vsphere-hostname.service"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(4b): [finished] processing unit "vsphere-hostname.service"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(52): [started]  setting preset to enabled for "vsphere-hostname.service"
Dec 02 21:38:59 localhost ignition[1430]: INFO     : files: op(52): [finished] setting preset to enabled for "vsphere-hostname.service"

[fortinj66]

https://github.com/openshift/okd/issues/407#issuecomment-737520891

[JaimeMagiera]

@dustymabe Actually, it's not working. When I went to collect the NM log (journalctl -u NetworkManager), I noticed there were "option host_name" responses. Sure enough, when I went to BlueCat (DHCP and DNS system), the client DHCP option was set further up in configuration, attached to the IP as opposed to the MAC address where I usually do it (will have to investigate how that happens). I just did a fresh vm with new IP and MAC address. The build fails to get the hostname. So, it looks like we're not there yet.

[pflaeging]

I've got the problem with false hostnames since first installing OKD 4 (4.3) due to a funny behaviour of my KVM provider. They always showing up in DHCP with something like server1234433.myprovider.com. I've changed the DNS back resolving and everything else, but FCOS is not using the right name.

Here's my solution for the problem:

• Generate an ignition for every node and add the following config at the end:

storage:
  files:
    - path: /etc/hostname
      mode: 0420
      overwrite: true
      contents:
        inline: mynodename.should.be.filled.in.here

• Replace mynodename... with your real nodename
• Generate the ignition with fcct
• Be sure to use the right ignition for every node (either in bootp or static)

This is not a solution, but more a workaround for the problem, but it works for me.

:peter

[JaimeMagiera]

Great find @fortinj66.

My concern with the vsphere-hostname.service, and the upstream changes to systemd which started this debacle, is that for decades incorrect hostname has been a telltale sign of network problems and/or misconfigured DNS. When you open a shell or glance at the console and see "localhost", or "xyz-some-department-that-no-longer-exists", you know that the host is either not on the network or that DNS is misconfigured/stale. In addition to breaking a bunch of things, changing that functionality removes a helpful signpost.

[dustymabe]

My concern with the vsphere-hostname.service, and the upstream changes to NetworkManager which started this debacle,

Slight correction. NetworkManager didn't change. There are a few things that happened in Fedora 33 that are causing some growing pains. In Fedora the systemd team changed to use fedora as the fallback hostname instead of localhost. At the same time there was also a system wide change to use systemd-resolved and there was a subsequent change make to nsswitch.conf to add in resolve and it also lowered the priority of dns to later than myhostname. Unfortunately it's several changes that are compounding.

[JaimeMagiera]

Fixed.

[dustymabe]

@dustymabe Actually, it's not working. When I went to collect the NM log (journalctl -u NetworkManager), I noticed there were "option host_name" responses. Sure enough, when I went to BlueCat (DHCP and DNS system), the client DHCP option was set further up in configuration, attached to the IP as opposed to the MAC address where I usually do it (will have to investigate how that happens). I just did a fresh vm with new IP and MAC address. The build fails to get the hostname. So, it looks like we're not there yet.

On that fresh VM can you give me the output of:

• grep hosts /etc/nsswitch.conf
• systemctl is-active systemd-resolved
• systemctl is-enabled systemd-resolved
• rpm-ostree status

[JaimeMagiera]

I destroyed it last night while writing a testing system of this issue. (Script that downloads an ova from URL, installs the template in vSphere, spins up a host with predesigned .ign, and runs the hostname tests. If it fails, I get zipped files of the various logs) I'll add your items to my script and get that for you.

[LorbusChris]

I wonder if we then still need this PR: https://github.com/openshift/machine-config-operator/pull/2282

[fortinj66]

I wonder if we then still need this PR: openshift/machine-config-operator#2282

I don't think the NM changes fix the issues in my case where we are not using DHCP for Hostnames... I get the hostnames directly from vSphere and this will fail without the check for the fedora hostname change...

[alexanderniebuhr]

Does seem that it changed to fedora, however my hostnames are set correctly after reboot, but it might be too late. As I have same issues

[JaimeMagiera]

@dustymabe Today was quite busy. Sorry for the delay.

Timestamp: 12-03-20-225253
FQDN: fcos-33-test.lsait.lsa.umich.edu
Transient Name: fedora
Transient hostname does not match DNS name
========== Grabbing hosts from nswitch ==========

Valid databases are: aliases, ethers, group, gshadow, hosts,

hosts: files resolve [!UNAVAIL=return] myhostname dns
========== Checking active status of systemd-resolved ==========
active
========== Checking enabled status of systemd-resolved ==========
enabled
========== Checking rpm-ostree status ==========
State: idle
Deployments:
● ostree://fedora:fedora/x86_64/coreos/testing-devel
Version: 33.20201201.dev.1 (2020-12-01T17:14:54Z)
Commit: 05261ad8abe86bce155ec1b47dcc3c20b7d127a7af4d3382150c726c948303dc
GPGSignature: (unsigned)

[JaimeMagiera]

If anyone else wants to test this issue quickly as new builds are made, they can grab this script. It outputs to file and console for easy pasting in here.

https://github.com/JaimeMagiera/oct/blob/master/test-hostname.sh

[JaimeMagiera]

This issue appears to be addressed for vSphere UPI installs.