From 5bcca83a78812bd91ce8cb29be4fc4521cdc8f6f Mon Sep 17 00:00:00 2001 From: Heschi Kreinick Date: Fri, 28 Feb 2020 17:03:27 -0500 Subject: [PATCH] internal: rationalize debug logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 TryBot-Result: Gobot Gobot Reviewed-by: Daniel Martí Reviewed-by: Rebecca Stambler --- cmd/goimports/goimports.go | 2 +- imports/forward.go | 5 ++++- internal/gopathwalk/walk.go | 32 +++++++++++++++++--------------- internal/gopathwalk/walk_test.go | 3 ++- internal/imports/fix.go | 19 +++++++++---------- internal/imports/fix_test.go | 5 +++-- internal/imports/mod.go | 6 +++--- internal/imports/mod_test.go | 6 +++--- internal/lsp/cache/view.go | 13 +++++++------ 9 files changed, 49 insertions(+), 42 deletions(-) diff --git a/cmd/goimports/goimports.go b/cmd/goimports/goimports.go index 2cca292359..a5680d8d6c 100644 --- a/cmd/goimports/goimports.go +++ b/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) diff --git a/imports/forward.go b/imports/forward.go index b4f4287679..dbe5b49a9f 100644 --- a/imports/forward.go +++ b/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) } diff --git a/internal/gopathwalk/walk.go b/internal/gopathwalk/walk.go index 64309db74c..390cb9db79 100644 --- a/internal/gopathwalk/walk.go +++ b/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 - ModulesEnabled bool // Search module caches. Also disables legacy goimports ignore rules. + // If Logf is non-nil, debug logging is enabled through this function. + 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 { - log.Printf("skipping nonexistent directory: %v", root.Path) + if opts.Logf != nil { + opts.Logf("skipping nonexistent directory: %v", root.Path) } return } start := time.Now() - if opts.Debug { - log.Printf("gopathwalk: scanning %s", root.Path) + if opts.Logf != nil { + 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 { - log.Printf("gopathwalk: scanned %s in %v", root.Path, time.Since(start)) + if opts.Logf != nil { + 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 { - log.Printf("Directory added to ignore list: %s", full) + if w.opts.Logf != nil { + w.opts.Logf("Directory added to ignore list: %s", full) } - } else if w.opts.Debug { - log.Printf("Error statting ignored directory: %v", err) + } else if w.opts.Logf != nil { + 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 { diff --git a/internal/gopathwalk/walk_test.go b/internal/gopathwalk/walk_test.go index 7d48e5e136..2d887a655f 100644 --- a/internal/gopathwalk/walk_test.go +++ b/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) } diff --git a/internal/imports/fix.go b/internal/imports/fix.go index 5e0c9dff03..92a23439ff 100644 --- a/internal/imports/fix.go +++ b/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 diff --git a/internal/imports/fix_test.go b/internal/imports/fix_test.go index f2bc5b639a..5f96952016 100644 --- a/internal/imports/fix_test.go +++ b/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. diff --git a/internal/imports/mod.go b/internal/imports/mod.go index 28d4b1ff33..69e3eecc4c 100644 --- a/internal/imports/mod.go +++ b/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{ diff --git a/internal/imports/mod_test.go b/internal/imports/mod_test.go index 8df024fd0a..d92211e54f 100644 --- a/internal/imports/mod_test.go +++ b/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, diff --git a/internal/lsp/cache/view.go b/internal/lsp/cache/view.go index 2922460b10..be175a1c91 100644 --- a/internal/lsp/cache/view.go +++ b/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(), - BuildFlags: buildFlags, - Logf: func(format string, args ...interface{}) { - log.Print(ctx, fmt.Sprintf(format, args...)) - }, + WorkingDir: v.folder.Filename(), + BuildFlags: buildFlags, 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, "=")