MCD rebooting early after set up

[jlebon]

From @crawford:

I1129 21:37:29.566704    8105 start.go:51] Version: 3.11.0-278-g628ad5d1-dirty
I1129 21:37:29.567579    8105 start.go:78] starting node writer
I1129 21:37:29.572698    8105 run.go:22] Running captured: chroot /rootfs rpm-ostree status --json
I1129 21:37:29.971743    8105 daemon.go:115] Booted osImageURL: registry.svc.ci.openshift.org/rhcos/maipo@sha256:9c7f465ed8a84ed9d47356258ede44b7aec8b11b4e89defaf3ecee3cef33f0a0 (47.153)
I1129 21:37:30.009173    8105 start.go:127] Calling chroot("/rootfs")
E1129 21:37:30.029005    8105 daemon.go:303] Marking degraded due to: machineconfigs.machineconfiguration.openshift.io "0788cf371d56ac505e5b0e78392ccb14" not found
I1129 21:37:30.044992    8105 start.go:146] Starting MachineConfigDaemon
I1129 21:37:30.045012    8105 daemon.go:187] Enabling Kubelet Healthz Monitor
W1129 21:37:30.804003    8105 reflector.go:341] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: watch of *v1.Node ended with: very short watch: github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Unexpected watch close - watch lasted less than a second and no items received
E1129 21:37:31.805751    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
...
I1129 21:38:09.151806    8105 update.go:489] Rebooting

I1129 21:40:52.851825    5989 start.go:51] Version: 3.11.0-278-g628ad5d1-dirty
I1129 21:40:52.856779    5989 start.go:78] starting node writer
I1129 21:40:52.870226    5989 run.go:22] Running captured: chroot /rootfs rpm-ostree status --json
I1129 21:40:53.263929    5989 daemon.go:115] Booted osImageURL: registry.svc.ci.openshift.org/rhcos/maipo@sha256:9c7f465ed8a84ed9d47356258ede44b7aec8b11b4e89defaf3ecee3cef33f0a0 (47.153)
I1129 21:40:57.364959    5989 start.go:127] Calling chroot("/rootfs")
I1129 21:40:57.387466    5989 daemon.go:293] Node is degraded; going to sleep

[abhinavdahiya]

machine-config-operator/pkg/daemon/daemon.go

Lines 421 to 439 in f915a1b

	// executeUpdateFromClusterWithMachineConfig starts the actual update process. The provided config
	// will be used as the desired config, while the current config will be pulled from the cluster. If
	// you want both pulled from the cluster please use executeUpdateFromCluster().
	func (dn *Daemon) executeUpdateFromClusterWithMachineConfig(desiredConfig *mcfgv1.MachineConfig) error {
	// The desired machine config has changed, trigger update
	if err := dn.triggerUpdateWithMachineConfig(desiredConfig); err != nil {
	glog.Errorf("Marking degraded due to: %v", err)
	if errSet := dn.nodeWriter.SetUpdateDegraded(dn.kubeClient.CoreV1().Nodes(), dn.name); errSet != nil {
	glog.Errorf("Futher error attempting to set the node to degraded: %v", errSet)
	}
	// reboot the node, which will catch the degraded state and sleep
	dn.reboot()
	}
	// we managed to update the machine without rebooting. in this case,
	// continue as usual waiting for the next update
	glog.V(2).Infof("Successfully updated without reboot")
	return nil
	}

[cgwalters]

Let's change dn.reboot() to take a string that it also logs to the journal.

[cgwalters]

Offhand it looks like we want to refactor triggerUpdateWithMachineConfig to gather all the state it can before executing the final return dn.update(currentConfig, desiredConfig) - and any errors before that should be non-fatal and not cause a reboot.

[kikisdeliveryservice]

@cgwalters is that the full log? or is there more before rebooting??

[cgwalters]

Sorry I just noticed I'd duplicated the initial comment here. @crawford can you attach any more info you have? Or even better if this is reproducible let's ensure the person who's going to hack on it has access to an affected cluster.

[crawford]

@kikisdeliveryservice Full logs:

I1129 21:37:29.566704    8105 start.go:51] Version: 3.11.0-278-g628ad5d1-dirty
I1129 21:37:29.567579    8105 start.go:78] starting node writer
I1129 21:37:29.572698    8105 run.go:22] Running captured: chroot /rootfs rpm-ostree status --json
I1129 21:37:29.971743    8105 daemon.go:115] Booted osImageURL: registry.svc.ci.openshift.org/rhcos/maipo@sha256:9c7f465ed8a84ed9d47356258ede44b7aec8b11b4e89defaf3ecee3cef33f0a0 (47.153)
I1129 21:37:30.009173    8105 start.go:127] Calling chroot("/rootfs")
E1129 21:37:30.029005    8105 daemon.go:303] Marking degraded due to: machineconfigs.machineconfiguration.openshift.io "0788cf371d56ac505e5b0e78392ccb14" not found
I1129 21:37:30.044992    8105 start.go:146] Starting MachineConfigDaemon
I1129 21:37:30.045012    8105 daemon.go:187] Enabling Kubelet Healthz Monitor
W1129 21:37:30.804003    8105 reflector.go:341] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: watch of *v1.Node ended with: very short watch: github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Unexpected watch close - watch lasted less than a second and no items received
E1129 21:37:31.805751    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:32.811382    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:33.812646    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:34.813839    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:35.815140    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:36.816228    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:37.817344    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:38.819359    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:39.822668    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:40.825108    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:41.826651    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:42.828049    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:43.829583    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:44.830751    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:45.831858    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:46.832873    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:47.833954    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:48.837630    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:49.838736    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:50.839882    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:51.841095    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:52.842167    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:53.843289    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:54.844598    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:55.849005    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:56.850123    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:57.851250    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:58.852454    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:37:59.859095    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:00.860407    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:01.861913    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:02.864036    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:03.865084    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:04.866203    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:05.867314    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:06.868602    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
E1129 21:38:07.869742    8105 reflector.go:205] github.com/openshift/machine-config-operator/vendor/k8s.io/client-go/informers/factory.go:130: Failed to list *v1.Node: Get https://172.30.0.1:443/api/v1/nodes?limit=500&resourceVersion=0: dial tcp 172.30.0.1:443: connect: connection refused
I1129 21:38:09.151806    8105 update.go:489] Rebooting

[crawford]

@kikisdeliveryservice I can reproduce this locally with libvirt. From my new cluster I see the following:

I1129 23:22:55.592557    9549 start.go:51] Version: 3.11.0-278-g628ad5d1-dirty
I1129 23:22:55.597479    9549 start.go:78] starting node writer
I1129 23:22:55.613222    9549 run.go:22] Running captured: chroot /rootfs rpm-ostree status --json
I1129 23:22:55.852915    9549 daemon.go:115] Booted osImageURL: registry.svc.ci.openshift.org/rhcos/maipo@sha256:9c7f465ed8a84ed9d47356258ede44b7aec8b11b4e89defaf3ecee3cef33f0a0 (47.153)
I1129 23:22:55.921893    9549 start.go:127] Calling chroot("/rootfs")
E1129 23:22:55.972253    9549 daemon.go:303] Marking degraded due to: machineconfigs.machineconfiguration.openshift.io "7f7366afead827ab5aa47ce67d5903c9" not found
I1129 23:22:55.998869    9549 start.go:146] Starting MachineConfigDaemon
I1129 23:22:55.998951    9549 daemon.go:187] Enabling Kubelet Healthz Monitor
I1129 23:22:57.963093    9549 update.go:489] Rebooting

It took quite a while for the MCC to create the MachineConfigs:

$ kubectl get machineconfigs
No resources found.

A few minutes later:

$ kubectl get machineconfigs
NAME        AGE
00-master   1m
00-worker   1m

I'm sure 7f7366afead827ab5aa47ce67d5903c9 will show up if I wait a bit longer.

The MCC logs show the following:

I1129 23:24:23.120333       1 start.go:44] Version: 3.11.0-278-g628ad5d1-dirty
I1129 23:24:23.319527       1 leaderelection.go:185] attempting to acquire leader lease  openshift-machine-config-operator/machine-config-controller...
E1129 23:26:19.915022       1 event.go:259] Could not construct reference to: '&v1.ConfigMap{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"machine-config-controller", GenerateName:"", Namespace:"openshift-machine-config-operator", SelfLink:"/api/v1/namespaces/openshift-machine-config-operator/configmaps/machine-config-controller", UID:"913656b5-f42d-11e8-9834-12202f72768c", ResourceVersion:"7816", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63679130518, loc:(*time.Location)(0x1c60aa0)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string{"control-plane.alpha.kubernetes.io/leader":"{\"holderIdentity\":\"machine-config-controller-5f644d794f-l55l5_e7aa2bc2-f42d-11e8-a035-0a580a800025\",\"leaseDurationSeconds\":90,\"acquireTime\":\"2018-11-29T23:26:19Z\",\"renewTime\":\"2018-11-29T23:26:19Z\",\"leaderTransitions\":1}"}, OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, Data:map[string]string(nil), BinaryData:map[string][]uint8(nil)}'
due to: 'no kind is registered for the type v1.ConfigMap'. Will not report event: 'Normal' 'LeaderElection' 'machine-config-controller-5f644d794f-l55l5_e7aa2bc2-f42d-11e8-a035-0a580a800025 became leader'
I1129 23:26:19.922331       1 leaderelection.go:194] successfully acquired lease openshift-machine-config-operator/machine-config-controller
I1129 23:26:20.128953       1 template_controller.go:111] Starting MachineConfigController-TemplateController
I1129 23:26:20.221709       1 render_controller.go:103] Starting MachineConfigController-RenderController
I1129 23:26:20.323361       1 node_controller.go:117] Starting MachineConfigController-NodeController
I1129 23:26:21.319588       1 render.go:91] ignoring non-directory path ".gitkeep"
E1129 23:29:05.801651       1 node_controller.go:345] Empty CurrentMachineConfig
E1129 23:29:05.804675       1 node_controller.go:345] Empty CurrentMachineConfig

