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.

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 (v2) #51499

Closed
wants to merge 2 commits into from

Conversation

knz
Copy link
Contributor

@knz knz commented Jul 16, 2020

Fixes #51409.

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 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 changing
(*TestLogScope).Close() to detect when there was a panic and/or
stderr output by the process, and copying it in the test log if
available.

For example, consider this pseudo-test:

func TestFoo(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 else")
}

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 only going to a separate file.

With this patch, we get the following output instead:

=== RUN   TestFoo
    TestFoo: test_log_scope.go:78: test logs captured to: /tmp/tmp.9f5zDKNo/logTestFoo038131792
    TestFoo: test_log_scope.go:59: use -show-logs to present logs inline
    TestFoo: foo_test.go:21: i'm t.Logging
i'm on stdout
    TestFoo: test_log_scope.go:152: panic during test: %v i panicked somewhere else
    TestFoo: test_log_scope.go:165: stderr output from /tmp/tmp.9f5zDKNo/logTestFoo038131792/logtest-stderr.log:
        i'm on stderr
        E200716 10:21:13.082285 41 /usr/local/go/src/runtime/panic.go:969  panic: i panicked somewhere else
        goroutine 41 [running]:
        runtime/debug.Stack(0xc0001fe080, 0x16a3340, 0xc0001ae010)
        	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
        github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).printPanicToFile(0xc0001fe080, 0x16a3340, 0xc0001ae010, 0x1, 0x641c00, 0x15d6a70)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:389 +0x137
        github.com/cockroachdb/cockroach/pkg/util/log.(*TestLogScope).Close(0xc0002f2340, 0x16ecfa0, 0xc000c98120)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:153 +0x76f
        panic(0x641c00, 0x15d6a70)
        	/usr/local/go/src/runtime/panic.go:969 +0x166
        github.com/cockroachdb/cockroach/pkg/util/log.TestFoo(0xc000c98120)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/foo_test.go:24 +0x1a8
        testing.tRunner(0xc000c98120, 0xddefe8)
        	/usr/local/go/src/testing/testing.go:991 +0xdc
        created by testing.(*T).Run
        	/usr/local/go/src/testing/testing.go:1042 +0x357
test logs left over in: /tmp/tmp.9f5zDKNo/logTestFoo038131792
--- FAIL: TestFoo (0.00s)
FAIL
FAIL	github.com/cockroachdb/cockroach/pkg/util/log	0.095s
FAIL

knz added 2 commits July 16, 2020 12:22
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 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 changing
`(*TestLogScope).Close()` to detect when there was a panic and/or
stderr output by the process, and copying it in the test log if
available.

For example, consider this pseudo-test:

```go
func TestFoo(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 else")
}
```

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 only going to a separate file.

With this patch, we get the following output instead:

```
=== RUN   TestFoo
    TestFoo: test_log_scope.go:78: test logs captured to: /tmp/tmp.9f5zDKNo/logTestFoo038131792
    TestFoo: test_log_scope.go:59: use -show-logs to present logs inline
    TestFoo: foo_test.go:21: i'm t.Logging
i'm on stdout
    TestFoo: test_log_scope.go:152: panic during test: %v i panicked somewhere else
    TestFoo: test_log_scope.go:165: stderr output from /tmp/tmp.9f5zDKNo/logTestFoo038131792/logtest-stderr.log:
        i'm on stderr
        E200716 10:21:13.082285 41 /usr/local/go/src/runtime/panic.go:969  panic: i panicked somewhere else
        goroutine 41 [running]:
        runtime/debug.Stack(0xc0001fe080, 0x16a3340, 0xc0001ae010)
        	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
        github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).printPanicToFile(0xc0001fe080, 0x16a3340, 0xc0001ae010, 0x1, 0x641c00, 0x15d6a70)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:389 +0x137
        github.com/cockroachdb/cockroach/pkg/util/log.(*TestLogScope).Close(0xc0002f2340, 0x16ecfa0, 0xc000c98120)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/test_log_scope.go:153 +0x76f
        panic(0x641c00, 0x15d6a70)
        	/usr/local/go/src/runtime/panic.go:969 +0x166
        github.com/cockroachdb/cockroach/pkg/util/log.TestFoo(0xc000c98120)
        	/data/home/kena/src/go/src/github.com/cockroachdb/cockroach/pkg/util/log/foo_test.go:24 +0x1a8
        testing.tRunner(0xc000c98120, 0xddefe8)
        	/usr/local/go/src/testing/testing.go:991 +0xdc
        created by testing.(*T).Run
        	/usr/local/go/src/testing/testing.go:1042 +0x357
test logs left over in: /tmp/tmp.9f5zDKNo/logTestFoo038131792
--- FAIL: TestFoo (0.00s)
FAIL
FAIL	github.com/cockroachdb/cockroach/pkg/util/log	0.095s
FAIL
```

Release note: None
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@tbg
Copy link
Member

tbg commented Jul 31, 2020

The other PR would perform similarly in this particular test, since there isn't an off-goroutine panic, right? Assuming this is true am leaning towards #51410 over this one.

@knz
Copy link
Contributor Author

knz commented Jul 31, 2020

This PR is better when a test fails in the stress pre-req in teamcity-common.

In that case, the details of the test failure are hidden by Go, but it's still possible to find it in the artifacts. With the other PR #51410 we don't have that.

@tbg
Copy link
Member

tbg commented Jul 31, 2020

Ok. Let's merge this PR now. I do worry a fair bit about off-goroutine panics but, we're not making anything worse here and besides, if we do anything else we can always walk this back rather easily.

@knz
Copy link
Contributor Author

knz commented Aug 1, 2020

closing in favor of #52200

@knz knz closed this Aug 1, 2020
craig bot pushed a commit that referenced this pull request Aug 6, 2020
52200: util/log: improvements, simplifications and bug fixes r=irfansharif a=knz

Fixes #52026
Fixes #52176
Fixes #52128 
Fixes #51332 
Supersedes #51499, #51410 

For context, I was working on #51990, #51499 and #51410  when I stumbled upon bug #52128 in the logging package. I decided to clean up the code and fix that bug, and I ended up removing a lot of complexity and add many missing comments.

Example CI output:
![image](https://user-images.githubusercontent.com/642886/89288431-efaedc80-d655-11ea-97d9-b096b580d951.png)


By removing the complexity, I removed the problem otherwise solved by  #51499 & #51410 and  I removed the source of the flake causing #52026 and #52176.

Salient bits in this PR:

- **util/log: reinforce the behavior of log file rotation** - "This patch "does the right thing" by opening the new file before switching over whatever redirection may have been set up from the old file to the new one."
- **util/log: simplify TestLogScope+don't capture internal stderr writes** 
  - "This complexity was thus removed and the doc clarified that TestLogScope is only valid under the default configuration, when there was no file output configured yet and no secondary loggers active yet."
  - "However we also have other reasons to dislike the stderr redirect in tests, so I decided to remove it here instead of conjuring new code."
- **pgwire: un-skip TestauthenticationAndHBARules**


Co-authored-by: Raphael 'kena' Poss <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

util: improve log.Scope runtime output handling
3 participants