Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/build: windows-amd64-longtest builder not keeping up with commits #52591

Closed
bcmills opened this issue Apr 27, 2022 · 14 comments
Closed

x/build: windows-amd64-longtest builder not keeping up with commits #52591

bcmills opened this issue Apr 27, 2022 · 14 comments
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. OS-Windows Soon This needs to be done soon. (regressions, serious bugs, outages)
Milestone

Comments

@bcmills
Copy link
Contributor

bcmills commented Apr 27, 2022

The windows-amd64-longtest builder is currently backlogged by almost two days: there are builds still running back to at least CL 361212, merged on the afternoon of Apr. 25:
image

My understanding is that the windows-amd64-longtest builder runs on GCE, and thus should not be hardware-limited. I also don't see anything on https://farmer.golang.org/ that would explain the backlog.

@golang/release: could you look into this backlog? I wonder if this indicates a problem in the coordinator.

@bcmills bcmills added OS-Windows Builders x/build issues (builders, bots, dashboards) labels Apr 27, 2022
@gopherbot gopherbot added this to the Unreleased milestone Apr 27, 2022
@bcmills bcmills added the Soon This needs to be done soon. (regressions, serious bugs, outages) label Apr 27, 2022
@bcmills
Copy link
Contributor Author

bcmills commented Apr 27, 2022

I generally triage build failures from over the past day when I get in in the mornings, so having a multi-day backlog means that if these builds fail they may be missed during triage.

@heschi
Copy link
Contributor

heschi commented Apr 27, 2022

They're almost certainly timing out. I looked at a random ongoing run:

started: 2022-04-27 13:50:10.804674216 +0000 UTC m=+79277.527862464
[...]
  2022-04-27T14:21:14Z run_test:runtime:cpu124 10.128.0.14:80
  2022-04-27T14:21:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:22:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:22:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:23:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:23:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:24:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:24:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:25:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:25:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:26:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:26:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:27:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:27:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:28:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:28:44Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:29:14Z still_waiting_on_test runtime:cpu124
  2022-04-27T14:29:44Z still_waiting_on_test runtime:cpu124

I thought the VM would be shut down after 30 minutes, so I'm not sure why it's still running. But it appears that something is wrong with runtime:cpu124 -- it appears in many ongoing logs.

@heschi
Copy link
Contributor

heschi commented Apr 27, 2022

For completeness, here's a run I was watching that died:

  builder: windows-amd64-longtest
      rev: e845750744b648b8b348bbcebe2ff85d4e6247c5
 buildlet: http://10.128.0.15 GCE VM: buildlet-windows-amd64-2016-big-rna1ddcc0
  started: 2022-04-27 13:51:10.786923276 +0000 UTC m=+79337.510111514
   status: still running

Events:
2022-04-27T13:51:10Z checking_for_snapshot
2022-04-27T13:51:10Z finish_checking_for_snapshot after 23.6ms
2022-04-27T13:51:10Z get_buildlet
2022-04-27T13:51:41Z finish_get_buildlet after 30.4s
2022-04-27T13:51:41Z using_buildlet 10.128.0.15:80
2022-04-27T13:51:41Z write_snapshot_tar
2022-04-27T13:51:50Z finish_write_snapshot_tar after 9.34s
2022-04-27T13:51:50Z make_and_test
2022-04-27T13:51:50Z discovering_tests
2022-04-27T13:51:51Z get_test_stats
2022-04-27T13:51:51Z finish_get_test_stats after 0s
2022-04-27T13:51:51Z starting_tests 290 tests
2022-04-27T13:51:51Z run_tests_multi 10.128.0.15:80: [go_test:archive/tar go_test:archive/zip go_test:bufio]
2022-04-27T13:52:19Z finish_run_tests_multi after 27.4s; 10.128.0.15:80: [go_test:archive/tar go_test:archive/zip go_test:bufio]
2022-04-27T13:52:19Z run_tests_multi 10.128.0.15:80: [go_test:bytes go_test:compress/bzip2 go_test:compress/flate]
2022-04-27T13:52:30Z finish_run_tests_multi after 10.9s; 10.128.0.15:80: [go_test:bytes go_test:compress/bzip2 go_test:compress/flate]
2022-04-27T13:52:30Z run_tests_multi 10.128.0.15:80: [go_test:compress/gzip go_test:compress/lzw go_test:compress/zlib]
2022-04-27T13:52:35Z finish_run_tests_multi after 5.62s; 10.128.0.15:80: [go_test:compress/gzip go_test:compress/lzw go_test:compress/zlib]
2022-04-27T13:52:35Z run_tests_multi 10.128.0.15:80: [go_test:container/heap go_test:container/list go_test:container/ring]
2022-04-27T13:52:39Z finish_run_tests_multi after 3.07s; 10.128.0.15:80: [go_test:container/heap go_test:container/list go_test:container/ring]
2022-04-27T13:52:39Z run_tests_multi 10.128.0.15:80: [go_test:context go_test:crypto go_test:crypto/aes]
2022-04-27T13:52:43Z finish_run_tests_multi after 4.02s; 10.128.0.15:80: [go_test:context go_test:crypto go_test:crypto/aes]
2022-04-27T13:52:43Z run_tests_multi 10.128.0.15:80: [go_test:crypto/cipher go_test:crypto/des go_test:crypto/dsa]
2022-04-27T13:52:51Z finish_run_tests_multi after 8.12s; 10.128.0.15:80: [go_test:crypto/cipher go_test:crypto/des go_test:crypto/dsa]
2022-04-27T13:52:51Z run_tests_multi 10.128.0.15:80: [go_test:crypto/ecdsa go_test:crypto/ed25519 go_test:crypto/ed25519/internal/edwards25519]
2022-04-27T13:52:58Z finish_run_tests_multi after 6.76s; 10.128.0.15:80: [go_test:crypto/ecdsa go_test:crypto/ed25519 go_test:crypto/ed25519/internal/edwards25519]
2022-04-27T13:52:58Z run_tests_multi 10.128.0.15:80: [go_test:crypto/ed25519/internal/edwards25519/field go_test:crypto/elliptic go_test:crypto/elliptic/internal/fiat]
2022-04-27T13:53:04Z finish_run_tests_multi after 6.08s; 10.128.0.15:80: [go_test:crypto/ed25519/internal/edwards25519/field go_test:crypto/elliptic go_test:crypto/elliptic/internal/fiat]
2022-04-27T13:53:04Z run_tests_multi 10.128.0.15:80: [go_test:crypto/elliptic/internal/nistec go_test:crypto/hmac go_test:crypto/internal/subtle]
2022-04-27T13:53:08Z finish_run_tests_multi after 3.87s; 10.128.0.15:80: [go_test:crypto/elliptic/internal/nistec go_test:crypto/hmac go_test:crypto/internal/subtle]
2022-04-27T13:53:08Z run_tests_multi 10.128.0.15:80: [go_test:crypto/md5 go_test:crypto/rand go_test:crypto/rc4]
2022-04-27T13:53:11Z finish_run_tests_multi after 3.35s; 10.128.0.15:80: [go_test:crypto/md5 go_test:crypto/rand go_test:crypto/rc4]
2022-04-27T13:53:11Z run_tests_multi 10.128.0.15:80: [go_test:crypto/rsa go_test:crypto/sha1 go_test:crypto/sha256]
2022-04-27T13:53:15Z finish_run_tests_multi after 4.19s; 10.128.0.15:80: [go_test:crypto/rsa go_test:crypto/sha1 go_test:crypto/sha256]
2022-04-27T13:53:15Z run_tests_multi 10.128.0.15:80: [go_test:crypto/sha512 go_test:crypto/subtle go_test:crypto/tls]
2022-04-27T13:53:24Z finish_run_tests_multi after 8.94s; 10.128.0.15:80: [go_test:crypto/sha512 go_test:crypto/subtle go_test:crypto/tls]
2022-04-27T13:53:24Z run_tests_multi 10.128.0.15:80: [go_test:crypto/x509 go_test:database/sql go_test:database/sql/driver]
2022-04-27T13:53:31Z finish_run_tests_multi after 6.42s; 10.128.0.15:80: [go_test:crypto/x509 go_test:database/sql go_test:database/sql/driver]
2022-04-27T13:53:31Z run_tests_multi 10.128.0.15:80: [go_test:debug/buildinfo go_test:debug/dwarf go_test:debug/elf]
2022-04-27T13:53:34Z finish_run_tests_multi after 3.68s; 10.128.0.15:80: [go_test:debug/buildinfo go_test:debug/dwarf go_test:debug/elf]
2022-04-27T13:53:34Z run_tests_multi 10.128.0.15:80: [go_test:debug/gosym go_test:debug/macho go_test:debug/pe]
2022-04-27T13:53:43Z finish_run_tests_multi after 8.84s; 10.128.0.15:80: [go_test:debug/gosym go_test:debug/macho go_test:debug/pe]
2022-04-27T13:53:43Z run_tests_multi 10.128.0.15:80: [go_test:debug/plan9obj go_test:embed go_test:embed/internal/embedtest]
2022-04-27T13:53:47Z finish_run_tests_multi after 3.35s; 10.128.0.15:80: [go_test:debug/plan9obj go_test:embed go_test:embed/internal/embedtest]
2022-04-27T13:53:47Z run_tests_multi 10.128.0.15:80: [go_test:encoding/ascii85 go_test:encoding/asn1 go_test:encoding/base32]
2022-04-27T13:53:50Z finish_run_tests_multi after 3.27s; 10.128.0.15:80: [go_test:encoding/ascii85 go_test:encoding/asn1 go_test:encoding/base32]
2022-04-27T13:53:50Z run_tests_multi 10.128.0.15:80: [go_test:encoding/base64 go_test:encoding/binary go_test:encoding/csv]
2022-04-27T13:53:54Z finish_run_tests_multi after 3.86s; 10.128.0.15:80: [go_test:encoding/base64 go_test:encoding/binary go_test:encoding/csv]
2022-04-27T13:53:54Z run_tests_multi 10.128.0.15:80: [go_test:encoding/gob go_test:encoding/hex go_test:encoding/json]
2022-04-27T13:53:59Z finish_run_tests_multi after 5.31s; 10.128.0.15:80: [go_test:encoding/gob go_test:encoding/hex go_test:encoding/json]
2022-04-27T13:53:59Z run_tests_multi 10.128.0.15:80: [go_test:encoding/pem go_test:encoding/xml go_test:errors]
2022-04-27T13:54:03Z finish_run_tests_multi after 3.92s; 10.128.0.15:80: [go_test:encoding/pem go_test:encoding/xml go_test:errors]
2022-04-27T13:54:03Z run_tests_multi 10.128.0.15:80: [go_test:expvar go_test:flag go_test:fmt]
2022-04-27T13:54:08Z finish_run_tests_multi after 4.62s; 10.128.0.15:80: [go_test:expvar go_test:flag go_test:fmt]
2022-04-27T13:54:08Z run_tests_multi 10.128.0.15:80: [go_test:go/ast go_test:go/build go_test:go/build/constraint]
2022-04-27T13:54:13Z finish_run_tests_multi after 5.01s; 10.128.0.15:80: [go_test:go/ast go_test:go/build go_test:go/build/constraint]
2022-04-27T13:54:13Z run_tests_multi 10.128.0.15:80: [go_test:go/constant go_test:go/doc go_test:go/doc/comment]
2022-04-27T13:54:18Z finish_run_tests_multi after 4.41s; 10.128.0.15:80: [go_test:go/constant go_test:go/doc go_test:go/doc/comment]
2022-04-27T13:54:18Z run_tests_multi 10.128.0.15:80: [go_test:go/format go_test:go/importer go_test:go/internal/gccgoimporter]
2022-04-27T13:54:21Z finish_run_tests_multi after 3.51s; 10.128.0.15:80: [go_test:go/format go_test:go/importer go_test:go/internal/gccgoimporter]
2022-04-27T13:54:21Z run_tests_multi 10.128.0.15:80: [go_test:go/internal/gcimporter go_test:go/internal/srcimporter go_test:go/parser]
2022-04-27T13:54:39Z finish_run_tests_multi after 17.5s; 10.128.0.15:80: [go_test:go/internal/gcimporter go_test:go/internal/srcimporter go_test:go/parser]
2022-04-27T13:54:39Z run_tests_multi 10.128.0.15:80: [go_test:go/printer go_test:go/scanner go_test:go/token]
2022-04-27T13:54:43Z finish_run_tests_multi after 4.41s; 10.128.0.15:80: [go_test:go/printer go_test:go/scanner go_test:go/token]
2022-04-27T13:54:43Z run_tests_multi 10.128.0.15:80: [go_test:go/types go_test:hash go_test:hash/adler32]
2022-04-27T13:55:13Z still_waiting_on_test go_test:go/types
2022-04-27T13:55:30Z finish_run_tests_multi after 47.1s; 10.128.0.15:80: [go_test:go/types go_test:hash go_test:hash/adler32]
2022-04-27T13:55:30Z run_tests_multi 10.128.0.15:80: [go_test:hash/crc32 go_test:hash/crc64 go_test:hash/fnv]
2022-04-27T13:55:34Z finish_run_tests_multi after 3.84s; 10.128.0.15:80: [go_test:hash/crc32 go_test:hash/crc64 go_test:hash/fnv]
2022-04-27T13:55:34Z run_tests_multi 10.128.0.15:80: [go_test:hash/maphash go_test:html go_test:html/template]
2022-04-27T13:56:04Z still_waiting_on_test go_test:hash/maphash
2022-04-27T13:56:34Z still_waiting_on_test go_test:hash/maphash
2022-04-27T13:57:04Z still_waiting_on_test go_test:hash/maphash
2022-04-27T13:57:34Z still_waiting_on_test go_test:hash/maphash
2022-04-27T13:57:42Z finish_run_tests_multi after 2m8s; 10.128.0.15:80: [go_test:hash/maphash go_test:html go_test:html/template]
2022-04-27T13:57:42Z run_tests_multi 10.128.0.15:80: [go_test:image go_test:image/color go_test:image/draw]
2022-04-27T13:57:46Z finish_run_tests_multi after 3.9s; 10.128.0.15:80: [go_test:image go_test:image/color go_test:image/draw]
2022-04-27T13:57:46Z run_tests_multi 10.128.0.15:80: [go_test:image/gif go_test:image/jpeg go_test:image/png]
2022-04-27T13:58:01Z finish_run_tests_multi after 14.7s; 10.128.0.15:80: [go_test:image/gif go_test:image/jpeg go_test:image/png]
2022-04-27T13:58:01Z run_test:go_test:index/suffixarray 10.128.0.15:80
2022-04-27T13:58:31Z still_waiting_on_test go_test:index/suffixarray
2022-04-27T13:58:53Z finish_run_test:go_test:index/suffixarray after 52s; 10.128.0.15:80
2022-04-27T13:58:53Z run_tests_multi 10.128.0.15:80: [go_test:internal/abi go_test:internal/buildcfg go_test:internal/cpu]
2022-04-27T13:59:02Z finish_run_tests_multi after 9.22s; 10.128.0.15:80: [go_test:internal/abi go_test:internal/buildcfg go_test:internal/cpu]
2022-04-27T13:59:02Z run_tests_multi 10.128.0.15:80: [go_test:internal/diff go_test:internal/execabs go_test:internal/fmtsort]
2022-04-27T13:59:07Z finish_run_tests_multi after 4.41s; 10.128.0.15:80: [go_test:internal/diff go_test:internal/execabs go_test:internal/fmtsort]
2022-04-27T13:59:07Z run_tests_multi 10.128.0.15:80: [go_test:internal/fuzz go_test:internal/godebug go_test:internal/intern]
2022-04-27T13:59:13Z finish_run_tests_multi after 5.84s; 10.128.0.15:80: [go_test:internal/fuzz go_test:internal/godebug go_test:internal/intern]
2022-04-27T13:59:13Z run_tests_multi 10.128.0.15:80: [go_test:internal/itoa go_test:internal/poll go_test:internal/profile]
2022-04-27T13:59:20Z finish_run_tests_multi after 7.45s; 10.128.0.15:80: [go_test:internal/itoa go_test:internal/poll go_test:internal/profile]
2022-04-27T13:59:20Z run_tests_multi 10.128.0.15:80: [go_test:internal/reflectlite go_test:internal/singleflight go_test:internal/syscall/windows]
2022-04-27T13:59:26Z finish_run_tests_multi after 6.04s; 10.128.0.15:80: [go_test:internal/reflectlite go_test:internal/singleflight go_test:internal/syscall/windows]
2022-04-27T13:59:26Z run_tests_multi 10.128.0.15:80: [go_test:internal/syscall/windows/registry go_test:internal/trace go_test:internal/unsafeheader]
2022-04-27T13:59:31Z finish_run_tests_multi after 4.99s; 10.128.0.15:80: [go_test:internal/syscall/windows/registry go_test:internal/trace go_test:internal/unsafeheader]
2022-04-27T13:59:31Z run_tests_multi 10.128.0.15:80: [go_test:internal/xcoff go_test:io go_test:io/fs]
2022-04-27T13:59:37Z finish_run_tests_multi after 5.13s; 10.128.0.15:80: [go_test:internal/xcoff go_test:io go_test:io/fs]
2022-04-27T13:59:37Z run_tests_multi 10.128.0.15:80: [go_test:io/ioutil go_test:log go_test:math]
2022-04-27T13:59:42Z finish_run_tests_multi after 5.62s; 10.128.0.15:80: [go_test:io/ioutil go_test:log go_test:math]
2022-04-27T13:59:42Z run_tests_multi 10.128.0.15:80: [go_test:math/big go_test:math/bits go_test:math/cmplx]
2022-04-27T13:59:50Z finish_run_tests_multi after 7.57s; 10.128.0.15:80: [go_test:math/big go_test:math/bits go_test:math/cmplx]
2022-04-27T13:59:50Z run_tests_multi 10.128.0.15:80: [go_test:math/rand go_test:mime go_test:mime/multipart]
2022-04-27T13:59:57Z finish_run_tests_multi after 7.44s; 10.128.0.15:80: [go_test:math/rand go_test:mime go_test:mime/multipart]
2022-04-27T13:59:57Z run_test:go_test:mime/quotedprintable 10.128.0.15:80
2022-04-27T14:00:01Z finish_run_test:go_test:mime/quotedprintable after 3.44s; 10.128.0.15:80
2022-04-27T14:00:01Z run_test:go_test:net 10.128.0.15:80
2022-04-27T14:00:31Z still_waiting_on_test go_test:net
2022-04-27T14:01:01Z still_waiting_on_test go_test:net
2022-04-27T14:01:03Z finish_run_test:go_test:net after 1m1.9s; 10.128.0.15:80
2022-04-27T14:01:03Z run_test:go_test:net/http 10.128.0.15:80
2022-04-27T14:01:33Z still_waiting_on_test go_test:net/http
2022-04-27T14:02:03Z still_waiting_on_test go_test:net/http
2022-04-27T14:02:06Z finish_run_test:go_test:net/http after 1m3.1s; 10.128.0.15:80
2022-04-27T14:02:06Z run_tests_multi 10.128.0.15:80: [go_test:net/http/cgi go_test:net/http/cookiejar go_test:net/http/fcgi]
2022-04-27T14:02:10Z finish_run_tests_multi after 3.93s; 10.128.0.15:80: [go_test:net/http/cgi go_test:net/http/cookiejar go_test:net/http/fcgi]
2022-04-27T14:02:10Z run_tests_multi 10.128.0.15:80: [go_test:net/http/httptest go_test:net/http/httptrace go_test:net/http/httputil]
2022-04-27T14:02:16Z finish_run_tests_multi after 5.8s; 10.128.0.15:80: [go_test:net/http/httptest go_test:net/http/httptrace go_test:net/http/httputil]
2022-04-27T14:02:16Z run_tests_multi 10.128.0.15:80: [go_test:net/http/internal go_test:net/http/internal/ascii go_test:net/http/pprof]
2022-04-27T14:02:25Z finish_run_tests_multi after 8.48s; 10.128.0.15:80: [go_test:net/http/internal go_test:net/http/internal/ascii go_test:net/http/pprof]
2022-04-27T14:02:25Z run_tests_multi 10.128.0.15:80: [go_test:net/internal/socktest go_test:net/mail go_test:net/netip]
2022-04-27T14:02:29Z finish_run_tests_multi after 4.49s; 10.128.0.15:80: [go_test:net/internal/socktest go_test:net/mail go_test:net/netip]
2022-04-27T14:02:29Z run_tests_multi 10.128.0.15:80: [go_test:net/rpc go_test:net/rpc/jsonrpc go_test:net/smtp]
2022-04-27T14:02:33Z finish_run_tests_multi after 3.63s; 10.128.0.15:80: [go_test:net/rpc go_test:net/rpc/jsonrpc go_test:net/smtp]
2022-04-27T14:02:33Z run_tests_multi 10.128.0.15:80: [go_test:net/textproto go_test:net/url]
2022-04-27T14:02:36Z finish_run_tests_multi after 3.53s; 10.128.0.15:80: [go_test:net/textproto go_test:net/url]
2022-04-27T14:02:36Z run_test:go_test:os 10.128.0.15:80
2022-04-27T14:03:06Z still_waiting_on_test go_test:os
2022-04-27T14:03:36Z still_waiting_on_test go_test:os
2022-04-27T14:03:45Z finish_run_test:go_test:os after 1m8.2s; 10.128.0.15:80
2022-04-27T14:03:45Z run_tests_multi 10.128.0.15:80: [go_test:os/exec go_test:os/exec/internal/fdtest go_test:os/signal]
2022-04-27T14:03:51Z finish_run_tests_multi after 6.81s; 10.128.0.15:80: [go_test:os/exec go_test:os/exec/internal/fdtest go_test:os/signal]
2022-04-27T14:03:51Z run_tests_multi 10.128.0.15:80: [go_test:os/user go_test:path]
2022-04-27T14:03:55Z finish_run_tests_multi after 3.21s; 10.128.0.15:80: [go_test:os/user go_test:path]
2022-04-27T14:03:55Z run_tests_multi 10.128.0.15:80: [go_test:path/filepath go_test:plugin]
2022-04-27T14:04:00Z finish_run_tests_multi after 5.05s; 10.128.0.15:80: [go_test:path/filepath go_test:plugin]
2022-04-27T14:04:00Z run_test:go_test:reflect 10.128.0.15:80
2022-04-27T14:04:07Z finish_run_test:go_test:reflect after 6.75s; 10.128.0.15:80
2022-04-27T14:04:07Z run_test:go_test:regexp 10.128.0.15:80
2022-04-27T14:04:25Z finish_run_test:go_test:regexp after 17.9s; 10.128.0.15:80
2022-04-27T14:04:25Z run_test:go_test:regexp/syntax 10.128.0.15:80
2022-04-27T14:04:29Z finish_run_test:go_test:regexp/syntax after 3.84s; 10.128.0.15:80
2022-04-27T14:04:29Z run_test:go_test:runtime 10.128.0.15:80
2022-04-27T14:04:59Z still_waiting_on_test go_test:runtime
2022-04-27T14:05:29Z still_waiting_on_test go_test:runtime
2022-04-27T14:05:59Z still_waiting_on_test go_test:runtime
2022-04-27T14:06:29Z still_waiting_on_test go_test:runtime
2022-04-27T14:06:59Z still_waiting_on_test go_test:runtime
2022-04-27T14:07:29Z still_waiting_on_test go_test:runtime
2022-04-27T14:07:59Z still_waiting_on_test go_test:runtime
2022-04-27T14:07:59Z finish_run_test:go_test:runtime after 3m29.9s; 10.128.0.15:80
2022-04-27T14:07:59Z run_tests_multi 10.128.0.15:80: [go_test:runtime/cgo go_test:runtime/debug]
2022-04-27T14:08:03Z finish_run_tests_multi after 4.46s; 10.128.0.15:80: [go_test:runtime/cgo go_test:runtime/debug]
2022-04-27T14:08:03Z run_tests_multi 10.128.0.15:80: [go_test:runtime/internal/atomic go_test:runtime/internal/math]
2022-04-27T14:08:09Z finish_run_tests_multi after 5.77s; 10.128.0.15:80: [go_test:runtime/internal/atomic go_test:runtime/internal/math]
2022-04-27T14:08:09Z run_tests_multi 10.128.0.15:80: [go_test:runtime/internal/sys go_test:runtime/metrics]
2022-04-27T14:08:12Z finish_run_tests_multi after 3.15s; 10.128.0.15:80: [go_test:runtime/internal/sys go_test:runtime/metrics]
2022-04-27T14:08:12Z run_test:go_test:runtime/pprof 10.128.0.15:80
2022-04-27T14:08:42Z still_waiting_on_test go_test:runtime/pprof
2022-04-27T14:09:12Z still_waiting_on_test go_test:runtime/pprof
2022-04-27T14:09:16Z finish_run_test:go_test:runtime/pprof after 1m3.2s; 10.128.0.15:80
2022-04-27T14:09:16Z run_test:go_test:runtime/trace 10.128.0.15:80
2022-04-27T14:09:28Z finish_run_test:go_test:runtime/trace after 12.9s; 10.128.0.15:80
2022-04-27T14:09:28Z run_test:go_test:sort 10.128.0.15:80
2022-04-27T14:09:34Z finish_run_test:go_test:sort after 5.44s; 10.128.0.15:80
2022-04-27T14:09:34Z run_test:go_test:strconv 10.128.0.15:80
2022-04-27T14:09:40Z finish_run_test:go_test:strconv after 6.4s; 10.128.0.15:80
2022-04-27T14:09:40Z run_test:go_test:strings 10.128.0.15:80
2022-04-27T14:09:46Z finish_run_test:go_test:strings after 5.31s; 10.128.0.15:80
2022-04-27T14:09:46Z run_test:go_test:sync 10.128.0.15:80
2022-04-27T14:09:55Z finish_run_test:go_test:sync after 9.16s; 10.128.0.15:80
2022-04-27T14:09:55Z run_test:go_test:sync/atomic 10.128.0.15:80
2022-04-27T14:10:25Z still_waiting_on_test go_test:sync/atomic
2022-04-27T14:10:53Z finish_run_test:go_test:sync/atomic after 57.7s; 10.128.0.15:80
2022-04-27T14:10:53Z run_test:go_test:syscall 10.128.0.15:80
2022-04-27T14:11:02Z finish_run_test:go_test:syscall after 9.56s; 10.128.0.15:80
2022-04-27T14:11:02Z run_tests_multi 10.128.0.15:80: [go_test:testing go_test:testing/fstest]
2022-04-27T14:11:08Z finish_run_tests_multi after 5.49s; 10.128.0.15:80: [go_test:testing go_test:testing/fstest]
2022-04-27T14:11:08Z run_tests_multi 10.128.0.15:80: [go_test:testing/iotest go_test:testing/quick go_test:text/scanner]
2022-04-27T14:11:12Z finish_run_tests_multi after 3.58s; 10.128.0.15:80: [go_test:testing/iotest go_test:testing/quick go_test:text/scanner]
2022-04-27T14:11:12Z run_tests_multi 10.128.0.15:80: [go_test:text/tabwriter go_test:text/template]
2022-04-27T14:11:16Z finish_run_tests_multi after 4.57s; 10.128.0.15:80: [go_test:text/tabwriter go_test:text/template]
2022-04-27T14:11:16Z run_test:go_test:text/template/parse 10.128.0.15:80
2022-04-27T14:11:20Z finish_run_test:go_test:text/template/parse after 3.67s; 10.128.0.15:80
2022-04-27T14:11:20Z run_test:go_test:time 10.128.0.15:80
2022-04-27T14:11:35Z finish_run_test:go_test:time after 15s; 10.128.0.15:80
2022-04-27T14:11:35Z run_tests_multi 10.128.0.15:80: [go_test:unicode go_test:unicode/utf16]
2022-04-27T14:11:41Z finish_run_tests_multi after 5.57s; 10.128.0.15:80: [go_test:unicode go_test:unicode/utf16]
2022-04-27T14:11:41Z run_tests_multi 10.128.0.15:80: [go_test:unicode/utf8 go_test:cmd/addr2line]
2022-04-27T14:11:46Z finish_run_tests_multi after 4.9s; 10.128.0.15:80: [go_test:unicode/utf8 go_test:cmd/addr2line]
2022-04-27T14:11:46Z run_test:go_test:cmd/api 10.128.0.15:80
2022-04-27T14:11:59Z finish_run_test:go_test:cmd/api after 12.8s; 10.128.0.15:80
2022-04-27T14:11:59Z run_tests_multi 10.128.0.15:80: [go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex]
2022-04-27T14:12:03Z finish_run_tests_multi after 4.17s; 10.128.0.15:80: [go_test:cmd/asm/internal/asm go_test:cmd/asm/internal/lex]
2022-04-27T14:12:03Z run_test:go_test:cmd/compile/internal/amd64 10.128.0.15:80
2022-04-27T14:12:09Z finish_run_test:go_test:cmd/compile/internal/amd64 after 6.64s; 10.128.0.15:80
2022-04-27T14:12:09Z run_tests_multi 10.128.0.15:80: [go_test:cmd/compile/internal/dwarfgen go_test:cmd/compile/internal/importer]
2022-04-27T14:12:15Z finish_run_tests_multi after 5.07s; 10.128.0.15:80: [go_test:cmd/compile/internal/dwarfgen go_test:cmd/compile/internal/importer]
2022-04-27T14:12:15Z run_tests_multi 10.128.0.15:80: [go_test:cmd/compile/internal/ir go_test:cmd/compile/internal/logopt]
2022-04-27T14:12:19Z finish_run_tests_multi after 4.37s; 10.128.0.15:80: [go_test:cmd/compile/internal/ir go_test:cmd/compile/internal/logopt]
2022-04-27T14:12:19Z run_tests_multi 10.128.0.15:80: [go_test:cmd/compile/internal/noder go_test:cmd/compile/internal/reflectdata]
2022-04-27T14:12:24Z finish_run_tests_multi after 4.98s; 10.128.0.15:80: [go_test:cmd/compile/internal/noder go_test:cmd/compile/internal/reflectdata]
2022-04-27T14:12:24Z run_test:go_test:cmd/compile/internal/ssa 10.128.0.15:80
2022-04-27T14:12:54Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:13:24Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:13:54Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:14:24Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:14:54Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:15:24Z still_waiting_on_test go_test:cmd/compile/internal/ssa
2022-04-27T14:15:28Z finish_run_test:go_test:cmd/compile/internal/ssa after 3m3.8s; 10.128.0.15:80
2022-04-27T14:15:28Z run_test:go_test:cmd/compile/internal/syntax 10.128.0.15:80
2022-04-27T14:15:35Z finish_run_test:go_test:cmd/compile/internal/syntax after 6.9s; 10.128.0.15:80
2022-04-27T14:15:35Z run_test:go_test:cmd/compile/internal/test 10.128.0.15:80
2022-04-27T14:15:59Z finish_run_test:go_test:cmd/compile/internal/test after 23.8s; 10.128.0.15:80
2022-04-27T14:15:59Z run_tests_multi 10.128.0.15:80: [go_test:cmd/compile/internal/typecheck go_test:cmd/compile/internal/types]
2022-04-27T14:16:04Z finish_run_tests_multi after 5.18s; 10.128.0.15:80: [go_test:cmd/compile/internal/typecheck go_test:cmd/compile/internal/types]
2022-04-27T14:16:04Z run_test:go_test:cmd/compile/internal/types2 10.128.0.15:80
2022-04-27T14:16:23Z finish_run_test:go_test:cmd/compile/internal/types2 after 19.3s; 10.128.0.15:80
2022-04-27T14:16:23Z run_tests_multi 10.128.0.15:80: [go_test:cmd/cover go_test:cmd/dist]
2022-04-27T14:16:29Z finish_run_tests_multi after 5.29s; 10.128.0.15:80: [go_test:cmd/cover go_test:cmd/dist]
2022-04-27T14:16:29Z run_tests_multi 10.128.0.15:80: [go_test:cmd/doc go_test:cmd/fix]
2022-04-27T14:16:34Z finish_run_tests_multi after 5.07s; 10.128.0.15:80: [go_test:cmd/doc go_test:cmd/fix]
2022-04-27T14:16:34Z run_test:go_test:cmd/go 10.128.0.15:80
2022-04-27T14:17:04Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:17:34Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:18:04Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:18:34Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:19:04Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:19:34Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:20:04Z still_waiting_on_test go_test:cmd/go
2022-04-27T14:20:25Z finish_run_test:go_test:cmd/go after 3m51.2s; 10.128.0.15:80
2022-04-27T14:20:25Z run_test:go_test:cmd/go/internal/auth 10.128.0.15:80
2022-04-27T14:20:29Z finish_run_test:go_test:cmd/go/internal/auth after 3.63s; 10.128.0.15:80
2022-04-27T14:20:29Z run_test:go_test:cmd/go/internal/cache 10.128.0.15:80
2022-04-27T14:20:45Z finish_run_test:go_test:cmd/go/internal/cache after 16s; 10.128.0.15:80
2022-04-27T14:20:45Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/fsys go_test:cmd/go/internal/generate]
2022-04-27T14:20:49Z finish_run_tests_multi after 3.97s; 10.128.0.15:80: [go_test:cmd/go/internal/fsys go_test:cmd/go/internal/generate]
2022-04-27T14:20:49Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/get go_test:cmd/go/internal/imports]
2022-04-27T14:20:53Z finish_run_tests_multi after 3.54s; 10.128.0.15:80: [go_test:cmd/go/internal/get go_test:cmd/go/internal/imports]
2022-04-27T14:20:53Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile]
2022-04-27T14:20:57Z finish_run_tests_multi after 4.12s; 10.128.0.15:80: [go_test:cmd/go/internal/load go_test:cmd/go/internal/lockedfile]
2022-04-27T14:20:57Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/lockedfile/internal/filelock go_test:cmd/go/internal/modconv]
2022-04-27T14:21:00Z finish_run_tests_multi after 3.28s; 10.128.0.15:80: [go_test:cmd/go/internal/lockedfile/internal/filelock go_test:cmd/go/internal/modconv]
2022-04-27T14:21:00Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/modfetch go_test:cmd/go/internal/modfetch/codehost]
2022-04-27T14:21:05Z finish_run_tests_multi after 4.98s; 10.128.0.15:80: [go_test:cmd/go/internal/modfetch go_test:cmd/go/internal/modfetch/codehost]
2022-04-27T14:21:05Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/modfetch/zip_sum_test go_test:cmd/go/internal/modload]
2022-04-27T14:21:09Z finish_run_tests_multi after 3.96s; 10.128.0.15:80: [go_test:cmd/go/internal/modfetch/zip_sum_test go_test:cmd/go/internal/modload]
2022-04-27T14:21:09Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/search]
2022-04-27T14:21:12Z finish_run_tests_multi after 3.18s; 10.128.0.15:80: [go_test:cmd/go/internal/mvs go_test:cmd/go/internal/par go_test:cmd/go/internal/search]
2022-04-27T14:21:12Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/str go_test:cmd/go/internal/test]
2022-04-27T14:21:16Z finish_run_tests_multi after 3.75s; 10.128.0.15:80: [go_test:cmd/go/internal/str go_test:cmd/go/internal/test]
2022-04-27T14:21:16Z run_tests_multi 10.128.0.15:80: [go_test:cmd/go/internal/vcs go_test:cmd/go/internal/web]
2022-04-27T14:21:20Z finish_run_tests_multi after 3.93s; 10.128.0.15:80: [go_test:cmd/go/internal/vcs go_test:cmd/go/internal/web]
2022-04-27T14:21:20Z run_test:go_test:cmd/go/internal/work 10.128.0.15:80
2022-04-27T14:21:24Z finish_run_test:go_test:cmd/go/internal/work after 4.15s; 10.128.0.15:80
2022-04-27T14:21:24Z run_test:go_test:cmd/gofmt 10.128.0.15:80
2022-04-27T14:21:34Z finish_run_test:go_test:cmd/gofmt after 9.99s; 10.128.0.15:80
2022-04-27T14:21:34Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/archive go_test:cmd/internal/buildid]
2022-04-27T14:21:39Z finish_run_tests_multi after 4.42s; 10.128.0.15:80: [go_test:cmd/internal/archive go_test:cmd/internal/buildid]
2022-04-27T14:21:39Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/dwarf go_test:cmd/internal/edit]
2022-04-27T14:21:42Z finish_run_tests_multi after 3.1s; 10.128.0.15:80: [go_test:cmd/internal/dwarf go_test:cmd/internal/edit]
2022-04-27T14:21:42Z run_test:go_test:cmd/internal/goobj 10.128.0.15:80
2022-04-27T14:22:01Z finish_run_test:go_test:cmd/internal/goobj after 19.2s; 10.128.0.15:80
2022-04-27T14:22:01Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/moddeps go_test:cmd/internal/obj]
2022-04-27T14:22:07Z finish_run_tests_multi after 5.23s; 10.128.0.15:80: [go_test:cmd/internal/moddeps go_test:cmd/internal/obj]
2022-04-27T14:22:07Z run_test:go_test:cmd/internal/obj/ppc64 10.128.0.15:80
2022-04-27T14:22:14Z finish_run_test:go_test:cmd/internal/obj/ppc64 after 6.87s; 10.128.0.15:80
2022-04-27T14:22:14Z run_test:go_test:cmd/internal/obj/riscv 10.128.0.15:80
2022-04-27T14:22:24Z finish_run_test:go_test:cmd/internal/obj/riscv after 10.7s; 10.128.0.15:80
2022-04-27T14:22:24Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/obj/s390x go_test:cmd/internal/obj/x86]
2022-04-27T14:22:30Z finish_run_tests_multi after 5.86s; 10.128.0.15:80: [go_test:cmd/internal/obj/s390x go_test:cmd/internal/obj/x86]
2022-04-27T14:22:30Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/objabi go_test:cmd/internal/pkgpath go_test:cmd/internal/quoted]
2022-04-27T14:22:33Z finish_run_tests_multi after 3.25s; 10.128.0.15:80: [go_test:cmd/internal/objabi go_test:cmd/internal/pkgpath go_test:cmd/internal/quoted]
2022-04-27T14:22:33Z run_tests_multi 10.128.0.15:80: [go_test:cmd/internal/src go_test:cmd/internal/sys go_test:cmd/internal/test2json]
2022-04-27T14:22:37Z finish_run_tests_multi after 3.3s; 10.128.0.15:80: [go_test:cmd/internal/src go_test:cmd/internal/sys go_test:cmd/internal/test2json]
2022-04-27T14:22:37Z run_test:go_test:cmd/link 10.128.0.15:80
2022-04-27T14:22:45Z finish_run_test:go_test:cmd/link after 7.87s; 10.128.0.15:80
2022-04-27T14:22:45Z run_test:go_test:cmd/link/internal/benchmark 10.128.0.15:80
2022-04-27T14:22:48Z finish_run_test:go_test:cmd/link/internal/benchmark after 2.92s; 10.128.0.15:80
2022-04-27T14:22:48Z run_test:go_test:cmd/link/internal/ld 10.128.0.15:80
2022-04-27T14:23:12Z finish_run_test:go_test:cmd/link/internal/ld after 23.6s; 10.128.0.15:80
2022-04-27T14:23:12Z run_tests_multi 10.128.0.15:80: [go_test:cmd/link/internal/loader go_test:cmd/nm]
2022-04-27T14:23:17Z finish_run_tests_multi after 5.56s; 10.128.0.15:80: [go_test:cmd/link/internal/loader go_test:cmd/nm]
2022-04-27T14:23:17Z run_test:go_test:cmd/objdump 10.128.0.15:80
2022-04-27T14:23:24Z finish_run_test:go_test:cmd/objdump after 6.34s; 10.128.0.15:80
2022-04-27T14:23:24Z run_test:go_test:cmd/pack 10.128.0.15:80
2022-04-27T14:23:30Z finish_run_test:go_test:cmd/pack after 6.52s; 10.128.0.15:80
2022-04-27T14:23:30Z run_tests_multi 10.128.0.15:80: [go_test:cmd/pprof go_test:cmd/trace]
2022-04-27T14:23:35Z finish_run_tests_multi after 4.9s; 10.128.0.15:80: [go_test:cmd/pprof go_test:cmd/trace]
2022-04-27T14:23:35Z run_test:go_test:cmd/vet 10.128.0.15:80
2022-04-27T14:23:44Z finish_run_test:go_test:cmd/vet after 8.55s; 10.128.0.15:80
2022-04-27T14:23:44Z run_test:osusergo 10.128.0.15:80
2022-04-27T14:23:47Z finish_run_test:osusergo after 3.18s; 10.128.0.15:80
2022-04-27T14:23:47Z run_test:runtime:cpu124 10.128.0.15:80
2022-04-27T14:24:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:24:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:25:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:25:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:26:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:26:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:27:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:27:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:28:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:28:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:29:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:29:47Z still_waiting_on_test runtime:cpu124
2022-04-27T14:30:17Z still_waiting_on_test runtime:cpu124
2022-04-27T14:30:47Z still_waiting_on_test runtime:cpu124
+19.9s (now)

