Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

✨ Improve startup logs #1687

Merged

Conversation

sbueringer
Copy link
Member

@sbueringer sbueringer commented Oct 7, 2021

Signed-off-by: Stefan Büringer [email protected]

Just a few improvements to the startup log:

  • use upper case
  • there are a few cases where we currently log empty objects which looks pretty strange

Full startup log example in CAPI with these changes:

I1007 19:21:44.108670   72015 request.go:665] Waited for 1.030197259s due to client-side throttling, not priority and fairness, request: GET:https://127.0.0.1:53980/apis/controlplane.cluster.x-k8s.io/v1alpha4?timeout=32s
I1007 19:21:44.263389   72015 deleg.go:130] controller-runtime/metrics "msg"="Metrics server is starting to listen"  "addr"="localhost:8080"
I1007 19:21:44.267053   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterClass"} "path"="/mutate-cluster-x-k8s-io-v1beta1-clusterclass"
I1007 19:21:44.267302   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-clusterclass" 
I1007 19:21:44.267452   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterClass"} "path"="/validate-cluster-x-k8s-io-v1beta1-clusterclass"
I1007 19:21:44.267518   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-clusterclass" 
I1007 19:21:44.267676   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/convert" 
I1007 19:21:44.267723   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterClass"}
I1007 19:21:44.267751   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1beta1-cluster"
I1007 19:21:44.267807   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-cluster" 
I1007 19:21:44.267861   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1beta1-cluster"
I1007 19:21:44.267973   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-cluster" 
I1007 19:21:44.268137   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Cluster"}
I1007 19:21:44.268175   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1beta1-machine"
I1007 19:21:44.268262   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-machine" 
I1007 19:21:44.268336   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Machine"} "path"="/validate-cluster-x-k8s-io-v1beta1-machine"
I1007 19:21:44.268401   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-machine" 
I1007 19:21:44.268486   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"Machine"}
I1007 19:21:44.268518   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineSet"} "path"="/mutate-cluster-x-k8s-io-v1beta1-machineset"
I1007 19:21:44.268576   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-machineset" 
I1007 19:21:44.268625   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineSet"} "path"="/validate-cluster-x-k8s-io-v1beta1-machineset"
I1007 19:21:44.268689   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-machineset" 
I1007 19:21:44.268812   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineSet"}
I1007 19:21:44.268863   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineDeployment"} "path"="/mutate-cluster-x-k8s-io-v1beta1-machinedeployment"
I1007 19:21:44.268962   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-machinedeployment" 
I1007 19:21:44.269022   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineDeployment"} "path"="/validate-cluster-x-k8s-io-v1beta1-machinedeployment"
I1007 19:21:44.269083   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-machinedeployment" 
I1007 19:21:44.269173   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineDeployment"}
I1007 19:21:44.269209   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachinePool"} "path"="/mutate-cluster-x-k8s-io-v1beta1-machinepool"
I1007 19:21:44.269264   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-machinepool" 
I1007 19:21:44.269313   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachinePool"} "path"="/validate-cluster-x-k8s-io-v1beta1-machinepool"
I1007 19:21:44.269369   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-machinepool" 
I1007 19:21:44.269454   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachinePool"}
I1007 19:21:44.269484   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterResourceSet"} "path"="/mutate-addons-cluster-x-k8s-io-v1beta1-clusterresourceset"
I1007 19:21:44.269564   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-addons-cluster-x-k8s-io-v1beta1-clusterresourceset" 
I1007 19:21:44.269626   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1beta1-clusterresourceset"
I1007 19:21:44.269683   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-addons-cluster-x-k8s-io-v1beta1-clusterresourceset" 
I1007 19:21:44.269759   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1beta1","Kind":"ClusterResourceSet"}
I1007 19:21:44.269788   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineHealthCheck"} "path"="/mutate-cluster-x-k8s-io-v1beta1-machinehealthcheck"
I1007 19:21:44.270035   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/mutate-cluster-x-k8s-io-v1beta1-machinehealthcheck" 
I1007 19:21:44.270094   72015 deleg.go:130] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineHealthCheck"} "path"="/validate-cluster-x-k8s-io-v1beta1-machinehealthcheck"
I1007 19:21:44.270149   72015 server.go:145] controller-runtime/webhook "msg"="Registering webhook" "path"="/validate-cluster-x-k8s-io-v1beta1-machinehealthcheck" 
I1007 19:21:44.270473   72015 deleg.go:130] controller-runtime/builder "msg"="Conversion webhook enabled"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1beta1","Kind":"MachineHealthCheck"}
I1007 19:21:44.270494   72015 deleg.go:130] setup "msg"="starting manager"  "version"=""
I1007 19:21:44.373646   72015 server.go:213] controller-runtime/webhook/webhooks "msg"="Starting webhook server"  
I1007 19:21:44.373790   72015 internal.go:383]  "msg"="Starting metrics server"  "path"="/metrics"
I1007 19:21:44.374420   72015 controller.go:178] controller/machinepool "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachinePool" "source"="kind source: *v1beta1.MachinePool"
I1007 19:21:44.374431   72015 controller.go:178] controller/topology/machinedeployment "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "source"="kind source: *v1beta1.MachineDeployment"
I1007 19:21:44.374420   72015 controller.go:178] controller/machine "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Machine" "source"="kind source: *v1beta1.Machine"
I1007 19:21:44.374421   72015 controller.go:178] controller/topology/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374469   72015 controller.go:178] controller/machinepool "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachinePool" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374440   72015 controller.go:178] controller/topology/machineset "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "source"="kind source: *v1beta1.MachineSet"
I1007 19:21:44.374495   72015 controller.go:178] controller/machineset "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "source"="kind source: *v1beta1.MachineSet"
I1007 19:21:44.374470   72015 controller.go:186] controller/topology/machinedeployment "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" 
I1007 19:21:44.374520   72015 controller.go:186] controller/topology/machineset "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" 
I1007 19:21:44.374527   72015 controller.go:178] controller/topology/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.ClusterClass"
I1007 19:21:44.374681   72015 controller.go:178] controller/machinehealthcheck "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" "source"="kind source: *v1beta1.MachineHealthCheck"
I1007 19:21:44.374500   72015 controller.go:186] controller/machinepool "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachinePool" 
I1007 19:21:44.374721   72015 controller.go:178] controller/topology/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.MachineDeployment"
I1007 19:21:44.374743   72015 controller.go:178] controller/machinedeployment "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "source"="kind source: *v1beta1.MachineDeployment"
I1007 19:21:44.374795   72015 controller.go:178] controller/clusterresourcesetbinding "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSetBinding" "source"="kind source: *v1beta1.ClusterResourceSetBinding"
I1007 19:21:44.374518   72015 controller.go:178] controller/machine "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Machine" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374544   72015 controller.go:178] controller/machineset "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "source"="kind source: *v1beta1.Machine"
I1007 19:21:44.374866   72015 controller.go:178] controller/machinedeployment "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "source"="kind source: *v1beta1.MachineSet"
I1007 19:21:44.374885   72015 controller.go:178] controller/clusterresourcesetbinding "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSetBinding" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374910   72015 controller.go:178] controller/machineset "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "source"="kind source: *v1beta1.Machine"
I1007 19:21:44.374917   72015 controller.go:186] controller/machine "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Machine" 
I1007 19:21:44.374602   72015 controller.go:178] controller/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374931   72015 controller.go:178] controller/machinedeployment "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "source"="kind source: *v1beta1.MachineSet"
I1007 19:21:44.374949   72015 controller.go:178] controller/machineset "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374614   72015 controller.go:178] controller/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.375501   72015 controller.go:178] controller/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"="kind source: *v1beta1.Machine"
I1007 19:21:44.374748   72015 controller.go:186] controller/topology/cluster "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" 
I1007 19:21:44.375558   72015 controller.go:186] controller/cluster "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" 
I1007 19:21:44.375577   72015 controller.go:186] controller/machineset "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" 
I1007 19:21:44.374675   72015 controller.go:178] controller/clusterresourceset "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" "source"="kind source: *v1beta1.ClusterResourceSet"
I1007 19:21:44.375681   72015 controller.go:186] controller/cluster "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" 
I1007 19:21:44.374721   72015 controller.go:178] controller/machinehealthcheck "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" "source"="kind source: *v1beta1.Machine"
I1007 19:21:44.375816   72015 controller.go:178] controller/machinehealthcheck "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.375852   72015 controller.go:186] controller/machinehealthcheck "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" 
I1007 19:21:44.375962   72015 controller.go:178] controller/clusterresourceset "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.374941   72015 controller.go:186] controller/clusterresourcesetbinding "msg"="Starting Controller" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSetBinding" 
I1007 19:21:44.374981   72015 controller.go:178] controller/machinedeployment "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "source"="kind source: *v1beta1.Cluster"
I1007 19:21:44.375017   72015 deleg.go:130] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I1007 19:21:44.376384   72015 controller.go:178] controller/clusterresourceset "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" "source"="kind source: *v1.PartialObjectMetadata"
I1007 19:21:44.376458   72015 controller.go:178] controller/clusterresourceset "msg"="Starting EventSource" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" "source"="kind source: *v1.PartialObjectMetadata"
I1007 19:21:44.376485   72015 controller.go:186] controller/machinedeployment "msg"="Starting Controller" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" 
I1007 19:21:44.376526   72015 controller.go:186] controller/clusterresourceset "msg"="Starting Controller" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" 
I1007 19:21:44.376772   72015 deleg.go:130] controller-runtime/webhook "msg"="Serving webhook server"  "host"="" "port"=9443
I1007 19:21:44.377638   72015 deleg.go:130] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I1007 19:21:44.476509   72015 controller.go:220] controller/machine "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Machine" "worker count"=10
I1007 19:21:44.476524   72015 controller.go:220] controller/machinepool "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachinePool" "worker count"=10
I1007 19:21:44.476610   72015 controller.go:220] controller/topology/machineset "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "worker count"=1
I1007 19:21:44.476661   72015 controller.go:220] controller/cluster "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "worker count"=10
I1007 19:21:44.477479   72015 controller.go:220] controller/cluster "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "worker count"=10
I1007 19:21:44.477941   72015 controller.go:220] controller/machinedeployment "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "worker count"=10
I1007 19:21:44.477971   72015 controller.go:220] controller/clusterresourceset "msg"="Starting workers" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSet" "worker count"=10
I1007 19:21:44.478006   72015 controller.go:220] controller/topology/cluster "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "worker count"=10
I1007 19:21:44.478182   72015 controller.go:220] controller/topology/machinedeployment "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineDeployment" "worker count"=1
I1007 19:21:44.478241   72015 controller.go:220] controller/machineset "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineSet" "worker count"=10
I1007 19:21:44.478288   72015 controller.go:220] controller/machinehealthcheck "msg"="Starting workers" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" "worker count"=10
I1007 19:21:44.478313   72015 controller.go:220] controller/clusterresourcesetbinding "msg"="Starting workers" "reconciler group"="addons.cluster.x-k8s.io" "reconciler kind"="ClusterResourceSetBinding" "worker count"=10
I1007 19:21:44.590389   72015 tracker.go:55] controller/cluster "msg"="Adding watcher on external object" "name"="quick-start-sl8djg" "namespace"="quick-start-g5oqcm" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1beta1, Kind=DockerCluster"
I1007 19:21:44.590475   72015 controller.go:143] controller/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1beta1","kind":"DockerCluster"}}
I1007 19:21:44.600194   72015 tracker.go:55] controller/cluster "msg"="Adding watcher on external object" "name"="quick-start-sl8djg" "namespace"="quick-start-g5oqcm" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "GroupVersionKind"="controlplane.cluster.x-k8s.io/v1beta1, Kind=KubeadmControlPlane"
I1007 19:21:44.600252   72015 controller.go:143] controller/cluster "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Cluster" "source"={"Type":{"apiVersion":"controlplane.cluster.x-k8s.io/v1beta1","kind":"KubeadmControlPlane"}}
E1007 19:21:49.533596   72015 machine_controller.go:236] controller/machine "msg"="error watching nodes on target cluster" "error"="error creating client and cache for remote cluster: error creating dynamic rest mapper for remote cluster \"quick-start-g5oqcm/quick-start-sl8djg\": Get \"https://172.18.0.3:6443/api?timeout=10s\": dial tcp 172.18.0.3:6443: connect: network is unreachable" "name"="quick-start-sl8djg-control-plane-d6p2n" "namespace"="quick-start-g5oqcm" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="Machine" 

