// Copyright 2020 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. // Package gocommand is a helper for calling the go command. package gocommand import ( "bytes" "context" "errors" "fmt" "io" "log" "os" "reflect" "regexp" "runtime" "strconv" "strings" "sync" "time" exec "golang.org/x/sys/execabs" "golang.org/x/tools/internal/event" "golang.org/x/tools/internal/event/keys" "golang.org/x/tools/internal/event/label" "golang.org/x/tools/internal/event/tag" ) // An Runner will run go command invocations and serialize // them if it sees a concurrency error. type Runner struct { // once guards the runner initialization. once sync.Once // inFlight tracks available workers. inFlight chan struct{} // serialized guards the ability to run a go command serially, // to avoid deadlocks when claiming workers. serialized chan struct{} } const maxInFlight = 10 func (runner *Runner) initialize() { runner.once.Do(func() { runner.inFlight = make(chan struct{}, maxInFlight) runner.serialized = make(chan struct{}, 1) }) } // 1.13: go: updates to go.mod needed, but contents have changed // 1.14: go: updating go.mod: existing contents have changed since last read var modConcurrencyError = regexp.MustCompile(`go:.*go.mod.*contents have changed`) // verb is an event label for the go command verb. var verb = keys.NewString("verb", "go command verb") func invLabels(inv Invocation) []label.Label { return []label.Label{verb.Of(inv.Verb), tag.Directory.Of(inv.WorkingDir)} } // Run is a convenience wrapper around RunRaw. // It returns only stdout and a "friendly" error. func (runner *Runner) Run(ctx context.Context, inv Invocation) (*bytes.Buffer, error) { ctx, done := event.Start(ctx, "gocommand.Runner.Run", invLabels(inv)...) defer done() stdout, _, friendly, _ := runner.RunRaw(ctx, inv) return stdout, friendly } // RunPiped runs the invocation serially, always waiting for any concurrent // invocations to complete first. func (runner *Runner) RunPiped(ctx context.Context, inv Invocation, stdout, stderr io.Writer) error { ctx, done := event.Start(ctx, "gocommand.Runner.RunPiped", invLabels(inv)...) defer done() _, err := runner.runPiped(ctx, inv, stdout, stderr) return err } // RunRaw runs the invocation, serializing requests only if they fight over // go.mod changes. func (runner *Runner) RunRaw(ctx context.Context, inv Invocation) (*bytes.Buffer, *bytes.Buffer, error, error) { ctx, done := event.Start(ctx, "gocommand.Runner.RunRaw", invLabels(inv)...) defer done() // Make sure the runner is always initialized. runner.initialize() // First, try to run the go command concurrently. stdout, stderr, friendlyErr, err := runner.runConcurrent(ctx, inv) // If we encounter a load concurrency error, we need to retry serially. if friendlyErr == nil || !modConcurrencyError.MatchString(friendlyErr.Error()) { return stdout, stderr, friendlyErr, err } event.Error(ctx, "Load concurrency error, will retry serially", err) // Run serially by calling runPiped. stdout.Reset() stderr.Reset() friendlyErr, err = runner.runPiped(ctx, inv, stdout, stderr) return stdout, stderr, friendlyErr, err } func (runner *Runner) runConcurrent(ctx context.Context, inv Invocation) (*bytes.Buffer, *bytes.Buffer, error, error) { // Wait for 1 worker to become available. select { case <-ctx.Done(): return nil, nil, nil, ctx.Err() case runner.inFlight <- struct{}{}: defer func() { <-runner.inFlight }() } stdout, stderr := &bytes.Buffer{}, &bytes.Buffer{} friendlyErr, err := inv.runWithFriendlyError(ctx, stdout, stderr) return stdout, stderr, friendlyErr, err } func (runner *Runner) runPiped(ctx context.Context, inv Invocation, stdout, stderr io.Writer) (error, error) { // Make sure the runner is always initialized. runner.initialize() // Acquire the serialization lock. This avoids deadlocks between two // runPiped commands. select { case <-ctx.Done(): return nil, ctx.Err() case runner.serialized <- struct{}{}: defer func() { <-runner.serialized }() } // Wait for all in-progress go commands to return before proceeding, // to avoid load concurrency errors. for i := 0; i < maxInFlight; i++ { select { case <-ctx.Done(): return nil, ctx.Err() case runner.inFlight <- struct{}{}: // Make sure we always "return" any workers we took. defer func() { <-runner.inFlight }() } } return inv.runWithFriendlyError(ctx, stdout, stderr) } // An Invocation represents a call to the go command. type Invocation struct { Verb string Args []string BuildFlags []string // If ModFlag is set, the go command is invoked with -mod=ModFlag. ModFlag string // If ModFile is set, the go command is invoked with -modfile=ModFile. ModFile string // If Overlay is set, the go command is invoked with -overlay=Overlay. Overlay string // If CleanEnv is set, the invocation will run only with the environment // in Env, not starting with os.Environ. CleanEnv bool Env []string WorkingDir string Logf func(format string, args ...interface{}) } func (i *Invocation) runWithFriendlyError(ctx context.Context, stdout, stderr io.Writer) (friendlyError error, rawError error) { rawError = i.run(ctx, stdout, stderr) if rawError != nil { friendlyError = rawError // Check for 'go' executable not being found. if ee, ok := rawError.(*exec.Error); ok && ee.Err == exec.ErrNotFound { friendlyError = fmt.Errorf("go command required, not found: %v", ee) } if ctx.Err() != nil { friendlyError = ctx.Err() } friendlyError = fmt.Errorf("err: %v: stderr: %s", friendlyError, stderr) } return } func (i *Invocation) run(ctx context.Context, stdout, stderr io.Writer) error { log := i.Logf if log == nil { log = func(string, ...interface{}) {} } goArgs := []string{i.Verb} appendModFile := func() { if i.ModFile != "" { goArgs = append(goArgs, "-modfile="+i.ModFile) } } appendModFlag := func() { if i.ModFlag != "" { goArgs = append(goArgs, "-mod="+i.ModFlag) } } appendOverlayFlag := func() { if i.Overlay != "" { goArgs = append(goArgs, "-overlay="+i.Overlay) } } switch i.Verb { case "env", "version": goArgs = append(goArgs, i.Args...) case "mod": // mod needs the sub-verb before flags. goArgs = append(goArgs, i.Args[0]) appendModFile() goArgs = append(goArgs, i.Args[1:]...) case "get": goArgs = append(goArgs, i.BuildFlags...) appendModFile() goArgs = append(goArgs, i.Args...) default: // notably list and build. goArgs = append(goArgs, i.BuildFlags...) appendModFile() appendModFlag() appendOverlayFlag() goArgs = append(goArgs, i.Args...) } cmd := exec.Command("go", goArgs...) cmd.Stdout = stdout cmd.Stderr = stderr // cmd.WaitDelay was added only in go1.20 (see #50436). if waitDelay := reflect.ValueOf(cmd).Elem().FieldByName("WaitDelay"); waitDelay.IsValid() { // https://go.dev/issue/59541: don't wait forever copying stderr // after the command has exited. // After CL 484741 we copy stdout manually, so we we'll stop reading that as // soon as ctx is done. However, we also don't want to wait around forever // for stderr. Give a much-longer-than-reasonable delay and then assume that // something has wedged in the kernel or runtime. waitDelay.Set(reflect.ValueOf(30 * time.Second)) } // On darwin the cwd gets resolved to the real path, which breaks anything that // expects the working directory to keep the original path, including the // go command when dealing with modules. // The Go stdlib has a special feature where if the cwd and the PWD are the // same node then it trusts the PWD, so by setting it in the env for the child // process we fix up all the paths returned by the go command. if !i.CleanEnv { cmd.Env = os.Environ() } cmd.Env = append(cmd.Env, i.Env...) if i.WorkingDir != "" { cmd.Env = append(cmd.Env, "PWD="+i.WorkingDir) cmd.Dir = i.WorkingDir } defer func(start time.Time) { log("%s for %v", time.Since(start), cmdDebugStr(cmd)) }(time.Now()) return runCmdContext(ctx, cmd) } // DebugHangingGoCommands may be set by tests to enable additional // instrumentation (including panics) for debugging hanging Go commands. // // See golang/go#54461 for details. var DebugHangingGoCommands = false // runCmdContext is like exec.CommandContext except it sends os.Interrupt // before os.Kill. func runCmdContext(ctx context.Context, cmd *exec.Cmd) (err error) { // If cmd.Stdout is not an *os.File, the exec package will create a pipe and // copy it to the Writer in a goroutine until the process has finished and // either the pipe reaches EOF or command's WaitDelay expires. // // However, the output from 'go list' can be quite large, and we don't want to // keep reading (and allocating buffers) if we've already decided we don't // care about the output. We don't want to wait for the process to finish, and // we don't wait to wait for the WaitDelay to expire either. // // Instead, if cmd.Stdout requires a copying goroutine we explicitly replace // it with a pipe (which is an *os.File), which we can close in order to stop // copying output as soon as we realize we don't care about it. var stdoutW *os.File if cmd.Stdout != nil { if _, ok := cmd.Stdout.(*os.File); !ok { var stdoutR *os.File stdoutR, stdoutW, err = os.Pipe() if err != nil { return err } prevStdout := cmd.Stdout cmd.Stdout = stdoutW stdoutErr := make(chan error, 1) go func() { _, err := io.Copy(prevStdout, stdoutR) if err != nil { err = fmt.Errorf("copying stdout: %w", err) } stdoutErr <- err }() defer func() { // We started a goroutine to copy a stdout pipe. // Wait for it to finish, or terminate it if need be. var err2 error select { case err2 = <-stdoutErr: stdoutR.Close() case <-ctx.Done(): stdoutR.Close() // Per https://pkg.go.dev/os#File.Close, the call to stdoutR.Close // should cause the Read call in io.Copy to unblock and return // immediately, but we still need to receive from stdoutErr to confirm // that that has happened. <-stdoutErr err2 = ctx.Err() } if err == nil { err = err2 } }() // Per https://pkg.go.dev/os/exec#Cmd, “If Stdout and Stderr are the // same writer, and have a type that can be compared with ==, at most // one goroutine at a time will call Write.” // // Since we're starting a goroutine that writes to cmd.Stdout, we must // also update cmd.Stderr so that that still holds. func() { defer func() { recover() }() if cmd.Stderr == prevStdout { cmd.Stderr = cmd.Stdout } }() } } err = cmd.Start() if stdoutW != nil { // The child process has inherited the pipe file, // so close the copy held in this process. stdoutW.Close() stdoutW = nil } if err != nil { return err } resChan := make(chan error, 1) go func() { resChan <- cmd.Wait() }() // If we're interested in debugging hanging Go commands, stop waiting after a // minute and panic with interesting information. debug := DebugHangingGoCommands if debug { timer := time.NewTimer(1 * time.Minute) defer timer.Stop() select { case err := <-resChan: return err case <-timer.C: HandleHangingGoCommand(cmd.Process) case <-ctx.Done(): } } else { select { case err := <-resChan: return err case <-ctx.Done(): } } // Cancelled. Interrupt and see if it ends voluntarily. if err := cmd.Process.Signal(os.Interrupt); err == nil { // (We used to wait only 1s but this proved // fragile on loaded builder machines.) timer := time.NewTimer(5 * time.Second) defer timer.Stop() select { case err := <-resChan: return err case <-timer.C: } } // Didn't shut down in response to interrupt. Kill it hard. // TODO(rfindley): per advice from bcmills@, it may be better to send SIGQUIT // on certain platforms, such as unix. if err := cmd.Process.Kill(); err != nil && !errors.Is(err, os.ErrProcessDone) && debug { log.Printf("error killing the Go command: %v", err) } return <-resChan } func HandleHangingGoCommand(proc *os.Process) { switch runtime.GOOS { case "linux", "darwin", "freebsd", "netbsd": fmt.Fprintln(os.Stderr, `DETECTED A HANGING GO COMMAND The gopls test runner has detected a hanging go command. In order to debug this, the output of ps and lsof/fstat is printed below. See golang/go#54461 for more details.`) fmt.Fprintln(os.Stderr, "\nps axo ppid,pid,command:") fmt.Fprintln(os.Stderr, "-------------------------") psCmd := exec.Command("ps", "axo", "ppid,pid,command") psCmd.Stdout = os.Stderr psCmd.Stderr = os.Stderr if err := psCmd.Run(); err != nil { panic(fmt.Sprintf("running ps: %v", err)) } listFiles := "lsof" if runtime.GOOS == "freebsd" || runtime.GOOS == "netbsd" { listFiles = "fstat" } fmt.Fprintln(os.Stderr, "\n"+listFiles+":") fmt.Fprintln(os.Stderr, "-----") listFilesCmd := exec.Command(listFiles) listFilesCmd.Stdout = os.Stderr listFilesCmd.Stderr = os.Stderr if err := listFilesCmd.Run(); err != nil { panic(fmt.Sprintf("running %s: %v", listFiles, err)) } } panic(fmt.Sprintf("detected hanging go command (pid %d): see golang/go#54461 for more details", proc.Pid)) } func cmdDebugStr(cmd *exec.Cmd) string { env := make(map[string]string) for _, kv := range cmd.Env { split := strings.SplitN(kv, "=", 2) if len(split) == 2 { k, v := split[0], split[1] env[k] = v } } var args []string for _, arg := range cmd.Args { quoted := strconv.Quote(arg) if quoted[1:len(quoted)-1] != arg || strings.Contains(arg, " ") { args = append(args, quoted) } else { args = append(args, arg) } } return fmt.Sprintf("GOROOT=%v GOPATH=%v GO111MODULE=%v GOPROXY=%v PWD=%v %v", env["GOROOT"], env["GOPATH"], env["GO111MODULE"], env["GOPROXY"], env["PWD"], strings.Join(args, " ")) }