cmd/go: print toolchain switching with GODEBUG=toolchaintrace

This CL introduces the ability to print information about the toolchain switch used in the
go command, controlled by the `toolchaintrace` setting. This setting defaults to `toolchaintrace=0`,
meaning no information is printed. Setting it to `toolchaintrace=1` will cause the go command
to print a message indicating the toolchain used and where it was found.

Fixes: #63939
Cq-Include-Trybots: luci.golang.try:gotip-linux-amd64-longtest,gotip-windows-amd64-longtest
Change-Id: Idc58e3d5bc76573aa48e1f7df352caa13004c25e
Reviewed-on: https://go-review.googlesource.com/c/go/+/610235
Reviewed-by: Michael Matloob <matloob@golang.org>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>

src/cmd/go/internal/toolchain/exec.go

@@ -8,6 +8,7 @@ package toolchain
 
 import (
 	"cmd/go/internal/base"
+	"fmt"
 	"internal/godebug"
 	"os"
 	"os/exec"
@@ -26,6 +27,13 @@ func execGoToolchain(gotoolchain, dir, exe string) {
 	} else {
 		os.Setenv("GOROOT", dir)
 	}
+	if toolchainTrace {
+		if dir == "" {
+			fmt.Fprintf(os.Stderr, "go: using %s toolchain located in system PATH (%s)\n", gotoolchain, exe)
+		} else {
+			fmt.Fprintf(os.Stderr, "go: using %s toolchain from cache located at %s\n", gotoolchain, exe)
+		}
+	}
 
 	// On Windows, there is no syscall.Exec, so the best we can do
 	// is run a subprocess and exit with the same status.

src/cmd/go/internal/toolchain/select.go

@@ -6,11 +6,14 @@
 package toolchain
 
 import (
+	"bytes"
 	"context"
 	"errors"
 	"flag"
 	"fmt"
 	"go/build"
+	"internal/godebug"
+	"io"
 	"io/fs"
 	"log"
 	"os"
@@ -84,6 +87,7 @@ func FilterEnv(env []string) []string {
 }
 
 var counterErrorsInvalidToolchainInFile = counter.New("go/errors:invalid-toolchain-in-file")
+var toolchainTrace = godebug.New("#toolchaintrace").Value() == "1"
 
 // Select invokes a different Go toolchain if directed by
 // the GOTOOLCHAIN environment variable or the user's configuration
@@ -137,6 +141,7 @@ func Select() {
 	minToolchain := gover.LocalToolchain()
 	minVers := gover.Local()
 	var mode string
+	var toolchainTraceBuffer bytes.Buffer
 	if gotoolchain == "auto" {
 		mode = "auto"
 	} else if gotoolchain == "path" {
@@ -158,6 +163,9 @@ func Select() {
 			base.Fatalf("invalid GOTOOLCHAIN %q: only version suffixes are +auto and +path", gotoolchain)
 		}
 		mode = suffix
+		if toolchainTrace {
+			fmt.Fprintf(&toolchainTraceBuffer, "go: default toolchain set to %s from GOTOOLCHAIN=%s\n", minToolchain, gotoolchain)
+		}
 	}
 
 	gotoolchain = minToolchain
@@ -190,6 +198,13 @@ func Select() {
 					base.Fatalf("invalid toolchain %q in %s", toolchain, base.ShortPath(file))
 				}
 				if gover.Compare(toolVers, minVers) > 0 {
+					if toolchainTrace {
+						modeFormat := mode
+						if strings.Contains(cfg.Getenv("GOTOOLCHAIN"), "+") { // go1.2.3+auto
+							modeFormat = fmt.Sprintf("<name>+%s", mode)
+						}
+						fmt.Fprintf(&toolchainTraceBuffer, "go: upgrading toolchain to %s (required by toolchain line in %s; upgrade allowed by GOTOOLCHAIN=%s)\n", toolchain, base.ShortPath(file), modeFormat)
+					}
 					gotoolchain = toolchain
 					minVers = toolVers
 					gover.Startup.AutoToolchain = toolchain
@@ -206,6 +221,13 @@ func Select() {
 				}
 				gover.Startup.AutoGoVersion = goVers
 				gover.Startup.AutoToolchain = "" // in case we are overriding it for being too old
+				if toolchainTrace {
+					modeFormat := mode
+					if strings.Contains(cfg.Getenv("GOTOOLCHAIN"), "+") { // go1.2.3+auto
+						modeFormat = fmt.Sprintf("<name>+%s", mode)
+					}
+					fmt.Fprintf(&toolchainTraceBuffer, "go: upgrading toolchain to %s (required by go line in %s; upgrade allowed by GOTOOLCHAIN=%s)\n", gotoolchain, base.ShortPath(file), modeFormat)
+				}
 			}
 		}
 	}
@@ -237,8 +259,16 @@ func Select() {
 		return
 	}
 
+	if toolchainTrace {
+		// Flush toolchain tracing buffer only in the parent process (targetEnv is unset).
+		io.Copy(os.Stderr, &toolchainTraceBuffer)
+	}
+
 	if gotoolchain == "local" || gotoolchain == gover.LocalToolchain() {
 		// Let the current binary handle the command.
+		if toolchainTrace {
+			fmt.Fprintf(os.Stderr, "go: using local toolchain %s\n", gover.LocalToolchain())
+		}
 		return
 	}
 

src/cmd/go/testdata/script/gotoolchain_godebug_trace.txt

@@ -0,0 +1,122 @@
+# Test the GODEBUG=toolchaintrace behavior
+# See https://go.dev/issue/63939
+env GODEBUG=toolchaintrace=1
+env TESTGO_VERSION=go1.21.0
+env TESTGO_VERSION_SWITCH=switch
+env GOTOOLCHAIN=auto
+
+# Go line is newer than local go version.
+go mod init m
+go mod edit -go=1.21.1
+go version
+stderr -count=1 'go: upgrading toolchain to go1.21.1 \(required by go line in go.mod; upgrade allowed by GOTOOLCHAIN=auto\)'
+stderr -count=1 'go: using go1.21.1 toolchain from cache located at .*'
+stdout 'go version go1.21.1'
+rm go.mod
+
+# Toolchain line is newer than go line.
+go mod init m
+go mod edit -go=1.21.1 -toolchain=go1.21.2
+go version
+stderr -count=1 'go: upgrading toolchain to go1.21.2 \(required by toolchain line in go.mod; upgrade allowed by GOTOOLCHAIN=auto\)'
+stderr -count=1 'go: using go1.21.2 toolchain from cache located at .*'
+stdout 'go version go1.21.2'
+rm go.mod
+
+# Go line is newer than local go version and toolchain line.
+go mod init m
+go mod edit -go=1.22 -toolchain=go1.21.2
+go version
+stderr -count=1 'go: upgrading toolchain to go1.21.2 \(required by toolchain line in go.mod; upgrade allowed by GOTOOLCHAIN=auto\)'
+stderr -count=1 'go: upgrading toolchain to go1.22.0 \(required by go line in go.mod; upgrade allowed by GOTOOLCHAIN=auto\)'
+stderr -count=1 'go: using go1.22.0 toolchain from cache located at .*'
+stdout 'go version go1.22.0'
+rm go.mod
+
+# No switch.
+go mod init m
+go mod edit -go=1.21.0 -toolchain=go1.21.0
+go version
+stderr -count=1 'go: using local toolchain go1.21.0'
+! stderr 'go: upgrading toolchain'
+stdout 'go version go1.21.0'
+rm go.mod
+
+# GOTOOLCHAIN+auto is older than go line and toolchain line.
+go mod init m
+go mod edit -go=1.22 -toolchain=go1.21.2
+env GOTOOLCHAIN=go1.21.0+auto
+go version
+stderr -count=1 'go: default toolchain set to go1.21.0 from GOTOOLCHAIN=go1.21.0\+auto'
+stderr -count=1 'go: upgrading toolchain to go1.21.2 \(required by toolchain line in go.mod; upgrade allowed by GOTOOLCHAIN=<name>\+auto\)'
+stderr -count=1 'go: upgrading toolchain to go1.22.0 \(required by go line in go.mod; upgrade allowed by GOTOOLCHAIN=<name>\+auto\)'
+stderr -count=1 'go: using go1.22.0 toolchain from cache located at .*'
+stdout 'go version go1.22.0'
+rm go.mod
+
+# GOTOOLCHAIN is older than go line and toolchain line.
+go mod init m
+go mod edit -go=1.22 -toolchain=go1.21.2
+env GOTOOLCHAIN=go1.21.1
+go version
+stderr -count=1 'go: default toolchain set to go1.21.1 from GOTOOLCHAIN=go1.21.1'
+stderr -count=1 'go: using go1.21.1 toolchain from cache located at .*'
+! stderr 'go: upgrading toolchain'
+stdout 'go version go1.21.1'
+rm go.mod
+env GOTOOLCHAIN=auto
+
+# GOTOOLCHAIN+auto is newer than go line and toolchain line.
+go mod init m
+go mod edit -go=1.21.1 -toolchain=go1.21.2
+env GOTOOLCHAIN=go1.22.0+auto
+go version
+stderr -count=1 'go: default toolchain set to go1.22.0 from GOTOOLCHAIN=go1.22.0\+auto'
+stderr -count=1 'go: using go1.22.0 toolchain from cache located at .*'
+stdout 'go version go1.22.0'
+rm go.mod
+
+# GOTOOLCHAIN=local
+env GOTOOLCHAIN=local
+go mod init m
+go mod edit -go=1.21.1 -toolchain=go1.21.2
+go version
+stderr -count=1 'go: default toolchain set to go1.21.0 from GOTOOLCHAIN=local'
+stderr -count=1 'go: using local toolchain go1.21.0'
+stdout 'go version go1.21.0'
+rm go.mod
+
+[short] stop 'requires build'
+# If toolchain found in PATH, ensure we print that.
+env GOTOOLCHAIN=auto
+env TESTGO_VERSION_SWITCH=
+mkdir $WORK/bin
+go build -o $WORK/bin/go1.22.0$GOEXE ./fake/fakego.go  # adds .exe extension implicitly on Windows
+[!GOOS:plan9] env PATH=$WORK/bin
+[GOOS:plan9] env path=$WORK/bin
+go mod init m
+go mod edit -go=1.22.0
+! go version
+stderr -count=1 'go: upgrading toolchain to go1.22.0 \(required by go line in go.mod; upgrade allowed by GOTOOLCHAIN=auto\)'
+stderr -count=1 'go: using go1.22.0 toolchain located in system PATH \('$WORK'[/\\]bin[/\\]go1.22.0'$GOEXE'\)'
+stderr 'running go1.22.0 from PATH'
+rm go.mod
+
+
+-- fake/fakego.go --
+package main
+
+import (
+	"fmt"
+	"os"
+	"path/filepath"
+	"strings"
+)
+
+func main() {
+	exe, _ := os.Executable()
+	name := filepath.Base(exe)
+	name = strings.TrimSuffix(name, ".exe")
+	fmt.Fprintf(os.Stderr, "running %s from PATH\n", name)
+	os.Exit(1) // fail in case we are running this accidentally (like in "go mod edit")
+}