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 Static linter for structured logging #213

Merged
merged 1 commit into from
Mar 3, 2021
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
1 change: 1 addition & 0 deletions .github/workflows/test.yml
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ jobs:
run: |
go get -t -v ./...
go test -v -race ./...
cd hack/tools && go test -v -race ./...
dims marked this conversation as resolved.
Show resolved Hide resolved
lint:
runs-on: ubuntu-latest
steps:
Expand Down
5 changes: 5 additions & 0 deletions hack/tools/go.mod
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
module k8s.io/klog/hack/tools

go 1.15

require golang.org/x/tools v0.1.0
26 changes: 26 additions & 0 deletions hack/tools/go.sum
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
golang.org/x/mod v0.3.0 h1:RM4zey1++hCTbCVQfnWeKs9/IEsaBLA8vTkd0WVtmH4=
golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
golang.org/x/net v0.0.0-20201021035429-f5854403a974/go.mod h1:sp8m0HH+o8qH0wwXwYZr8TS3Oi6o0r6Gce1SSxlDquU=
golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4 h1:myAQVi0cGEoqQVR5POX+8RR2mrocKqNN1hmeMqhX27k=
golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.1.0 h1:po9/4sTYwZU9lPhi1tOrb4hCv3qrhiQ77LZfGa2OjwY=
golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
5 changes: 5 additions & 0 deletions hack/tools/logcheck/README.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
This directory contains tool for checking use of unstructured logs in a package. It is created to prevent regression after packages have been migrated to use structured logs.

**Installation:**`go install k8s.io/klog/hack/tools/logcheck`
**Usage:** `$logcheck.go <package_name>`
`e.g $logcheck ./pkg/kubelet/lifecycle/`
112 changes: 112 additions & 0 deletions hack/tools/logcheck/main.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,112 @@
/*
Copyright 2021 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.
*/

package main

import (
"fmt"
"go/ast"

"golang.org/x/tools/go/analysis"
"golang.org/x/tools/go/analysis/singlechecker"
)

// Doc explaining the tool.
const Doc = "Tool to check use of unstructured logging patterns."

// Analyzer runs static analysis.
var Analyzer = &analysis.Analyzer{
Name: "logcheck",
Doc: Doc,
Run: run,
}

func main() {
singlechecker.Main(Analyzer)
}

func run(pass *analysis.Pass) (interface{}, error) {

for _, file := range pass.Files {

ast.Inspect(file, func(n ast.Node) bool {

// We are intrested in function calls, as we want to detect klog.* calls
// passing all function calls to checkForFunctionExpr
if fexpr, ok := n.(*ast.CallExpr); ok {

checkForFunctionExpr(fexpr.Fun, pass)
}

return true
})
}
return nil, nil
}