Signed-off-by: Stefan Büringer [email protected]
@k8s-ci-robot k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Oct 7, 2021
@k8s-ci-robot k8s-ci-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Oct 7, 2021
@@ -132,14 +132,14 @@ func (blder *WebhookBuilder) registerValidatingWebhook() {
func (blder *WebhookBuilder) registerConversionWebhook() error {
ok, err := conversion.IsConvertible(blder.mgr.GetScheme(), blder.apiType)
if err != nil {
log.Error(err, "conversion check failed", "object", blder.apiType)
log.Error(err, "conversion check failed", "GVK", blder.gvk)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

apiType is usually just an empty API type (e.g. https://github.com/kubernetes-sigs/cluster-api/blob/f4380fc82fa2eef5119967d9bfea9d428e103e76/api/v1beta1/cluster_webhook.go#L34-L38)
So it's better to log gvk

We're also doing it already for the other webhooks, e.g. l.125

@@ -175,7 +175,7 @@ func (c *Controller) Start(ctx context.Context) error {
// caches to sync so that they have a chance to register their intendeded
// caches.
for _, watch := range c.startWatches {
c.Log.Info("Starting EventSource", "source", watch.src)
c.Log.Info("Starting EventSource", "source", fmt.Sprintf("%s", watch.src))
Copy link
Member Author

@sbueringer sbueringer Oct 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Otherwise the String() func is not called and instead the watch.src is logged, which is again mostly an empty api struct (link). Which looks roughly like that:

I1007 16:29:17.183304       1 controller.go:178] controller/machinehealthcheck "msg"="Starting EventSource" "reconciler group"="cluster.x-k8s.io" "reconciler kind"="MachineHealthCheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","selector":{},"unhealthyConditions":null},"status":{"expectedMachines":0,"currentHealthy":0,"remediationsAllowed":0}}}

https://storage.googleapis.com/kubernetes-jenkins/logs/periodic-cluster-api-e2e-main/1446148448939151360/artifacts/clusters/bootstrap/controllers/capi-controller-manager/capi-controller-manager-77b95c5bc7-xrdd4/manager.log

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Interesting, I would have expected the logger to call .String() if it is implemented. Maybe get rid of the fmt.Sprintf anduse just watch.src.String()?

Copy link
Member Author

@sbueringer sbueringer Oct 11, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That was my first thought. But as String() is not part of the source.Source interface it's not possible without a cast (or adding it to the interface).

@@ -142,10 +142,10 @@ func (ks *Kind) Start(ctx context.Context, handler handler.EventHandler, queue w
}

func (ks *Kind) String() string {
if ks.Type != nil && ks.Type.GetObjectKind() != nil {
return fmt.Sprintf("kind source: %v", ks.Type.GetObjectKind().GroupVersionKind().String())
if ks.Type != nil {
Copy link
Member Author

@sbueringer sbueringer Oct 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assuming that source.Kind is usually created with an empty struct like here there is in ObjectKind but it's empty. So this would look something like this kind source: .

So if we don't want to look up the gvk via the struct, the best we can do is simply log the Go type.

@vincepri
Copy link
Member

vincepri commented Oct 9, 2021

Lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 11, 2021
@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: alvaroaleman, sbueringer

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 11, 2021
@k8s-ci-robot k8s-ci-robot merged commit 4d6d8ef into kubernetes-sigs:master Oct 11, 2021
@k8s-ci-robot k8s-ci-robot added this to the v0.10.x milestone Oct 11, 2021
@sbueringer sbueringer deleted the pr-improve-startup-logs branch October 11, 2021 17:37
@sbueringer
Copy link
Member Author

/cherrypick release-0.10

@k8s-infra-cherrypick-robot

@sbueringer: new pull request created: #1692

In response to this:

/cherrypick release-0.10

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. lgtm "Looks good to me", indicates that a PR is ready to be merged. size/S Denotes a PR that changes 10-29 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants