go: x/build/cmd/coordinator: test “ran over” time limit output doesn't make it easy to tell where

#!watchflakes
default <- log ~ `^Test .* ran over .* limit`

From https://storage.googleapis.com/go-build-log/a1471cf8/openbsd-amd64-68_eba704c3.log (a TryBot on CL 400376):

openbsd-amd64-68 at a1471cf8dea8e0a6025e5ca649cc94871d436211

:: Running /tmp/workdir/go/src/make.bash with args ["/tmp/workdir/go/src/make.bash"] and env ["HOME=/" "PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin" "PWD=/" "INRC=1" "_=/bin/sh" "WORKDIR=/tmp/workdir" "GOROOT_BOOTSTRAP=/tmp/workdir/go1.4" "GO_BUILDER_NAME=openbsd-amd64-68" "GOBIN=" "TMPDIR=/tmp/workdir/tmp" "GOCACHE=/tmp/workdir/gocache"] in dir /tmp/workdir/go/src

…

Test "go_test:crypto/internal/subtle" ran over 20m0s limit (20m0.000698974s); saw output:

XXXBANNERXXX:Test execution environment.
# GOARCH: amd64
# CPU: Intel(R) Xeon(R) CPU @ 0.00GHz
# GOOS: openbsd
# OS Version: OpenBSD 6.8 OpenBSD 6.8 (GENERIC.MP) #2: Sat Dec  5 07:17:48 MST 2020     root@syspatch-68-amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP  amd64

XXXBANNERXXX:Testing packages.
ok  	crypto/internal/subtle	0.017s
ok  	crypto/md5	0.023s
ok  	crypto/rand	0.054s


Error: tests failed: dist test failed: go_test:crypto/internal/subtle: Test "go_test:crypto/internal/subtle" ran over 20m0s limit (20m0.000698974s); saw output:

XXXBANNERXXX:Test execution environment.
# GOARCH: amd64
# CPU: Intel(R) Xeon(R) CPU @ 0.00GHz
# GOOS: openbsd
# OS Version: OpenBSD 6.8 OpenBSD 6.8 (GENERIC.MP) #2: Sat Dec  5 07:17:48 MST 2020     root@syspatch-68-amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP  amd64

XXXBANNERXXX:Testing packages.
ok  	crypto/internal/subtle	0.017s
ok  	crypto/md5	0.023s
ok  	crypto/rand	0.054s

There are a few issues with this result:

  1. The error message claims that go_test:crypto/internal/subtle ran over the time limit, but AFAICT it actually completed in 17ms. I’m not sure how to reconcile that.
  2. The output from the test run is duplicated. (But duplicated is better than missing, at least! 😅)
  3. The XXXBANNERXXX lines have not been stripped as expected.

Of those, I am most concerned with (1), so I’d like to focus this issue on that (but incidentally fixing the others would be nice too).

(attn @golang/release; I think this may be a latent issue uncovered by @dmitshur’s recent timeout fix in CL 407555.)

About this issue

  • Original URL
  • State: open
  • Created 2 years ago
  • Comments: 57 (7 by maintainers)

Most upvoted comments

I looked into this a while back, and wanted to do more, but never got around to it. For now I’ll just update this issue with a summary of what I found.

I think the timeout is accurate, but there’s not enough information in the log to point out where. It likely wasn’t crypto/internal/subtle but one of the packages after crypto/rand, i.e., crypto/rc4 or later. Our build error reporting can be improved to make investigating these types of findings easier.