// checkForFunctionExpr checks for unstructured logging function, prints error if found any.
func checkForFunctionExpr(fun ast.Expr, pass *analysis.Pass) {

/* we are extracting external package function calls e.g. klog.Infof fmt.Printf
and eliminating calls like setLocalHost()
basically function calls that has selector expression like .
*/
if selExpr, ok := fun.(*ast.SelectorExpr); ok {
// extracting function Name like Infof
fName := selExpr.Sel.Name
dims marked this conversation as resolved.
Show resolved Hide resolved

// for nested function cases klog.V(1).Infof scenerios
// if selExpr.X contains one more caller expression which is selector expression
// we are extracting klog and discarding V(1)
if n, ok := selExpr.X.(*ast.CallExpr); ok {
if _, ok = n.Fun.(*ast.SelectorExpr); ok {
selExpr = n.Fun.(*ast.SelectorExpr)
}
}

// extracting package name
pName, ok := selExpr.X.(*ast.Ident)
Copy link

Choose a reason for hiding this comment

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

This is taking a shortcut. Was that intentional because the alternative is too complex?

What we want to compare against is k8s.io/klog/v2, not just the name that the package was imported under. As it stands now, the following code will not be recognized as using klog.Info:

import glog "k8s.io/klog/v2"

func someFunc() {
  glog.Info("hello world"
}

It must be possible to lookup the selector, but after staring at the analysis.Pass for a while I still haven't figured out how. Any ideas?

Copy link

Choose a reason for hiding this comment

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

I found a solution. This here works and also covers other cases that weren't handled before, like if klogV := klog.V(1); klogV.Enabled() { klogV.Info("should not be used") }:

// isKlog checks whether an expression is klog.Verbose or the klog package itself.
func isKlog(expr ast.Expr, pass *analysis.Pass) bool {
	// For klog.V(1) and klogV := klog.V(1) we can decide based on the type.
	if typeAndValue, ok := pass.TypesInfo.Types[expr]; ok {
		switch t := typeAndValue.Type.(type) {
		case *types.Named:
			typeName := t.Obj()
			name := typeName.Name()
			pkg := typeName.Pkg()
			pkgPath := pkg.Path()
			if name == "Verbose" && pkgPath == "k8s.io/klog/v2" {
				return true
			}
		}
	}

	// In "klog.Info", "klog" is a package identifier. It doesn't need to
	// be "klog" because here we look up the actual package.
	if ident, ok := expr.(*ast.Ident); ok {
		if object, ok := pass.TypesInfo.Uses[ident]; ok {
			switch object := object.(type) {
			case *types.PkgName:
				pkg := object.Imported()
				if pkg.Path() == "k8s.io/klog/v2" {
					return true
				}
			}
		}
	}

	return false
}

I'm currently collecting some improvements of logcheck for contextual logging and will include this in that patch set.

IMHO it's not important enough to be fixed right away. Import renaming was done in some projects that migrated from glog, but seems less common nowadays.


// Matching if package name is klog and any unstructured logging function is used.
if ok && pName.Name == "klog" && isUnstructured((fName)) {

msg := fmt.Sprintf("unstructured logging function %q should not be used", fName)
pass.Report(analysis.Diagnostic{
Pos: fun.Pos(),
Message: msg,
})
}
}
}

func isUnstructured(fName string) bool {

// List of klog functions we do not want to use after migration to structured logging.
unstrucured := []string{
"Infof", "Info", "Infoln", "InfoDepth",
"Warning", "Warningf", "Warningln", "WarningDepth",
"Error", "Errorf", "Errorln", "ErrorDepth",
"Fatal", "Fatalf", "Fatalln", "FatalDepth",
Copy link
Member

@nikhita nikhita Mar 4, 2021

Choose a reason for hiding this comment

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

There is no FatalS so what would be recommend to use as an alternative?

Edit: never mind, I guess the recommend approach is to use ErrorS :)

Copy link
Author

Choose a reason for hiding this comment

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

Copy link
Member

@neolit123 neolit123 Mar 4, 2021

Choose a reason for hiding this comment

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

Fatal* must be replaced with ErrorS + os.Exit() or this would be a change in behavior.
the migrate guide is inaccurate in this regard.

EDIT: actually NVM it does mention it:
https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#replacing-fatal-calls

}

for _, name := range unstrucured {
if fName == name {
return true
}
}

return false
}
27 changes: 27 additions & 0 deletions hack/tools/logcheck/main_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
/*
Copyright 2021 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.
*/

package main

import (
"testing"

"golang.org/x/tools/go/analysis/analysistest"
)

func TestAnalyzer(t *testing.T) {
analysistest.Run(t, analysistest.TestData(), Analyzer)
dims marked this conversation as resolved.
Show resolved Hide resolved
}
47 changes: 47 additions & 0 deletions hack/tools/logcheck/testdata/data.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,47 @@
/*
Copyright 2021 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.
*/

// test file for unstructured logging static check tool unit tests.

package testdata

import (
klog "k8s.io/klog/v2"
)

func printUnstructuredLog() {
klog.V(1).Infof("test log") // want `unstructured logging function "Infof" should not be used`
klog.Infof("test log") // want `unstructured logging function "Infof" should not be used`
klog.Info("test log") // want `unstructured logging function "Info" should not be used`
klog.Infoln("test log") // want `unstructured logging function "Infoln" should not be used`
klog.InfoDepth(1, "test log") // want `unstructured logging function "InfoDepth" should not be used`
klog.Warning("test log") // want `unstructured logging function "Warning" should not be used`
klog.Warningf("test log") // want `unstructured logging function "Warningf" should not be used`
klog.WarningDepth(1, "test log") // want `unstructured logging function "WarningDepth" should not be used`
klog.Error("test log") // want `unstructured logging function "Error" should not be used`
klog.Errorf("test log") // want `unstructured logging function "Errorf" should not be used`
klog.Errorln("test log") // want `unstructured logging function "Errorln" should not be used`
klog.ErrorDepth(1, "test log") // want `unstructured logging function "ErrorDepth" should not be used`
klog.Fatal("test log") // want `unstructured logging function "Fatal" should not be used`
klog.Fatalf("test log") // want `unstructured logging function "Fatalf" should not be used`
klog.Fatalln("test log") // want `unstructured logging function "Fatalln" should not be used`
klog.FatalDepth(1, "test log") // want `unstructured logging function "FatalDepth" should not be used`
}

func printStructuredLog() {
klog.InfoS("test log")
klog.ErrorS(nil, "test log")
}
Loading