cmd/vet: use vet-specific export data to record detected printf wrappers

This CL takes advantage of the ability to record vet-specific export data,
added in CL 108558, to save information about observed printf wrappers.
Then calls to those wrappers from other packages can be format-checked.
This found a few real mistakes using previously-unrecognized printf
wrappers in cmd/compile. It will no doubt find real mistakes in external code.

Change-Id: I9c29c92d89bbdc984571a174a96e6054585e9cd4
Reviewed-on: https://go-review.googlesource.com/108559
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Alan Donovan <adonovan@google.com>

src/cmd/vet/print.go

@@ -8,6 +8,7 @@ package main
 
 import (
 	"bytes"
+	"encoding/gob"
 	"flag"
 	"fmt"
 	"go/ast"
@@ -27,6 +28,9 @@ func init() {
 		"check printf-like invocations",
 		checkFmtPrintfCall,
 		funcDecl, callExpr)
+	registerPkgCheck("printf", findPrintfLike)
+	registerExport("printf", exportPrintfLike)
+	gob.Register(map[string]int(nil))
 }
 
 func initPrintFlags() {
@@ -44,73 +48,244 @@ func initPrintFlags() {
 			name = name[:colon]
 		}
 
-		isPrint[strings.ToLower(name)] = true
+		if !strings.Contains(name, ".") {
+			name = strings.ToLower(name)
+		}
+		isPrint[name] = true
 	}
 }
 
