go/packages: add debug logging via the packages.Config

This change adds a Logf field to the packages.Config.

Change-Id: I144a9a1e1181585bbe621898c4a3e6a007a38322
Reviewed-on: https://go-review.googlesource.com/c/tools/+/185993
Run-TryBot: Rebecca Stambler <rstambler@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Michael Matloob <matloob@golang.org>

go/packages/golist.go

@@ -316,9 +316,7 @@ func runNamedQueries(cfg *Config, driver driver, response *responseDeduper, quer
 
 	startWalk := time.Now()
 	gopathwalk.Walk(roots, add, gopathwalk.Options{ModulesEnabled: modRoot != "", Debug: debug})
-	if debug {
+	cfg.Logf("%v for walk", time.Since(startWalk))
-		log.Printf("%v for walk", time.Since(startWalk))
-	}
 
 	// Weird special case: the top-level package in a module will be in
 	// whatever directory the user checked the repository out into. It's
@@ -759,11 +757,9 @@ func invokeGo(cfg *Config, args ...string) (*bytes.Buffer, error) {
 	cmd.Dir = cfg.Dir
 	cmd.Stdout = stdout
 	cmd.Stderr = stderr
-	if debug {
+	defer func(start time.Time) {
-		defer func(start time.Time) {
+		cfg.Logf("%s for %v, stderr: <<%s>>\n", time.Since(start), cmdDebugStr(cmd, args...), stderr)
-			log.Printf("%s for %v, stderr: <<%s>>\n", time.Since(start), cmdDebugStr(cmd, args...), stderr)
+	}(time.Now())
-		}(time.Now())
-	}
 
 	if err := cmd.Run(); err != nil {
 		// Check for 'go' executable not being found.

go/packages/packages.go

@@ -103,6 +103,12 @@ type Config struct {
 	// If Context is nil, the load cannot be cancelled.
 	Context context.Context
 
+	// Logf is the logger for the config.
+	// If the user provides a logger, debug logging is enabled.
+	// If the GOPACKAGESDEBUG environment variable is set to true,
+	// but the logger is nil, default to log.Printf.
+	Logf func(format string, args ...interface{})
+
 	// Dir is the directory in which to run the build system's query tool
 	// that provides information about the packages.
 	// If Dir is empty, the tool is run in the current directory.
@@ -429,6 +435,17 @@ func newLoader(cfg *Config) *loader {
 	}
 	if cfg != nil {
 		ld.Config = *cfg
+		// If the user has provided a logger, use it.
+		ld.Config.Logf = cfg.Logf
+	}
+	if ld.Config.Logf == nil {
+		// If the GOPACKAGESDEBUG environment variable is set to true,
+		// but the user has not provided a logger, default to log.Printf.
+		if debug {
+			ld.Config.Logf = log.Printf
+		} else {
+			ld.Config.Logf = func(format string, args ...interface{}) {}
+		}
 	}
 	if ld.Config.Mode == 0 {
 		ld.Config.Mode = NeedName | NeedFiles | NeedCompiledGoFiles // Preserve zero behavior of Mode for backwards compatibility.

internal/lsp/cache/load.go

@@ -85,7 +85,7 @@ func (v *view) checkMetadata(ctx context.Context, f *goFile) (map[packageID]*met
 		return nil, nil, ctx.Err()
 	}
 
-	pkgs, err := packages.Load(v.Config(), fmt.Sprintf("file=%s", f.filename()))
+	pkgs, err := packages.Load(v.Config(ctx), fmt.Sprintf("file=%s", f.filename()))
 	if len(pkgs) == 0 {
 		if err == nil {
 			err = fmt.Errorf("go/packages.Load: no packages found for %s", f.filename())

internal/lsp/cache/session.go

@@ -91,7 +91,7 @@ func (s *session) NewView(ctx context.Context, name string, folder span.URI) sou
 	}
 	// Preemptively build the builtin package,
 	// so we immediately add builtin.go to the list of ignored files.
-	v.buildBuiltinPkg()
+	v.buildBuiltinPkg(ctx)
 
 	s.views = append(s.views, v)
 	// we always need to drop the view map

internal/lsp/cache/view.go

@@ -118,7 +118,7 @@ func (v *view) Folder() span.URI {
 
 // Config returns the configuration used for the view's interaction with the
 // go/packages API. It is shared across all views.
-func (v *view) Config() *packages.Config {
+func (v *view) Config(ctx context.Context) *packages.Config {
 	// TODO: Should we cache the config and/or overlay somewhere?
 	return &packages.Config{
 		Dir:        v.folder.Filename(),
@@ -135,22 +135,25 @@ func (v *view) Config() *packages.Config {
 		ParseFile: func(*token.FileSet, string, []byte) (*ast.File, error) {
 			panic("go/packages must not be used to parse files")
 		},
+		Logf: func(format string, args ...interface{}) {
+			xlog.Infof(ctx, format, args...)
+		},
 		Tests: true,
 	}
 }
 
-func (v *view) ProcessEnv() *imports.ProcessEnv {
+func (v *view) ProcessEnv(ctx context.Context) *imports.ProcessEnv {
 	v.mu.Lock()
 	defer v.mu.Unlock()
 
 	if v.processEnv == nil {
-		v.processEnv = v.buildProcessEnv()
+		v.processEnv = v.buildProcessEnv(ctx)
 	}
 	return v.processEnv
 }
 
-func (v *view) buildProcessEnv() *imports.ProcessEnv {
+func (v *view) buildProcessEnv(ctx context.Context) *imports.ProcessEnv {
-	cfg := v.Config()
+	cfg := v.Config(ctx)
 	env := &imports.ProcessEnv{
 		WorkingDir: cfg.Dir,
 		Logf: func(format string, u ...interface{}) {
@@ -235,9 +238,12 @@ func (v *view) BuiltinPackage() *ast.Package {
 // buildBuiltinPkg builds the view's builtin package.
 // It assumes that the view is not active yet,
 // i.e. it has not been added to the session's list of views.
-func (v *view) buildBuiltinPkg() {
+func (v *view) buildBuiltinPkg(ctx context.Context) {
-	cfg := *v.Config()
+	cfg := *v.Config(ctx)
-	pkgs, _ := packages.Load(&cfg, "builtin")
+	pkgs, err := packages.Load(&cfg, "builtin")
+	if err != nil {
+		xlog.Errorf(ctx, "error getting package metadata for \"builtin\" package: %v", err)
+	}
 	if len(pkgs) != 1 {
 		v.builtinPkg, _ = ast.NewPackage(cfg.Fset, nil, nil, nil)
 		return

internal/lsp/source/format.go

@@ -68,7 +68,7 @@ func Imports(ctx context.Context, view View, f GoFile, rng span.Range) ([]TextEd
 		return nil, fmt.Errorf("%s has list errors, not running goimports", f.URI())
 	}
 
-	if resolver, ok := view.ProcessEnv().GetResolver().(*imports.ModuleResolver); ok && resolver.Initialized {
+	if resolver, ok := view.ProcessEnv(ctx).GetResolver().(*imports.ModuleResolver); ok && resolver.Initialized {
 		// TODO(suzmue): only reset this state when necessary (eg when the go.mod files of this
 		// module or modules with replace directive changes).
 		resolver.Initialized = false
@@ -77,7 +77,7 @@ func Imports(ctx context.Context, view View, f GoFile, rng span.Range) ([]TextEd
 		resolver.ModsByDir = nil
 	}
 	options := &imports.Options{
-		Env: view.ProcessEnv(),
+		Env: view.ProcessEnv(ctx),
 		// Defaults.
 		AllErrors:  true,
 		Comments:   true,

internal/lsp/source/view.go

@@ -208,7 +208,7 @@ type View interface {
 	// Ignore returns true if this file should be ignored by this view.
 	Ignore(span.URI) bool
 
-	Config() *packages.Config
+	Config(ctx context.Context) *packages.Config
 
 	// Process returns the process for this view.
 	// Note: this contains cached module and filesystem state, which must
@@ -217,7 +217,7 @@ type View interface {
 	// TODO(suzmue): the state cached in the process env is specific to each view,
 	// however, there is state that can be shared between views that is not currently
 	// cached, like the module cache.
-	ProcessEnv() *imports.ProcessEnv
+	ProcessEnv(ctx context.Context) *imports.ProcessEnv
 }
 
 // File represents a source file of any type.