invoke.go 14 KB

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