From 43e644e9f9af6cac59650252431287984a40eec5 Mon Sep 17 00:00:00 2001 From: Fabian Meumertzheim Date: Mon, 11 Dec 2023 08:10:46 +0100 Subject: [PATCH] Panic when a test times out (#3749) By calling `panic` when a Bazel test times out, which is indicated by Bazel sending a SIGTERM, stack traces of all Go routines are printed, similar to the behavior of native `go test`. --- go/tools/builders/generate_test_main.go | 2 +- go/tools/bzltestutil/BUILD.bazel | 1 + go/tools/bzltestutil/timeout.go | 36 ++++++++++++++ go/tools/bzltestutil/wrap.go | 27 +++++++--- tests/core/go_test/BUILD.bazel | 7 ++- tests/core/go_test/timeout_test.go | 66 +++++++++++++++++++++++++ 6 files changed, 130 insertions(+), 9 deletions(-) create mode 100644 go/tools/bzltestutil/timeout.go create mode 100644 tests/core/go_test/timeout_test.go diff --git a/go/tools/builders/generate_test_main.go b/go/tools/builders/generate_test_main.go index bc24aca2e4..c061d5e993 100644 --- a/go/tools/builders/generate_test_main.go +++ b/go/tools/builders/generate_test_main.go @@ -235,7 +235,7 @@ func main() { } } {{end}} - + bzltestutil.RegisterTimeoutHandler() {{if not .TestMain}} res := m.Run() {{else}} diff --git a/go/tools/bzltestutil/BUILD.bazel b/go/tools/bzltestutil/BUILD.bazel index a97a7516b9..e6b3637d3a 100644 --- a/go/tools/bzltestutil/BUILD.bazel +++ b/go/tools/bzltestutil/BUILD.bazel @@ -5,6 +5,7 @@ go_tool_library( srcs = [ "lcov.go", "test2json.go", + "timeout.go", "wrap.go", "xml.go", ], diff --git a/go/tools/bzltestutil/timeout.go b/go/tools/bzltestutil/timeout.go new file mode 100644 index 0000000000..f6d45776a4 --- /dev/null +++ b/go/tools/bzltestutil/timeout.go @@ -0,0 +1,36 @@ +// Copyright 2020 The Bazel Authors. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package bzltestutil + +import ( + "os" + "os/signal" + "runtime/debug" + "syscall" +) + +func RegisterTimeoutHandler() { + go func() { + // When the Bazel test timeout is reached, Bazel sends a SIGTERM. We + // panic just like native go test would so that the user gets stack + // traces of all running go routines. + // See https://github.com/golang/go/blob/e816eb50140841c524fd07ecb4eaa078954eb47c/src/testing/testing.go#L2351 + c := make(chan os.Signal, 1) + signal.Notify(c, syscall.SIGTERM) + <-c + debug.SetTraceback("all") + panic("test timed out") + }() +} diff --git a/go/tools/bzltestutil/wrap.go b/go/tools/bzltestutil/wrap.go index 4f325dbe55..b2ae457a4b 100644 --- a/go/tools/bzltestutil/wrap.go +++ b/go/tools/bzltestutil/wrap.go @@ -23,10 +23,12 @@ import ( "log" "os" "os/exec" + "os/signal" "path/filepath" "strconv" "strings" "sync" + "syscall" "github.com/bazelbuild/rules_go/go/tools/bzltestutil/chdir" ) @@ -67,9 +69,9 @@ func shouldAddTestV() bool { // ensure that one line at a time is written to the inner writer. type streamMerger struct { OutW, ErrW *io.PipeWriter - mutex sync.Mutex - inner io.Writer - wg sync.WaitGroup + mutex sync.Mutex + inner io.Writer + wg sync.WaitGroup outR, errR *bufio.Reader } @@ -78,10 +80,10 @@ func NewStreamMerger(w io.Writer) *streamMerger { errR, errW := io.Pipe() return &streamMerger{ inner: w, - OutW: outW, - ErrW: errW, - outR: bufio.NewReader(outR), - errR: bufio.NewReader(errR), + OutW: outW, + ErrW: errW, + outR: bufio.NewReader(outR), + errR: bufio.NewReader(errR), } } @@ -126,6 +128,17 @@ func Wrap(pkg string) error { cmd.Env = append(os.Environ(), "GO_TEST_WRAP=0") cmd.Stderr = io.MultiWriter(os.Stderr, streamMerger.ErrW) cmd.Stdout = io.MultiWriter(os.Stdout, streamMerger.OutW) + go func() { + // When the Bazel test timeout is reached, Bazel sends a SIGTERM that + // we need to forward to the inner process. + // TODO: This never triggers on Windows, even though Go should simulate + // a SIGTERM when Windows asks the process to close. It is not clear + // whether Bazel uses the required graceful shutdown mechanism. + c := make(chan os.Signal, 1) + signal.Notify(c, syscall.SIGTERM) + <-c + cmd.Process.Signal(syscall.SIGTERM) + }() streamMerger.Start() err := cmd.Run() streamMerger.ErrW.Close() diff --git a/tests/core/go_test/BUILD.bazel b/tests/core/go_test/BUILD.bazel index 96c7ac9a66..8750e7e978 100644 --- a/tests/core/go_test/BUILD.bazel +++ b/tests/core/go_test/BUILD.bazel @@ -263,4 +263,9 @@ go_bazel_test( go_bazel_test( name = "filter_test_cases_test", srcs = ["filter_test_cases_test.go"], -) \ No newline at end of file +) + +go_bazel_test( + name = "timeout_test", + srcs = ["timeout_test.go"], +) diff --git a/tests/core/go_test/timeout_test.go b/tests/core/go_test/timeout_test.go new file mode 100644 index 0000000000..3c05206bf0 --- /dev/null +++ b/tests/core/go_test/timeout_test.go @@ -0,0 +1,66 @@ +package timeout_test + +import ( + "os" + "path/filepath" + "runtime" + "strings" + "testing" + + "github.com/bazelbuild/rules_go/go/tools/bazel_testing" +) + +func TestMain(m *testing.M) { + bazel_testing.TestMain(m, bazel_testing.Args{ + Main: ` +-- BUILD.bazel -- +load("@io_bazel_rules_go//go:def.bzl", "go_test") + +go_test( + name = "timeout_test", + srcs = ["timeout_test.go"], +) +-- timeout_test.go -- +package timeout + +import "testing" + +func TestFoo(t *testing.T) { + neverTerminates() +} + +func neverTerminates() { + for {} +} +`, + }) +} + +func TestTimeout(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("panics on timeouts are not yet supported on Windows") + } + + if err := bazel_testing.RunBazel("test", "//:timeout_test", "--test_timeout=3"); err == nil { + t.Fatal("expected bazel test to fail") + } else if exitErr, ok := err.(*bazel_testing.StderrExitError); !ok || exitErr.Err.ExitCode() != 3 { + t.Fatalf("expected bazel test to fail with exit code 3", err) + } + p, err := bazel_testing.BazelOutput("info", "bazel-testlogs") + if err != nil { + t.Fatalf("could not find testlogs root: %s", err) + } + path := filepath.Join(strings.TrimSpace(string(p)), "timeout_test/test.log") + b, err := os.ReadFile(path) + if err != nil { + t.Fatalf("could not read test log: %s", err) + } + + testLog := string(b) + if !strings.Contains(testLog, "panic: test timed out") { + t.Fatalf("test log does not contain expected panic:\n%s", testLog) + } + if !strings.Contains(testLog, "timeout_test.neverTerminates(") { + t.Fatalf("test log does not contain expected stack trace:\n%s", testLog) + } +}