invoke.go 17 KB

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