Bug 1860372 - ill log format "nodeconfig worker label %s already present on node %s"
Summary: ill log format "nodeconfig worker label %s already present on node %s"
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Windows Containers
Version: 4.6
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
: 4.6.0
Assignee: ravig
QA Contact: gaoshang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-07-24 11:33 UTC by gaoshang
Modified: 2020-10-27 16:17 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-10-27 16:16:56 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift windows-machine-config-operator pull 100 0 None closed Bug 1860372: [wmco] Remove applying worker label 2020-09-16 17:19:33 UTC
Red Hat Product Errata RHBA-2020:4196 0 None None None 2020-10-27 16:17:14 UTC

Description gaoshang 2020-07-24 11:33:42 UTC
Description of problem:
When WMCO config Windows machines, found following message in nodeconfig log:
2020-07-24T08:35:13.261Z	DEBUG	nodeconfig	worker label %s already present on node %s	{"node-role.kubernetes.io/worker": "ip-10-0-151-105.us-east-2.compute.internal"}
seems like "%s" can not be recognized in https://github.com/openshift/windows-machine-config-operator/blob/9de618aa7d273e8bdfaff782ec6ce61f6b894770/pkg/controller/windowsmachine/nodeconfig/nodeconfig.go#L184

Version-Release number of selected component (if applicable):
OCP version: 4.6.0-0.nightly-2020-07-24-002417
windows-machine-config-operator git commit: 9de618aa7d273e8bdfaff782ec6ce61f6b894770

How reproducible:
Always

Steps to Reproduce:
1. Install OCP cluster and run WMCO operator
2. Create a Windows machineset, check WMCO log

# oc logs -f deployment.apps/windows-machine-config-operator
...
2020-07-24T08:27:59.854Z	INFO	windowsmachine-controller	reconciling	{"namespace": "openshift-machine-api", "name": "sgao-d2wtc-windows-worker-us-east-2a-6nr8v"}
2020-07-24T08:27:59.862Z	DEBUG	windowsmachine-controller	configuring the Windows VM	{"ID": "i-0181b2e1f467b1298"}
2020-07-24T08:30:11.982Z	DEBUG	VM i-0181b2e1f467b1298	SSH dial	{"IP Address": "10.0.151.105", "error": "dial tcp 10.0.151.105:22: connect: connection timed out"}
2020-07-24T08:33:20.398Z	DEBUG	VM i-0181b2e1f467b1298	SSH dial	{"IP Address": "10.0.151.105", "error": "dial tcp 10.0.151.105:22: connect: connection timed out"}
2020-07-24T08:34:53.685Z	DEBUG	VM i-0181b2e1f467b1298	ignition file download	{"cmd": "C:\\Temp\\wget-ignore-cert.ps1 -server https://api-int.sgao.qe.devcluster.openshift.com:22623/config/worker -output C:\\Windows\\Temp\\worker.ign -useragent Ignition/0.35.0", "output": ""}
2020-07-24T08:34:58.255Z	DEBUG	VM i-0181b2e1f467b1298	output from wmcb	{"output": "Bootstrapping completed successfully"}
2020-07-24T08:35:13.261Z	DEBUG	nodeconfig	worker label %s already present on node %s	{"node-role.kubernetes.io/worker": "ip-10-0-151-105.us-east-2.compute.internal"}
2020-07-24T08:38:08.664Z	DEBUG	VM i-0181b2e1f467b1298	started service	{"name": "kube-proxy", "binary": "C:\\k\\kube-proxy.exe", "args": "--windows-service --v=4 --proxy-mode=kernelspace --feature-gates=WinOverlay=true --hostname-override=ip-10-0-151-105.us-east-2.compute.internal --kubeconfig=c:\\k\\kubeconfig --cluster-cidr=10.132.0.0/24 --log-dir=C:\\k\\log\\kube-proxy\\ --logtostderr=false --network-name=OVNKubernetesHybridOverlayNetwork --source-vip=10.132.0.23 --enable-dsr=false"}
2020-07-24T08:38:08.664Z	INFO	windowsmachine-controller	Windows VM has joined the cluster as a worker node	{"ID": "i-0181b2e1f467b1298"}
2020-07-24T08:38:08.664Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "windowsmachine-controller", "request": "openshift-machine-api/sgao-d2wtc-windows-worker-us-east-2a-6nr8v"}
2020-07-24T08:38:08.664Z	INFO	windowsmachine-controller	reconciling	{"namespace": "openshift-machine-api", "name": "sgao-d2wtc-windows-worker-us-east-2a-6nr8v"}
2020-07-24T08:38:08.665Z	DEBUG	controller-runtime.manager.events	Normal	{"object": {"kind":"Machine","namespace":"openshift-machine-api","name":"sgao-d2wtc-windows-worker-us-east-2a-6nr8v","uid":"637fa39c-1c09-476f-a21a-e68c202fddfa","apiVersion":"machine.openshift.io/v1beta1","resourceVersion":"297231"}, "reason": "WMCO Setup", "message": "Machine sgao-d2wtc-windows-worker-us-east-2a-6nr8v Configured Successfully"}
2020-07-24T08:38:08.673Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "windowsmachine-controller", "request": "openshift-machine-api/sgao-d2wtc-windows-worker-us-east-2a-6nr8v"}


Actual results:
ill log format "nodeconfig	worker label %s already present on node %s"

Expected results:
log format correct

Additional info:

Comment 3 gaoshang 2020-09-02 15:36:16 UTC
This bug has been verified on OCP 4.6.0-0.nightly-2020-09-01-070508 by checking WMCO logs, related code removed, thanks.

Comment 5 errata-xmlrpc 2020-10-27 16:16:56 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 (OpenShift Container Platform 4.6 GA Images), 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-2020:4196


Note You need to log in before you can comment on or make changes to this bug.