Bug 1817186
| Summary: | logr messages are not properly constructed | ||
|---|---|---|---|
| Product: | OpenShift Container Platform | Reporter: | Aravindh Puthiyaparambil <aravindh> |
| Component: | Windows Containers | Assignee: | Mansi Kulkarni <mankulka> |
| Status: | CLOSED ERRATA | QA Contact: | gaoshang <sgao> |
| Severity: | low | Docs Contact: | |
| Priority: | low | ||
| Version: | 4.5 | CC: | aos-bugs, gmarkley, rgudimet |
| Target Milestone: | --- | ||
| Target Release: | 4.5.0 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2020-07-13 17:23:43 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: | |||
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"}
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 |
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