[kikisdeliveryservice]

I've reproduced this locally on libvirt. One of the daemons does seem to have rebooted and now is degraded and the backlogs show the same error coming from reflector.go as in the above logs.

[cgwalters]

I am not an expert in this, but one approach would be for the MCD to exit if it can't query the current state - then we'll be respawned as usual when things have hopefully stabilized, and it'll be visible to the cluster as a usual CrashLoopBackOff.

[abhinavdahiya]

It took quite a while for the MCC to create the MachineConfigs:

$ kubectl get machineconfigs
No resources found.

A few minutes later:

$ kubectl get machineconfigs
NAME        AGE
00-master   1m
00-worker   1m

I'm sure 7f7366afead827ab5aa47ce67d5903c9 will show up if I wait a bit longer.

The MCC logs show the following:

I1129 23:24:23.120333       1 start.go:44] Version: 3.11.0-278-g628ad5d1-dirty
I1129 23:24:23.319527       1 leaderelection.go:185] attempting to acquire leader lease  openshift-machine-config-operator/machine-config-controller...
E1129 23:26:19.915022       1 event.go:259] Could not construct reference to: '&v1.ConfigMap{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"machine-config-controller", GenerateName:"", Namespace:"openshift-machine-config-operator", SelfLink:"/api/v1/namespaces/openshift-machine-config-operator/configmaps/machine-config-controller", UID:"913656b5-f42d-11e8-9834-12202f72768c", ResourceVersion:"7816", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63679130518, loc:(*time.Location)(0x1c60aa0)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string{"control-plane.alpha.kubernetes.io/leader":"{\"holderIdentity\":\"machine-config-controller-5f644d794f-l55l5_e7aa2bc2-f42d-11e8-a035-0a580a800025\",\"leaseDurationSeconds\":90,\"acquireTime\":\"2018-11-29T23:26:19Z\",\"renewTime\":\"2018-11-29T23:26:19Z\",\"leaderTransitions\":1}"}, OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, Data:map[string]string(nil), BinaryData:map[string][]uint8(nil)}'
due to: 'no kind is registered for the type v1.ConfigMap'. Will not report event: 'Normal' 'LeaderElection' 'machine-config-controller-5f644d794f-l55l5_e7aa2bc2-f42d-11e8-a035-0a580a800025 became leader'
I1129 23:26:19.922331       1 leaderelection.go:194] successfully acquired lease openshift-machine-config-operator/machine-config-controller
I1129 23:26:20.128953       1 template_controller.go:111] Starting MachineConfigController-TemplateController
I1129 23:26:20.221709       1 render_controller.go:103] Starting MachineConfigController-RenderController
I1129 23:26:20.323361       1 node_controller.go:117] Starting MachineConfigController-NodeController
I1129 23:26:21.319588       1 render.go:91] ignoring non-directory path ".gitkeep"
E1129 23:29:05.801651       1 node_controller.go:345] Empty CurrentMachineConfig
E1129 23:29:05.804675       1 node_controller.go:345] Empty CurrentMachineConfig

So MCC has max retries of 15 here on error for an event and i suspect we are hitting the max retries but we only print that on loglevel 2 here and therefore a little blind and then MCC will manually resync after 20mins here

[jlebon]

OK, so there's three separate issues here it seems:

1. MCC takes a while to create the machineconfigs
2. MCD marking degraded when machineconfig not found -- seems like we want to hang around a bit here and keep retrying a certain number of times/minutes?
3. Making triggerUpdateWithMachineConfig error handling smarter so that we don't mark degraded on transient errors.

I can take a look at 2 and 3. Let's split 1 into a separate issue?

/assign

[jlebon]

(Just gonna answer here a question from the chat.) Re. "MCD should never set the node to degraded/go to sleep". The key here is distinguishing between fatal and non-fatal errors. On fatal errors, there's not much we can do. E.g. what should it do if the node state isn't reconciled after an update is applied and rebooted? Or if rpm-ostree status fails to start? Or pivot fails to update the node? Sure, we could try again a few times, but eventually, we need to notify the cluster that this node is a lost cause and should be torn down by marking it degraded. Once we do that though, there's no point in trying to operate on the node any longer since it's expected to be torn down at any moment, hence the immediate sleep on restart into a degraded node.

In this specific instance, we hit a false positive treating a non-fatal error as fatal. Clearly, failing to watch for updates shouldn't cause node degradation. The tricky part is making error handling smart enough at each point to discern between those two.

[jlebon]

Let's split 1 into a separate issue?

Split that into #203.

[jlebon]

Hmm, I still can't reproduce this yet. I'm running with RHCOS 47.153 and openshift/installer@25757c6.

Though I did hit this on the MCD of the worker node once it comes up:

F1130 14:59:12.035567    3799 start.go:123] failed to initialize daemon: Failed to set initial annotations: Unable to update node "test1-worker-0-trhs6": Get https://172.30.0.1:443/api/v1/nodes/test1-worker-0-trhs6: x509: certificate signed by unknown authority

That eventually fixes itself after the pod restarts a few times.