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 104fce8..947192b 100644
--- a/src/cmd/go/internal/modfetch/cache.go
+++ b/src/cmd/go/internal/modfetch/cache.go
@@ -13,7 +13,6 @@
"os"
"path/filepath"
"strings"
- "time"
"cmd/go/internal/base"
"cmd/go/internal/cfg"
@@ -28,8 +27,6 @@
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 @@
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 @@
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) 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 3170ffa..5906d64 100644
--- a/src/cmd/go/internal/modload/import.go
+++ b/src/cmd/go/internal/modload/import.go
@@ -269,6 +269,8 @@
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 2c532f1..67d9a15 100644
--- a/src/cmd/go/testdata/script/mod_load_badchain.txt
+++ b/src/cmd/go/testdata/script/mod_load_badchain.txt
@@ -75,12 +75,14 @@
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
