internal: rationalize debug logging

In all cases, use a Logf field to configure debug logging. Non-nil means
that logging is enabled through the given function.

Fixes accidental debug spam from goimports, which had a separate Debug
flag that was supposed to guard logging, but wasn't used when creating
the gocommand.Invocation.

Change-Id: I448fa282111db556ac2e49801268d0affc19ae30
Reviewed-on: https://go-review.googlesource.com/c/tools/+/221557
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Daniel Martí <mvdan@mvdan.cc>
Reviewed-by: Rebecca Stambler <rstambler@golang.org>

cmd/goimports/goimports.go

@@ -262,7 +262,7 @@ func gofmtMain() {
 
 	if verbose {
 		log.SetFlags(log.LstdFlags | log.Lmicroseconds)
-		options.Env.Debug = true
+		options.Env.Logf = log.Printf
 	}
 	if options.TabWidth < 0 {
 		fmt.Fprintf(os.Stderr, "negative tabwidth %d\n", options.TabWidth)

imports/forward.go

@@ -4,6 +4,7 @@ package imports // import "golang.org/x/tools/imports"
 
 import (
 	"go/build"
+	"log"
 	"os"
 
 	intimp "golang.org/x/tools/internal/imports"
@@ -47,7 +48,6 @@ func Process(filename string, src []byte, opt *Options) ([]byte, error) {
 			GO111MODULE: os.Getenv("GO111MODULE"),
 			GOPROXY:     os.Getenv("GOPROXY"),
 			GOSUMDB:     os.Getenv("GOSUMDB"),
-			Debug:       Debug,
 			LocalPrefix: LocalPrefix,
 		},
 		AllErrors:  opt.AllErrors,
@@ -57,6 +57,9 @@ func Process(filename string, src []byte, opt *Options) ([]byte, error) {
 		TabIndent:  opt.TabIndent,
 		TabWidth:   opt.TabWidth,
 	}
+	if Debug {
+		intopt.Env.Logf = log.Printf
+	}
 	return intimp.Process(filename, src, intopt)
 }
 

internal/gopathwalk/walk.go

@@ -23,8 +23,10 @@ import (
 
 // Options controls the behavior of a Walk call.
 type Options struct {
-	Debug          bool // Enable debug logging
+	// If Logf is non-nil, debug logging is enabled through this function.
-	ModulesEnabled bool // Search module caches. Also disables legacy goimports ignore rules.
+	Logf func(format string, args ...interface{})
+	// Search module caches. Also disables legacy goimports ignore rules.
+	ModulesEnabled bool
 }
 
 // RootType indicates the type of a Root.
@@ -80,14 +82,14 @@ func WalkSkip(roots []Root, add func(root Root, dir string), skip func(root Root
 // walkDir creates a walker and starts fastwalk with this walker.
 func walkDir(root Root, add func(Root, string), skip func(root Root, dir string) bool, opts Options) {
 	if _, err := os.Stat(root.Path); os.IsNotExist(err) {
-		if opts.Debug {
+		if opts.Logf != nil {
-			log.Printf("skipping nonexistent directory: %v", root.Path)
+			opts.Logf("skipping nonexistent directory: %v", root.Path)
 		}
 		return
 	}
 	start := time.Now()
-	if opts.Debug {
+	if opts.Logf != nil {
-		log.Printf("gopathwalk: scanning %s", root.Path)
+		opts.Logf("gopathwalk: scanning %s", root.Path)
 	}
 	w := &walker{
 		root: root,
@@ -100,8 +102,8 @@ func walkDir(root Root, add func(Root, string), skip func(root Root, dir string)
 		log.Printf("gopathwalk: scanning directory %v: %v", root.Path, err)
 	}
 
-	if opts.Debug {
+	if opts.Logf != nil {
-		log.Printf("gopathwalk: scanned %s in %v", root.Path, time.Since(start))
+		opts.Logf("gopathwalk: scanned %s in %v", root.Path, time.Since(start))
 	}
 }
 
@@ -130,11 +132,11 @@ func (w *walker) init() {
 		full := filepath.Join(w.root.Path, p)
 		if fi, err := os.Stat(full); err == nil {
 			w.ignoredDirs = append(w.ignoredDirs, fi)
-			if w.opts.Debug {
+			if w.opts.Logf != nil {
-				log.Printf("Directory added to ignore list: %s", full)
+				w.opts.Logf("Directory added to ignore list: %s", full)
 			}
-		} else if w.opts.Debug {
+		} else if w.opts.Logf != nil {
-			log.Printf("Error statting ignored directory: %v", err)
+			w.opts.Logf("Error statting ignored directory: %v", err)
 		}
 	}
 }
@@ -145,11 +147,11 @@ func (w *walker) init() {
 func (w *walker) getIgnoredDirs(path string) []string {
 	file := filepath.Join(path, ".goimportsignore")
 	slurp, err := ioutil.ReadFile(file)
-	if w.opts.Debug {
+	if w.opts.Logf != nil {
 		if err != nil {
-			log.Print(err)
+			w.opts.Logf("%v", err)
 		} else {
-			log.Printf("Read %s", file)
+			w.opts.Logf("Read %s", file)
 		}
 	}
 	if err != nil {

internal/gopathwalk/walk_test.go

@@ -6,6 +6,7 @@ package gopathwalk
 
 import (
 	"io/ioutil"
+	"log"
 	"os"
 	"path/filepath"
 	"reflect"
@@ -116,7 +117,7 @@ func TestSkip(t *testing.T) {
 			found = append(found, dir[len(root.Path)+1:])
 		}, func(root Root, dir string) bool {
 			return false
-		}, Options{ModulesEnabled: false, Debug: true})
+		}, Options{ModulesEnabled: false, Logf: log.Printf})
 	if want := []string{"shouldfind"}; !reflect.DeepEqual(found, want) {
 		t.Errorf("expected to find only %v, got %v", want, found)
 	}

internal/imports/fix.go

@@ -262,7 +262,7 @@ type pass struct {
 
 // loadPackageNames saves the package names for everything referenced by imports.
 func (p *pass) loadPackageNames(imports []*ImportInfo) error {
-	if p.env.Debug {
+	if p.env.Logf != nil {
 		p.env.Logf("loading package names for %v packages", len(imports))
 		defer func() {
 			p.env.Logf("done loading package names for %v packages", len(imports))
@@ -334,7 +334,7 @@ func (p *pass) load() ([]*ImportFix, bool) {
 	if p.loadRealPackageNames {
 		err := p.loadPackageNames(append(imports, p.candidates...))
 		if err != nil {
-			if p.env.Debug {
+			if p.env.Logf != nil {
 				p.env.Logf("loading package names: %v", err)
 			}
 			return nil, false
@@ -528,7 +528,7 @@ func getFixes(fset *token.FileSet, f *ast.File, filename string, env *ProcessEnv
 		return nil, err
 	}
 	srcDir := filepath.Dir(abs)
-	if env.Debug {
+	if env.Logf != nil {
 		env.Logf("fixImports(filename=%q), abs=%q, srcDir=%q ...", filename, abs, srcDir)
 	}
 
@@ -746,7 +746,6 @@ func getPackageExports(ctx context.Context, wrapped func(PackageExport), searchP
 // the go command, the go/build package, etc.
 type ProcessEnv struct {
 	LocalPrefix string
-	Debug       bool
 
 	BuildFlags []string
 
@@ -755,7 +754,7 @@ type ProcessEnv struct {
 	GOPATH, GOROOT, GO111MODULE, GOPROXY, GOFLAGS, GOSUMDB string
 	WorkingDir                                             string
 
-	// Logf is the default logger for the ProcessEnv.
+	// If Logf is non-nil, debug logging is enabled through this function.
 	Logf func(format string, args ...interface{})
 
 	resolver Resolver
@@ -1238,7 +1237,7 @@ func (r *gopathResolver) scan(ctx context.Context, callback *scanCallback) error
 		case <-r.scanSema:
 		}
 		defer func() { r.scanSema <- struct{}{} }()
-		gopathwalk.Walk(roots, add, gopathwalk.Options{Debug: r.env.Debug, ModulesEnabled: false})
+		gopathwalk.Walk(roots, add, gopathwalk.Options{Logf: r.env.Logf, ModulesEnabled: false})
 		close(scanDone)
 	}()
 	select {
@@ -1342,7 +1341,7 @@ func loadExportsFromFiles(ctx context.Context, env *ProcessEnv, dir string, incl
 		}
 	}
 
-	if env.Debug {
+	if env.Logf != nil {
 		sortedExports := append([]string(nil), exports...)
 		sort.Strings(sortedExports)
 		env.Logf("loaded exports in dir %v (package %v): %v", dir, pkgName, strings.Join(sortedExports, ", "))
@@ -1358,7 +1357,7 @@ func findImport(ctx context.Context, pass *pass, candidates []pkgDistance, pkgNa
 	// ones.  Note that this sorts by the de-vendored name, so
 	// there's no "penalty" for vendoring.
 	sort.Sort(byDistanceOrImportPathShortLength(candidates))
-	if pass.env.Debug {
+	if pass.env.Logf != nil {
 		for i, c := range candidates {
 			pass.env.Logf("%s candidate %d/%d: %v in %v", pkgName, i+1, len(candidates), c.pkg.importPathShort, c.pkg.dir)
 		}
@@ -1396,14 +1395,14 @@ func findImport(ctx context.Context, pass *pass, candidates []pkgDistance, pkgNa
 					wg.Done()
 				}()
 
-				if pass.env.Debug {
+				if pass.env.Logf != nil {
 					pass.env.Logf("loading exports in dir %s (seeking package %s)", c.pkg.dir, pkgName)
 				}
 				// If we're an x_test, load the package under test's test variant.
 				includeTest := strings.HasSuffix(pass.f.Name.Name, "_test") && c.pkg.dir == pass.srcDir
 				_, exports, err := pass.env.GetResolver().loadExports(ctx, c.pkg, includeTest)
 				if err != nil {
-					if pass.env.Debug {
+					if pass.env.Logf != nil {
 						pass.env.Logf("loading exports in dir %s (seeking package %s): %v", c.pkg.dir, pkgName, err)
 					}
 					resc <- nil

internal/imports/fix_test.go

@@ -1638,11 +1638,12 @@ func (c testConfig) test(t *testing.T, fn func(*goimportTest)) {
 					GO111MODULE: env["GO111MODULE"],
 					GOSUMDB:     env["GOSUMDB"],
 					WorkingDir:  exported.Config.Dir,
-					Debug:       *testDebug,
-					Logf:        log.Printf,
 				},
 				exported: exported,
 			}
+			if *testDebug {
+				it.env.Logf = log.Printf
+			}
 			if it.env.GOROOT == "" {
 				// packagestest clears out GOROOT to work around https://golang.org/issue/32849,
 				// which isn't relevant here. Fill it back in so we can find the standard library.

internal/imports/mod.go

@@ -156,7 +156,7 @@ func (r *ModuleResolver) initAllMods() error {
 			return err
 		}
 		if mod.Dir == "" {
-			if r.env.Debug {
+			if r.env.Logf != nil {
 				r.env.Logf("module %v has not been downloaded and will be ignored", mod.Path)
 			}
 			// Can't do anything with a module that's not downloaded.
@@ -470,7 +470,7 @@ func (r *ModuleResolver) scan(ctx context.Context, callback *scanCallback) error
 			if r.scannedRoots[root] {
 				continue
 			}
-			gopathwalk.WalkSkip([]gopathwalk.Root{root}, add, skip, gopathwalk.Options{Debug: r.env.Debug, ModulesEnabled: true})
+			gopathwalk.WalkSkip([]gopathwalk.Root{root}, add, skip, gopathwalk.Options{Logf: r.env.Logf, ModulesEnabled: true})
 			r.scannedRoots[root] = true
 		}
 		close(scanDone)
@@ -583,7 +583,7 @@ func (r *ModuleResolver) scanDirForPackage(root gopathwalk.Root, dir string) dir
 		}
 		modPath, err := module.UnescapePath(filepath.ToSlash(matches[1]))
 		if err != nil {
-			if r.env.Debug {
+			if r.env.Logf != nil {
 				r.env.Logf("decoding module cache path %q: %v", subdir, err)
 			}
 			return directoryPackageInfo{

internal/imports/mod_test.go

@@ -676,8 +676,9 @@ func setup(t *testing.T, main, wd string) *modTest {
 		GOPROXY:     proxyDirToURL(proxyDir),
 		GOSUMDB:     "off",
 		WorkingDir:  filepath.Join(mainDir, wd),
-		Debug:       *testDebug,
+	}
-		Logf:        log.Printf,
+	if *testDebug {
+		env.Logf = log.Printf
 	}
 
 	// go mod download gets mad if we don't have a go.mod, so make sure we do.
@@ -917,7 +918,6 @@ import _ "rsc.io/quote"
 
 func BenchmarkScanModCache(b *testing.B) {
 	env := &ProcessEnv{
-		Debug:  true,
 		GOPATH: build.Default.GOPATH,
 		GOROOT: build.Default.GOROOT,
 		Logf:   log.Printf,

internal/lsp/cache/view.go

@@ -332,13 +332,14 @@ func (v *view) refreshProcessEnv() {
 func (v *view) buildProcessEnv(ctx context.Context) (*imports.ProcessEnv, error) {
 	env, buildFlags := v.env()
 	processEnv := &imports.ProcessEnv{
-		WorkingDir: v.folder.Filename(),
+		WorkingDir:  v.folder.Filename(),
-		BuildFlags: buildFlags,
+		BuildFlags:  buildFlags,
-		Logf: func(format string, args ...interface{}) {
-			log.Print(ctx, fmt.Sprintf(format, args...))
-		},
 		LocalPrefix: v.options.LocalPrefix,
-		Debug:       v.options.VerboseOutput,
+	}
+	if v.options.VerboseOutput {
+		processEnv.Logf = func(format string, args ...interface{}) {
+			log.Print(ctx, fmt.Sprintf(format, args...))
+		}
 	}
 	for _, kv := range env {
 		split := strings.Split(kv, "=")