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

Jump to bottom

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

wants to merge 2 commits into from

Commits on Jul 15, 2020

  1. 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
    @knz
    knz committed Jul 15, 2020
    Configuration menu
    Copy the full SHA
    9025075 View commit details
    Browse the repository at this point in the history

  2. log: dummy test 

    Release note (<category, see below>): <what> <show> <why>
    @knz
    knz committed Jul 15, 2020
    Configuration menu
    Copy the full SHA
    88815d7 View commit details
    Browse the repository at this point in the history