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>

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.

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) {

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