-// TODO(rsc): Incorporate user-defined printf wrappers again.
+var localPrintfLike = make(map[string]int)
-// The general plan is to allow vet of one package P to output
+
-// additional information to supply to later vets of packages
+type printfWrapper struct {
-// importing P. Then vet of P can record a list of printf wrappers
+	name       string
-// and the later vet using P.Printf will find it in the list and check it.
+	fn         *ast.FuncDecl
-// That's not ready for Go 1.10.
+	format     *ast.Field
-// When that does happen, uncomment the user-defined printf
+	args       *ast.Field
-// wrapper tests in testdata/print.go.
+	callers    []printfCaller
+	printfLike bool
+}
+
+type printfCaller struct {
+	w    *printfWrapper
+	call *ast.CallExpr
+}
+
+// maybePrintfWrapper decides whether decl (a declared function) may be a wrapper
+// around a fmt.Printf or fmt.Print function. If so it returns a printfWrapper
+// function describing the declaration. Later processing will analyze the
+// graph of potential printf wrappers to pick out the ones that are true wrappers.
+// A function may be a Printf or Print wrapper if its last argument is ...interface{}.
+// If the next-to-last argument is a string, then this may be a Printf wrapper.
+// Otherwise it may be a Print wrapper.
+func maybePrintfWrapper(decl ast.Decl) *printfWrapper {
+	// Look for functions with final argument type ...interface{}.
+	fn, ok := decl.(*ast.FuncDecl)
+	if !ok || fn.Body == nil {
+		return nil
+	}
+	name := fn.Name.Name
+	if fn.Recv != nil {
+		// For (*T).Name or T.name, use "T.name".
+		rcvr := fn.Recv.List[0].Type
+		if ptr, ok := rcvr.(*ast.StarExpr); ok {
+			rcvr = ptr.X
+		}
+		id, ok := rcvr.(*ast.Ident)
+		if !ok {
+			return nil
+		}
+		name = id.Name + "." + name
+	}
+	params := fn.Type.Params.List
+	if len(params) == 0 {
+		return nil
+	}
+	args := params[len(params)-1]
+	if len(args.Names) != 1 {
+		return nil
+	}
+	ddd, ok := args.Type.(*ast.Ellipsis)
+	if !ok {
+		return nil
+	}
+	iface, ok := ddd.Elt.(*ast.InterfaceType)
+	if !ok || len(iface.Methods.List) > 0 {
+		return nil
+	}
+	var format *ast.Field
+	if len(params) >= 2 {
+		p := params[len(params)-2]
+		if len(p.Names) == 1 {
+			if id, ok := p.Type.(*ast.Ident); ok && id.Name == "string" {
+				format = p
+			}
+		}
+	}
+
+	return &printfWrapper{
+		name:   name,
+		fn:     fn,
+		format: format,
+		args:   args,
+	}
+}
+
+// findPrintfLike scans the entire package to find printf-like functions.
+func findPrintfLike(pkg *Package) {
+	if vcfg.ImportPath == "" { // no type or vetx information; don't bother
+		return
+	}
+
+	// Gather potential wrappesr and call graph between them.
+	byName := make(map[string]*printfWrapper)
+	var wrappers []*printfWrapper
+	for _, file := range pkg.files {
+		if file.file == nil {
+			continue
+		}
+		for _, decl := range file.file.Decls {
+			w := maybePrintfWrapper(decl)
+			if w == nil {
+				continue
+			}
+			byName[w.name] = w
+			wrappers = append(wrappers, w)
+		}
+	}
+
+	// Walk the graph to figure out which are really printf wrappers.
+	for _, w := range wrappers {
+		// Scan function for calls that could be to other printf-like functions.
+		ast.Inspect(w.fn.Body, func(n ast.Node) bool {
+			call, ok := n.(*ast.CallExpr)
+			if !ok || len(call.Args) == 0 || !match(call.Args[len(call.Args)-1], w.args) {
+				return true
+			}
+
+			pkgpath, name, kind := printfNameAndKind(pkg, call.Fun)
+			if kind != 0 {
+				checkPrintfFwd(pkg, w, call, kind)
+				return true
+			}
+
+			// If the call is to another function in this package,
+			// maybe we will find out it is printf-like later.
+			// Remember this call for later checking.
+			if pkgpath == "" && byName[name] != nil {
+				callee := byName[name]
+				callee.callers = append(callee.callers, printfCaller{w, call})
+			}
+
+			return true
+		})
+	}
+}
+
+func match(arg ast.Expr, param *ast.Field) bool {
+	id, ok := arg.(*ast.Ident)
+	return ok && id.Obj != nil && id.Obj.Decl == param
+}
+
+const (
+	kindPrintf = 1
+	kindPrint  = 2
+)
+
+// printfLike reports whether a call to fn should be considered a call to a printf-like function.
+// It returns 0 (indicating not a printf-like function), kindPrintf, or kindPrint.
+func printfLike(pkg *Package, fn ast.Expr, byName map[string]*printfWrapper) int {
+	if id, ok := fn.(*ast.Ident); ok && id.Obj != nil {
+		if w := byName[id.Name]; w != nil && id.Obj.Decl == w.fn {
+			// Found call to function in same package.
+			return localPrintfLike[id.Name]
+		}
+	}
+	if sel, ok := fn.(*ast.SelectorExpr); ok {
+		if id, ok := sel.X.(*ast.Ident); ok && id.Name == "fmt" && strings.Contains(sel.Sel.Name, "rint") {
+			if strings.HasSuffix(sel.Sel.Name, "f") {
+				return kindPrintf
+			}
+			return kindPrint
+		}
+	}
+	return 0
+}
+
+// checkPrintfFwd checks that a printf-forwarding wrapper is forwarding correctly.
+// It diagnoses writing fmt.Printf(format, args) instead of fmt.Printf(format, args...).
+func checkPrintfFwd(pkg *Package, w *printfWrapper, call *ast.CallExpr, kind int) {
+	matched := kind == kindPrint ||
+		kind == kindPrintf && len(call.Args) >= 2 && match(call.Args[len(call.Args)-2], w.format)
+	if !matched {
+		return
+	}
+
+	if !call.Ellipsis.IsValid() {
+		if !vcfg.VetxOnly {
+			desc := "printf"
+			if kind == kindPrint {
+				desc = "print"
+			}
+			pkg.files[0].Badf(call.Pos(), "missing ... in args forwarded to %s-like function", desc)
+		}
+		return
+	}
+	name := w.name
+	if localPrintfLike[name] == 0 {
+		localPrintfLike[name] = kind
+		for _, caller := range w.callers {
+			checkPrintfFwd(pkg, caller.w, caller.call, kind)
+		}
+	}
+}
+
+func exportPrintfLike() interface{} {
+	return localPrintfLike
+}
 
 // isPrint records the print functions.
 // If a key ends in 'f' then it is assumed to be a formatted print.
 var isPrint = map[string]bool{
-	"fmt.Errorf":         true,
+	"fmt.Errorf":   true,
-	"fmt.Fprint":         true,
+	"fmt.Fprint":   true,
-	"fmt.Fprintf":        true,
+	"fmt.Fprintf":  true,
-	"fmt.Fprintln":       true,
+	"fmt.Fprintln": true,
-	"fmt.Print":          true,
+	"fmt.Print":    true,
-	"fmt.Printf":         true,
+	"fmt.Printf":   true,
-	"fmt.Println":        true,
+	"fmt.Println":  true,
-	"fmt.Sprint":         true,
+	"fmt.Sprint":   true,
-	"fmt.Sprintf":        true,
+	"fmt.Sprintf":  true,
-	"fmt.Sprintln":       true,
+	"fmt.Sprintln": true,
-	"log.Fatal":          true,
+
-	"log.Fatalf":         true,
+	// testing.B, testing.T not auto-detected
-	"log.Fatalln":        true,
+	// because the methods are picked up by embedding.
-	"log.Logger.Fatal":   true,
+	"testing.B.Error":  true,
-	"log.Logger.Fatalf":  true,
+	"testing.B.Errorf": true,
-	"log.Logger.Fatalln": true,
+	"testing.B.Fatal":  true,
-	"log.Logger.Panic":   true,
+	"testing.B.Fatalf": true,
-	"log.Logger.Panicf":  true,
+	"testing.B.Log":    true,
-	"log.Logger.Panicln": true,
+	"testing.B.Logf":   true,
-	"log.Logger.Printf":  true,
+	"testing.B.Skip":   true,
-	"log.Logger.Println": true,
+	"testing.B.Skipf":  true,
-	"log.Panic":          true,
+	"testing.T.Error":  true,
-	"log.Panicf":         true,
+	"testing.T.Errorf": true,
-	"log.Panicln":        true,
+	"testing.T.Fatal":  true,
-	"log.Print":          true,
+	"testing.T.Fatalf": true,
-	"log.Printf":         true,
+	"testing.T.Log":    true,
-	"log.Println":        true,
+	"testing.T.Logf":   true,
-	"testing.B.Error":    true,
+	"testing.T.Skip":   true,
-	"testing.B.Errorf":   true,
+	"testing.T.Skipf":  true,
-	"testing.B.Fatal":    true,
+
-	"testing.B.Fatalf":   true,
+	// testing.TB is an interface, so can't detect wrapping.
-	"testing.B.Log":      true,
+	"testing.TB.Error":  true,
-	"testing.B.Logf":     true,
+	"testing.TB.Errorf": true,
-	"testing.B.Skip":     true,
+	"testing.TB.Fatal":  true,
-	"testing.B.Skipf":    true,
+	"testing.TB.Fatalf": true,
-	"testing.T.Error":    true,
+	"testing.TB.Log":    true,
-	"testing.T.Errorf":   true,
+	"testing.TB.Logf":   true,
-	"testing.T.Fatal":    true,
+	"testing.TB.Skip":   true,
-	"testing.T.Fatalf":   true,
+	"testing.TB.Skipf":  true,
-	"testing.T.Log":      true,
-	"testing.T.Logf":     true,
-	"testing.T.Skip":     true,
-	"testing.T.Skipf":    true,
-	"testing.TB.Error":   true,
-	"testing.TB.Errorf":  true,
-	"testing.TB.Fatal":   true,
-	"testing.TB.Fatalf":  true,
-	"testing.TB.Log":     true,
-	"testing.TB.Logf":    true,
-	"testing.TB.Skip":    true,
-	"testing.TB.Skipf":   true,
 }
 
 // formatString returns the format string argument and its index within
