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

add klog.v(0) and logger.v(0) check #4

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions logcheck/main_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -103,6 +103,21 @@ func TestAnalyzer(t *testing.T) {
},
testPackage: "helpers",
},
{
name: "Do not allow Verbosity Zero logs",
enabled: map[string]string{
"structured": "false",
},
testPackage: "doNotAllowVerbosityZeroLogs",
},
{
name: "Allow Verbosity Zero logs",
enabled: map[string]string{
"structured": "false",
"verbosity-zero": "false",
},
testPackage: "allowVerbosityZeroLogs",
},
}
for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
Expand Down
72 changes: 64 additions & 8 deletions logcheck/pkg/logcheck.go
Original file line number Diff line number Diff line change
Expand Up @@ -32,10 +32,11 @@ import (
)

const (
structuredCheck = "structured"
parametersCheck = "parameters"
contextualCheck = "contextual"
withHelpersCheck = "with-helpers"
structuredCheck = "structured"
parametersCheck = "parameters"
contextualCheck = "contextual"
withHelpersCheck = "with-helpers"
verbosityZeroCheck = "verbosity-zero"
)

type checks map[string]*bool
Expand All @@ -53,10 +54,11 @@ func (c config) isEnabled(check string, filename string) bool {
func Analyser() *analysis.Analyzer {
c := config{
enabled: checks{
structuredCheck: new(bool),
parametersCheck: new(bool),
contextualCheck: new(bool),
withHelpersCheck: new(bool),
structuredCheck: new(bool),
parametersCheck: new(bool),
contextualCheck: new(bool),
withHelpersCheck: new(bool),
verbosityZeroCheck: new(bool),
},
}
c.fileOverrides.validChecks = map[string]bool{}
Expand All @@ -70,6 +72,7 @@ klog methods (Info, Infof, Error, Errorf, Warningf, etc).`)
logcheckFlags.BoolVar(c.enabled[parametersCheck], prefix+parametersCheck, true, `When true, logcheck will check parameters of structured logging calls.`)
logcheckFlags.BoolVar(c.enabled[contextualCheck], prefix+contextualCheck, false, `When true, logcheck will only allow log calls for contextual logging (retrieving a Logger from klog or the context and logging through that) and warn about all others.`)
logcheckFlags.BoolVar(c.enabled[withHelpersCheck], prefix+withHelpersCheck, false, `When true, logcheck will warn about direct calls to WithName, WithValues and NewContext.`)
logcheckFlags.BoolVar(c.enabled[verbosityZeroCheck], prefix+verbosityZeroCheck, true, `When true, logcheck will check whether the parameter for V() is 0.`)
logcheckFlags.Var(&c.fileOverrides, "config", `A file which overrides the global settings for checks on a per-file basis via regular expressions.`)

// Use env variables as defaults. This is necessary when used as plugin
Expand Down Expand Up @@ -172,6 +175,11 @@ func checkForFunctionExpr(fexpr *ast.CallExpr, pass *analysis.Pass, c *config) {
checkForFormatSpecifier(fexpr, pass)
}
}
// verbosity Zero Check
if c.isEnabled(verbosityZeroCheck, filename) {
checkForVerbosityZero(fexpr, pass)
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you move the pass.Report down into checkForVerboseZero to avoid the code duplication? If we ever decide to make it better (for example, by suggesting a code update), then we only need to make that change in one place.

checkForVerboseZero can call a isVerboseZero that is equivalent to the current function.

Copy link
Contributor Author

@yangjunmyfm192085 yangjunmyfm192085 Aug 30, 2022

Choose a reason for hiding this comment

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

Yeah, this part is duplicated.
I have optimized it.


} else if isGoLogger(selExpr.X, pass) {
if c.isEnabled(parametersCheck, filename) {
checkForFormatSpecifier(fexpr, pass)
Expand All @@ -193,6 +201,10 @@ func checkForFunctionExpr(fexpr *ast.CallExpr, pass *analysis.Pass, c *config) {
})
}
}
// verbosity Zero Check
if c.isEnabled(verbosityZeroCheck, filename) {
checkForVerbosityZero(fexpr, pass)
}
} else if fName == "NewContext" &&
isPackage(selExpr.X, "github.com/go-logr/logr", pass) &&
c.isEnabled(withHelpersCheck, filename) {
Expand Down Expand Up @@ -496,3 +508,47 @@ func checkForIfEnabled(i *ast.IfStmt, pass *analysis.Pass, c *config) {
funcCall, varName, funcCall, varName, varName),
})
}

func checkForVerbosityZero(fexpr *ast.CallExpr, pass *analysis.Pass) {
iselExpr, ok := fexpr.Fun.(*ast.SelectorExpr)
if !ok {
return
}
expr := iselExpr.X
if !isKlogVerbose(expr, pass) && !isGoLogger(expr, pass) {
return
}
if isVerbosityZero(expr) {
msg := fmt.Sprintf("Logging with V(0) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.")
pass.Report(analysis.Diagnostic{
Pos: fexpr.Fun.Pos(),
Message: msg,
})
}
}

func isVerbosityZero(expr ast.Expr) bool {
subCallExpr, ok := expr.(*ast.CallExpr)
if !ok {
return false
}
subSelExpr, ok := subCallExpr.Fun.(*ast.SelectorExpr)
if !ok || subSelExpr.Sel.Name != "V" || len(subCallExpr.Args) != 1 {
return false
}

if lit, ok := subCallExpr.Args[0].(*ast.BasicLit); ok && lit.Value == "0" {
return true
}

if id, ok := subCallExpr.Args[0].(*ast.Ident); ok && id.Obj.Kind == 2 {
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm not sure what is nil, but when I tried this change on top of your kubernetes/kubernetes#111708 I got a nil pointer access:

ERRO [runner] Panic: logcheck: package "vclib" (isInitialPkg: true, needAnalyzeSource: true): runtime error: invalid memory address or nil pointer dereference: goroutine 18650 [running]:
runtime/debug.Stack()
	/nvme/gopath/go-1.19/src/runtime/debug/stack.go:24 +0x65
github.com/golangci/golangci-lint/pkg/golinters/goanalysis.(*action).analyzeSafe.func1()
	/nvme/gopath/pkg/mod/github.com/golangci/golangci-lint@v1.48.0/pkg/golinters/goanalysis/runner_action.go:101 +0x155
panic({0x153a9e0, 0x2024fd0})
	/nvme/gopath/go-1.19/src/runtime/panic.go:884 +0x212
sigs.k8s.io/logtools/logcheck/pkg.isVerbosityZero({0x18ff6c0?, 0xc01b9c4000?})
	/nvme/gopath/pkg/mod/sigs.k8s.io/logtools@v0.2.1-0.20220830112100-f68289b649a5/logcheck/pkg/logcheck.go:544 +0xb5

To reproduce, check out your Kubernetes branch and patch it:

diff --git a/hack/tools/go.mod b/hack/tools/go.mod
index 8728f260aa4..ffcc1ab1519 100644
--- a/hack/tools/go.mod
+++ b/hack/tools/go.mod
@@ -11,7 +11,7 @@ require (
        github.com/google/go-flow-levee v0.1.5
        gotest.tools/gotestsum v1.6.4
        honnef.co/go/tools v0.3.3
-       sigs.k8s.io/logtools v0.1.0
+       sigs.k8s.io/logtools v0.2.1-0.20220830112100-f68289b649a5
        sigs.k8s.io/zeitgeist v0.2.0
 )
 
diff --git a/hack/tools/go.sum b/hack/tools/go.sum
index 0dc6f65d798..c39cafc35cd 100644
--- a/hack/tools/go.sum
+++ b/hack/tools/go.sum
@@ -829,6 +829,7 @@ github.com/yuin/goldmark v1.1.32/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9de
 github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
 github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
 github.com/yuin/goldmark v1.4.1/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
+github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
 gitlab.com/bosi/decorder v0.2.3 h1:gX4/RgK16ijY8V+BRQHAySfQAb354T7/xQpDB2n10P0=
 gitlab.com/bosi/decorder v0.2.3/go.mod h1:9K1RB5+VPNQYtXtTDAzd2OEftsZb1oV0IrJrzChSdGE=
 go.etcd.io/bbolt v1.3.2/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU=
@@ -1077,6 +1078,7 @@ golang.org/x/sys v0.0.0-20220114195835-da31bd327af9/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20220319134239-a9b59b0215f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220328115105-d36c6a25d886/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220412211240-33da011f77ad/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220702020025-31831981b65f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f h1:v4INt8xihDGvnrfjMDVXGxw9wrfxYyCjk0KbXjhR55s=
@@ -1368,6 +1370,10 @@ rsc.io/quote/v3 v3.1.0/go.mod h1:yEA65RcK8LyAZtP9Kv3t0HmxON59tX3rD+tICJqUlj0=
 rsc.io/sampler v1.3.0/go.mod h1:T1hPZKmBbMNahiBKFy5HrXp6adAjACjK9JXDnKaTXpA=
 sigs.k8s.io/logtools v0.1.0 h1:BWdoZu2PK6/lj5QhSXBGlHFu3d/ST1HlINXwE/CkJRQ=
 sigs.k8s.io/logtools v0.1.0/go.mod h1:/Rp/yzQWyUgsNCRb1HKRnrVujUV9CmzksOlsQR2OVvw=
+sigs.k8s.io/logtools v0.2.0 h1:FMy0Td6HnWP+Iqq9QWEZigS130aZSMtlhRn5pcZbwCo=
+sigs.k8s.io/logtools v0.2.0/go.mod h1:2HGcCK1vi9YvsBoUDMXvrf588j890iRtsymJX2biE0Q=
+sigs.k8s.io/logtools v0.2.1-0.20220830112100-f68289b649a5 h1:dy8gOoe/fHFqY1vN16XTgl/S8TIpuyxkE0wCTUr1UV4=
+sigs.k8s.io/logtools v0.2.1-0.20220830112100-f68289b649a5/go.mod h1:2HGcCK1vi9YvsBoUDMXvrf588j890iRtsymJX2biE0Q=
 sigs.k8s.io/yaml v1.1.0/go.mod h1:UJmg0vDUVViEyp3mgSv9WPwZCDxu4rQW1olrI1uml+o=
 sigs.k8s.io/yaml v1.2.0 h1:kr/MCeFWJWTwyaHoR9c8EjH9OumOmoF9YGiZd7lFm/Q=
 sigs.k8s.io/yaml v1.2.0/go.mod h1:yfXDCHCao9+ENCvLSE62v9VSji2MKu5jeNfTrofGhJc=

Then run hack/verify-golangci-lint.sh. That also shows that there are several more code lines which need to be modified.

If you want to try out a modified logcheck then you can point towards a local copy with:

(cd hack/tools && go mod edit -replace sigs.k8s.io/logtools=<absolute path>/logtools/)

Copy link
Contributor

Choose a reason for hiding this comment

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

No code survives first contact with the real world 😁

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Let me analyze why

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hi, @pohly , This is an interesting issue, but I don't reproduce it.
I don't know what scenario will appear that obj is nil.
In the pr below I have added protection, do we need to continue the analysis or could we merge this pr?
#5

Copy link
Contributor

Choose a reason for hiding this comment

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

It's indeed a bit odd. I can only reproduce it by running hack/verify-golangci-lint.sh, but not when invoking logcheck directly.

Copy link
Contributor

Choose a reason for hiding this comment

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

And now I cannot reproduce it anymore. Perhaps it was a problem with the golangci-lint cache.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hi, @pohly ,I think I caught the issue.
When Constants of value is defined in different files, there will be cases where it cannot be parsed directly
such as
https://github.com/kubernetes/kubernetes/blob/2b2be7fa6b69c7591a31475fc4fb1dcff362a128/staging/src/k8s.io/legacy-cloud-providers/vsphere/vclib/datastore.go#L62

https://github.com/kubernetes/kubernetes/blob/2b2be7fa6b69c7591a31475fc4fb1dcff362a128/staging/src/k8s.io/legacy-cloud-providers/vsphere/vclib/constants.go#L43

Do we need to continue dealing with this scenario, is it a bit complicated?
Or do we just need to fix panic?

Copy link
Contributor

Choose a reason for hiding this comment

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

I think it is sufficient to avoid the panic. Please reopen #5 and add an explanation in the code why the additional if conditions are needed, then I can merge it.

v, ok := id.Obj.Decl.(*ast.ValueSpec)
if !ok || len(v.Values) != 1 {
return false
}
if lit, ok := v.Values[0].(*ast.BasicLit); ok && lit.Value == "0" {
return true
}
}
return false
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
/*
Copyright 2022 The Kubernetes Authors.

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

// This fake package is created as golang.org/x/tools/go/analysis/analysistest
// expects it to be here for loading. This package is used to test allow-unstructured
// flag which suppresses errors when unstructured logging is used.
// This is a test file for unstructured logging static check tool unit tests.

package Verbosity

import (
"github.com/go-logr/logr"
klog "k8s.io/klog/v2"
)

const (
zeroConst = 0
oneConst = 1
)

var (
zeroVar klog.Level = 0
oneVar klog.Level = 1
l, logger logr.Logger
)

func verbosityLogging() {
klog.V(0).Info("test log")
klog.V(0).Infof("test log")
klog.V(0).Infoln("test log")
klog.V(0).InfoS("I'm logging at level 0.")
klog.V(zeroConst).InfoS("I'm logging at level 0.")
klog.V(zeroVar).InfoS("I'm logging at level 0.")
klog.V(1).Info("test log")
klog.V(1).Infof("test log")
klog.V(1).Infoln("test log")
klog.V(1).InfoS("I'm logging at level 1.")
klog.V(oneConst).InfoS("I'm logging at level 1.")
klog.V(oneVar).InfoS("I'm logging at level 1.")
klog.Info("test log")
klog.Infof("test log")
klog.Infoln("test log")
klog.InfoS("I'm logging at level 0.")

logger.Info("hello", "1", "2")
logger.Error(nil, "hello", "1", "2")
logger.WithValues("1", "2")

logger.V(0).Info("hello", "1", "2")
logger.V(0).Error(nil, "hello", "1", "2")
logger.V(0).WithValues("1", "2")

logger.V(1).Info("hello", "1", "2")
logger.V(1).Error(nil, "hello", "1", "2")
logger.V(1).WithValues("1", "2")
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
/*
Copyright 2022 The Kubernetes Authors.

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

// This fake package is created as golang.org/x/tools/go/analysis/analysistest
// expects it to be here for loading. This package is used to test allow-unstructured
// flag which suppresses errors when unstructured logging is used.
// This is a test file for unstructured logging static check tool unit tests.

package Verbosity

import (
"github.com/go-logr/logr"
klog "k8s.io/klog/v2"
)

const (
zeroConst = 0
oneConst = 1
)

var (
zeroVar klog.Level = 0
oneVar klog.Level = 1
l, logger logr.Logger
)

func verbosityLogging() {
klog.V(0).Info("test log") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
klog.V(0).Infof("test log") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
klog.V(0).Infoln("test log") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
klog.V(0).InfoS("I'm logging at level 0.") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
klog.V(zeroConst).InfoS("I'm logging at level 0.") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
klog.V(zeroVar).InfoS("I'm logging at level 0.")
klog.V(1).Info("test log")
klog.V(1).Infof("test log")
klog.V(1).Infoln("test log")
klog.V(1).InfoS("I'm logging at level 1.")
klog.V(oneConst).InfoS("I'm logging at level 1.")
klog.V(oneVar).InfoS("I'm logging at level 1.")
klog.Info("test log")
klog.Infof("test log")
klog.Infoln("test log")
klog.InfoS("I'm logging at level 0.")

logger.Info("hello", "1", "2")
logger.Error(nil, "hello", "1", "2")
logger.WithValues("1", "2")

logger.V(0).Info("hello", "1", "2") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
logger.V(0).Error(nil, "hello", "1", "2") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`
logger.V(0).WithValues("1", "2") // want `Logging with V\(0\) is semantically equivalent to the same expression without it and just causes unnecessary overhead. It should get removed.`

logger.V(1).Info("hello", "1", "2")
logger.V(1).Error(nil, "hello", "1", "2")
logger.V(1).WithValues("1", "2")
}