Bug 1709907

Summary: MCD logs are spammed with "controller syncing started"
Product: OpenShift Container Platform Reporter: Antonio Murdaca <amurdaca>
Component: Machine Config OperatorAssignee: Antonio Murdaca <amurdaca>
Status: CLOSED ERRATA QA Contact: Micah Abbott <miabbott>
Severity: medium Docs Contact:
Priority: medium    
Version: 4.1.0CC: sponnaga
Target Milestone: ---Keywords: OSE41z_next
Target Release: 4.1.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: 4.1.3
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-06-26 08:50:22 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Antonio Murdaca 2019-05-14 14:16:50 UTC 
Description of problem:

MCD logs are flooded with:

I0514 14:13:55.119046    3091 update.go:755] controller syncing started
I0514 14:13:56.725861    3091 update.go:755] controller syncing started
I0514 14:13:56.750052    3091 update.go:755] controller syncing started
I0514 14:13:58.759426    3091 update.go:755] controller syncing started
I0514 14:13:59.668271    3091 update.go:755] controller syncing started
I0514 14:14:01.040087    3091 update.go:755] controller syncing started

Logs may be rotated as well due to the high rate we're logging. That was a debug being put there to investigate another issue and no longer needed.


Version-Release number of selected component (if applicable):


How reproducible:

always


Steps to Reproduce:
1. oc logs <any-mcd-instance>
2.
3.

Actual results:

I0514 14:13:55.119046    3091 update.go:755] controller syncing started
I0514 14:13:56.725861    3091 update.go:755] controller syncing started
I0514 14:13:56.750052    3091 update.go:755] controller syncing started
I0514 14:13:58.759426    3091 update.go:755] controller syncing started
I0514 14:13:59.668271    3091 update.go:755] controller syncing started
I0514 14:14:01.040087    3091 update.go:755] controller syncing started


Expected results:

no "controller syncing started" logs.

