add slowg analyzer to check inappropriate use of log/slog

Signed-off-by: Robin Hahling <[email protected]>

.gitignore

@@ -1 +1 @@
-customvet
+linters

README.md

@@ -16,6 +16,31 @@ file which fills up memory leader to a denial of service attack). Users are
 encouraged to use alternative constructs such as making use of
 [io.LimitReader](https://pkg.go.dev/io#LimitReader).
 
+slowg
+-----
+
+`slowg` is an analyzer that checks for inappropriate use of `Logger.With` from
+the `log/slog` (or `golang.org/x/exp/slog`) package.
+
+`Logger.With()` (and `Logger.WithGroup()` creates a new Logger containing the
+provided attributes. The parent logger is cloned when arguments are supplied,
+which is a relatively expensive operation which should not be used in hot code
+path.
+
+For example, slowg would report the following call:
+
+    log.With("key", val).Info("message")
+
+Which should be replaced with the following one:
+
+    log.Info("message", "key", val)
+
+However, the slowg checker does not prevent the use of With and WithGroup.
+
+	wlog := log.With("key", val)             // this is fine
+	wlog.Info("info")                        // this is also fine
+	wlog.With("more", "attr").Debug("debug") // this is flagged as inappropriate use
+
 timeafter
 ---------
 

go.mod

@@ -2,7 +2,10 @@ module github.com/cilium/linters
 
 go 1.19
 
-require golang.org/x/tools v0.11.0
+require (
+	golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1
+	golang.org/x/tools v0.11.0
+)
 
 require (
 	golang.org/x/mod v0.12.0 // indirect

go.sum

@@ -1,3 +1,5 @@
+golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1 h1:MGwJjxBy0HJshjDNfLsYO8xppfqWlA5ZT9OhtUUhTNw=
+golang.org/x/exp v0.0.0-20230713183714-613f0c0eb8a1/go.mod h1:FXUEEKJgO7OQYeo8N01OfiKP8RXMtf6e8aTskBGqWdc=
 golang.org/x/mod v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc=
 golang.org/x/mod v0.12.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs=
 golang.org/x/sync v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E=

ioreadall/io_readall.go

@@ -22,8 +22,9 @@ var ioReadAllPkgs = []string{"io", "ioutil"}
 // Analyzer implements an analysis function that checks for the use of
 // io.ReadAll.
 var Analyzer = &analysis.Analyzer{
-	Name:     "readall",
+	Name:     "ioreadall",
 	Doc:      `check for "io.ReadAll" instances`,
+	URL:      "https://github.com/cilium/linters/ioreadall",
 	Requires: []*analysis.Analyzer{inspect.Analyzer},
 	Run:      run,
 }

main.go

@@ -6,11 +6,16 @@ package main
 
 import (
 	"github.com/cilium/linters/ioreadall"
+	"github.com/cilium/linters/slowg"
 	"github.com/cilium/linters/timeafter"
 
 	"golang.org/x/tools/go/analysis/multichecker"
 )
 
 func main() {
-	multichecker.Main(timeafter.Analyzer, ioreadall.Analyzer)
+	multichecker.Main(
+		ioreadall.Analyzer,
+		slowg.Analyzer,
+		timeafter.Analyzer,
+	)
 }

slowg/doc.go

@@ -0,0 +1,28 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+// Package slowg defines an Analyzer that checks for inappropriate use of
+// Logger.With() from the log/slog package.
+//
+// # Analyzer slowg
+//
+// slowg: check for inappropriate use of Logger.With().
+//
+// The slowg checker looks for calls to Logger.With() from the log/slog
+// package. Logger.With() constructs a new Logger containing the provided
+// attributes. The parent logger is cloned when arguments are supplied, which
+// is a relatively expensive operation which should not be used in hot code path.
+// For example, slowg would report the following call:
+//
+//	log.With("key", val).Info("message")
+//
+// And suggest to replace it with the following one:
+//
+//	log.Info("message", "key", val)
+//
+// However, the slowg checker does not prevent the use of With and WithGroup.
+//
+//	wlog := log.With("key", val)             // this is fine
+//	wlog.Info("info")                        // this is also fine
+//	wlog.With("more", "attr").Debug("debug") // this is flagged as inappropriate use
+package slowg

slowg/slowg.go

@@ -0,0 +1,115 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+package slowg
+
+import (
+	"errors"
+	"go/ast"
+	"go/types"
+
+	_ "golang.org/x/exp/slog" // require the exp module for the unit tests
+	"golang.org/x/tools/go/analysis"
+	"golang.org/x/tools/go/analysis/passes/inspect"
+	"golang.org/x/tools/go/ast/inspector"
+	"golang.org/x/tools/go/types/typeutil"
+)
+
+// Analyzer implements an analysis function that checks for inappropriate use
+// of Logger.With.
+var Analyzer = &analysis.Analyzer{
+	Name:     "slowg",
+	Doc:      "check for inappropriate use of Logger.With()",
+	URL:      "https://github.com/cilium/linters/slowg",
+	Requires: []*analysis.Analyzer{inspect.Analyzer},
+	Run:      run,
+}
+
+func run(pass *analysis.Pass) (any, error) {
+	inspect, ok := pass.ResultOf[inspect.Analyzer].(*inspector.Inspector)
+	if !ok {
+		return nil, errors.New("require analyzer of type *inspector.Inspector")
+	}
+	nodeFilter := []ast.Node{
+		(*ast.SelectorExpr)(nil),
+	}
+	inspect.Preorder(nodeFilter, func(node ast.Node) {
+		sel, ok := node.(*ast.SelectorExpr)
+		if !ok {
+			return
+		}
+
+		if sel.Sel == nil {
+			return
+		}
+		call, ok := sel.X.(*ast.CallExpr)
+		if !ok {
+			return
+		}
+		fn := typeutil.StaticCallee(pass.TypesInfo, call)
+		if fn == nil {
+			// not a static call
+			return
+		}
+		if !isSlogPkg(fn) {
+			// not the log/slog or x/exp/slog package
+			return
+		}
+		if recvName(fn) != "Logger" {
+			// not a receiver of the Logger struct
+			return
+		}
+		switch fn.Name() {
+		case "With", "WithGroup":
+		default:
+			// not one of the call we need to care about
+			return
+		}
+		meth := sel.Sel.Name
+		if !isLogMethod(meth) {
+			// not a logging method (e.g. Info, DebugCtx, ...)
+			return
+		}
+		pass.ReportRangef(call, "call to %s on a newly instantiated Logger", meth)
+	})
+	return nil, nil
+}
+
+func isSlogPkg(fn *types.Func) bool {
+	switch fn.Pkg().Path() {
+	case "log/slog":
+		return true
+	case "golang.org/x/exp/slog":
+		return true
+	}
+	return false
+}
+
+func isLogMethod(s string) bool {
+	switch s {
+	case "Log", "LogAttrs",
+		"Debug", "Info", "Warn", "Error",
+		"DebugCtx", "InfoCtx", "WarnCtx", "ErrorCtx", // old method names, still used in x/exp/slog
+		"DebugContext", "InfoContext", "WarnContext", "ErrorContext":
+		return true
+	}
+	return false
+}
+
+func recvName(fn *types.Func) string {
+	sig, ok := fn.Type().(*types.Signature)
+	if !ok {
+		return ""
+	}
+	recv := sig.Recv()
+	if recv != nil {
+		t := recv.Type()
+		if pt, ok := t.(*types.Pointer); ok {
+			t = pt.Elem()
+		}
+		if nt, ok := t.(*types.Named); ok {
+			return nt.Obj().Name()
+		}
+	}
+	return ""
+}

slowg/slowg_stdlib_test.go

@@ -0,0 +1,17 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+//go:build go1.21
+
+package slowg
+
+import (
+	"testing"
+
+	"golang.org/x/tools/go/analysis/analysistest"
+)
+
+func TestStdlib(t *testing.T) {
+	testdata := analysistest.TestData()
+	analysistest.Run(t, testdata, Analyzer, "stdlib")
+}

slowg/slowg_xexp_test.go

@@ -0,0 +1,15 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+package slowg
+
+import (
+	"testing"
+
+	"golang.org/x/tools/go/analysis/analysistest"
+)
+
+func TestExp(t *testing.T) {
+	testdata := analysistest.TestData()
+	analysistest.Run(t, testdata, Analyzer, "xexp")
+}

slowg/testdata/src/golang.org

@@ -0,0 +1 @@
+../../../vendor/golang.org

slowg/testdata/src/stdlib/stdlib.go

@@ -0,0 +1,60 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+//go:build go1.21
+
+package stdlib
+
+import (
+	"context"
+	"io"
+	"log/slog"
+)
+
+func main() {
+	ctx := context.Background()
+	log := slog.New(slog.NewTextHandler(io.Discard, nil))
+
+	// calling any of the logging function shouldn't be flagged
+	log.Debug("debug")
+	log.Info("info")
+	log.Warn("warn")
+	log.Error("error")
+	log.DebugContext(ctx, "debug")
+	log.InfoContext(ctx, "info")
+	log.WarnContext(ctx, "warn")
+	log.ErrorContext(ctx, "error")
+	log.Log(ctx, slog.LevelInfo, "log")
+	log.LogAttrs(ctx, slog.LevelInfo, "log")
+
+	// creating a new logger with With or WithGroup for use later shouldn't
+	// be flagged
+	wlog := log.With("key", "va")
+	wlog.Info("info")
+	glog := log.WithGroup("group")
+	glog.Info("info")
+
+	// With
+	log.With("key", "val").Debug("debug")                       // want `call to Debug on a newly instantiated Logger`
+	log.With("key", "val").Info("info")                         // want `call to Info on a newly instantiated Logger`
+	log.With("key", "val").Warn("warn")                         // want `call to Warn on a newly instantiated Logger`
+	log.With("key", "val").Error("error")                       // want `call to Error on a newly instantiated Logger`
+	log.With("key", "val").DebugContext(ctx, "debug")           // want `call to DebugContext on a newly instantiated Logger`
+	log.With("key", "val").InfoContext(ctx, "info")             // want `call to InfoContext on a newly instantiated Logger`
+	log.With("key", "val").WarnContext(ctx, "warn")             // want `call to WarnContext on a newly instantiated Logger`
+	log.With("key", "val").ErrorContext(ctx, "error")           // want `call to ErrorContext on a newly instantiated Logger`
+	log.With("key", "val").Log(ctx, slog.LevelInfo, "log")      // want `call to Log on a newly instantiated Logger`
+	log.With("key", "val").LogAttrs(ctx, slog.LevelInfo, "log") // want `call to LogAttrs on a newly instantiated Logger`
+
+	// WithGroup
+	log.WithGroup("group").Debug("debug")                       // want `call to Debug on a newly instantiated Logger`
+	log.WithGroup("group").Info("info")                         // want `call to Info on a newly instantiated Logger`
+	log.WithGroup("group").Warn("warn")                         // want `call to Warn on a newly instantiated Logger`
+	log.WithGroup("group").Error("error")                       // want `call to Error on a newly instantiated Logger`
+	log.WithGroup("group").DebugContext(ctx, "debug")           // want `call to DebugContext on a newly instantiated Logger`
+	log.WithGroup("group").InfoContext(ctx, "info")             // want `call to InfoContext on a newly instantiated Logger`
+	log.WithGroup("group").WarnContext(ctx, "warn")             // want `call to WarnContext on a newly instantiated Logger`
+	log.WithGroup("group").ErrorContext(ctx, "error")           // want `call to ErrorContext on a newly instantiated Logger`
+	log.WithGroup("group").Log(ctx, slog.LevelInfo, "log")      // want `call to Log on a newly instantiated Logger`
+	log.WithGroup("group").LogAttrs(ctx, slog.LevelInfo, "log") // want `call to LogAttrs on a newly instantiated Logger`
+}

slowg/testdata/src/xexp/xexp.go

@@ -0,0 +1,71 @@
+// SPDX-License-Identifier: Apache-2.0
+// Copyright Authors of Cilium
+
+package xexp
+
+import (
+	"context"
+	"io"
+
+	"golang.org/x/exp/slog"
+)
+
+func main() {
+	ctx := context.Background()
+	log := slog.New(slog.NewTextHandler(io.Discard, nil))
+
+	// calling any of the logging function shouldn't be flagged
+	log.Debug("debug")
+	log.Info("info")
+	log.Warn("warn")
+	log.Error("error")
+	log.DebugContext(ctx, "debug")
+	log.InfoContext(ctx, "info")
+	log.WarnContext(ctx, "warn")
+	log.ErrorContext(ctx, "error")
+	log.DebugCtx(ctx, "debug")
+	log.InfoCtx(ctx, "info")
+	log.WarnCtx(ctx, "warn")
+	log.ErrorCtx(ctx, "error")
+	log.Log(ctx, slog.LevelInfo, "log")
+	log.LogAttrs(ctx, slog.LevelInfo, "log")
+
+	// creating a new logger with With or WithGroup for use later shouldn't
+	// be flagged
+	wlog := log.With("key", "va")
+	wlog.Info("info")
+	glog := log.WithGroup("group")
+	glog.Info("info")
+
+	// With
+	log.With("key", "val").Debug("debug")                       // want `call to Debug on a newly instantiated Logger`
+	log.With("key", "val").Info("info")                         // want `call to Info on a newly instantiated Logger`
+	log.With("key", "val").Warn("warn")                         // want `call to Warn on a newly instantiated Logger`
+	log.With("key", "val").Error("error")                       // want `call to Error on a newly instantiated Logger`
+	log.With("key", "val").DebugContext(ctx, "debug")           // want `call to DebugContext on a newly instantiated Logger`
+	log.With("key", "val").InfoContext(ctx, "info")             // want `call to InfoContext on a newly instantiated Logger`
+	log.With("key", "val").WarnContext(ctx, "warn")             // want `call to WarnContext on a newly instantiated Logger`
+	log.With("key", "val").ErrorContext(ctx, "error")           // want `call to ErrorContext on a newly instantiated Logger`
+	log.With("key", "val").DebugCtx(ctx, "debug")               // want `call to DebugCtx on a newly instantiated Logger`
+	log.With("key", "val").InfoCtx(ctx, "info")                 // want `call to InfoCtx on a newly instantiated Logger`
+	log.With("key", "val").WarnCtx(ctx, "warn")                 // want `call to WarnCtx on a newly instantiated Logger`
+	log.With("key", "val").ErrorCtx(ctx, "error")               // want `call to ErrorCtx on a newly instantiated Logger`
+	log.With("key", "val").Log(ctx, slog.LevelInfo, "log")      // want `call to Log on a newly instantiated Logger`
+	log.With("key", "val").LogAttrs(ctx, slog.LevelInfo, "log") // want `call to LogAttrs on a newly instantiated Logger`
+
+	// WithGroup
+	log.WithGroup("group").Debug("debug")                       // want `call to Debug on a newly instantiated Logger`
+	log.WithGroup("group").Info("info")                         // want `call to Info on a newly instantiated Logger`
+	log.WithGroup("group").Warn("warn")                         // want `call to Warn on a newly instantiated Logger`
+	log.WithGroup("group").Error("error")                       // want `call to Error on a newly instantiated Logger`
+	log.WithGroup("group").DebugContext(ctx, "debug")           // want `call to DebugContext on a newly instantiated Logger`
+	log.WithGroup("group").InfoContext(ctx, "info")             // want `call to InfoContext on a newly instantiated Logger`
+	log.WithGroup("group").WarnContext(ctx, "warn")             // want `call to WarnContext on a newly instantiated Logger`
+	log.WithGroup("group").ErrorContext(ctx, "error")           // want `call to ErrorContext on a newly instantiated Logger`
+	log.WithGroup("group").DebugCtx(ctx, "debug")               // want `call to DebugCtx on a newly instantiated Logger`
+	log.WithGroup("group").InfoCtx(ctx, "info")                 // want `call to InfoCtx on a newly instantiated Logger`
+	log.WithGroup("group").WarnCtx(ctx, "warn")                 // want `call to WarnCtx on a newly instantiated Logger`
+	log.WithGroup("group").ErrorCtx(ctx, "error")               // want `call to ErrorCtx on a newly instantiated Logger`
+	log.WithGroup("group").Log(ctx, slog.LevelInfo, "log")      // want `call to Log on a newly instantiated Logger`
+	log.WithGroup("group").LogAttrs(ctx, slog.LevelInfo, "log") // want `call to LogAttrs on a newly instantiated Logger`
+}