Build log:
windows-amd64-longtest at e845750744b648b8b348bbcebe2ff85d4e6247c5

Test execution environment.

GOARCH: amd64

CPU: Intel(R) Xeon(R) CPU @ 2.20GHz

GOOS: windows

OS Version: 10.0.14393

Testing packages.

ok archive/tar 0.042s
ok archive/zip 23.119s
ok bufio 0.063s
ok bytes 1.340s
ok compress/bzip2 0.080s
ok compress/flate 7.122s
ok compress/gzip 0.170s
ok compress/lzw 0.073s
ok compress/zlib 0.692s
ok container/heap 0.026s
ok container/list 0.021s
ok container/ring 0.023s
ok context 0.229s
ok crypto 0.021s
ok crypto/aes 0.048s
ok crypto/cipher 0.130s
ok crypto/des 0.027s
ok crypto/dsa 5.111s
ok crypto/ecdsa 1.163s
ok crypto/ed25519 0.211s
ok crypto/ed25519/internal/edwards25519 3.569s
ok crypto/ed25519/internal/edwards25519/field 2.847s
ok crypto/elliptic 0.260s
ok crypto/elliptic/internal/fiat 0.022s [no tests to run]
ok crypto/elliptic/internal/nistec 0.756s
ok crypto/hmac 0.021s
ok crypto/internal/subtle 0.024s
ok crypto/md5 0.024s
ok crypto/rand 0.155s
ok crypto/rc4 0.041s
ok crypto/rsa 0.500s
ok crypto/sha1 0.022s
ok crypto/sha256 0.022s
ok crypto/sha512 0.024s
ok crypto/subtle 0.024s
ok crypto/tls 2.561s
ok crypto/x509 1.628s
ok database/sql 0.967s
ok database/sql/driver 0.030s
ok debug/buildinfo 0.371s
ok debug/dwarf 0.035s
ok debug/elf 0.040s
ok debug/gosym 2.730s
ok debug/macho 0.026s
ok debug/pe 5.387s
ok debug/plan9obj 0.022s
ok embed 0.020s [no tests to run]
ok embed/internal/embedtest 0.023s
ok encoding/ascii85 0.021s
ok encoding/asn1 0.022s
ok encoding/base32 0.034s
ok encoding/base64 0.023s
ok encoding/binary 0.023s
ok encoding/csv 0.029s
ok encoding/gob 0.040s
ok encoding/hex 0.024s
ok encoding/json 0.980s
ok encoding/pem 0.414s
ok encoding/xml 0.035s
ok errors 0.025s
ok expvar 0.026s
ok flag 0.101s
ok fmt 0.107s
ok go/ast 0.029s
ok go/build 1.228s
ok go/build/constraint 0.027s
ok go/constant 0.030s
ok go/doc 0.068s
ok go/doc/comment 0.870s
ok go/format 0.025s
ok go/importer 0.131s
ok go/internal/gccgoimporter 0.039s
ok go/internal/gcimporter 13.551s
ok go/internal/srcimporter 6.228s
ok go/parser 0.051s
ok go/printer 0.332s
ok go/scanner 0.026s
ok go/token 0.032s
ok go/types 29.267s
ok hash 0.023s
ok hash/adler32 0.027s
ok hash/crc32 0.027s
ok hash/crc64 0.027s
ok hash/fnv 0.025s
ok hash/maphash 124.678s
ok html 0.023s
ok html/template 0.300s
ok image 0.180s
ok image/color 0.044s
ok image/draw 0.087s
ok image/gif 11.225s
ok image/jpeg 2.709s
ok image/png 0.698s
ok index/suffixarray 48.569s
ok internal/abi 0.111s
ok internal/buildcfg 0.027s
ok internal/cpu 0.025s
ok internal/diff 0.028s
ok internal/execabs 0.029s
ok internal/fmtsort 0.021s
ok internal/fuzz 0.027s
ok internal/godebug 0.021s
ok internal/intern 2.572s
ok internal/itoa 0.023s
ok internal/poll 2.516s
ok internal/profile 0.029s
ok internal/reflectlite 0.072s
ok internal/singleflight 0.039s
ok internal/syscall/windows 0.045s
ok internal/syscall/windows/registry 0.024s
ok internal/trace 1.094s
ok internal/unsafeheader 0.023s
ok internal/xcoff 0.032s
ok io 0.058s
ok io/fs 0.029s
ok io/ioutil 0.033s
ok log 0.027s
ok math 0.025s
ok math/big 2.946s
ok math/bits 0.025s
ok math/cmplx 0.026s
ok math/rand 3.597s
ok mime 0.046s
ok mime/multipart 0.269s
ok mime/quotedprintable 0.133s
ok net 56.823s
ok net/http 55.339s
ok net/http/cgi 0.222s
ok net/http/cookiejar 0.028s
ok net/http/fcgi 0.128s
ok net/http/httptest 2.072s
ok net/http/httptrace 0.021s
ok net/http/httputil 0.723s
ok net/http/internal 0.021s
ok net/http/internal/ascii 0.022s
ok net/http/pprof 5.186s
ok net/internal/socktest 0.023s
ok net/mail 0.026s
ok net/netip 0.425s
ok net/rpc 0.047s
ok net/rpc/jsonrpc 0.028s
ok net/smtp 0.033s
ok net/textproto 0.023s
ok net/url 0.027s
ok os 62.699s
ok os/exec 2.933s
ok os/exec/internal/fdtest 0.029s
ok os/signal 1.472s
ok os/user 0.029s
ok path 0.026s
ok path/filepath 0.532s
ok plugin 0.023s
ok reflect 0.748s
ok regexp 14.548s
ok regexp/syntax 0.268s
ok runtime 199.403s
ok runtime/cgo 0.020s
ok runtime/debug 0.059s
ok runtime/internal/atomic 2.862s
ok runtime/internal/math 0.021s
ok runtime/internal/sys 0.021s
ok runtime/metrics 0.019s
ok runtime/pprof 59.824s
ok runtime/trace 9.880s
ok sort 0.523s
ok strconv 1.131s
ok strings 0.940s
ok sync 3.679s
ok sync/atomic 54.691s
ok syscall 3.636s
ok testing 1.634s
ok testing/fstest 0.030s
ok testing/iotest 0.026s
ok testing/quick 0.056s
ok text/scanner 0.027s
ok text/tabwriter 0.026s
ok text/template 0.743s
ok text/template/parse 0.037s
ok time 9.401s
ok unicode 0.027s
ok unicode/utf16 0.023s
ok unicode/utf8 0.029s
ok cmd/addr2line 1.419s
ok cmd/api 9.219s
ok cmd/asm/internal/asm 0.404s
ok cmd/asm/internal/lex 0.024s
ok cmd/compile/internal/amd64 0.026s
ok cmd/compile/internal/dwarfgen 0.363s
ok cmd/compile/internal/importer 0.783s
ok cmd/compile/internal/ir 0.025s
ok cmd/compile/internal/logopt 0.699s
ok cmd/compile/internal/noder 0.029s
ok cmd/compile/internal/reflectdata 0.026s [no tests to run]
ok cmd/compile/internal/ssa 166.815s
ok cmd/compile/internal/syntax 2.598s
ok cmd/compile/internal/test 18.681s
ok cmd/compile/internal/typecheck 0.570s
ok cmd/compile/internal/types 0.026s
ok cmd/compile/internal/types2 9.774s
ok cmd/cover 1.807s
ok cmd/dist 0.023s
ok cmd/doc 0.272s
ok cmd/fix 1.565s
ok cmd/go 218.269s
ok cmd/go/internal/auth 0.023s
ok cmd/go/internal/cache 7.129s
ok cmd/go/internal/fsys 0.099s
ok cmd/go/internal/generate 0.039s
ok cmd/go/internal/get 0.035s
ok cmd/go/internal/imports 0.023s
ok cmd/go/internal/load 0.031s
ok cmd/go/internal/lockedfile 0.521s
ok cmd/go/internal/lockedfile/internal/filelock 0.062s
ok cmd/go/internal/modconv 0.024s
ok cmd/go/internal/modfetch 0.968s
ok cmd/go/internal/modfetch/codehost 0.037s
ok cmd/go/internal/modfetch/zip_sum_test 0.024s
ok cmd/go/internal/modload 0.028s
ok cmd/go/internal/mvs 0.027s
ok cmd/go/internal/par 0.049s
ok cmd/go/internal/search 0.021s
ok cmd/go/internal/str 0.022s
ok cmd/go/internal/test 0.036s
ok cmd/go/internal/vcs 0.250s
ok cmd/go/internal/web 0.024s
ok cmd/go/internal/work 0.093s
ok cmd/gofmt 6.089s
ok cmd/internal/archive 1.066s
ok cmd/internal/buildid 0.155s
ok cmd/internal/dwarf 0.022s
ok cmd/internal/edit 0.021s
ok cmd/internal/goobj 15.817s
ok cmd/internal/moddeps 1.758s
ok cmd/internal/obj 0.076s
ok cmd/internal/obj/ppc64 3.072s
ok cmd/internal/obj/riscv 7.187s
ok cmd/internal/obj/s390x 0.020s
ok cmd/internal/obj/x86 2.139s
ok cmd/internal/objabi 0.020s
ok cmd/internal/pkgpath 0.083s
ok cmd/internal/quoted 0.025s
ok cmd/internal/src 0.021s
ok cmd/internal/sys 0.022s
ok cmd/internal/test2json 0.087s
ok cmd/link 4.103s
ok cmd/link/internal/benchmark 0.024s
ok cmd/link/internal/ld 18.436s
ok cmd/link/internal/loader 0.038s
ok cmd/nm 2.208s
ok cmd/objdump 2.827s
ok cmd/pack 3.154s
ok cmd/pprof 1.187s
ok cmd/trace 0.435s
ok cmd/vet 5.329s

