build: unrecognized build failure on gotip-linux-amd64-newinliner that was actually due to a core file being left behind

[gopherbot]

#!watchflakes
default <- builder == "gotip-linux-amd64-newinliner" && repo == "go" && mode == "build"

Issue created automatically to collect these failures.

Example (log):

[I2024-02-26T20:58:04.487210Z 42557 0 sink.go:276] SinkServer: warm-up started
[I2024-02-26T20:58:04.487257Z 42557 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-02-26T20:58:04.488280Z 42557 0 sink.go:281] SinkServer: warm-up ended
[I2024-02-26T20:58:04.488580Z 42557 0 cmd_stream.go:473] rdb-stream: starting the test command - ["/home/swarming/.swarming/w/ir/cache/tools/bin/result_adapter" "go" "-v=false" "--" "/home/swarming/.swarming/w/ir/x/w/goroot/bin/go" "tool" "dist" "test" "-json" "archive/tar" "bufio" "compress/bzip2" "compress/flate" "crypto/ed25519" "crypto/hmac" "crypto/internal/alias" "crypto/internal/boring" "crypto/internal/edwards25519/field" "crypto/x509" "debug/buildinfo" "debug/elf" "debug/gosym" "embed" "encoding/base32" "encoding/base64" "encoding/hex" "encoding/json" "fmt" "go/doc" "go/internal/srcimporter" "go/printer" "go/scanner" "hash/fnv" "html/template" "image" "image/gif" "image/jpeg" "image/png" "internal/buildcfg" "internal/coverage/cmerge" "internal/coverage/slicereader" "internal/cpu" "internal/diff" "internal/itoa" "internal/xcoff" "log/slog" "net" "net/http/httputil" "net/http/internal/ascii" "net/internal/cgotest" "net/netip" "net/smtp" "net/textproto" "os/signal" "path" "path/filepath" "regexp" "regexp/syntax" "runtime" "runtime/debug" "runtime/internal/wasitest" "testing/slogtest" "text/tabwriter" "cmd/cgo/internal/swig" "cmd/cgo/internal/testerrors" "cmd/cgo/internal/testfortran" "cmd/cgo/internal/testgodefs" "cmd/compile/internal/amd64" "cmd/compile/internal/importer" "cmd/compile/internal/loopvar" "cmd/compile/internal/noder" "cmd/compile/internal/types2" "cmd/go" "cmd/go/internal/envcmd" "cmd/go/internal/fsys" "cmd/go/internal/generate" "cmd/go/internal/modfetch/codehost" "cmd/go/internal/modindex" "cmd/go/internal/par" "cmd/go/internal/toolchain" "cmd/go/internal/vcweb" "cmd/internal/archive" "cmd/internal/buildid" "cmd/internal/edit" "cmd/internal/obj" "cmd/link/internal/ld" "cmd/objdump" "runtime:cpu124" "iter:iter" "os/user:pie_internal" "flag:race" "flag:race-external" "cmd/cgo/internal/test:external-g0" "cmd/cgo/internal/testtls:static" "cmd/cgo/internal/testnocgo:auto-pie" "cmd/internal/testdir:2_10" "cmd/internal/testdir:4_10" "cmd/internal/testdir:8_10" "cmd/api:check"]
go tool dist: Failed: exit status 1
ok  	archive/tar	0.268s
ok  	bufio	0.106s
ok  	compress/bzip2	0.086s
ok  	compress/flate	1.004s
ok  	crypto/ed25519	0.096s
...
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-02-26T20:59:55.757484Z 42557 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-02-26T20:59:55.757653Z 42557 0 sink.go:371] SinkServer: shutdown started
[I2024-02-26T20:59:55.757747Z 42557 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-02-26T20:59:55.757781Z 42557 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-02-26T20:59:56.460178Z 42557 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-02-26T20:59:56.460245Z 42557 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-02-26T20:59:56.551910Z 42557 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-02-26T20:59:56.551969Z 42557 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-02-26T20:59:56.552046Z 42557 0 cmd_stream.go:401] rdb-stream: exiting with 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder == "gotip-linux-amd64-newinliner" && repo == "go" && mode == "build"

2024-02-26 20:46 gotip-linux-amd64-newinliner go@4760b333 [build] (log)

