x/build/cmd/coordinator: transparent TryBot retries mask stalls that should be fixed

[bcmills]

I noticed a stall on a SlowBot (#39665 (comment)), and when I went to check on it again I noticed that the counter had reset and the builder had restarted.

This behavior closely mimics the js-wasm stall-and-restart behavior reported in #35170, and I wonder if it explains other observed stalls too (probably #39349; perhaps #36482 and/or #32632 as well).

This timeout-and-retry behavior seems to paper over a systemic problem to make it less noticeable, but if it were instead more noticeable we might have a better picture of how and why it occurs — and might be better equipped to fix the underlying problem (and speed up the perceived TryBot speed by eliminating the spurious timeouts entirely).

CC @golang/release

[bcmills]

See previously #13026.

[dmitshur]

This timeout-and-retry behavior

@bcmills Is the issue here that there's an unbounded number of transparent retries, or that even a bounded number of retries—like 3—is considered problematic in this context? (Or is it not known whether these are bounded and needs investigation?)

If they're unbounded, we should definitely cap it at a fixed number and promote to fatal error. That should be comparatively easy and high value. If already bounded, then improving this situation is more involved, especially if there isn't a good way to differentiate a network communication issue from a build stall.

[bcmills]

I would consider even a bounded number of retries to be problematic for the GCE builders. If we've tuned the builders properly no retries should actually ever be needed, and even a single retry doubles the latency of its shard. (If there is a network communication issue to the GCE builders that occurs frequently enough to matter, we should diagnose and fix that.)

I'm more sympathetic to having a few bounded retries to the reverse builders, since those could reasonably have less-reliable consumer network connections — but even then, I think it would be a better experience to have an explicit SlowBot failure (for which I can remove the missing SlowBot) than to have a whole SlowBot run stalled on some particular builder that has gone AWOL.

[bcmills]

Now that the GopherBot leaves more detailed status comments, the problematic retry behavior is becoming clearer.

For example, on https://go.dev/cl/381734 I requested two plan9 SlowBots. The Gopher Robot has now commented three times on “SlowBots beginning”, and has “Superseded” itself twice without further explanation.

[bcmills]

This caused a 20-minute SlowBot delay on https://go.dev/cl/391805 PS15.

The linux-arm64-aws TryBot got stuck in testsanitizers for 20 minutes, and instead of producing a diagnosable failure it timed out the machine and started over. 😠

https://farmer.golang.org/temporarylogs?name=linux-arm64-aws&rev=6553c0d1d16000f564fc64b13600792f8662dcd5&st=0xc039bf4680:

  builder: linux-arm64-aws
      rev: 6553c0d1d16000f564fc64b13600792f8662dcd5
 buildlet: https://3.17.152.2 EC2 VM: buildlet-linux-arm64-aws-rnc35ea30
  started: 2022-03-18 21:47:04.595869047 +0000 UTC m=+18819.820715051
   status: still running

Events:
…
  2022-03-18T22:10:37Z finish_run_test:testsanitizers after 20m0s; err=error copying response: context deadline exceeded; 52.15.88.103:443
  2022-03-18T22:10:37Z test_helper_is_broken 52.15.88.103:443
  2022-03-18T22:10:37Z closed_helper 52.15.88.103:443
  2022-03-18T22:10:40Z run_test:testsanitizers 3.17.152.2:443

[bcmills]

I noticed a 1-minute delay on https://go.dev/cl/360354 PS9 due to an early failure on the windows-amd64-2016 builder.

I didn't catch the error message in the logs before the builder restarted.

[gopherbot]

Change https://go.dev/cl/406216 mentions this issue: cmd/coordinator: consolidate and increase global VM deletion timeout

[dmitshur]

I ran into this most recently while sending a trivial fix in https://go.dev/cl/406897, where a linux-amd64-longtest SlowBot request took almost 2 hrs instead of the usual 10-15 min, and while waiting I spent that time making progress on investigating this issue. I found that the new behavior was introduced during a cmd/coordinator refactor in late 2019, and it was a bug rather than an intentional change. We also filed issue #36629 in 2020 that was trying to investigate what happened, which I've now closed in favor of this issue. I've also opened #52998 for tracking progress on the testsanitizers hang specifically (also pointed out above in #42699 (comment)).

Moving this issue to NeedsFix because I don't believe further investigation is needed here—I know where the problem is. I plan to discuss this with the team and will update this issue soon after that.

[gopherbot]

Change https://go.dev/cl/407555 mentions this issue: buildlet: fix Exec to return ErrTimeout on timeout

[dmitshur]

I believe the change in CL 407555 should be sufficient to resolve this issue. If there's any evidence to the contrary, it'd be helpful to know.

There were some additional timeout efficiency improvements I was considering and discussed with the team, and though there's agreement that we can make those improvements, they're not necessary for resolving this problem.

[bcmills]

Hmm. As far as I can tell CL 407555 fixes the main source of the failures that led to retries, but doesn't change the fact that retries would still be attempted (and would still mask stalls) for other issues, such as communication errors with reverse SlowBots.

[bcmills]

At the very least, though, I would say that with that CL in we can probably deprioritize further work on this issue. Reverse-builder SlowBot failures are much more rare than js-wasm TryBots or linux-amd64-longtest SlowBots.

[dmitshur]

The LUCI infrastructure doesn't have this problem. For a recent instance and comparison, see here.

At this point of the LUCI migration I don't expect we'll resolve this issue in the old coordinator infrastructure.

[gopherbot]

Change https://go.dev/cl/586077 mentions this issue: buildlet: don't rely on io.Copy error to be context.DeadlineExceeded