From 9025075fea2eb2fa7288916cb7e2df7b084bce55 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Tue, 14 Jul 2020 12:26:20 +0200 Subject: [PATCH 1/2] util/log: make test report their stderr in the test output Previously, a `log.Scope()` would capture logs from tests in the same way as a running server; that is, by also capturing direct writes to stderr (such as those performed by the Go runtime for uncaught panics, or internal errors) to a separate `cockroach-stderr.log`. This behavior, while desirable for running servers, is problematic for unit testing: in that case, we prefer that uncaught panics and possible other Go runtime errors are interleaved in the test output, so as to automate the triage of test failures. This patch improves the situation by carving an exception to the default logging behavior for the purpose of `log.Scope()`. With this change, direct writes to stderr by code ran under a test will go to the test output, regardless of the logging configuration. The few tests that are truly interested in checking that stderr writes go to a log file can use the new constructor `log.ScopeWithoutShowLogsAndForcedStderrCapture()`. For example, consider this pseudo-test: ```go func TestFoo(t *testing.T) { defer log.Scope(t).Close(t) t.Log("i'm t.Logging") fmt.Println("i'm on stdout") fmt.Fprintln(os.Stderr, "i'm on stderr") go func() { panic("i panicked somewhere else") }() time.Sleep(time.Second) } ``` Before this patch, the output is like: ``` === RUN TestFoo TestFoo: test_log_scope.go:77: test logs captured to: /var/folders/yy/4q8rrssd27vdgbr59w9qbffr0000gn/T/logTestFoo927366034 TestFoo: test_log_scope.go:58: use -show-logs to present logs inline TestFoo: stopper_test.go:743: i'm t.Logging i'm on stdout FAIL github.com/cockroachdb/cockroach/pkg/util/stop 1.624s FAIL ``` And the stderr writes + panic are going to a separate file. With this patch, we get the following output instead: ``` === RUN TestFoo TestFoo: test_log_scope.go:88: test logs captured to: /tmp/tmp.v9jl56br/logTestFoo207407502 TestFoo: test_log_scope.go:58: use -show-logs to present logs inline TestFoo: clog_test.go:721: i'm t.Logging i'm on stdout i'm on stderr panic: i panicked somewhere else goroutine 69 [running]: github.com/cockroachdb/cockroach/pkg/util/log.TestFoo.func1() /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog_test.go:725 +0x39 created by github.com/cockroachdb/cockroach/pkg/util/log.TestFoo /data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog_test.go:724 +0x1db FAIL github.com/cockroachdb/cockroach/pkg/util/log 0.047s FAIL ``` Alternatives that were considered: - have the deferred `Close()` method of the TestLogScope pull out the contents of `cockroach-stderr.log` and manually duplicate them on the test output. This solution was rejected because when a go runtime error occurs on a separate goroutine than the one where the TestLogScope is defined, the deferred don't get a chance to run. - use a "tee writer" for the stderr stream. There are two problems with this: - the Go runtime writes to file descriptor 2 directly, so it's not sufficient to override `os.Stderr` with a tee writer. - teeing writes to fd 2 would require spawning a goroutine that captures the writes and duplicates them, asynchronously. The problem here is that the go runtime promptly terminates the process after it completes writing to fd 2. An async tee goroutine would not get a chance to run and the fd 2 output would get lost. Release note: None --- pkg/cli/testdata/zip/partial1 | 2 -- pkg/cli/testdata/zip/partial1_excluded | 2 -- pkg/cli/testdata/zip/partial2 | 2 -- pkg/cli/testdata/zip/unavailable | 1 - pkg/server/status_test.go | 4 +-- pkg/util/log/clog_test.go | 2 +- pkg/util/log/flags.go | 35 ++++++++++++++++++-------- pkg/util/log/secondary_log_test.go | 2 +- pkg/util/log/test_log_scope.go | 17 ++++++++++--- 9 files changed, 43 insertions(+), 24 deletions(-) diff --git a/pkg/cli/testdata/zip/partial1 b/pkg/cli/testdata/zip/partial1 index 4cc80a3e9df5..708bb4a426b8 100644 --- a/pkg/cli/testdata/zip/partial1 +++ b/pkg/cli/testdata/zip/partial1 @@ -55,7 +55,6 @@ requesting goroutine files for node 1... writing: debug/nodes/1/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/1/ranges/1.json writing: debug/nodes/1/ranges/2.json @@ -183,7 +182,6 @@ requesting goroutine files for node 3... writing: debug/nodes/3/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/3/ranges/1.json writing: debug/nodes/3/ranges/2.json diff --git a/pkg/cli/testdata/zip/partial1_excluded b/pkg/cli/testdata/zip/partial1_excluded index 73f2402d9858..6dd3a57cdd53 100644 --- a/pkg/cli/testdata/zip/partial1_excluded +++ b/pkg/cli/testdata/zip/partial1_excluded @@ -55,7 +55,6 @@ requesting goroutine files for node 1... writing: debug/nodes/1/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/1/ranges/1.json writing: debug/nodes/1/ranges/2.json @@ -120,7 +119,6 @@ requesting goroutine files for node 3... writing: debug/nodes/3/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/3/ranges/1.json writing: debug/nodes/3/ranges/2.json diff --git a/pkg/cli/testdata/zip/partial2 b/pkg/cli/testdata/zip/partial2 index 971d333cfbe0..dbc84feba79b 100644 --- a/pkg/cli/testdata/zip/partial2 +++ b/pkg/cli/testdata/zip/partial2 @@ -55,7 +55,6 @@ requesting goroutine files for node 1... writing: debug/nodes/1/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/1/ranges/1.json writing: debug/nodes/1/ranges/2.json @@ -119,7 +118,6 @@ requesting goroutine files for node 3... writing: debug/nodes/3/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting ranges... 34 found writing: debug/nodes/3/ranges/1.json writing: debug/nodes/3/ranges/2.json diff --git a/pkg/cli/testdata/zip/unavailable b/pkg/cli/testdata/zip/unavailable index 746b23214dc3..bfe39425936e 100644 --- a/pkg/cli/testdata/zip/unavailable +++ b/pkg/cli/testdata/zip/unavailable @@ -84,6 +84,5 @@ requesting goroutine files for node 1... writing: debug/nodes/1/goroutines.err.t ^- resulted in ... requesting log file ... requesting log file ... -requesting log file ... requesting list of SQL databases... writing: debug/schema.err.txt ^- resulted in ... diff --git a/pkg/server/status_test.go b/pkg/server/status_test.go index 33a391fbc6d2..0fc2ecf0d377 100644 --- a/pkg/server/status_test.go +++ b/pkg/server/status_test.go @@ -499,7 +499,7 @@ func TestStatusLocalLogs(t *testing.T) { t.Skip("Test only works with low verbosity levels") } - s := log.ScopeWithoutShowLogs(t) + s := log.ScopeWithoutShowLogsAndForcedStderrCapture(t) defer s.Close(t) ts := startServer(t) @@ -686,7 +686,7 @@ func TestStatusLogRedaction(t *testing.T) { testutils.RunTrueAndFalse(t, "redactableLogs", func(t *testing.T, redactableLogs bool) { - s := log.ScopeWithoutShowLogs(t) + s := log.ScopeWithoutShowLogsAndForcedStderrCapture(t) defer s.Close(t) // Apply the redactable log boolean for this test. diff --git a/pkg/util/log/clog_test.go b/pkg/util/log/clog_test.go index 0941f85c9369..29195d5fb532 100644 --- a/pkg/util/log/clog_test.go +++ b/pkg/util/log/clog_test.go @@ -615,7 +615,7 @@ func TestFatalStacktraceStderr(t *testing.T) { } func TestRedirectStderr(t *testing.T) { - s := ScopeWithoutShowLogs(t) + s := ScopeWithoutShowLogsAndForcedStderrCapture(t) defer s.Close(t) setFlags() diff --git a/pkg/util/log/flags.go b/pkg/util/log/flags.go index d154c9c82851..93a9cc904252 100644 --- a/pkg/util/log/flags.go +++ b/pkg/util/log/flags.go @@ -47,6 +47,17 @@ func init() { // ensures that any Go runtime assertion failures on the way to // termination can be properly captured. func SetupRedactionAndStderrRedirects() (cleanup func(), err error) { + return setupRedactionAndStderrRedirectsInternal(true /* captureStderr */) +} + +// setupRedactionAndStderrRedirectsInternal does the work for +// SetupRedactionAndStderrRedirects. +// +// The boolean argument should be set to true in the general case, +// i.e. a running server. It is set to false by TestLogScope, to +// ensure that tests see uncaught Go runtime errors in the test +// output, instead of a stderr log file in artifacts. +func setupRedactionAndStderrRedirectsInternal(captureStderr bool) (cleanup func(), err error) { // The general goal of this function is to set up a secondary logger // to capture internal Go writes to os.Stderr / fd 2 and redirect // them to a separate (non-redactable) log file, This is, of course, @@ -65,7 +76,20 @@ func SetupRedactionAndStderrRedirects() (cleanup func(), err error) { // won't be positioned outside of log redaction markers and // mistakenly considered as "safe for reporting". - if mainLog.logDir.IsSet() { + sendingStderrToFile := mainLog.logDir.IsSet() && captureStderr + + // If redaction is requested, + // and we have a chance to produce some log entries on stderr, + // and stderr is not being sent to a separate log file, + // + // that's a configuration we cannot support safely. Reject it. + if redactableLogsRequested && (mainLog.stderrThreshold.get() != Severity_NONE) && !sendingStderrToFile { + return nil, errors.WithHint( + errors.New("cannot enable redactable logging without creating a stderr log file"), + "Check that the logging output directory is properly configured.") + } + + if sendingStderrToFile { // We have a log directory. We can enable stderr redirection. // Our own cancellable context to stop the secondary logger. @@ -116,15 +140,6 @@ func SetupRedactionAndStderrRedirects() (cleanup func(), err error) { return cleanup, nil } - // There is no log directory. - - // If redaction is requested and we have a change to produce some - // log entries on stderr, that's a configuration we cannot support - // safely. Reject it. - if redactableLogsRequested && mainLog.stderrThreshold.get() != Severity_NONE { - return nil, errors.New("cannot enable redactable logging without a logging directory") - } - // Configuration valid. Assign it. // (Note: This is a no-op, because either redactableLogsRequested is false, // or it's true but stderrThreshold filters everything.) diff --git a/pkg/util/log/secondary_log_test.go b/pkg/util/log/secondary_log_test.go index 55bdcd364a4f..6f784353758b 100644 --- a/pkg/util/log/secondary_log_test.go +++ b/pkg/util/log/secondary_log_test.go @@ -75,7 +75,7 @@ func TestSecondaryLog(t *testing.T) { } func TestRedirectStderrWithSecondaryLoggersActive(t *testing.T) { - s := ScopeWithoutShowLogs(t) + s := ScopeWithoutShowLogsAndForcedStderrCapture(t) defer s.Close(t) setFlags() diff --git a/pkg/util/log/test_log_scope.go b/pkg/util/log/test_log_scope.go index 696e75cedab4..5671c5901db8 100644 --- a/pkg/util/log/test_log_scope.go +++ b/pkg/util/log/test_log_scope.go @@ -62,6 +62,17 @@ func Scope(t tShim) *TestLogScope { // ScopeWithoutShowLogs ignores the -show-logs flag and should be used for tests // that require the logs go to files. func ScopeWithoutShowLogs(t tShim) *TestLogScope { + return scopeWithoutShowLogsInternal(t, false /* captureStderr */) +} + +// ScopeWithoutShowLogsAndForcedStderrCapture ignores the -show-logs flag and forces +// redirecting writes to stderr to go to a stderr log file. +// This should be used by tests that check the stderr capture behavior. +func ScopeWithoutShowLogsAndForcedStderrCapture(t tShim) *TestLogScope { + return scopeWithoutShowLogsInternal(t, true /* captureStderr */) +} + +func scopeWithoutShowLogsInternal(t tShim, captureStderr bool) *TestLogScope { tempDir, err := ioutil.TempDir("", "log"+fileutil.EscapeFilename(t.Name())) if err != nil { t.Fatal(err) @@ -69,7 +80,7 @@ func ScopeWithoutShowLogs(t tShim) *TestLogScope { if err := dirTestOverride("", tempDir); err != nil { t.Fatal(err) } - undo, err := enableLogFileOutput(tempDir, Severity_NONE) + undo, err := enableLogFileOutput(tempDir, Severity_NONE, captureStderr) if err != nil { undo() t.Fatal(err) @@ -80,7 +91,7 @@ func ScopeWithoutShowLogs(t tShim) *TestLogScope { // enableLogFileOutput turns on logging using the specified directory. // For unittesting only. -func enableLogFileOutput(dir string, stderrSeverity Severity) (func(), error) { +func enableLogFileOutput(dir string, stderrSeverity Severity, captureStderr bool) (func(), error) { oldStderrThreshold, err := func() (Severity, error) { mainLog.mu.Lock() defer mainLog.mu.Unlock() @@ -104,7 +115,7 @@ func enableLogFileOutput(dir string, stderrSeverity Severity) (func(), error) { } mainLog.stderrThreshold.set(stderrSeverity) - cancelStderr, err = SetupRedactionAndStderrRedirects() + cancelStderr, err = setupRedactionAndStderrRedirectsInternal(captureStderr) return undo, err } From 88815d78c905bf6d4330b56dbdc01fcb38b10b4d Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Tue, 14 Jul 2020 14:11:32 +0200 Subject: [PATCH 2/2] log: dummy test Release note (): --- pkg/util/log/dummy_test.go | 38 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) create mode 100644 pkg/util/log/dummy_test.go diff --git a/pkg/util/log/dummy_test.go b/pkg/util/log/dummy_test.go new file mode 100644 index 000000000000..5d1ee42d506f --- /dev/null +++ b/pkg/util/log/dummy_test.go @@ -0,0 +1,38 @@ +// Copyright 2020 The Cockroach Authors. +// +// Use of this software is governed by the Business Source License +// included in the file licenses/BSL.txt. +// +// As of the Change Date specified in that file, in accordance with +// the Business Source License, use of this software will be governed +// by the Apache License, Version 2.0, included in the file +// licenses/APL.txt. + +package log + +import ( + "fmt" + "os" + "testing" + "time" +) + +func TestBar(t *testing.T) { + defer Scope(t).Close(t) + t.Log("i'm t.Logging") + fmt.Println("i'm on stdout") + fmt.Fprintln(os.Stderr, "i'm on stderr") + panic("i panicked somewhere") +} + +func TestFoo(t *testing.T) { + defer Scope(t).Close(t) + t.Skip("panicy") + t.Log("i'm t.Logging") + fmt.Println("i'm on stdout") + fmt.Fprintln(os.Stderr, "i'm on stderr") + go func() { + panic("i panicked somewhere else") + }() + time.Sleep(time.Second) +}