Okd: Hardlinking <....>.file to VGAuthService: File exists

[kai-uwe-rommel]

Describe the bug
I have a cluster at 4.6.0-0.okd-2020-12-12-135354, it was previously upgrade already 7 times from earlier OKD releases and this was always successful. Now I am trying to upgrade to the new 4.6.0-0.okd-2021-01-17-185703 but it fails.
All but the MCO are done but the MCO does not progress. I saw that it set a worker (and a master) to SchedulingDisabled but then nothing happened over a long period of time. I decided to reboot the nodes in question but soon thereafter the same worker is in SchedulingDisabled state again and nothing happens.

Also, since the upgrade any AD/LDAP login fails with internal server error 500 but this may be unrelated and I'll open a separate issue for this

Version
4.6.0-0.okd-2020-12-12-135354 to 4.6.0-0.okd-2021-01-17-185703

How reproducible
See above.

Log bundle
Unfortunately, must-gather fails:

$ oc adm must-gather
[must-gather      ] OUT Using must-gather plugin-in image: quay.io/openshift/okd-content@sha256:c46390d74c9ac6152264da87b5667eacc42871cf4eb9ab444cd953ae56b81b07
[must-gather      ] OUT namespace/openshift-must-gather-lb75x created
[must-gather      ] OUT clusterrolebinding.rbac.authorization.k8s.io/must-gather-zz8lq created
[must-gather      ] OUT pod for plug-in image quay.io/openshift/okd-content@sha256:c46390d74c9ac6152264da87b5667eacc42871cf4eb9ab444cd953ae56b81b07 created
[must-gather-vfwbk] OUT gather did not start: Get https://api.devqs.ars.de:6443/api/v1/namespaces/openshift-must-gather-lb75x/pods/must-gather-vfwbk: unexpected EOF [must-gather      ] OUT clusterrolebinding.rbac.authorization.k8s.io/must-gather-zz8lq deleted
[must-gather      ] OUT namespace/openshift-must-gather-lb75x deleted
error: gather did not start for pod must-gather-vfwbk: Get https://api.devqs.ars.de:6443/api/v1/namespaces/openshift-must-gather-lb75x/pods/must-gather-vfwbk: unexpected EOF

[kai-uwe-rommel]

I checked with journalctl to see what the SchedulingDisabled worker does all the time and found that it is looping with failing rpm-ostree attempts:

Jan 19 12:42:59 worker-01.devqs.ars.de rpm-ostree[96916]: client(id:machine-config-operator dbus:1.432 unit:crio-f1cec2ed1f6a38ad5afe618d6f044ee7d999d001128648296cb0c1795636b8ac.scope uid:0) added; new total=1
Jan 19 12:42:59 worker-01.devqs.ars.de rpm-ostree[96916]: client(id:machine-config-operator dbus:1.432 unit:crio-f1cec2ed1f6a38ad5afe618d6f044ee7d999d001128648296cb0c1795636b8ac.scope uid:0) vanished; remaining=0
Jan 19 12:42:59 worker-01.devqs.ars.de rpm-ostree[96916]: In idle state; will auto-exit in 63 seconds
Jan 19 12:43:01 worker-01.devqs.ars.de rpm-ostree[96916]: client(id:machine-config-operator dbus:1.434 unit:crio-f1cec2ed1f6a38ad5afe618d6f044ee7d999d001128648296cb0c1795636b8ac.scope uid:0) added; new total=1
Jan 19 12:43:01 worker-01.devqs.ars.de rpm-ostree[96916]: Locked sysroot
Jan 19 12:43:01 worker-01.devqs.ars.de rpm-ostree[96916]: Initiated txn UpdateDeployment for client(id:machine-config-operator dbus:1.434 unit:crio-f1cec2ed1f6a38ad5afe618d6f044ee7d999d001128648296cb0c1795636b8ac.scope uid:0): /org/projectatomic/rpmostree1/fedora_coreos
Jan 19 12:43:03 worker-01.devqs.ars.de rpm-ostree[96916]: warning: Found bdb Packages database while attempting sqlite backend: using bdb backend.
Jan 19 12:43:03 worker-01.devqs.ars.de rpm-ostree[96916]: Librepo version: 1.12.1 with CURL_GLOBAL_ACK_EINTR support (libcurl/7.71.1 OpenSSL/1.1.1h-fips zlib/1.2.11 brotli/1.0.9 libidn2/2.3.0 libpsl/0.21.1 (+libidn2/2.3.0) libssh/0.9.5/openssl/zlib nghttp2/1.41.0)
Jan 19 12:43:03 worker-01.devqs.ars.de rpm-ostree[96916]: warning: Found bdb Packages database while attempting sqlite backend: using bdb backend.
Jan 19 12:43:05 worker-01.devqs.ars.de rpm-ostree[96916]: warning: Found bdb Packages database while attempting sqlite backend: using bdb backend.
Jan 19 12:43:07 worker-01.devqs.ars.de rpm-ostree[96916]: Preparing pkg txn; enabled repos: ['fedora-cisco-openh264', 'updates', 'fedora', 'coreos-extensions', 'updates-archive'] solvables: 93213
Jan 19 12:43:08 worker-01.devqs.ars.de rpm-ostree[96916]: warning: Found bdb Packages database while attempting sqlite backend: using bdb backend.
Jan 19 12:43:08 worker-01.devqs.ars.de rpm-ostree[96916]: Txn UpdateDeployment on /org/projectatomic/rpmostree1/fedora_coreos failed: Checkout open-vm-tools-11.2.5-1.fc33.x86_64: Hardlinking 57/2d1e0a8b85be28856aa9655c6ef42462a8aabdc30868f3a7a910bfa0f8dd3d.file to VGAuthService: File exists
Jan 19 12:43:08 worker-01.devqs.ars.de rpm-ostree[96916]: Unlocked sysroot
Jan 19 12:43:08 worker-01.devqs.ars.de rpm-ostree[96916]: client(id:machine-config-operator dbus:1.434 unit:crio-f1cec2ed1f6a38ad5afe618d6f044ee7d999d001128648296cb0c1795636b8ac.scope uid:0) vanished; remaining=0
Jan 19 12:43:08 worker-01.devqs.ars.de rpm-ostree[96916]: In idle state; will auto-exit in 60 seconds

Is there something I can do manually to fix this?

[kai-uwe-rommel]

A co-worker checked/researched/experimented with the cluster and removed the open-vm-tools from the cluster nodes. Then the MCO made progress and updated successfully all worker nodes. The vSphere persistent volumes still work and vSphere integration also works after enabling/starting the vmtoolsd service.
However, the master nodes still are not updated, and we can not see any progress there.

[ssams]

I ran into the same situation (same versions, but I didn't experience the mentioned LDAP issues).
The line Checkout open-vm-tools-11.2.5-1.fc33.x86_64: Hardlinking 57/2d1e0a8b85be28856aa9655c6ef42462a8aabdc30868f3a7a910bfa0f8dd3d.file to VGAuthService: File exists seems to be crucial here, I had exactly the same entry in the logs.

Manually removing the open-vm-tools on all nodes seems to solve the problem - in my case the master nodes continued automatically after the removal, the MCO upgrade completed without further actions.

[kai-uwe-rommel]

Yes, it only took the MCO a while of thinking before it also upgraded the masters of our cluster.
So the upgrade is done now.

(But the AD/LDAP problem persists but that is another issue.)

[vrutkovs]

See https://github.com/openshift/okd-machine-os/pull/63

[klzsysy]

remove open-vm-tools invalid, a new error

[root@master02 ~]# rpm-ostree uninstall open-vm-tools
Checking out tree d2e23f9... done
Resolving dependencies... done
Relabeling... done
Checking out packages... done
Running pre scripts... done
Running post scripts... done
Running posttrans scripts... done
Writing rpmdb... done
Writing OSTree commit... done
Staging deployment... done
Freed: 1.4 GB (pkgcache branches: 7)
Upgraded:
  gdbm-libs 1:1.18.1-5.fc33 -> 1:1.19-1.fc33
  python-unversioned-command 3.9.0-1.fc33 -> 3.9.1-1.fc33
  python3 3.9.0-1.fc33 -> 3.9.1-1.fc33
  python3-libs 3.9.0-1.fc33 -> 3.9.1-1.fc33
  qemu-guest-agent 2:5.1.0-8.fc33 -> 2:5.1.0-9.fc33
Removed:
  libdrm-2.4.102-2.fc33.x86_64
  libmspack-0.10.1-0.4.alpha.fc33.x86_64
  libpciaccess-0.16-3.fc33.x86_64
  libtool-ltdl-2.4.6-36.fc33.x86_64
  libxslt-1.1.34-4.fc33.x86_64
  open-vm-tools-11.2.0-1.fc33.x86_64
  xmlsec1-1.2.29-2.fc33.x86_64
  xmlsec1-openssl-1.2.29-2.fc33.x86_64
Run "systemctl reboot" to start a reboot
[root@master02 ~]#
[root@master02 ~]#
[root@master02 ~]# rpm -qa | grep open-vm-tools
warn：Found bdb Packages database while attempting sqlite backend: using bdb backend.
open-vm-tools-11.2.0-1.fc33.x86_64
[root@master02 ~]#
[root@master02 ~]#
[root@master02 ~]# systemctl reboot

# oc -n openshift-machine-config-operator logs machine-config-daemon-666bs machine-config-daemon -f
I0120 14:09:24.584661    6816 start.go:108] Version: machine-config-daemon-4.6.0-202006240615.p0-374-ga72f402c-dirty (a72f402cce4a683d4f9ba3956b5dcd297b458a54)
I0120 14:09:24.588389    6816 start.go:121] Calling chroot("/rootfs")
I0120 14:09:24.588516    6816 rpm-ostree.go:261] Running captured: rpm-ostree status --json
I0120 14:09:24.678275    6816 daemon.go:226] Booted osImageURL: quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829 ()
I0120 14:09:24.689869    6816 daemon.go:233] Installed Ignition binary version: 2.8.1
I0120 14:09:24.718133    6816 start.go:97] Copied self to /run/bin/machine-config-daemon on host
I0120 14:09:24.720604    6816 metrics.go:106] Registering Prometheus metrics
I0120 14:09:24.720710    6816 metrics.go:111] Starting metrics listener on 127.0.0.1:8797
I0120 14:09:24.728387    6816 update.go:1661] Starting to manage node: master02.manage-dev.oc4.forchange.cn
I0120 14:09:24.735549    6816 rpm-ostree.go:261] Running captured: rpm-ostree status
I0120 14:09:24.795731    6816 daemon.go:862] State: idle
Deployments:
* pivot://quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829
              CustomOrigin: Managed by machine-config-operator
                 Timestamp: 2020-12-12T05:05:37Z
           LayeredPackages: NetworkManager-ovs glusterfs glusterfs-fuse qemu-guest-agent

  pivot://quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829
              CustomOrigin: Managed by machine-config-operator
                 Timestamp: 2020-12-12T05:05:37Z
           LayeredPackages: NetworkManager-ovs glusterfs glusterfs-fuse open-vm-tools
                            qemu-guest-agent