Additional info:
Comment 1 Antonio Murdaca 2019-05-14 14:19:19 UTC 
https://github.com/openshift/machine-config-operator/pull/747
Comment 4 Sudha Ponnaganti 2019-06-07 02:15:51 UTC 
This should be in 4.1.0 itself. Why this is being listed for 4.1.1?
Comment 6 Antonio Murdaca 2019-06-07 08:01:25 UTC 
(In reply to Antonio Murdaca from comment #1)
> https://github.com/openshift/machine-config-operator/pull/747

This has been missed the branching altogether actually. I've created a cherrypick now https://github.com/openshift/machine-config-operator/pull/833
Comment 8 Micah Abbott 2019-06-19 19:18:00 UTC 
Verified with 4.1.0-0.nightly-2019-06-19-033215

```
$ oc get clusterversion                                                                                           
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS                                                                                                                              
version   4.1.0-0.nightly-2019-06-19-033215   True        False         168m    Cluster version is 4.1.0-0.nightly-2019-06-19-033215

$ oc -n openshift-machine-config-operator get po                                                                  
NAME                                         READY   STATUS    RESTARTS   AGE                                                                                                                                       
etcd-quorum-guard-6c55b46b4-ksp7k            1/1     Running   0          177m                                                                                                                                      
etcd-quorum-guard-6c55b46b4-mmtd6            1/1     Running   0          177m
etcd-quorum-guard-6c55b46b4-pngd8            1/1     Running   0          177m                                                                                                                                      
machine-config-controller-6d779485ff-xd592   1/1     Running   0          178m                                                                                                                                       machine-config-daemon-49lp2                  1/1     Running   0          178m
machine-config-daemon-c2n5t                  1/1     Running   0          178m                                                                                                                                      
machine-config-daemon-g5qjs                  1/1     Running   0          173m                                                                                                                                      
machine-config-daemon-g5t8q                  1/1     Running   0          173m                                                                                                                                       machine-config-daemon-nt5bj                  1/1     Running   0          172m
machine-config-daemon-qhjxb                  1/1     Running   0          178m                        
machine-config-operator-84bfb7f699-bnb6x     1/1     Running   0          179m
machine-config-server-nc2nn                  1/1     Running   0          178m
machine-config-server-sdfms                  1/1     Running   0          178m
machine-config-server-wtr68                  1/1     Running   0          178m

$ oc -n openshift-machine-config-operator logs po/machine-config-daemon-49lp2                                     
I0619 16:18:20.642814    4131 start.go:67] Version: 4.1.3-201906181537-dirty (b2ee2cf36a40ae41dc98d1e880faa8279e0feba2)                                                                                             
I0619 16:18:20.643195    4131 start.go:100] Starting node writer
I0619 16:18:20.646190    4131 run.go:22] Running captured: chroot /rootfs rpm-ostree status --json
I0619 16:18:20.720219    4131 daemon.go:200] Booted osImageURL: quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:067bba989d1c6c570fc2b17424207c8020cdcef528513eeafa48faf3fa5d496e (410.8.20190619.0)           
I0619 16:18:20.724602    4131 start.go:196] Calling chroot("/rootfs")
I0619 16:18:20.724638    4131 start.go:206] Starting MachineConfigDaemon
I0619 16:18:20.724750    4131 update.go:836] Starting to manage node: ip-10-0-141-41.us-west-2.compute.internal                                                                                                     
I0619 16:18:20.728883    4131 run.go:22] Running captured: rpm-ostree status
I0619 16:18:20.767947    4131 daemon.go:740] State: idle
AutomaticUpdates: disabled
Deployments:
* pivot://quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:067bba989d1c6c570fc2b17424207c8020cdcef528513eeafa48faf3fa5d496e                                                                                    
              CustomOrigin: Managed by pivot tool
                   Version: 410.8.20190619.0 (2019-06-19T00:47:13Z)

  pivot://docker-registry-default.cloud.registry.upshift.redhat.com/redhat-coreos/ootpa@sha256:683a6a866a8ec789fedb5da63b6a2ff68c1b0788ec90e7def778f0c4c13197a4                                                     
              CustomOrigin: Provisioned from oscontainer
                   Version: 410.8.20190520.0 (2019-05-20T20:10:04Z)
I0619 16:18:20.767974    4131 run.go:22] Running captured: journalctl --list-boots
I0619 16:18:20.773567    4131 daemon.go:747] journalctl --list-boots:
-1 b04921b5b94d4a9a92722eacf4d8f0f1 Wed 2019-06-19 16:08:02 UTC—Wed 2019-06-19 16:11:46 UTC
 0 3eaf0df833bf4596b774131924f7be38 Wed 2019-06-19 16:12:13 UTC—Wed 2019-06-19 16:18:20 UTC
I0619 16:18:20.773602    4131 daemon.go:494] Enabling Kubelet Healthz Monitor
I0619 16:18:22.044788    4131 node.go:24] No machineconfiguration.openshift.io/currentConfig annotation on node ip-10-0-141-41.us-west-2.compute.internal: map[volumes.kubernetes.io/controller-managed-attach-detach:true], in cluster bootstrap, loading initial node annotation from /etc/machine-config-daemon/node-annotations.json                                                                                                 
I0619 16:18:22.045505    4131 node.go:45] Setting initial node config: rendered-master-81817228087f0894c3ab77a8a8254eba                                                                                             
I0619 16:18:22.058203    4131 update.go:723] logger doesn't support --jounald, grepping the journal
I0619 16:18:22.096584    4131 update.go:836] error loading pending config open /etc/machine-config-daemon/state.json: no such file or directory                                                                     
I0619 16:18:22.105724    4131 daemon.go:667] In bootstrap mode
I0619 16:18:22.105751    4131 daemon.go:695] Current+desired config: rendered-master-81817228087f0894c3ab77a8a8254eba                                                                                               
I0619 16:18:22.113422    4131 daemon.go:854] No bootstrap pivot required; unlinking bootstrap node annotations                                                                                                      
I0619 16:18:22.113484    4131 update.go:836] Validating against current config rendered-master-81817228087f0894c3ab77a8a8254eba                                                                                     
I0619 16:18:22.117404    4131 daemon.go:898] Validating against current config rendered-master-81817228087f0894c3ab77a8a8254eba                                                                                     
I0619 16:18:22.129680    4131 daemon.go:904] Validated on-disk state
I0619 16:18:22.134984    4131 daemon.go:944] In desired config rendered-master-81817228087f0894c3ab77a8a8254eba                                                                                                     
W0619 16:21:31.138023    4131 reflector.go:270] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: watch of *v1.MachineConfig ended with: too old resource version: 3266 (5506)
E0619 16:28:38.425628    4131 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=9, ErrCode=NO_ERROR, debug=""                
E0619 16:28:38.426609    4131 streamwatcher.go:109] Unable to decode an event from the watch stream: http2: server sent GOAWAY and closed the connection; LastStreamID=9, ErrCode=NO_ERROR, debug=""                
W0619 16:28:39.345825    4131 reflector.go:270] github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions/factory.go:101: watch of *v1.MachineConfig ended with: too old resource version: 5506 (14665)
```
Comment 11 errata-xmlrpc 2019-06-26 08:50:22 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, 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/RHBA-2019:1589