Merge pull request #108159 from pohly/logcheck

logcheck update and golangci-lint integration

.golangci.yaml

@@ -21,10 +21,17 @@ linters:
   # - structcheck
   # - varcheck
     - ineffassign
+    - logcheck
     - staticcheck
     - unused
 
 linters-settings: # please keep this alphabetized
+  custom:
+    logcheck:
+      # Installed there by hack/verify-golangci-lint.sh.
+      path: _output/local/bin/logcheck.so
+      description: structured logging checker
+      original-url: k8s.io/klog/hack/tools
   staticcheck:
     go: "1.17"
     checks: [

cmd/kube-scheduler/app/options/configfile.go

@@ -93,7 +93,7 @@ func LogOrWriteConfig(fileName string, cfg *config.KubeSchedulerConfiguration, c
 	}
 
 	if klogV.Enabled() {
-		klogV.Info("Using component config", "\n-------------------------Configuration File Contents Start Here---------------------- \n", buf.String(), "\n------------------------------------Configuration File Contents End Here---------------------------------\n")
+		klogV.InfoS("Using component config", "config", buf.String())
 	}
 
 	if len(fileName) > 0 {

cmd/kubeadm/app/util/users/users_linux.go

@@ -149,11 +149,11 @@ func addUsersAndGroupsImpl(pathLoginDef, pathUsers, pathGroups string) (*UsersAn
 	var loginDef string
 	f, close, err := openFileWithLock(pathLoginDef)
 	if err != nil {
-		klog.V(1).Info("Could not open %q, using default system limits: %v", pathLoginDef, err)
+		klog.V(1).Infof("Could not open %q, using default system limits: %v", pathLoginDef, err)
 	} else {
 		loginDef, err = readFile(f)
 		if err != nil {
-			klog.V(1).Info("Could not read %q, using default system limits: %v", pathLoginDef, err)
+			klog.V(1).Infof("Could not read %q, using default system limits: %v", pathLoginDef, err)
 		}
 		close()
 	}

hack/logcheck.conf

@@ -0,0 +1,22 @@
+# This file contains regular expressions that are matched against <pkg>/<file>,
+# for example k8s.io/cmd/kube-scheduler/app/config/config.go.
+#
+# By default, structured logging call parameters are checked, but usage of
+# those calls is not required. That is changed on a per-file basis.
+#
+# Remember to clean the golangci-lint cache when changing the configuration and
+# running the verify-golangci-lint.sh script multiple times, otherwise
+# golangci-lint will report stale results:
+#    _output/local/bin/golangci-lint cache clean
+
+# At this point we don't enforce the usage structured logging calls except in
+# those packages that were migrated. This disables the check for other files.
+-structured .*
+
+# Now enable it again for migrated packages.
+structured k8s.io/kubernetes/cmd/kube-proxy/.*
+structured k8s.io/kubernetes/cmd/kube-scheduler/.*
+structured k8s.io/kubernetes/cmd/kubelet/.*
+structured k8s.io/kubernetes/pkg/kubelet/.*
+structured k8s.io/kubernetes/pkg/proxy/.*
+structured k8s.io/kubernetes/pkg/scheduler/.*

hack/make-rules/verify.sh

@@ -35,7 +35,6 @@ EXCLUDED_PATTERNS=(
   "verify-linkcheck.sh"          # runs in separate Jenkins job once per day due to high network usage
   "verify-*-dockerized.sh"       # Don't run any scripts that intended to be run dockerized
   "verify-govet-levee.sh"        # Do not run levee analysis by default while KEP-1933 implementation is in alpha.
-  "verify-structured-logging.sh"        # TODO(dims) Need to get this running with golang 1.18
   )
 
 # Exclude generated-files-remake in certain cases, if they're running in a separate job.

hack/tools/go.mod

@@ -11,6 +11,6 @@ require (
 	github.com/google/go-flow-levee v0.1.5
 	gotest.tools/gotestsum v1.6.4
 	honnef.co/go/tools v0.2.2
-	k8s.io/klog/hack/tools v0.0.0-20210917071902-331d2323a192
+	k8s.io/klog/hack/tools v0.0.0-20220321210246-c697110cd8ac
 	sigs.k8s.io/zeitgeist v0.2.0
 )

hack/tools/go.sum

@@ -1521,8 +1521,8 @@ honnef.co/go/tools v0.0.1-2020.1.3/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9
 honnef.co/go/tools v0.0.1-2020.1.4/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k=
 honnef.co/go/tools v0.2.2 h1:MNh1AVMyVX23VUHE2O27jm6lNj3vjO5DexS4A1xvnzk=
 honnef.co/go/tools v0.2.2/go.mod h1:lPVVZ2BS5TfnjLyizF7o7hv7j9/L+8cZY2hLyjP9cGY=
-k8s.io/klog/hack/tools v0.0.0-20210917071902-331d2323a192 h1:u27Xm1of9MTDM1CZW3hg0Vv04ohywEG152G8mpr9n8Y=
-k8s.io/klog/hack/tools v0.0.0-20210917071902-331d2323a192/go.mod h1:DXW3Mv8xqJvjXWiBSBHrK2O4mq5LMD0clqkv3b1g9HA=
+k8s.io/klog/hack/tools v0.0.0-20220321210246-c697110cd8ac h1:c2NQfDLtcwrPdD9pnUcRPlMJ719zgRzdlufHULIW7mU=
+k8s.io/klog/hack/tools v0.0.0-20220321210246-c697110cd8ac/go.mod h1:DXW3Mv8xqJvjXWiBSBHrK2O4mq5LMD0clqkv3b1g9HA=
 k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE=
 k8s.io/utils v0.0.0-20210802155522-efc7438f0176/go.mod h1:jPW/WVKK9YHAvNhRxK0md/EJ228hCsBRufyofKtW8HA=
 mvdan.cc/gofumpt v0.3.0 h1:kTojdZo9AcEYbQYhGuLf/zszYthRdhDNDUi2JKTxas4=

hack/verify-golangci-lint.sh

@@ -36,14 +36,25 @@ PATH="${GOBIN}:${PATH}"
 export GO111MODULE=on
 
 # Install golangci-lint
-echo 'installing golangci-lint '
+echo "installing golangci-lint and logcheck plugin from hack/tools into ${GOBIN}"
 pushd "${KUBE_ROOT}/hack/tools" >/dev/null
   go install github.com/golangci/golangci-lint/cmd/golangci-lint
+  go build -o "${GOBIN}/logcheck.so" -buildmode=plugin k8s.io/klog/hack/tools/logcheck/plugin
 popd >/dev/null
 
 cd "${KUBE_ROOT}"
 
-# The config is in ${KUBE_ROOT}/.golangci.yaml
+# The config is in ${KUBE_ROOT}/.golangci.yaml where it will be found
+# even when golangci-lint is invoked in a sub-directory.
+#
+# The logcheck plugin currently has to be configured via env variables
+# (https://github.com/golangci/golangci-lint/issues/1512).
+#
+# Remember to clean the golangci-lint cache when changing
+# the configuration and running this script multiple times,
+# otherwise golangci-lint will report stale results:
+# _output/local/bin/golangci-lint cache clean
+export LOGCHECK_CONFIG="${KUBE_ROOT}/hack/logcheck.conf"
 echo 'running golangci-lint ' >&2
 res=0
 if [[ "$#" -gt 0 ]]; then

pkg/kubelet/pleg/generic.go

@@ -406,6 +406,9 @@ func (g *GenericPLEG) updateCache(pod *kubecontainer.Pod, pid types.UID) error {
 	// all containers again.
 	status, err := g.runtime.GetPodStatus(pod.ID, pod.Name, pod.Namespace)
 	if err != nil {
+		// nolint:logcheck // Not using the result of klog.V inside the
+		// if branch is okay, we just use it to determine whether the
+		// additional "podStatus" key and its value should be added.
 		if klog.V(6).Enabled() {
 			klog.ErrorS(err, "PLEG: Write status", "pod", klog.KRef(pod.Namespace, pod.Name), "podStatus", status)
 		} else {

pkg/registry/apps/deployment/storage/storage.go

@@ -399,7 +399,7 @@ func (i *scaleUpdatedObjectInfo) UpdatedObject(ctx context.Context, oldObj runti
 		if _, ok := replicasPathInDeployment[requestGroupVersion.String()]; ok {
 			groupVersion = requestGroupVersion
 		} else {
-			klog.Fatal("Unrecognized group/version in request info %q", requestGroupVersion.String())
+			klog.Fatalf("Unrecognized group/version in request info %q", requestGroupVersion.String())
 		}
 	}
 

pkg/registry/apps/replicaset/storage/storage.go

@@ -300,7 +300,7 @@ func (i *scaleUpdatedObjectInfo) UpdatedObject(ctx context.Context, oldObj runti
 		if _, ok := replicasPathInReplicaSet[requestGroupVersion.String()]; ok {
 			groupVersion = requestGroupVersion
 		} else {
-			klog.Fatal("Unrecognized group/version in request info %q", requestGroupVersion.String())
+			klog.Fatalf("Unrecognized group/version in request info %q", requestGroupVersion.String())
 		}
 	}
 

pkg/registry/apps/statefulset/storage/storage.go

@@ -294,7 +294,7 @@ func (i *scaleUpdatedObjectInfo) UpdatedObject(ctx context.Context, oldObj runti
 		if _, ok := replicasPathInStatefulSet[requestGroupVersion.String()]; ok {
 			groupVersion = requestGroupVersion
 		} else {
-			klog.Fatal("Unrecognized group/version in request info %q", requestGroupVersion.String())
+			klog.Fatalf("Unrecognized group/version in request info %q", requestGroupVersion.String())
 		}
 	}
 

pkg/registry/core/replicationcontroller/storage/storage.go

@@ -266,7 +266,7 @@ func (i *scaleUpdatedObjectInfo) UpdatedObject(ctx context.Context, oldObj runti
 		if _, ok := replicasPathInReplicationController[requestGroupVersion.String()]; ok {
 			groupVersion = requestGroupVersion
 		} else {
-			klog.Fatal("Unrecognized group/version in request info %q", requestGroupVersion.String())
+			klog.Fatalf("Unrecognized group/version in request info %q", requestGroupVersion.String())
 		}
 	}
 

pkg/scheduler/internal/cache/debugger/dumper.go

@@ -44,10 +44,12 @@ func (d *CacheDumper) DumpAll() {
 // dumpNodes writes NodeInfo to the scheduler logs.
 func (d *CacheDumper) dumpNodes() {
 	dump := d.cache.Dump()
-	klog.InfoS("Dump of cached NodeInfo")
+	nodeInfos := make([]string, 0, len(dump.Nodes))
 	for name, nodeInfo := range dump.Nodes {
-		klog.Info(d.printNodeInfo(name, nodeInfo))
+		nodeInfos = append(nodeInfos, d.printNodeInfo(name, nodeInfo))
 	}
+	// Extra blank line added between node entries for readability.
+	klog.InfoS("Dump of cached NodeInfo", "nodes", strings.Join(nodeInfos, "\n\n"))
 }
 
 // dumpSchedulingQueue writes pods in the scheduling queue to the scheduler logs.
@@ -57,13 +59,13 @@ func (d *CacheDumper) dumpSchedulingQueue() {
 	for _, p := range pendingPods {
 		podData.WriteString(printPod(p))
 	}
-	klog.Infof("Dump of scheduling queue:\n%s", podData.String())
+	klog.InfoS("Dump of scheduling queue", "pods", podData.String())
 }
 
 // printNodeInfo writes parts of NodeInfo to a string.
 func (d *CacheDumper) printNodeInfo(name string, n *framework.NodeInfo) string {
 	var nodeData strings.Builder
-	nodeData.WriteString(fmt.Sprintf("\nNode name: %s\nDeleted: %t\nRequested Resources: %+v\nAllocatable Resources:%+v\nScheduled Pods(number: %v):\n",
+	nodeData.WriteString(fmt.Sprintf("Node name: %s\nDeleted: %t\nRequested Resources: %+v\nAllocatable Resources:%+v\nScheduled Pods(number: %v):\n",
 		name, n.Node() == nil, n.Requested, n.Allocatable, len(n.Pods)))
 	// Dumping Pod Info
 	for _, p := range n.Pods {

pkg/volume/iscsi/iscsi_util.go

@@ -971,10 +971,10 @@ func ignoreExitCodes(err error, ignoredExitCodes ...int) error {
 func execWithLog(b iscsiDiskMounter, cmd string, args ...string) (string, error) {
 	start := time.Now()
 	out, err := b.exec.Command(cmd, args...).CombinedOutput()
-	if klog.V(5).Enabled() {
+	if klogV := klog.V(5); klogV.Enabled() {
 		d := time.Since(start)
-		klog.V(5).Infof("Executed %s %v in %v, err: %v", cmd, args, d, err)
-		klog.V(5).Infof("Output: %s", string(out))
+		klogV.Infof("Executed %s %v in %v, err: %v", cmd, args, d, err)
+		klogV.Infof("Output: %s", string(out))
 	}
 	return string(out), err
 }

plugin/pkg/auth/authorizer/rbac/rbac.go

@@ -82,7 +82,7 @@ func (r *RBACAuthorizer) Authorize(ctx context.Context, requestAttributes author
 
 	// Build a detailed log of the denial.
 	// Make the whole block conditional so we don't do a lot of string-building we won't use.
-	if klog.V(5).Enabled() {
+	if klogV := klog.V(5); klogV.Enabled() {
 		var operation string
 		if requestAttributes.IsResourceRequest() {
 			b := &bytes.Buffer{}
@@ -116,7 +116,7 @@ func (r *RBACAuthorizer) Authorize(ctx context.Context, requestAttributes author
 			scope = "cluster-wide"
 		}
 
-		klog.Infof("RBAC: no rules authorize user %q with groups %q to %s %s", requestAttributes.GetUser().GetName(), requestAttributes.GetUser().GetGroups(), operation, scope)
+		klogV.Infof("RBAC: no rules authorize user %q with groups %q to %s %s", requestAttributes.GetUser().GetName(), requestAttributes.GetUser().GetGroups(), operation, scope)
 	}
 
 	reason := ""

staging/src/k8s.io/apiserver/pkg/registry/generic/registry/storage_factory.go

@@ -49,8 +49,9 @@ func StorageWithCacher() generic.StorageDecorator {
 		if err != nil {
 			return s, d, err
 		}
-		if klog.V(5).Enabled() {
-			klog.V(5).InfoS("Storage caching is enabled", objectTypeToArgs(newFunc())...)
+		if klogV := klog.V(5); klogV.Enabled() {
+			//nolint:logcheck // It complains about the key/value pairs because it cannot check them.
+			klogV.InfoS("Storage caching is enabled", objectTypeToArgs(newFunc())...)
 		}
 
 		cacherConfig := cacherstorage.Config{

staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness.go

@@ -125,6 +125,10 @@ func WithPriorityAndFairness(
 			workEstimate := workEstimator(r, classification.FlowSchemaName, classification.PriorityLevelName)
 
 			fcmetrics.ObserveWorkEstimatedSeats(classification.PriorityLevelName, classification.FlowSchemaName, workEstimate.MaxSeats())
+			// nolint:logcheck // Not using the result of klog.V
+			// inside the if branch is okay, we just use it to
+			// determine whether the additional information should
+			// be added.
 			if klog.V(4).Enabled() {
 				httplog.AddKeyValue(ctx, "apf_iseats", workEstimate.InitialSeats)
 				httplog.AddKeyValue(ctx, "apf_fseats", workEstimate.FinalSeats)

staging/src/k8s.io/apiserver/pkg/storage/etcd3/logger.go

@@ -32,19 +32,19 @@ type klogWrapper struct{}
 const klogWrapperDepth = 4
 
 func (klogWrapper) Info(args ...interface{}) {
-	if klog.V(5).Enabled() {
-		klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprint(args...))
+	if klogV := klog.V(5); klogV.Enabled() {
+		klogV.InfoSDepth(klogWrapperDepth, fmt.Sprint(args...))
 	}
 }
 
 func (klogWrapper) Infoln(args ...interface{}) {
-	if klog.V(5).Enabled() {
-		klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprintln(args...))
+	if klogV := klog.V(5); klogV.Enabled() {
+		klogV.InfoSDepth(klogWrapperDepth, fmt.Sprintln(args...))
 	}
 }
 
 func (klogWrapper) Infof(format string, args ...interface{}) {
-	if klog.V(5).Enabled() {
+	if klogV := klog.V(5); klogV.Enabled() {
 		klog.V(5).InfoSDepth(klogWrapperDepth, fmt.Sprintf(format, args...))
 	}
 }