I0120 14:09:24.795851    6816 rpm-ostree.go:261] Running captured: journalctl --list-boots
I0120 14:09:24.819288    6816 daemon.go:869] journalctl --list-boots:
-2 e195922e5b754a109b75474436df49f4 Mon 2021-01-18 20:48:14 UTC—Wed 2021-01-20 13:51:50 UTC
-1 01309413d4ab4dedbafd6e2640c94cf2 Wed 2021-01-20 13:54:53 UTC—Wed 2021-01-20 14:06:21 UTC
 0 e887d707d6084137b2ed56822f74b013 Wed 2021-01-20 14:07:06 UTC—Wed 2021-01-20 14:09:24 UTC
I0120 14:09:24.819316    6816 rpm-ostree.go:261] Running captured: systemctl list-units --state=failed --no-legend
I0120 14:09:24.830462    6816 daemon.go:884] systemd service state: OK
I0120 14:09:24.830576    6816 daemon.go:616] Starting MachineConfigDaemon
I0120 14:09:24.830827    6816 daemon.go:623] Enabling Kubelet Healthz Monitor
I0120 14:09:25.750968    6816 daemon.go:397] Node master02.manage-dev.oc4.forchange.cn is part of the control plane
I0120 14:09:25.794465    6816 daemon.go:815] Current config: rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:25.794512    6816 daemon.go:816] Desired config: rendered-master-27b5838883d09dd7eb035dc624c8ca11
I0120 14:09:25.808052    6816 update.go:1661] Disk currentConfig rendered-master-27b5838883d09dd7eb035dc624c8ca11 overrides node's currentConfig annotation rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:25.811130    6816 daemon.go:1085] Validating against current config rendered-master-27b5838883d09dd7eb035dc624c8ca11
E0120 14:09:25.811199    6816 writer.go:135] Marking Degraded due to: unexpected on-disk state validating against rendered-master-27b5838883d09dd7eb035dc624c8ca11: expected target osImageURL "quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c", have "quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829"
I0120 14:09:27.841136    6816 daemon.go:815] Current config: rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:27.841190    6816 daemon.go:816] Desired config: rendered-master-27b5838883d09dd7eb035dc624c8ca11
I0120 14:09:27.853565    6816 update.go:1661] Disk currentConfig rendered-master-27b5838883d09dd7eb035dc624c8ca11 overrides node's currentConfig annotation rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:27.856244    6816 daemon.go:1085] Validating against current config rendered-master-27b5838883d09dd7eb035dc624c8ca11
E0120 14:09:27.856385    6816 writer.go:135] Marking Degraded due to: unexpected on-disk state validating against rendered-master-27b5838883d09dd7eb035dc624c8ca11: expected target osImageURL "quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c", have "quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829"
I0120 14:09:31.878608    6816 daemon.go:815] Current config: rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:31.878683    6816 daemon.go:816] Desired config: rendered-master-27b5838883d09dd7eb035dc624c8ca11
I0120 14:09:31.890954    6816 update.go:1661] Disk currentConfig rendered-master-27b5838883d09dd7eb035dc624c8ca11 overrides node's currentConfig annotation rendered-master-18f16c1426810c6c3235ea1a1a08b07d
I0120 14:09:31.895787    6816 daemon.go:1085] Validating against current config rendered-master-27b5838883d09dd7eb035dc624c8ca11
E0120 14:09:31.895889    6816 writer.go:135] Marking Degraded due to: unexpected on-disk state validating against rendered-master-27b5838883d09dd7eb035dc624c8ca11: expected target osImageURL "quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c", have "quay.io/openshift/okd-content@sha256:95034a94e28949af41a53b9efb2fbb0651454a7c37bab002b0646e73c4721829"

