invoke.go

Documentation: golang.org/x/tools/internal/gocommand

     1  // Copyright 2020 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  // Package gocommand is a helper for calling the go command.
     6  package gocommand
     7  
     8  import (
     9  	"bytes"
    10  	"context"
    11  	"errors"
    12  	"fmt"
    13  	"io"
    14  	"log"
    15  	"os"
    16  	"os/exec"
    17  	"reflect"
    18  	"regexp"
    19  	"runtime"
    20  	"strconv"
    21  	"strings"
    22  	"sync"
    23  	"time"
    24  
    25  	"golang.org/x/tools/internal/event"
    26  	"golang.org/x/tools/internal/event/keys"
    27  	"golang.org/x/tools/internal/event/label"
    28  )
    29  
    30  // An Runner will run go command invocations and serialize
    31  // them if it sees a concurrency error.
    32  type Runner struct {
    33  	// once guards the runner initialization.
    34  	once sync.Once
    35  
    36  	// inFlight tracks available workers.
    37  	inFlight chan struct{}
    38  
    39  	// serialized guards the ability to run a go command serially,
    40  	// to avoid deadlocks when claiming workers.
    41  	serialized chan struct{}
    42  }
    43  
    44  const maxInFlight = 10
    45  
    46  func (runner *Runner) initialize() {
    47  	runner.once.Do(func() {
    48  		runner.inFlight = make(chan struct{}, maxInFlight)
    49  		runner.serialized = make(chan struct{}, 1)
    50  	})
    51  }
    52  
    53  // 1.13: go: updates to go.mod needed, but contents have changed
    54  // 1.14: go: updating go.mod: existing contents have changed since last read
    55  var modConcurrencyError = regexp.MustCompile(`go:.*go.mod.*contents have changed`)
    56  
    57  // event keys for go command invocations
    58  var (
    59  	verb      = keys.NewString("verb", "go command verb")
    60  	directory = keys.NewString("directory", "")
    61  )
    62  
    63  func invLabels(inv Invocation) []label.Label {
    64  	return []label.Label{verb.Of(inv.Verb), directory.Of(inv.WorkingDir)}
    65  }
    66  
    67  // Run is a convenience wrapper around RunRaw.
    68  // It returns only stdout and a "friendly" error.
    69  func (runner *Runner) Run(ctx context.Context, inv Invocation) (*bytes.Buffer, error) {
    70  	ctx, done := event.Start(ctx, "gocommand.Runner.Run", invLabels(inv)...)
    71  	defer done()
    72  
    73  	stdout, _, friendly, _ := runner.RunRaw(ctx, inv)
    74  	return stdout, friendly
    75  }
    76  
    77  // RunPiped runs the invocation serially, always waiting for any concurrent
    78  // invocations to complete first.
    79  func (runner *Runner) RunPiped(ctx context.Context, inv Invocation, stdout, stderr io.Writer) error {
    80  	ctx, done := event.Start(ctx, "gocommand.Runner.RunPiped", invLabels(inv)...)
    81  	defer done()
    82  
    83  	_, err := runner.runPiped(ctx, inv, stdout, stderr)
    84  	return err
    85  }
    86  
    87  // RunRaw runs the invocation, serializing requests only if they fight over
    88  // go.mod changes.
    89  // Postcondition: both error results have same nilness.
    90  func (runner *Runner) RunRaw(ctx context.Context, inv Invocation) (*bytes.Buffer, *bytes.Buffer, error, error) {
    91  	ctx, done := event.Start(ctx, "gocommand.Runner.RunRaw", invLabels(inv)...)
    92  	defer done()
    93  	// Make sure the runner is always initialized.
    94  	runner.initialize()
    95  
    96  	// First, try to run the go command concurrently.
    97  	stdout, stderr, friendlyErr, err := runner.runConcurrent(ctx, inv)
    98  
    99  	// If we encounter a load concurrency error, we need to retry serially.
   100  	if friendlyErr != nil && modConcurrencyError.MatchString(friendlyErr.Error()) {
   101  		event.Error(ctx, "Load concurrency error, will retry serially", err)
   102  
   103  		// Run serially by calling runPiped.
   104  		stdout.Reset()
   105  		stderr.Reset()
   106  		friendlyErr, err = runner.runPiped(ctx, inv, stdout, stderr)
   107  	}
   108  
   109  	return stdout, stderr, friendlyErr, err
   110  }
   111  
   112  // Postcondition: both error results have same nilness.
   113  func (runner *Runner) runConcurrent(ctx context.Context, inv Invocation) (*bytes.Buffer, *bytes.Buffer, error, error) {
   114  	// Wait for 1 worker to become available.
   115  	select {
   116  	case <-ctx.Done():
   117  		return nil, nil, ctx.Err(), ctx.Err()
   118  	case runner.inFlight <- struct{}{}:
   119  		defer func() { <-runner.inFlight }()
   120  	}
   121  
   122  	stdout, stderr := &bytes.Buffer{}, &bytes.Buffer{}
   123  	friendlyErr, err := inv.runWithFriendlyError(ctx, stdout, stderr)
   124  	return stdout, stderr, friendlyErr, err
   125  }
   126  
   127  // Postcondition: both error results have same nilness.
   128  func (runner *Runner) runPiped(ctx context.Context, inv Invocation, stdout, stderr io.Writer) (error, error) {
   129  	// Make sure the runner is always initialized.
   130  	runner.initialize()
   131  
   132  	// Acquire the serialization lock. This avoids deadlocks between two
   133  	// runPiped commands.
   134  	select {
   135  	case <-ctx.Done():
   136  		return ctx.Err(), ctx.Err()
   137  	case runner.serialized <- struct{}{}:
   138  		defer func() { <-runner.serialized }()
   139  	}
   140  
   141  	// Wait for all in-progress go commands to return before proceeding,
   142  	// to avoid load concurrency errors.
   143  	for i := 0; i < maxInFlight; i++ {
   144  		select {
   145  		case <-ctx.Done():
   146  			return ctx.Err(), ctx.Err()
   147  		case runner.inFlight <- struct{}{}:
   148  			// Make sure we always "return" any workers we took.
   149  			defer func() { <-runner.inFlight }()
   150  		}
   151  	}
   152  
   153  	return inv.runWithFriendlyError(ctx, stdout, stderr)
   154  }
   155  
   156  // An Invocation represents a call to the go command.
   157  type Invocation struct {
   158  	Verb       string
   159  	Args       []string
   160  	BuildFlags []string
   161  
   162  	// If ModFlag is set, the go command is invoked with -mod=ModFlag.
   163  	// TODO(rfindley): remove, in favor of Args.
   164  	ModFlag string
   165  
   166  	// If ModFile is set, the go command is invoked with -modfile=ModFile.
   167  	// TODO(rfindley): remove, in favor of Args.
   168  	ModFile string
   169  
   170  	// If Overlay is set, the go command is invoked with -overlay=Overlay.
   171  	// TODO(rfindley): remove, in favor of Args.
   172  	Overlay string
   173  
   174  	// If CleanEnv is set, the invocation will run only with the environment
   175  	// in Env, not starting with os.Environ.
   176  	CleanEnv   bool
   177  	Env        []string
   178  	WorkingDir string
   179  	Logf       func(format string, args ...interface{})
   180  }
   181  
   182  // Postcondition: both error results have same nilness.
   183  func (i *Invocation) runWithFriendlyError(ctx context.Context, stdout, stderr io.Writer) (friendlyError error, rawError error) {
   184  	rawError = i.run(ctx, stdout, stderr)
   185  	if rawError != nil {
   186  		friendlyError = rawError
   187  		// Check for 'go' executable not being found.
   188  		if ee, ok := rawError.(*exec.Error); ok && ee.Err == exec.ErrNotFound {
   189  			friendlyError = fmt.Errorf("go command required, not found: %v", ee)
   190  		}
   191  		if ctx.Err() != nil {
   192  			friendlyError = ctx.Err()
   193  		}
   194  		friendlyError = fmt.Errorf("err: %v: stderr: %s", friendlyError, stderr)
   195  	}
   196  	return
   197  }
   198  
   199  func (i *Invocation) run(ctx context.Context, stdout, stderr io.Writer) error {
   200  	log := i.Logf
   201  	if log == nil {
   202  		log = func(string, ...interface{}) {}
   203  	}
   204  
   205  	goArgs := []string{i.Verb}
   206  
   207  	appendModFile := func() {
   208  		if i.ModFile != "" {
   209  			goArgs = append(goArgs, "-modfile="+i.ModFile)
   210  		}
   211  	}
   212  	appendModFlag := func() {
   213  		if i.ModFlag != "" {
   214  			goArgs = append(goArgs, "-mod="+i.ModFlag)
   215  		}
   216  	}
   217  	appendOverlayFlag := func() {
   218  		if i.Overlay != "" {
   219  			goArgs = append(goArgs, "-overlay="+i.Overlay)
   220  		}
   221  	}
   222  
   223  	switch i.Verb {
   224  	case "env", "version":
   225  		goArgs = append(goArgs, i.Args...)
   226  	case "mod":
   227  		// mod needs the sub-verb before flags.
   228  		goArgs = append(goArgs, i.Args[0])
   229  		appendModFile()
   230  		goArgs = append(goArgs, i.Args[1:]...)
   231  	case "get":
   232  		goArgs = append(goArgs, i.BuildFlags...)
   233  		appendModFile()
   234  		goArgs = append(goArgs, i.Args...)
   235  
   236  	default: // notably list and build.
   237  		goArgs = append(goArgs, i.BuildFlags...)
   238  		appendModFile()
   239  		appendModFlag()
   240  		appendOverlayFlag()
   241  		goArgs = append(goArgs, i.Args...)
   242  	}
   243  	cmd := exec.Command("go", goArgs...)
   244  	cmd.Stdout = stdout
   245  	cmd.Stderr = stderr
   246  
   247  	// cmd.WaitDelay was added only in go1.20 (see #50436).
   248  	if waitDelay := reflect.ValueOf(cmd).Elem().FieldByName("WaitDelay"); waitDelay.IsValid() {
   249  		// https://go.dev/issue/59541: don't wait forever copying stderr
   250  		// after the command has exited.
   251  		// After CL 484741 we copy stdout manually, so we we'll stop reading that as
   252  		// soon as ctx is done. However, we also don't want to wait around forever
   253  		// for stderr. Give a much-longer-than-reasonable delay and then assume that
   254  		// something has wedged in the kernel or runtime.
   255  		waitDelay.Set(reflect.ValueOf(30 * time.Second))
   256  	}
   257  
   258  	// On darwin the cwd gets resolved to the real path, which breaks anything that
   259  	// expects the working directory to keep the original path, including the
   260  	// go command when dealing with modules.
   261  	// The Go stdlib has a special feature where if the cwd and the PWD are the
   262  	// same node then it trusts the PWD, so by setting it in the env for the child
   263  	// process we fix up all the paths returned by the go command.
   264  	if !i.CleanEnv {
   265  		cmd.Env = os.Environ()
   266  	}
   267  	cmd.Env = append(cmd.Env, i.Env...)
   268  	if i.WorkingDir != "" {
   269  		cmd.Env = append(cmd.Env, "PWD="+i.WorkingDir)
   270  		cmd.Dir = i.WorkingDir
   271  	}
   272  
   273  	defer func(start time.Time) { log("%s for %v", time.Since(start), cmdDebugStr(cmd)) }(time.Now())
   274  
   275  	return runCmdContext(ctx, cmd)
   276  }
   277  
   278  // DebugHangingGoCommands may be set by tests to enable additional
   279  // instrumentation (including panics) for debugging hanging Go commands.
   280  //
   281  // See golang/go#54461 for details.
   282  var DebugHangingGoCommands = false
   283  
   284  // runCmdContext is like exec.CommandContext except it sends os.Interrupt
   285  // before os.Kill.
   286  func runCmdContext(ctx context.Context, cmd *exec.Cmd) (err error) {
   287  	// If cmd.Stdout is not an *os.File, the exec package will create a pipe and
   288  	// copy it to the Writer in a goroutine until the process has finished and
   289  	// either the pipe reaches EOF or command's WaitDelay expires.
   290  	//
   291  	// However, the output from 'go list' can be quite large, and we don't want to
   292  	// keep reading (and allocating buffers) if we've already decided we don't
   293  	// care about the output. We don't want to wait for the process to finish, and
   294  	// we don't wait to wait for the WaitDelay to expire either.
   295  	//
   296  	// Instead, if cmd.Stdout requires a copying goroutine we explicitly replace
   297  	// it with a pipe (which is an *os.File), which we can close in order to stop
   298  	// copying output as soon as we realize we don't care about it.
   299  	var stdoutW *os.File
   300  	if cmd.Stdout != nil {
   301  		if _, ok := cmd.Stdout.(*os.File); !ok {
   302  			var stdoutR *os.File
   303  			stdoutR, stdoutW, err = os.Pipe()
   304  			if err != nil {
   305  				return err
   306  			}
   307  			prevStdout := cmd.Stdout
   308  			cmd.Stdout = stdoutW
   309  
   310  			stdoutErr := make(chan error, 1)
   311  			go func() {
   312  				_, err := io.Copy(prevStdout, stdoutR)
   313  				if err != nil {
   314  					err = fmt.Errorf("copying stdout: %w", err)
   315  				}
   316  				stdoutErr <- err
   317  			}()
   318  			defer func() {
   319  				// We started a goroutine to copy a stdout pipe.
   320  				// Wait for it to finish, or terminate it if need be.
   321  				var err2 error
   322  				select {
   323  				case err2 = <-stdoutErr:
   324  					stdoutR.Close()
   325  				case <-ctx.Done():
   326  					stdoutR.Close()
   327  					// Per https://pkg.go.dev/os#File.Close, the call to stdoutR.Close
   328  					// should cause the Read call in io.Copy to unblock and return
   329  					// immediately, but we still need to receive from stdoutErr to confirm
   330  					// that it has happened.
   331  					<-stdoutErr
   332  					err2 = ctx.Err()
   333  				}
   334  				if err == nil {
   335  					err = err2
   336  				}
   337  			}()
   338  
   339  			// Per https://pkg.go.dev/os/exec#Cmd, “If Stdout and Stderr are the
   340  			// same writer, and have a type that can be compared with ==, at most
   341  			// one goroutine at a time will call Write.”
   342  			//
   343  			// Since we're starting a goroutine that writes to cmd.Stdout, we must
   344  			// also update cmd.Stderr so that it still holds.
   345  			func() {
   346  				defer func() { recover() }()
   347  				if cmd.Stderr == prevStdout {
   348  					cmd.Stderr = cmd.Stdout
   349  				}
   350  			}()
   351  		}
   352  	}
   353  
   354  	err = cmd.Start()
   355  	if stdoutW != nil {
   356  		// The child process has inherited the pipe file,
   357  		// so close the copy held in this process.
   358  		stdoutW.Close()
   359  		stdoutW = nil
   360  	}
   361  	if err != nil {
   362  		return err
   363  	}
   364  
   365  	resChan := make(chan error, 1)
   366  	go func() {
   367  		resChan <- cmd.Wait()
   368  	}()
   369  
   370  	// If we're interested in debugging hanging Go commands, stop waiting after a
   371  	// minute and panic with interesting information.
   372  	debug := DebugHangingGoCommands
   373  	if debug {
   374  		timer := time.NewTimer(1 * time.Minute)
   375  		defer timer.Stop()
   376  		select {
   377  		case err := <-resChan:
   378  			return err
   379  		case <-timer.C:
   380  			HandleHangingGoCommand(cmd.Process)
   381  		case <-ctx.Done():
   382  		}
   383  	} else {
   384  		select {
   385  		case err := <-resChan:
   386  			return err
   387  		case <-ctx.Done():
   388  		}
   389  	}
   390  
   391  	// Cancelled. Interrupt and see if it ends voluntarily.
   392  	if err := cmd.Process.Signal(os.Interrupt); err == nil {
   393  		// (We used to wait only 1s but this proved
   394  		// fragile on loaded builder machines.)
   395  		timer := time.NewTimer(5 * time.Second)
   396  		defer timer.Stop()
   397  		select {
   398  		case err := <-resChan:
   399  			return err
   400  		case <-timer.C:
   401  		}
   402  	}
   403  
   404  	// Didn't shut down in response to interrupt. Kill it hard.
   405  	// TODO(rfindley): per advice from bcmills@, it may be better to send SIGQUIT
   406  	// on certain platforms, such as unix.
   407  	if err := cmd.Process.Kill(); err != nil && !errors.Is(err, os.ErrProcessDone) && debug {
   408  		log.Printf("error killing the Go command: %v", err)
   409  	}
   410  
   411  	return <-resChan
   412  }
   413  
   414  func HandleHangingGoCommand(proc *os.Process) {
   415  	switch runtime.GOOS {
   416  	case "linux", "darwin", "freebsd", "netbsd":
   417  		fmt.Fprintln(os.Stderr, `DETECTED A HANGING GO COMMAND
   418  
   419  The gopls test runner has detected a hanging go command. In order to debug
   420  this, the output of ps and lsof/fstat is printed below.
   421  
   422  See golang/go#54461 for more details.`)
   423  
   424  		fmt.Fprintln(os.Stderr, "\nps axo ppid,pid,command:")
   425  		fmt.Fprintln(os.Stderr, "-------------------------")
   426  		psCmd := exec.Command("ps", "axo", "ppid,pid,command")
   427  		psCmd.Stdout = os.Stderr
   428  		psCmd.Stderr = os.Stderr
   429  		if err := psCmd.Run(); err != nil {
   430  			panic(fmt.Sprintf("running ps: %v", err))
   431  		}
   432  
   433  		listFiles := "lsof"
   434  		if runtime.GOOS == "freebsd" || runtime.GOOS == "netbsd" {
   435  			listFiles = "fstat"
   436  		}
   437  
   438  		fmt.Fprintln(os.Stderr, "\n"+listFiles+":")
   439  		fmt.Fprintln(os.Stderr, "-----")
   440  		listFilesCmd := exec.Command(listFiles)
   441  		listFilesCmd.Stdout = os.Stderr
   442  		listFilesCmd.Stderr = os.Stderr
   443  		if err := listFilesCmd.Run(); err != nil {
   444  			panic(fmt.Sprintf("running %s: %v", listFiles, err))
   445  		}
   446  	}
   447  	panic(fmt.Sprintf("detected hanging go command (pid %d): see golang/go#54461 for more details", proc.Pid))
   448  }
   449  
   450  func cmdDebugStr(cmd *exec.Cmd) string {
   451  	env := make(map[string]string)
   452  	for _, kv := range cmd.Env {
   453  		split := strings.SplitN(kv, "=", 2)
   454  		if len(split) == 2 {
   455  			k, v := split[0], split[1]
   456  			env[k] = v
   457  		}
   458  	}
   459  
   460  	var args []string
   461  	for _, arg := range cmd.Args {
   462  		quoted := strconv.Quote(arg)
   463  		if quoted[1:len(quoted)-1] != arg || strings.Contains(arg, " ") {
   464  			args = append(args, quoted)
   465  		} else {
   466  			args = append(args, arg)
   467  		}
   468  	}
   469  	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, " "))
   470  }
   471
View as plain text