CoreOS 1745.4.0 upgrade failed

[yuko11]

Issue Report Template

Tectonic Version

1.8.9-tectonic.1

Environment

Baremetal
What hardware/cloud provider/hypervisor is being used with Tectonic?
VMware

Expected Behavior

CoreOS upgraed successfully

Actual Behavior

CoreOS node in cluster stuck in "Updating Docker...", status is Not Ready

Reproduction Steps

1. Upgrade CoreOS from 1688.5.3 to 1745.4.0 is failed.
2. It was master node and now it is in not ready. Other worker node just before this upgrade was successfully upgraded from 1688.5.3 to 1745.3.1
3. I'm wondering how to manage upgrade for specific version, why one node was upgraded to 1745.3.1 and other failed to upgrade to 1745.4.0 and how to troubleshoot that.
4. The same issue observed on other cluster/node
5. How to prevent production cluster to face the same failure, as new CoreOS version is auto installed and just awaiting reboot, which could actually happen due to any circumstances.

Other Information

Feature Request

Environment

What hardware/cloud provider/hypervisor is being used with Tectonic?

Desired Feature

Other Information

[yuko11]

So, basically seems issue is that docker was not updated, so it is not running, that's why Node is not ready.

core@kube-node1 ~ $ systemctl status docker.service
Unit docker.service could not be found.

tried to start node update again manually but not successful:

core@kube-node1 ~ $ update_engine_client -update
I0529 14:56:47.045148 18047 update_engine_client.cc:247] Initiating update check and install.
I0529 14:56:47.061167 18047 update_engine_client.cc:252] Waiting for update to complete.
LAST_CHECKED_TIME=1527605809
PROGRESS=0.000000
CURRENT_OP=UPDATE_STATUS_IDLE
NEW_VERSION=0.0.0
NEW_SIZE=0
E0529 14:56:52.785373 18047 update_engine_client.cc:190] Update failed.

[yuko11]

On test cluster, I've manually reverted to previous 1688.5.3 version. After some time (near 15 minutes) it becomes 1745.4.0 again with no issues and no reboot from my side, but Update Strategy: No Reboots. I'm wondering how could that happen.
On qa cluster, I reverted to previous 1688.5.3 and now it stack with "Updating Docker..." message in gui console for other node.

[yuko11]

After reboot of node with "Updating Docker..." it loaded 1745.4.0 with no issues. But how to know when it is done with "Updating Docker..." and you can safely reboot it?

[yuko11]

Other Node from cluster is saying:
UPDATE STATUS
Updating Docker...
Container Linux 1745.3.1 ➝ 1745.4.0

And when login to node:
Container Linux by CoreOS stable (1745.3.1)
Update Strategy: No Reboots
Failed Units: 1
proc-sys-fs-binfmt_misc.mount

[IvanCherepov]

@yuko11 can please provide an output of systemctl status docker and docker version?

[yuko11]

Hi @IvanCherepov,

Thanks for your attention, systemctl status docker has been provided above.
Currently nodes are updated with new CoreOS version, as I managed to load passive partition and initiate update again successfully on several nodes and 2 different clusters, other lately installed cluster is ok.
But raised questions are:

1. How to monitor CoreOS update process to know, once OS is updated and you can reboot node to load new version (there is no any notifications on Tectonic console, however it is present in manual cli update)
2. How to troubleshoot CoreOS update process (definitely something wrong with my cluster, I can play with revert-install wile cluster is 10 nodes, but it's not the case with cluster of 100+ nodes )
3. Does anyone else had similar issues with OS updates

[IvanCherepov]

CLUO is responsible for Container Linux auto updates and reboots. You can check logs for update_engine for updates troubleshooting.

[adarshaj]

I have nearly exact same issue, except that the upgrade was happening from 1745.6.0 -> 1745.7.0. The coreos seems to have upgraded, but I cannot find docker.service as reported by systemctl status docker which outputs ->

Unit docker.service could not be found.

Another issues seems to be related to this too: #266

journalctl -lf -u kubelet shows the following relevant error logs:

Jun 17 15:03:16 node kubelet-wrapper[12134]: I0617 15:03:16.824390   12134 client.go:80] Connecting to docker on unix:///var/run/docker.sock
Jun 17 15:03:16 node kubelet-wrapper[12134]: I0617 15:03:16.824406   12134 client.go:109] Start docker client with request timeout=2m0s
Jun 17 15:03:16 node kubelet-wrapper[12134]: E0617 15:03:16.824506   12134 kube_docker_client.go:91] failed to retrieve docker version: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
Jun 17 15:03:16 node kubelet-wrapper[12134]: W0617 15:03:16.824535   12134 kube_docker_client.go:92] Using empty version for docker client, this may sometimes cause compatibility issue.
Jun 17 15:03:16 node kubelet-wrapper[12134]: Error: failed to run Kubelet: failed to create kubelet: failed to get docker version: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
Jun 17 15:03:16 node systemd[1]: kubelet.service: Main process exited, code=exited, status=1/FAILURE
Jun 17 15:03:16 node systemd[1]: kubelet.service: Failed with result 'exit-code'.

