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.

Sign up for GitHub

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

util/log: make test report their stderr in the test output #51410

Closed
wants to merge 2 commits into from
Closed

util/log: make test report their stderr in the test output #51410

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
9025075
util/log: make test report their stderr in the test output
knz Jul 14, 2020
88815d7
log: dummy test
knz Jul 14, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 0 additions & 2 deletions pkg/cli/testdata/zip/partial1
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
2 changes: 0 additions & 2 deletions pkg/cli/testdata/zip/partial1_excluded
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
2 changes: 0 additions & 2 deletions pkg/cli/testdata/zip/partial2
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
1 change: 0 additions & 1 deletion pkg/cli/testdata/zip/unavailable
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 ...
4 changes: 2 additions & 2 deletions pkg/server/status_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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.
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/log/clog_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
38 changes: 38 additions & 0 deletions pkg/util/log/dummy_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
}
35 changes: 25 additions & 10 deletions pkg/util/log/flags.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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.
Expand Down Expand Up @@ -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.)
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/log/secondary_log_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
17 changes: 14 additions & 3 deletions pkg/util/log/test_log_scope.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,14 +62,25 @@ 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)
}
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)
Expand All @@ -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()
Expand All @@ -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
}

Expand Down