Bug 1817186 - logr messages are not properly constructed
Summary: logr messages are not properly constructed
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Windows Containers
Version: 4.5
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: ---
: 4.5.0
Assignee: Mansi Kulkarni
QA Contact: gaoshang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-03-25 18:26 UTC by Aravindh Puthiyaparambil
Modified: 2020-07-13 17:24 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-07-13 17:23:43 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 34 0 None closed Bug 1817186: [wmco] Fix log panic and correct formatting of log messages 2021-02-15 21:25:45 UTC
Red Hat Product Errata RHBA-2020:2409 0 None None None 2020-07-13 17:23:59 UTC

Description Aravindh Puthiyaparambil 2020-03-25 18:26:39 UTC
Description of problem:
As an WMCO developer I would like to not see panic logs like the following:

{"level":"dpanic","ts":1585152089.2548447,"logger":"controller_windowsmachineconfig","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"configuring node network failed: error waiting for hybrid overlay node annotation: timeout waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation","ignored keyVerbose":"error waiting for hybrid overlay node annotation: timeout waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation\nconfiguring node network failed\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).Configure\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:55\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:280\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:201\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88\nruntime.goexit\n\t/home/aravindh/.go/src/runtime/asm_amd64.s:1357","stacktrace":"github.com/go-logr/zapr.handleFields\n\t/home/aravindh/go/pkg/mod/github.com/go-logr/zapr.1/zapr.go:106\ngithub.com/go-logr/zapr.(*zapLogger).Error\n\t/home/aravindh/go/pkg/mod/github.com/go-logr/zapr.1/zapr.go:129\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:283\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:201\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/home/aravindh/devel/github/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/home/aravindh/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/home/aravindh/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88"}

https://github.com/openshift/windows-machine-config-operator/blob/master/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go#L261 is one such example

Expected behavior
Not see the above panic logs.


How reproducible:


Steps to Reproduce:
1. Bring up a 4.5 cluster without the hybrid overlay configuration
2. Run WMCO
3. Create a WMC CR and set Replicas to 1

Actual results:
The logs will show the above message

Expected results:
The log should not show the above message

Comment 3 gaoshang 2020-04-14 15:28:17 UTC
This bug has been verified and passed on 4.5.0-0.nightly-2020-04-14-084836.

Steps to Reproduce:
1. Bring up a 4.5 cluster without the hybrid overlay configuration
2. Run WMCO
3. Create a WMC CR and set Replicas to 1

# operator-sdk run --local --namespace=windows-machine-config-operator
INFO[0000] Running the operator locally in namespace windows-machine-config-operator. 
{"level":"info","ts":1586875332.7746716,"logger":"cmd","msg":"operator","version":"0.0.1"}
{"level":"info","ts":1586875332.7747426,"logger":"cmd","msg":"go","version":"go1.13.6","os":"linux","arch":"amd64"}
{"level":"info","ts":1586875332.774748,"logger":"cmd","msg":"operator-sdk","version":"v0.15.2"}
{"level":"info","ts":1586875332.7770452,"logger":"leader","msg":"Trying to become the leader."}
{"level":"info","ts":1586875332.777065,"logger":"leader","msg":"Skipping leader election; not running in a cluster."}
{"level":"info","ts":1586875335.0238614,"logger":"controller-runtime.metrics","msg":"metrics server is starting to listen","addr":"0.0.0.0:8383"}
{"level":"info","ts":1586875335.0240836,"logger":"cmd","msg":"registering Components."}
{"level":"info","ts":1586875335.024779,"logger":"cmd","msg":"skipping CR metrics server creation; not running in a cluster."}
{"level":"info","ts":1586875335.024793,"logger":"cmd","msg":"starting the Cmd."}
{"level":"info","ts":1586875335.0250785,"logger":"controller-runtime.manager","msg":"starting metrics server","path":"/metrics"}
{"level":"info","ts":1586875335.0251133,"logger":"controller-runtime.controller","msg":"Starting EventSource","controller":"windowsmachineconfig-controller","source":"kind source: /, Kind="}
{"level":"info","ts":1586875335.12556,"logger":"controller-runtime.controller","msg":"Starting EventSource","controller":"windowsmachineconfig-controller","source":"kind source: /, Kind="}
{"level":"info","ts":1586875335.2258768,"logger":"controller-runtime.controller","msg":"Starting Controller","controller":"windowsmachineconfig-controller"}
{"level":"info","ts":1586875335.2259357,"logger":"controller-runtime.controller","msg":"Starting workers","controller":"windowsmachineconfig-controller","worker count":1}
{"level":"info","ts":1586875456.7338836,"logger":"controller_windowsmachineconfig","msg":"reconciling WindowsMachineConfig","Request.Namespace":"windows-machine-config-operator","Request.Name":"instance"}
2020/04/14 10:44:16 kubeconfig source: /root/ocp/aws/cluster/auth/kubeconfig
2020/04/14 10:44:18 Using existing Security Group: sg-06fe07cac1e29b751
{"level":"info","ts":1586875699.506054,"logger":"windows","msg":"bootstrapper initialization failed","stderr":"{\"level\":\"info\",\"ts\":1586875736.5884628,\"logger\":\"wmcb\",\"msg\":\"Bootstrapping completed successfully\"}\n"}
{"level":"error","ts":1586876329.9807088,"logger":"controller_windowsmachineconfig","msg":"configuring Windows VM failed","error":"configuring node network failed: error waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation for ip-10-0-21-135.us-east-2.compute.internal: timeout waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation: timed out waiting for the condition","errorVerbose":"timed out waiting for the condition\ntimeout waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).waitForNodeAnnotation\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:259\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).configureNetwork\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:81\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).Configure\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:56\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:273\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:196\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1357\nerror waiting for k8s.ovn.org/hybrid-overlay-node-subnet node annotation for ip-10-0-21-135.us-east-2.compute.internal\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).configureNetwork\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:82\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).Configure\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:56\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:273\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:196\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1357\nconfiguring node network failed\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig.(*nodeConfig).Configure\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/nodeconfig/nodeconfig.go:57\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:273\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:196\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88\nruntime.goexit\n\t/usr/lib/golang/src/runtime/asm_amd64.s:1357","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/root/go/pkg/mod/github.com/go-logr/zapr.1/zapr.go:128\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).createWindowsWorkerNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:276\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).reconcileWindowsNodes\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:196\ngithub.com/openshift/windows-machine-config-operator/pkg/controller/windowsmachineconfig.(*ReconcileWindowsMachineConfig).Reconcile\n\t/root/go/src/windows-machine-config-operator/pkg/controller/windowsmachineconfig/windowsmachineconfig_controller.go:174\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:256\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:232\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker\n\t/root/go/pkg/mod/sigs.k8s.io/controller-runtime.0/pkg/internal/controller/controller.go:211\nk8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:152\nk8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:153\nk8s.io/apimachinery/pkg/util/wait.Until\n\t/root/go/pkg/mod/k8s.io/apimachinery.7/pkg/util/wait/wait.go:88"}

Comment 5 errata-xmlrpc 2020-07-13 17:23:43 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-2020:2409


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