[Reamer]

I now have a similar situation as @klzsysy.
Does anyone have any idea where the osImageURL quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c came from?

[effrafax]

If the master node is in a degraded state and complains with "Marking Degraded due to: unexpected on-disk state", try the following on the master node:
/run/bin/machine-config-daemon pivot "quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c"

[Reamer]

Thank you the command helped me. After changing some other files to the desired state, the upgrade of my cluster was successful.

[kai-uwe-rommel]

What other files did you need to change to "desired state"?

[Reamer]

In my case:

• /var/lib/kubelet/config.json, twice because I run into #264, but https://github.com/openshift/okd/issues/264#issuecomment-704087624 was very helpful
• /usr/local/bin/configure-ovs.sh
• /usr/local/bin/vsphere-hostname.sh

The machine-config-daemon pod should give you the information which files did not match.

[ibotty]

I only wanted to note, that I only had to rpm-ostree uninstall open-vm-tools at one point on the nodes. A reboot was not necessary.

[biggtimber]

In my case:

* `/var/lib/kubelet/config.json`, twice because I run into #264, but [#264 (comment)](https://github.com/openshift/okd/issues/264#issuecomment-704087624) was very helpful

* `/usr/local/bin/configure-ovs.sh`

* `/usr/local/bin/vsphere-hostname.sh`

The machine-config-daemon pod should give you the information which files did not match.

Where is the 'desired state' referenced? I don't see from that issue you linked where the desired state is set.

[biggtimber]

Found this solution stating that there needs to be an octal 0 before the mode numbers in the machine configs. at least with the error that I'm seeing in relation to the 'configure-ovs.sh' file. could this be a possible fix?

https://access.redhat.com/solutions/4773161

[johnlongo]

Here is what I'm seeing in the nodes:

Failed Units: 1
ovs-configuration.service
[core@okd4-compute-0 ~]$
[core@okd4-compute-0 ~]$
[core@okd4-compute-0 ~]$ systemctl status ovs-configuration
● ovs-configuration.service - Configures OVS with proper host networking configuration
Loaded: loaded (/etc/systemd/system/ovs-configuration.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since Fri 2021-01-22 13:02:21 UTC; 1h 42min ago
Process: 810 ExecStart=/usr/local/bin/configure-ovs.sh OpenShiftSDN (code=exited, status=1/FAILURE)
Main PID: 810 (code=exited, status=1/FAILURE)
CPU: 421ms

Jan 22 13:02:19 okd4-compute-0.okd4-2.apptecinc.com systemd[1]: Starting Configures OVS with proper host networking configuration...
Jan 22 13:02:19 okd4-compute-0.okd4-2.apptecinc.com configure-ovs.sh[811]: + rpm -qa
Jan 22 13:02:19 okd4-compute-0.okd4-2.apptecinc.com configure-ovs.sh[812]: + grep -q openvswitch
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com configure-ovs.sh[810]: + echo 'Warning: Openvswitch package is not installed!'
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com configure-ovs.sh[810]: Warning: Openvswitch package is not installed!
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com configure-ovs.sh[810]: + exit 1
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com systemd[1]: ovs-configuration.service: Main process exited, code=exited, status=1/FAILURE
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com systemd[1]: ovs-configuration.service: Failed with result 'exit-code'.
Jan 22 13:02:21 okd4-compute-0.okd4-2.apptecinc.com systemd[1]: Failed to start Configures OVS with proper host networking configuration.

[vrutkovs]

This is resolved in https://amd64.origin.releases.ci.openshift.org/releasestream/4-stable/release/4.6.0-0.okd-2021-01-23-132511 - MCD will no longer attempt to install duplicated open-vm-tools.

If you're upgrading from previous (4.6.0-0.okd-2021-01-17-185703) install run upgrade-master and upgrade-worker scripts to bring those to the necessary os content.
If that doesn't work try

# sed -i 's;enabled=1;enabled=0;g' /etc/yum.repos.d/fedora{,-updates}.repo
# /run/bin/machine-config-daemon pivot quay.io/openshift/okd-content@sha256:64f1cc9663a57d3bb9cc413502c9ccc04097be2033cf726aaf535e0e7ad5b5c4
# sed -i 's;enabled=0;enabled=1;g' /etc/yum.repos.d/fedora{,-updates}.repo

and reboot the node

[kai-uwe-rommel]

@vrutkovs, how are those scripts supposed to work?
Really need to run them _locally_ on the nodes?
There is normally no kubeconfig for core or root users on the node ...
Also, is it correct that the upgrade-worker script is assigning the rendered-master (!) config to the workers??

[vrutkovs]

Really need to run them locally on the nodes?

Yes

There is normally no kubeconfig for core or root users on the node ...

Masters have /etc/kubernetes/static-pod-resources/kube-apiserver-certs/secrets/node-kubeconfigs/localhost.kubeconfig, workers could use kubeadmin or any other privildged user token. In any case, worker MC can be fetched externally

Also, is it correct that the upgrade-worker script is assigning the rendered-master (!) config to the workers??

Good catch, fixed it

[kai-uwe-rommel]

Really need to run them locally on the nodes?

Yes

There is normally no kubeconfig for core or root users on the node ...

Masters have /etc/kubernetes/static-pod-resources/kube-apiserver-certs/secrets/node-kubeconfigs/localhost.kubeconfig, workers could use kubeadmin or any other privildged user token. In any case, worker MC can be fetched externally

Also, is it correct that the upgrade-worker script is assigning the rendered-master (!) config to the workers??

Good catch, fixed it

@vrutkovs, another question: when am I supposed to run this exactly? Before I start the cluster upgrade at all? Or when the upgrade of the cluster services is done and only the MCO is left to do its work?

[vrutkovs]

Before I start the cluster upgrade at all? Or when the upgrade of the cluster services is done and only the MCO is left to do its work?

During cluster upgrade, when MCO has generated new rendered-... Just to be safe you can set spec.paused:true in MCP so that MCO would not attempt to update nodes itself (don't forget to unset it when MCP shows the pool is updated)

[ofedotov51]

hello. I post a link to the must gathering file since it is more than 10 MB. please help my cluster went into degradation after the update.

https://yadi.sk/d/sM6rXTPHKXek1A

[vrutkovs]

@ofedotov51 your last complete install was 4.5.0-0.okd-2020-07-29-070316 then I see a lot of partial upgrades to 4.5.0-0.okd-2020-08-12-020541 and all the way up to 4.6.0-0.okd-2021-01-17-185703.

Why are these were not complete? Check if you can upgrade to 4.6.0-0.okd-2021-01-23-132511 (with mentioned workarounds)

[klzsysy]

I now have a similar situation as @klzsysy.
Does anyone have any idea where the osImageURL quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c came from?

1. ssh login host
2. exec /run/bin/machine-config-daemon pivot quay.io/openshift/okd-content@sha256:2fe2fd4d99c953d5bcf0d53b420a2012aae7fd12986dac8e757ad68f7b97030c , waiting success
3. reboot