Skip to content

Commit

Permalink
enhance and fix log calls
Browse files Browse the repository at this point in the history
Some of these changes are cosmetic (repeatedly calling klog.V instead of
reusing the result), others address real issues:

- Logging a message only above a certain verbosity threshold without
  recording that verbosity level (if klog.V().Enabled() { klog.Info... }):
  this matters when using a logging backend which records the verbosity
  level.

- Passing a format string with parameters to a logging function that
  doesn't do string formatting.

All of these locations where found by the enhanced logcheck tool from
kubernetes/klog#297.

In some cases it reports false positives, but those can be suppressed with
source code comments.
  • Loading branch information
pohly committed Mar 24, 2022
1 parent 0f4d066 commit edffc70
Show file tree
Hide file tree
Showing 17 changed files with 39 additions and 28 deletions.
4 changes: 2 additions & 2 deletions cmd/kubeadm/app/util/users/users_linux.go
Expand Up @@ -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()
}
Expand Down
3 changes: 3 additions & 0 deletions pkg/kubelet/pleg/generic.go
Expand Up @@ -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 {
Expand Down
2 changes: 1 addition & 1 deletion pkg/registry/apps/deployment/storage/storage.go
Expand Up @@ -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())
}
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/registry/apps/replicaset/storage/storage.go
Expand Up @@ -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())
}
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/registry/apps/statefulset/storage/storage.go
Expand Up @@ -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())
}
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/registry/core/replicationcontroller/storage/storage.go
Expand Up @@ -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())
}
}