@@ -206,66 +381,84 @@ func checkFmtPrintfCall(f *File, node ast.Node) {
 	}
 
 	// Construct name like pkg.Printf or pkg.Type.Printf for lookup.
-	var name string
+	_, name, kind := printfNameAndKind(f.pkg, call.Fun)
-	switch x := call.Fun.(type) {
+	if kind == kindPrintf {
+		f.checkPrintf(call, name)
+	}
+	if kind == kindPrint {
+		f.checkPrint(call, name)
+	}
+}
+
+func printfName(pkg *Package, called ast.Expr) (pkgpath, name string) {
+	switch x := called.(type) {
 	case *ast.Ident:
-		if fn, ok := f.pkg.uses[x].(*types.Func); ok {
+		if fn, ok := pkg.uses[x].(*types.Func); ok {
-			var pkg string
+			if fn.Pkg() == nil || fn.Pkg() == pkg.typesPkg {
-			if fn.Pkg() == nil || fn.Pkg() == f.pkg.typesPkg {
+				pkgpath = ""
-				pkg = vcfg.ImportPath
 			} else {
-				pkg = fn.Pkg().Path()
+				pkgpath = fn.Pkg().Path()
 			}
-			name = pkg + "." + x.Name
+			return pkgpath, x.Name
-			break
 		}
 
 	case *ast.SelectorExpr:
 		// Check for "fmt.Printf".
 		if id, ok := x.X.(*ast.Ident); ok {
-			if pkgName, ok := f.pkg.uses[id].(*types.PkgName); ok {
+			if pkgName, ok := pkg.uses[id].(*types.PkgName); ok {
-				name = pkgName.Imported().Path() + "." + x.Sel.Name
+				return pkgName.Imported().Path(), x.Sel.Name
-				break
 			}
 		}
 
 		// Check for t.Logf where t is a *testing.T.
-		if sel := f.pkg.selectors[x]; sel != nil {
+		if sel := pkg.selectors[x]; sel != nil {
 			recv := sel.Recv()
 			if p, ok := recv.(*types.Pointer); ok {
 				recv = p.Elem()
 			}
 			if named, ok := recv.(*types.Named); ok {
 				obj := named.Obj()
-				var pkg string
+				if obj.Pkg() == nil || obj.Pkg() == pkg.typesPkg {
-				if obj.Pkg() == nil || obj.Pkg() == f.pkg.typesPkg {
+					pkgpath = ""
-					pkg = vcfg.ImportPath
 				} else {
-					pkg = obj.Pkg().Path()
+					pkgpath = obj.Pkg().Path()
 				}
-				name = pkg + "." + obj.Name() + "." + x.Sel.Name
+				return pkgpath, obj.Name() + "." + x.Sel.Name
-				break
 			}
 		}
 	}
+	return "", ""
+}
+
+func printfNameAndKind(pkg *Package, called ast.Expr) (pkgpath, name string, kind int) {
+	pkgpath, name = printfName(pkg, called)
 	if name == "" {
-		return
+		return pkgpath, name, 0
 	}
 
-	shortName := name[strings.LastIndex(name, ".")+1:]
+	if pkgpath == "" {
-
+		kind = localPrintfLike[name]
-	_, ok = isPrint[name]
+	} else {
-	if !ok {
+		printfLike, _ := readVetx(pkgpath, "printf").(map[string]int)
-		// Next look up just "printf", for use with -printfuncs.
+		kind = printfLike[name]
-		_, ok = isPrint[strings.ToLower(shortName)]
 	}
-	if ok {
+
-		if strings.HasSuffix(name, "f") {
+	if kind == 0 {
-			f.checkPrintf(call, shortName)
+		_, ok := isPrint[pkgpath+"."+name]
-		} else {
+		if !ok {
-			f.checkPrint(call, shortName)
+			// Next look up just "printf", for use with -printfuncs.
+			short := name[strings.LastIndex(name, ".")+1:]
+			_, ok = isPrint[strings.ToLower(short)]
+		}
+		if ok {
+			if strings.HasSuffix(name, "f") {
+				kind = kindPrintf
+			} else {
+				kind = kindPrint
+			}
 		}
 	}
+	return pkgpath, name, kind
 }
 
 // isStringer returns true if the provided declaration is a "String() string"

src/cmd/vet/testdata/print.go

@@ -14,6 +14,7 @@ package testdata
 import (
 	"fmt"
 	. "fmt"
+	logpkg "log" // renamed to make it harder to see
 	"math"
 	"os"
 	"testing"
@@ -175,6 +176,18 @@ func PrintfTests() {
 	f.Warnf(0, "%s", "hello", 3)          // ERROR "Warnf call needs 1 arg but has 2 args"
 	f.Warnf(0, "%r", "hello")             // ERROR "Warnf format %r has unknown verb r"
 	f.Warnf(0, "%#s", "hello")            // ERROR "Warnf format %#s has unrecognized flag #"
+	f.Warn2(0, "%s", "hello", 3)          // ERROR "Warn2 call has possible formatting directive %s"
+	f.Warnf2(0, "%s", "hello", 3)         // ERROR "Warnf2 call needs 1 arg but has 2 args"
+	f.Warnf2(0, "%r", "hello")            // ERROR "Warnf2 format %r has unknown verb r"
+	f.Warnf2(0, "%#s", "hello")           // ERROR "Warnf2 format %#s has unrecognized flag #"
+	f.Wrap(0, "%s", "hello", 3)           // ERROR "Wrap call has possible formatting directive %s"
+	f.Wrapf(0, "%s", "hello", 3)          // ERROR "Wrapf call needs 1 arg but has 2 args"
+	f.Wrapf(0, "%r", "hello")             // ERROR "Wrapf format %r has unknown verb r"
+	f.Wrapf(0, "%#s", "hello")            // ERROR "Wrapf format %#s has unrecognized flag #"
+	f.Wrap2(0, "%s", "hello", 3)          // ERROR "Wrap2 call has possible formatting directive %s"
+	f.Wrapf2(0, "%s", "hello", 3)         // ERROR "Wrapf2 call needs 1 arg but has 2 args"
+	f.Wrapf2(0, "%r", "hello")            // ERROR "Wrapf2 format %r has unknown verb r"
+	f.Wrapf2(0, "%#s", "hello")           // ERROR "Wrapf2 format %#s has unrecognized flag #"
 	fmt.Printf("%#s", FormatterVal(true)) // correct (the type is responsible for formatting)
 	Printf("d%", 2)                       // ERROR "Printf format % is missing verb at end of string"
 	Printf("%d", percentDV)
@@ -283,6 +296,28 @@ func PrintfTests() {
 
 	Printf(someString(), "hello") // OK
 
+	// Printf wrappers in package log should be detected automatically
+	logpkg.Fatal("%d", 1)    // ERROR "Fatal call has possible formatting directive %d"
+	logpkg.Fatalf("%d", "x") // ERROR "Fatalf format %d has arg \x22x\x22 of wrong type string"
+	logpkg.Fatalln("%d", 1)  // ERROR "Fatalln call has possible formatting directive %d"
+	logpkg.Panic("%d", 1)    // ERROR "Panic call has possible formatting directive %d"
+	logpkg.Panicf("%d", "x") // ERROR "Panicf format %d has arg \x22x\x22 of wrong type string"
+	logpkg.Panicln("%d", 1)  // ERROR "Panicln call has possible formatting directive %d"
+	logpkg.Print("%d", 1)    // ERROR "Print call has possible formatting directive %d"
+	logpkg.Printf("%d", "x") // ERROR "Printf format %d has arg \x22x\x22 of wrong type string"
+	logpkg.Println("%d", 1)  // ERROR "Println call has possible formatting directive %d"
+
+	// Methods too.
+	var l *logpkg.Logger
+	l.Fatal("%d", 1)    // ERROR "Fatal call has possible formatting directive %d"
+	l.Fatalf("%d", "x") // ERROR "Fatalf format %d has arg \x22x\x22 of wrong type string"
+	l.Fatalln("%d", 1)  // ERROR "Fatalln call has possible formatting directive %d"
+	l.Panic("%d", 1)    // ERROR "Panic call has possible formatting directive %d"
+	l.Panicf("%d", "x") // ERROR "Panicf format %d has arg \x22x\x22 of wrong type string"
+	l.Panicln("%d", 1)  // ERROR "Panicln call has possible formatting directive %d"
+	l.Print("%d", 1)    // ERROR "Print call has possible formatting directive %d"
+	l.Printf("%d", "x") // ERROR "Printf format %d has arg \x22x\x22 of wrong type string"
+	l.Println("%d", 1)  // ERROR "Println call has possible formatting directive %d"
 }
 
 func someString() string { return "X" }
@@ -368,14 +403,46 @@ func (*ptrStringer) String() string {
 	return "string"
 }
 
-func (*ptrStringer) Warn(int, ...interface{}) string {
+func (p *ptrStringer) Warn2(x int, args ...interface{}) string {
+	return p.Warn(x, args...)
+}
+
+func (p *ptrStringer) Warnf2(x int, format string, args ...interface{}) string {
+	return p.Warnf(x, format, args...)
+}
+
+func (*ptrStringer) Warn(x int, args ...interface{}) string {
 	return "warn"
 }
 
-func (*ptrStringer) Warnf(int, string, ...interface{}) string {
+func (*ptrStringer) Warnf(x int, format string, args ...interface{}) string {
 	return "warnf"
 }
 
+func (p *ptrStringer) Wrap2(x int, args ...interface{}) string {
+	return p.Wrap(x, args...)
+}
+
+func (p *ptrStringer) Wrapf2(x int, format string, args ...interface{}) string {
+	return p.Wrapf(x, format, args...)
+}
+
+func (*ptrStringer) Wrap(x int, args ...interface{}) string {
+	return fmt.Sprint(args...)
+}
+
+func (*ptrStringer) Wrapf(x int, format string, args ...interface{}) string {
+	return fmt.Sprintf(format, args...)
+}
+
+func (*ptrStringer) BadWrap(x int, args ...interface{}) string {
+	return fmt.Sprint(args) // ERROR "missing ... in args forwarded to print-like function"
+}
+
+func (*ptrStringer) BadWrapf(x int, format string, args ...interface{}) string {
+	return fmt.Sprintf(format, args) // ERROR "missing ... in args forwarded to printf-like function"
+}
+
 type embeddedStringer struct {
 	foo string
 	ptrStringer