[I2024-02-26T20:58:04.487210Z 42557 0 sink.go:276] SinkServer: warm-up started
[I2024-02-26T20:58:04.487257Z 42557 0 sink.go:346] SinkServer: starting HTTP server...
[I2024-02-26T20:58:04.488280Z 42557 0 sink.go:281] SinkServer: warm-up ended
[I2024-02-26T20:58:04.488580Z 42557 0 cmd_stream.go:473] rdb-stream: starting the test command - ["/home/swarming/.swarming/w/ir/cache/tools/bin/result_adapter" "go" "-v=false" "--" "/home/swarming/.swarming/w/ir/x/w/goroot/bin/go" "tool" "dist" "test" "-json" "archive/tar" "bufio" "compress/bzip2" "compress/flate" "crypto/ed25519" "crypto/hmac" "crypto/internal/alias" "crypto/internal/boring" "crypto/internal/edwards25519/field" "crypto/x509" "debug/buildinfo" "debug/elf" "debug/gosym" "embed" "encoding/base32" "encoding/base64" "encoding/hex" "encoding/json" "fmt" "go/doc" "go/internal/srcimporter" "go/printer" "go/scanner" "hash/fnv" "html/template" "image" "image/gif" "image/jpeg" "image/png" "internal/buildcfg" "internal/coverage/cmerge" "internal/coverage/slicereader" "internal/cpu" "internal/diff" "internal/itoa" "internal/xcoff" "log/slog" "net" "net/http/httputil" "net/http/internal/ascii" "net/internal/cgotest" "net/netip" "net/smtp" "net/textproto" "os/signal" "path" "path/filepath" "regexp" "regexp/syntax" "runtime" "runtime/debug" "runtime/internal/wasitest" "testing/slogtest" "text/tabwriter" "cmd/cgo/internal/swig" "cmd/cgo/internal/testerrors" "cmd/cgo/internal/testfortran" "cmd/cgo/internal/testgodefs" "cmd/compile/internal/amd64" "cmd/compile/internal/importer" "cmd/compile/internal/loopvar" "cmd/compile/internal/noder" "cmd/compile/internal/types2" "cmd/go" "cmd/go/internal/envcmd" "cmd/go/internal/fsys" "cmd/go/internal/generate" "cmd/go/internal/modfetch/codehost" "cmd/go/internal/modindex" "cmd/go/internal/par" "cmd/go/internal/toolchain" "cmd/go/internal/vcweb" "cmd/internal/archive" "cmd/internal/buildid" "cmd/internal/edit" "cmd/internal/obj" "cmd/link/internal/ld" "cmd/objdump" "runtime:cpu124" "iter:iter" "os/user:pie_internal" "flag:race" "flag:race-external" "cmd/cgo/internal/test:external-g0" "cmd/cgo/internal/testtls:static" "cmd/cgo/internal/testnocgo:auto-pie" "cmd/internal/testdir:2_10" "cmd/internal/testdir:4_10" "cmd/internal/testdir:8_10" "cmd/api:check"]
go tool dist: Failed: exit status 1
ok  	archive/tar	0.268s
ok  	bufio	0.106s
ok  	compress/bzip2	0.086s
ok  	compress/flate	1.004s
ok  	crypto/ed25519	0.096s
...
Warning: no '=' in invocation-link-artifacts pair: "", ignoring
[I2024-02-26T20:59:55.757484Z 42557 0 cmd_stream.go:469] rdb-stream: the test process terminated
[I2024-02-26T20:59:55.757653Z 42557 0 sink.go:371] SinkServer: shutdown started
[I2024-02-26T20:59:55.757747Z 42557 0 sink.go:349] SinkServer: HTTP server stopped with "http: Server closed"
[I2024-02-26T20:59:55.757781Z 42557 0 sink_server.go:95] SinkServer: draining TestResult channel started
[I2024-02-26T20:59:56.460178Z 42557 0 sink_server.go:97] SinkServer: draining TestResult channel ended
[I2024-02-26T20:59:56.460245Z 42557 0 sink_server.go:99] SinkServer: draining Artifact channel started
[I2024-02-26T20:59:56.551910Z 42557 0 sink_server.go:101] SinkServer: draining Artifact channel ended
[I2024-02-26T20:59:56.551969Z 42557 0 sink.go:374] SinkServer: shutdown completed successfully
[I2024-02-26T20:59:56.552046Z 42557 0 cmd_stream.go:401] rdb-stream: exiting with 1

— watchflakes

[bcmills]

The actual failure in this log is:

runtime.test: some test left a core file behind
FAIL	runtime	67.790s

(attn @golang/runtime)

@cherrymui, the watchflakes snippet for this failure seems weird. Is this a problem with the watchflakes parser, or with the way the LUCI infrastructure framed the logs?

[mknyszek]

I think it looks odd because watchflakes talks to the result database directly, and there's currently no place to put package-level failures. When this happens, I bet watchflakes probably just tries to link to the output directly instead of picking out the package-level failure directly.

Seems like there are two things we can do here.

One thing is that we can modify result_adapter to create a test event for the package-level. Right now, it identifies test events that are at the package level, but does not forward them to the test result database. What's strange is that a lot of the logic for handling package-level failures is already there (including the test ID), it just never does the last step of emitting the event.

The other thing that can be done is to have watchflakes parse the output of the log and truncate it. This might actually be harder right now because of the text emitted by the wrapper commands.

[cherrymui]

The snippet is the failed test output (if any), if there is no individual test failure (like a build failure), then the log of the failed step, if still empty, the log of the build. It currently extracts the first and last a few lines, and middle a few lines if there is a "useful" information. For "useful" it currently looks for "panic:", "--- FAIL:", etc. but does not look for just "FAIL". I'll make it include "FAIL" as well, then it will print the middle lines including

runtime.test: some test left a core file behind
FAIL	runtime	67.790s

[dmitshur]

Based on issue #69457, the watchflakes change described in #65977 (comment) above is done. It sounds like there's nothing more to do here, and we can use that issue to track core files sometimes being left behind.