cmd/go: make "finding" logging deterministic

In CL 204777, I made the "finding" messages in cachingRepo only print
after a “longish” delay, on the theory that they would help diagnose
slow or stuck fetches.

However, as I've been testing Go 1.14 beta 1, I've found that these
messages are mostly just noise, and the fact that they are so
nondeterministic causes both confusion and test flakes (#35539).

Moreover, it currently triggers once for each candidate module, when
what we're usually after is actually a specific package within the
module.

So let's log the package operation unconditionally instead of the
module fetches nondeterministically.

Fixes #35539
Updates #26152

Change-Id: I41a1c772465b2f0b357d3402bc372b6907773741
Reviewed-on: https://go-review.googlesource.com/c/go/+/213679
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>

diff --git a/src/cmd/go/internal/modfetch/cache.go b/src/cmd/go/internal/modfetch/cache.go
index 104fce86dda91b02697ea873f5389c262c6e2fc9..947192bd83ee387bc94f23a8323cd5fb874e4454 100644 (file)
--- a/src/cmd/go/internal/modfetch/cache.go
+++ b/src/cmd/go/internal/modfetch/cache.go
@@ -13,7 +13,6 @@ import (
        "os"
        "path/filepath"
        "strings"
-       "time"
 
        "cmd/go/internal/base"
        "cmd/go/internal/cfg"
@@ -28,8 +27,6 @@ import (
 
 var PkgMod string // $GOPATH/pkg/mod; set by package modload
 
-const logFindingDelay = 1 * time.Second
-
 func cacheDir(path string) (string, error) {
        if PkgMod == "" {
                return "", fmt.Errorf("internal error: modfetch.PkgMod not set")
@@ -140,11 +137,6 @@ func (r *cachingRepo) Versions(prefix string) ([]string, error) {
                err  error
        }
        c := r.cache.Do("versions:"+prefix, func() interface{} {
-               logTimer := time.AfterFunc(logFindingDelay, func() {
-                       fmt.Fprintf(os.Stderr, "go: finding versions for %s\n", r.path)
-               })
-               defer logTimer.Stop()
-
                list, err := r.r.Versions(prefix)
                return cached{list, err}
        }).(cached)
@@ -167,11 +159,6 @@ func (r *cachingRepo) Stat(rev string) (*RevInfo, error) {
                        return cachedInfo{info, nil}
                }
 
-               logTimer := time.AfterFunc(logFindingDelay, func() {
-                       fmt.Fprintf(os.Stderr, "go: finding %s %s\n", r.path, rev)
-               })
-               defer logTimer.Stop()
-
                info, err = r.r.Stat(rev)
                if err == nil {
                        // If we resolved, say, 1234abcde to v0.0.0-20180604122334-1234abcdef78,
@@ -199,11 +186,6 @@ func (r *cachingRepo) Stat(rev string) (*RevInfo, error) {
 
 func (r *cachingRepo) Latest() (*RevInfo, error) {
        c := r.cache.Do("latest:", func() interface{} {
-               logTimer := time.AfterFunc(logFindingDelay, func() {
-                       fmt.Fprintf(os.Stderr, "go: finding %s latest\n", r.path)
-               })
-               defer logTimer.Stop()
-
                info, err := r.r.Latest()
 
                // Save info for likely future Stat call.

diff --git a/src/cmd/go/internal/modload/import.go b/src/cmd/go/internal/modload/import.go
index 3170ffab8897fee074f4d4444c619ec423c6ea23..5906d648b49afdb7065211eb9bec97cc7f1fbbbd 100644 (file)
--- a/src/cmd/go/internal/modload/import.go
+++ b/src/cmd/go/internal/modload/import.go
@@ -269,6 +269,8 @@ func Import(path string) (m module.Version, dir string, err error) {
                return module.Version{}, "", &ImportMissingError{Path: path}
        }
 
+       fmt.Fprintf(os.Stderr, "go: finding module for package %s\n", path)
+
        candidates, err := QueryPackage(path, "latest", Allowed)
        if err != nil {
                if errors.Is(err, os.ErrNotExist) {

diff --git a/src/cmd/go/testdata/script/mod_load_badchain.txt b/src/cmd/go/testdata/script/mod_load_badchain.txt
index 2c532f1fda33a6c239c6b675fe729c6c5b27f0cf..67d9a1584f51f8fcabbf62dc83a466bf95ae98db 100644 (file)
--- a/src/cmd/go/testdata/script/mod_load_badchain.txt
+++ b/src/cmd/go/testdata/script/mod_load_badchain.txt
@@ -75,12 +75,14 @@ go: example.com/badchain/a@v1.1.0 requires
        module declares its path as: badchain.example.com/c
                but was required as: example.com/badchain/c
 -- list-missing-expected --
+go: finding module for package example.com/badchain/c
 go: found example.com/badchain/c in example.com/badchain/c v1.1.0
 go: m/use imports
        example.com/badchain/c: example.com/badchain/c@v1.1.0: parsing go.mod:
        module declares its path as: badchain.example.com/c
                but was required as: example.com/badchain/c
 -- list-missing-test-expected --
+go: finding module for package example.com/badchain/c
 go: found example.com/badchain/c in example.com/badchain/c v1.1.0
 go: m/testuse tested by
        m/testuse.test imports