Expand Down
6 changes: 3 additions & 3 deletions pkg/volume/iscsi/iscsi_util.go
Expand Up @@ -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
}
4 changes: 2 additions & 2 deletions plugin/pkg/auth/authorizer/rbac/rbac.go
Expand Up @@ -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{}
Expand Down Expand Up @@ -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 := ""
Expand Down
Expand Up @@ -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{
Expand Down
Expand Up @@ -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)
Expand Down
10 changes: 5 additions & 5 deletions staging/src/k8s.io/apiserver/pkg/storage/etcd3/logger.go
Expand Up @@ -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...))
}
}
Expand Down
Expand Up @@ -434,8 +434,8 @@ func (cfgCtlr *configController) digestConfigObjects(newPLs []*flowcontrol.Prior

// if we are going to issue an update, be sure we track every name we update so we know if we update it too often.
currResult.updatedItems.Insert(fsu.flowSchema.Name)
if klog.V(4).Enabled() {
klog.V(4).Infof("%s writing Condition %s to FlowSchema %s, which had ResourceVersion=%s, because its previous value was %s, diff: %s",
if klogV := klog.V(4); klogV.Enabled() {
klogV.Infof("%s writing Condition %s to FlowSchema %s, which had ResourceVersion=%s, because its previous value was %s, diff: %s",
cfgCtlr.name, fsu.condition, fsu.flowSchema.Name, fsu.flowSchema.ResourceVersion, fcfmt.Fmt(fsu.oldValue), cmp.Diff(fsu.oldValue, fsu.condition))
}
fsIfc := cfgCtlr.flowcontrolClient.FlowSchemas()
Expand Down
Expand Up @@ -573,9 +573,9 @@ func (qs *queueSet) shuffleShardLocked(hashValue uint64, descr1, descr2 interfac
bestQueueIdx = queueIdx
}
}
if klog.V(6).Enabled() {
if klogV := klog.V(6); klogV.Enabled() {
chosenQueue := qs.queues[bestQueueIdx]
klog.V(6).Infof("QS(%s) at t=%s R=%v: For request %#+v %#+v chose queue %d, with sum: %#v & %d seats in use & nextDispatchR=%v", qs.qCfg.Name, qs.clock.Now().Format(nsTimeFmt), qs.currentR, descr1, descr2, bestQueueIdx, chosenQueue.requests.QueueSum(), chosenQueue.seatsInUse, chosenQueue.nextDispatchR)
klogV.Infof("QS(%s) at t=%s R=%v: For request %#+v %#+v chose queue %d, with sum: %#v & %d seats in use & nextDispatchR=%v", qs.qCfg.Name, qs.clock.Now().Format(nsTimeFmt), qs.currentR, descr1, descr2, bestQueueIdx, chosenQueue.requests.QueueSum(), chosenQueue.seatsInUse, chosenQueue.nextDispatchR)
}
return bestQueueIdx
}
Expand Down
6 changes: 3 additions & 3 deletions staging/src/k8s.io/client-go/rest/request.go
Expand Up @@ -1051,13 +1051,13 @@ func truncateBody(body string) string {
// allocating a new string for the body output unless necessary. Uses a simple heuristic to determine
// whether the body is printable.
func glogBody(prefix string, body []byte) {
if klog.V(8).Enabled() {
if klogV := klog.V(8); klogV.Enabled() {
if bytes.IndexFunc(body, func(r rune) bool {
return r < 0x0a
}) != -1 {
klog.Infof("%s:\n%s", prefix, truncateBody(hex.Dump(body)))
klogV.Infof("%s:\n%s", prefix, truncateBody(hex.Dump(body)))
} else {
klog.Infof("%s: %s", prefix, truncateBody(string(body)))
klogV.Infof("%s: %s", prefix, truncateBody(string(body)))
}
}
}
Expand Down
1 change: 1 addition & 0 deletions staging/src/k8s.io/component-base/logs/json/json_test.go
Expand Up @@ -65,6 +65,7 @@ func TestZapLoggerInfo(t *testing.T) {
var buffer bytes.Buffer
writer := zapcore.AddSync(&buffer)
sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil)
// nolint:logcheck // The linter cannot and doesn't need to check the key/value pairs.
sampleInfoLogger.Info(data.msg, data.keysValues...)
logStr := buffer.String()

Expand Down
2 changes: 2 additions & 0 deletions staging/src/k8s.io/kubectl/pkg/cmd/util/helpers.go
Expand Up @@ -93,6 +93,8 @@ func DefaultBehaviorOnFatal() {
// klog.Fatal is invoked for extended information. This is intended for maintainer
// debugging and out of a reasonable range for users.
func fatal(msg string, code int) {
// nolint:logcheck // Not using the result of klog.V(99) inside the if
// branch is okay, we just use it to determine how to terminate.
if klog.V(99).Enabled() {
klog.FatalDepth(2, msg)
}
Expand Down
Expand Up @@ -31,7 +31,7 @@ import (
"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/meta"
"github.com/google/go-cmp/cmp"
compute "google.golang.org/api/compute/v1"
"k8s.io/api/core/v1"
v1 "k8s.io/api/core/v1"
"k8s.io/apimachinery/pkg/types"
"k8s.io/apimachinery/pkg/util/sets"
cloudprovider "k8s.io/cloud-provider"
Expand Down Expand Up @@ -202,9 +202,9 @@ func (g *Cloud) ensureInternalLoadBalancer(clusterName, clusterID string, svc *v
// Delete existing forwarding rule before making changes to the backend service. For example - changing protocol
// of backend service without first deleting forwarding rule will throw an error since the linked forwarding
// rule would show the old protocol.
if klog.V(2).Enabled() {
if klogV := klog.V(2); klogV.Enabled() {
frDiff := cmp.Diff(existingFwdRule, newFwdRule)
klog.V(2).Infof("ensureInternalLoadBalancer(%v): forwarding rule changed - Existing - %+v\n, New - %+v\n, Diff(-existing, +new) - %s\n. Deleting existing forwarding rule.", loadBalancerName, existingFwdRule, newFwdRule, frDiff)
klogV.Infof("ensureInternalLoadBalancer(%v): forwarding rule changed - Existing - %+v\n, New - %+v\n, Diff(-existing, +new) - %s\n. Deleting existing forwarding rule.", loadBalancerName, existingFwdRule, newFwdRule, frDiff)
}
if err = ignoreNotFound(g.DeleteRegionForwardingRule(loadBalancerName, g.region)); err != nil {
return nil, err
Expand Down

0 comments on commit edffc70

Please sign in to comment.