os/user with tag osusergo

ok os/user 0.027s

GOMAXPROCS=2 runtime -cpu=1,2,4 -quick

ok runtime 561.691s

maymorestack=mayMoreStackPreempt

ok runtime 120.980s
ok reflect 1.063s
ok sync 3.583s

Error: runTests: dist test failed: all buildlets had network errors or timeouts, yet tests remain

@heschi
Copy link
Contributor

heschi commented Apr 27, 2022

https://go.dev/cl/361212 looks a little suspicious in that range?

cc @aclements

@cagedmantis cagedmantis added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 27, 2022
@bcmills
Copy link
Contributor Author

bcmills commented Apr 27, 2022

They're almost certainly timing out.

(In that case, #42699 may be related.)

@bcmills
Copy link
Contributor Author

bcmills commented May 9, 2022

It appears that this masked several of the early failures for #52800.

@bcmills
Copy link
Contributor Author

bcmills commented May 9, 2022

(And, FWIW, these builders still aren't keeping up. 😩)

@dmitshur
Copy link
Contributor

dmitshur commented May 9, 2022

I thought the VM would be shut down after 30 minutes, so I'm not sure why it's still running. But it appears that something is wrong with runtime:cpu124 -- it appears in many ongoing logs.

In a recent run, runtime:cpu124 completed after 9m4.7s (it's skipped in normal trybot runs for speed, but not skipped in the longtest post-submit builds). I suspect this longtest builder was previously close to 45 mins and CL 361212 happened to push it over the edge.

The builder host type doesn't have a custom DeleteTimeout field set, so it defers to the default 45 min one (vmDeleteTimeout), which appears to be consistently not enough for today's longtest runs. We've seen a similar issue in #49666 and bumped the VM delete timeout there. (#42699 is definitely relevant here, but making a small change there will help with this issue while adding more builder noise in other areas, and making a bigger change will take longer.)

@dmitshur dmitshur added NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels May 9, 2022
@heschi
Copy link
Contributor

heschi commented May 9, 2022

@dmitshur
Copy link
Contributor

dmitshur commented May 9, 2022

That kicks in only when opts.DeleteIn == 0, but that's not the case at the call site.

@aclements
Copy link
Member

https://go.dev/cl/361212 would definitely slow down the longtest builders a bit. Do we have any data on how long these builds have taken over time that would tell us if we were close and that just pushed us over the line?

@dmitshur
Copy link
Contributor

dmitshur commented May 9, 2022

Do we have any data on how long these builds have taken over time that would tell us if we were close and that just pushed us over the line?

The current 45 min limit is a hard cut-off (the VM is forcibly destroyed at that time), so until we increase it, the only information available is how far the build gets within the 45 mins. (It should be possible to find out how long they used to take some weeks/months ago when they were completing, but I don't have a query handy.)

I suspect the "45 min" was meant as a safety cut off with plenty of headroom, not to prevent legitimate builds from completing. Builds being slow can be a problem, but stopping before they complete and retrying without limit (#42699) isn't a good solution; not to mention longtest post-submit builders by definition have the least need for short completion times (compared to TryBots and non-long builders).

We probably didn't have as many long tests in 2015 when "45 mins" was chosen as we do by now. Maybe not even longtest builders? Yes, first longtest builder came to be in 2018! Similarly to how CL 167638 bumped their timeout scale, I think we should increase the VM-timeout for builders whose IsLongTest method reports positively—that'll give more information to work with and likely simply resolve this issue for some time to come. (If after that we're unhappy with longtest post-submit builds taking too long, we can address that problem in a way that's better than what the current state of builds not even completing.) I'll tentatively move this to NeedsFix.

@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. labels May 9, 2022
@heschi heschi added this to In Progress in Go Release Team May 10, 2022
@gopherbot
Copy link

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

@dmitshur
Copy link
Contributor

dmitshur commented May 16, 2022

CL 406216 increased the timeout to 2 hours, and longtest builds are completing on first try or so. Compare before and after.

One of the windows-amd64-longtest builds completed successfully in approximately 56 minutes:

  builder: windows-amd64-longtest
      rev: 08d6c4c2b96eb3e5012af9b346dc5b325e956844
 buildlet: http://10.128.3.53 GCE VM: buildlet-windows-amd64-2016-big-rnc8f6448
  started: 2022-05-13 22:32:57.995954624 +0000 UTC m=+17.207972604
    ended: 2022-05-13 23:28:34.277336896 +0000 UTC m=+3353.489354877
  success: true

If we want to find agreement on timing goals for longtest post-submit build times, that should be a new issue. For reference, the current goal for trybot (pre-submit) builds is tracked in subject of issue #17104, and the task of maintaining the hard timeout for builds is now issue #52929.

Go Release Team automation moved this from In Progress to Done May 16, 2022
@golang golang locked and limited conversation to collaborators Jun 22, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. OS-Windows Soon This needs to be done soon. (regressions, serious bugs, outages)
Projects
Archived in project
Development

No branches or pull requests

6 participants