Since kubelet hasn't come up the values being reported on tectonic dashboard is all outdated (i.e. its stuck at docker updating.. and reports older kernel version in the expanded output of Node).

How do I get docker running on this machine?

Edit: This is on a baremetal tectonic cluster.

[adarshaj]

Further inspection of torcx have following logs, but due to my lack of understanding of working of torcx, I am not sure what exactly the last few error lines mean and how to reproduce/debug/check for fix on this.

core@cores $ sudo journalctl -lb | grep torcx
Jun 17 12:29:56 node systemd[651]: /usr/lib64/systemd/system-generators/torcx-generator failed with exit status 1.
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="common configuration parsed" base_dir="/var/lib/torcx/" conf_dir="/etc/torcx/" run_dir="/run/torcx/" store_paths=[/usr/share/torcx/store/ /usr/share/oem/torcx/store/1745.7.0/ /usr/share/oem/torcx/store/ /var/lib/torcx/store/1745.7.0/ /var/lib/torcx/store/]
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-no path="/usr/share/torcx/profiles/docker-1.12-no.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-yes path="/usr/share/torcx/profiles/docker-1.12-yes.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=vendor path="/usr/share/torcx/profiles/vendor.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=tectonic path="/etc/torcx/profiles/tectonic.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=info msg="no vendor profile selected by /etc/coreos/docker-1.12"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="skipped missing lower profile" missing profile=oem
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-no path="/usr/share/torcx/profiles/docker-1.12-no.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-yes path="/usr/share/torcx/profiles/docker-1.12-yes.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=vendor path="/usr/share/torcx/profiles/vendor.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=tectonic path="/etc/torcx/profiles/tectonic.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="apply configuration parsed" lower profiles (vendor/oem)=[vendor] upper profile (user)=tectonic
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="mounted tmpfs" target="/run/torcx/unpack"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-no path="/usr/share/torcx/profiles/docker-1.12-no.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=docker-1.12-yes path="/usr/share/torcx/profiles/docker-1.12-yes.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=vendor path="/usr/share/torcx/profiles/vendor.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="profile found" name=tectonic path="/etc/torcx/profiles/tectonic.json"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="new archive/reference added to cache" name=docker path="/usr/share/torcx/store/docker:1.12.torcx.tgz" reference=1.12
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="new archive/reference added to cache" name=docker path="/usr/share/torcx/store/docker:18.03.torcx.tgz" reference=18.03
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=debug msg="new archive/reference added to cache" name=docker path="/usr/share/torcx/store/docker:com.coreos.cl.torcx.tgz" reference=com.coreos.cl
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=info msg="store skipped" err="open /usr/share/oem/torcx/store/1745.7.0/: no such file or directory" path="/usr/share/oem/torcx/store/1745.7.0/"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=info msg="store skipped" err="open /usr/share/oem/torcx/store/: no such file or directory" path="/usr/share/oem/torcx/store/"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=info msg="store skipped" err="open /var/lib/torcx/store/1745.7.0/: no such file or directory" path="/var/lib/torcx/store/1745.7.0/"
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=error msg="image docker:17.03 not found" image=docker reference=17.03
Jun 17 12:29:56 node /usr/lib64/systemd/system-generators/torcx-generator[662]: time="2018-06-17T12:29:56Z" level=error msg="apply failed: failed to install 1 images"

[adarshaj]

I had another node on cluster which had successfully upgarded just before the failing node. I just scp'ed the files in /var/lib/torcx/store/1745.7.0/ and rebooted the server, and kubelet came back up and the cluster healed itself and status got updated on dashboard as well. before doing this, I had tried in vain to trigger manual updates and reset the update status and tried to re-install the update, but none of it had worked. I still don't know what's the root cause of this issue and how to monitor and avoid this situation in future?

[yuko11]

For upgrade 1745.6.0 -> 1745.7.0 it happened again, but only for one cluster. And gui log me off it I'm trying to open node details, in the same time all other gui sections are working fine.

[yuko11]

@adarshaj
Thanks for pointing! Manual upgrade also didn't work for me this time. I copied docker:17.03.torcx.tgz from /var/lib/torcx/store/1745.5.0/ to /var/lib/torcx/store/1745.7.0/ and it works after reboot.