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: improve log.Scope runtime output handling #51409

Closed
tbg opened this issue Jul 14, 2020 · 5 comments
Closed

util: improve log.Scope runtime output handling #51409

tbg opened this issue Jul 14, 2020 · 5 comments
Assignees
@knz
Labels
A-logging In and around the logging infrastructure. A-testing Testing tools and infrastructure

Comments

@tbg
Copy link
Member

tbg commented Jul 14, 2020

Consider the following test which panics off the main goroutine (it also does other things, but just ignore that):

func TestFoo(t *testing.T) {
	defer leaktest.AfterTest(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)
}

The output is as follows:

$ go test -v -run Foo ./pkg/util/stop
=== 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

First of all I'm unsure whether "i'm on stdout" is supposed to be visible here. Why didn't it get redirected to the logs?

Secondly and more importantly, the panic got stashed into $TMPDIR/logTestFoo927366034/stoptest-stderr.log and does not have appropriate visibility (to unskilled investigators).

The Go test harness will not mark such tests as failed (rightly so, as multiple tests could have been running in parallel, so it can't blame any of them, though it would be desirable if in the absence of parallelism it did emit a FAIL line for the one running test which it does not).

Since the panic is off the main goroutine (as it often is in practice when we start test clusters, etc) the Scope can't use defer to handle it (in fact, the defer will never run in this case).

My best suggestion is to change log.Scope to keep os.Stderr untouched (or perhaps change it into a TeeWriter that goes to a log and actual stderr) and only redirect log output to the file.
s

However, even with this, since no test is marked as failed, the output is not readily available, though at least it will be in the build log. Adding to the complications, the build log is not very useful since we're using JSON output, which TeamCity makes hard to see. I would still suggest we try this approach to figure out the next step(s).
@tbg tbg added A-logging In and around the logging infrastructure. A-testing Testing tools and infrastructure labels Jul 14, 2020
@tbg tbg assigned knz Jul 14, 2020
@blathers-crl
Copy link

blathers-crl bot commented Jul 14, 2020

Hi @tbg, please add a C-ategory label to your issue. Check out the label system docs.

🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.

@knz knz mentioned this issue Jul 14, 2020
Closed
@knz knz mentioned this issue Jul 16, 2020
Closed
@knz
Copy link
Contributor

knz commented Jul 16, 2020 •
edited
Loading

This has been investigated in practice. We have two separate problems to solve and two separate approaches, with different trade-offs. Here is a summary.

  • problem 1: a test fails and the Go test runner sees it; in that case, we want stderr output and panic objects in the regular test output to facilitate investigation and auto-filing via the build log.

  • problem 2: a test process aborts and the Go test runner never knows(nor reports) what happened. In that case, we want some evidence left over and a clear path to investigation.

    Note: in problem 2, it is not sufficient to print the evidence in the regular test output. This is because there are some modes (e.g. stress) where the test output is accumulated in-RAM, so if the test process aborts the regular test output is lost.

Here are the two solutions that have been researched:

Solution #51410 #51499
Description Stderr output is not redirected during tests and goes to the test output. Stderr output is redirected to the artifact dir during test (this is consistent with server behavior) and the log.Scope pulls it out of artifacts at the end of a test if non-empty.
How it solves problem 1 Stderr bytes arrive in the test output directly. Stderr bytes arrive in the test output at the end. Additionally, stderr bytes are also preserved as file in artifacts.
How it solves problem 2 Stderr output is lost. There's no evidence left over. The evidence is always preserved as file in artifacts. Moreover, the log.Scope prints a message test logs captured to: /path/to/artifacts at the beginning of each test. If the test process fails, this message points to the directory too look for in artifacts.

In light of how #51410 fares poorly in problem 2, and how #51499 addresses both in a consistent manner, I recommend selecting the latter approach.

@tbg
Copy link
Member Author

tbg commented Jul 16, 2020

Note: in problem 2, it is not sufficient to print the evidence in the regular test output. This is because there are some modes (e.g. stress) where the test output is accumulated in-RAM, so if the test process aborts the regular test output is lost.

Already mentioned in DM, but I didn't see a reason why this should be true, and in a local experiment did not see this, so I wonder what's going on there. I'll take another look.

@tbg
Copy link
Member Author

tbg commented Jul 16, 2020 •
edited
Loading

Yeah I don't know, this seems to work just fine. With this test:

func TestFoo(t *testing.T) {
	go func() {
		panic("big boom!")
	}()
	time.Sleep(time.Second)
}

I get via

make stress PKG=./pkg/util/stop/ GOTESTFLAGS=-json STRESSFLAGS='-stderr -maxfails 1' 2>&1

the following

GOPATH set to /Users/tschottdorf/go
mkdir -p lib
rm -f lib/lib{geos,geos_c}.dylib
cp -L /Users/tschottdorf/go/native/x86_64-apple-darwin19.5.0/geos/lib/lib{geos,geos_c}.dylib lib
GOFLAGS= go test -json  -mod=vendor -exec 'stress -stderr -maxfails 1' -tags ' make x86_64_apple_darwin19.5.0' -ldflags '-X github.com/cockroachdb/cockroach/pkg/build.typ=development -extldflags "" -X "github.com/cockroachdb/cockroach/pkg/build.tag=v20.2.0-alpha.1-1258-g408e38fed9-dirty" -X "github.com/cockroachdb/cockroach/pkg/build.rev=408e38fed9612d0172307fd4495adb09914631dd" -X "github.com/cockroachdb/cockroach/pkg/build.cgoTargetTriple=x86_64-apple-darwin19.5.0"  ' -run "." -timeout 0 ./pkg/util/stop/  -v -args -test.timeout 30m
{"Time":"2020-07-16T12:57:46.364728+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Output":"\n"}
{"Time":"2020-07-16T12:57:46.365141+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopper"}
{"Time":"2020-07-16T12:57:46.365148+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopper","Output":"=== RUN   TestStopper\n"}
{"Time":"2020-07-16T12:57:46.365178+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopper","Output":"I200716 10:57:45.987076 38 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365195+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopper","Output":"--- PASS: TestStopper (0.10s)\n"}
{"Time":"2020-07-16T12:57:46.365214+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopper","Elapsed":0.1}
{"Time":"2020-07-16T12:57:46.365232+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperIsStopped"}
{"Time":"2020-07-16T12:57:46.365237+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperIsStopped","Output":"=== RUN   TestStopperIsStopped\n"}
{"Time":"2020-07-16T12:57:46.36525+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperIsStopped","Output":"I200716 10:57:46.089927 40 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365265+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperIsStopped","Output":"--- PASS: TestStopperIsStopped (0.11s)\n"}
{"Time":"2020-07-16T12:57:46.36527+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperIsStopped","Elapsed":0.11}
{"Time":"2020-07-16T12:57:46.365276+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperMultipleStopees"}
{"Time":"2020-07-16T12:57:46.36528+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperMultipleStopees","Output":"=== RUN   TestStopperMultipleStopees\n"}
{"Time":"2020-07-16T12:57:46.365285+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperMultipleStopees","Output":"I200716 10:57:46.195591 68 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365296+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperMultipleStopees","Output":"--- PASS: TestStopperMultipleStopees (0.01s)\n"}
{"Time":"2020-07-16T12:57:46.365302+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperMultipleStopees","Elapsed":0.01}
{"Time":"2020-07-16T12:57:46.365306+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperStartFinishTasks"}
{"Time":"2020-07-16T12:57:46.36531+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperStartFinishTasks","Output":"=== RUN   TestStopperStartFinishTasks\n"}
{"Time":"2020-07-16T12:57:46.365317+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperStartFinishTasks","Output":"I200716 10:57:46.200224 21 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365323+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperStartFinishTasks","Output":"--- PASS: TestStopperStartFinishTasks (0.11s)\n"}
{"Time":"2020-07-16T12:57:46.365328+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperStartFinishTasks","Elapsed":0.11}
{"Time":"2020-07-16T12:57:46.365332+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunWorker"}
{"Time":"2020-07-16T12:57:46.365349+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunWorker","Output":"=== RUN   TestStopperRunWorker\n"}
{"Time":"2020-07-16T12:57:46.365363+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunWorker","Output":"I200716 10:57:46.310598 43 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365371+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunWorker","Output":"--- PASS: TestStopperRunWorker (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365381+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunWorker","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365392+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce"}
{"Time":"2020-07-16T12:57:46.365396+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Output":"=== RUN   TestStopperQuiesce\n"}
{"Time":"2020-07-16T12:57:46.365401+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Output":"I200716 10:57:46.314139 86 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365416+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Output":"I200716 10:57:46.314181 86 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.36542+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Output":"I200716 10:57:46.314187 86 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365425+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Output":"--- PASS: TestStopperQuiesce (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365428+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperQuiesce","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365432+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperClosers"}
{"Time":"2020-07-16T12:57:46.365436+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperClosers","Output":"=== RUN   TestStopperClosers\n"}
{"Time":"2020-07-16T12:57:46.365447+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperClosers","Output":"I200716 10:57:46.317933 98 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365452+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperClosers","Output":"--- PASS: TestStopperClosers (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365457+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperClosers","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365462+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent"}
{"Time":"2020-07-16T12:57:46.365468+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"=== RUN   TestStopperCloserConcurrent\n"}
{"Time":"2020-07-16T12:57:46.365478+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321502 71 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365482+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321572 73 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365484+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321586 75 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365488+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321598 77 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365505+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321619 79 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365517+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321634 81 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365523+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321646 115 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365529+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321658 117 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365533+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321669 119 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365538+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"I200716 10:57:46.321680 121 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365545+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Output":"--- PASS: TestStopperCloserConcurrent (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365551+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperCloserConcurrent","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365557+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperNumTasks"}
{"Time":"2020-07-16T12:57:46.365561+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperNumTasks","Output":"=== RUN   TestStopperNumTasks\n"}
{"Time":"2020-07-16T12:57:46.365579+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperNumTasks","Output":"I200716 10:57:46.325782 44 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365591+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperNumTasks","Output":"--- PASS: TestStopperNumTasks (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365597+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperNumTasks","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365602+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunTaskPanic"}
{"Time":"2020-07-16T12:57:46.365607+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunTaskPanic","Output":"=== RUN   TestStopperRunTaskPanic\n"}
{"Time":"2020-07-16T12:57:46.365615+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunTaskPanic","Output":"--- PASS: TestStopperRunTaskPanic (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365621+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunTaskPanic","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365625+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancel"}
{"Time":"2020-07-16T12:57:46.365634+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancel","Output":"=== RUN   TestStopperWithCancel\n"}
{"Time":"2020-07-16T12:57:46.36564+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancel","Output":"I200716 10:57:46.333707 48 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365652+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancel","Output":"--- PASS: TestStopperWithCancel (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365658+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancel","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365663+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent"}
{"Time":"2020-07-16T12:57:46.365669+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"=== RUN   TestStopperWithCancelConcurrent\n"}
{"Time":"2020-07-16T12:57:46.365674+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338427 133 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365679+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338499 136 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365684+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338528 139 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365689+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338550 142 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365694+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338564 145 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365699+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338578 148 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365704+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338590 151 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365709+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338624 24 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365713+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338681 27 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365726+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"I200716 10:57:46.338693 30 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365736+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Output":"--- PASS: TestStopperWithCancelConcurrent (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365742+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperWithCancelConcurrent","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365747+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperShouldQuiesce"}
{"Time":"2020-07-16T12:57:46.365753+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperShouldQuiesce","Output":"=== RUN   TestStopperShouldQuiesce\n"}
{"Time":"2020-07-16T12:57:46.365758+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperShouldQuiesce","Output":"I200716 10:57:46.342154 164 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365769+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperShouldQuiesce","Output":"--- PASS: TestStopperShouldQuiesce (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365776+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperShouldQuiesce","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365781+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTask"}
{"Time":"2020-07-16T12:57:46.365785+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTask","Output":"=== RUN   TestStopperRunLimitedAsyncTask\n"}
{"Time":"2020-07-16T12:57:46.365789+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTask","Output":"I200716 10:57:46.347767 51 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365793+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTask","Output":"--- PASS: TestStopperRunLimitedAsyncTask (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365797+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTask","Elapsed":0}
{"Time":"2020-07-16T12:57:46.365802+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCloser"}
{"Time":"2020-07-16T12:57:46.365806+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCloser","Output":"=== RUN   TestStopperRunLimitedAsyncTaskCloser\n"}
{"Time":"2020-07-16T12:57:46.36581+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCloser","Output":"I200716 10:57:46.351933 179 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365817+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCloser","Output":"--- PASS: TestStopperRunLimitedAsyncTaskCloser (0.01s)\n"}
{"Time":"2020-07-16T12:57:46.365822+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCloser","Elapsed":0.01}
{"Time":"2020-07-16T12:57:46.365827+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCancelContext"}
{"Time":"2020-07-16T12:57:46.365831+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCancelContext","Output":"=== RUN   TestStopperRunLimitedAsyncTaskCancelContext\n"}
{"Time":"2020-07-16T12:57:46.365844+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCancelContext","Output":"I200716 10:57:46.356783 31 util/stop/stopper.go:539  quiescing\n"}
{"Time":"2020-07-16T12:57:46.365849+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCancelContext","Output":"--- PASS: TestStopperRunLimitedAsyncTaskCancelContext (0.00s)\n"}
{"Time":"2020-07-16T12:57:46.365856+02:00","Action":"pass","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestStopperRunLimitedAsyncTaskCancelContext","Elapsed":0}
{"Time":"2020-07-16T12:57:46.36586+02:00","Action":"run","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo"}
{"Time":"2020-07-16T12:57:46.365864+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2020-07-16T12:57:46.365868+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"panic: big boom!\n"}
{"Time":"2020-07-16T12:57:46.365886+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.365895+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 199 [running]:\n"}
{"Time":"2020-07-16T12:57:46.365906+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"github.com/cockroachdb/cockroach/pkg/util/stop_test.TestFoo.func1()\n"}
{"Time":"2020-07-16T12:57:46.365911+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper_test.go:740 +0x39\n"}
{"Time":"2020-07-16T12:57:46.365915+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"created by github.com/cockroachdb/cockroach/pkg/util/stop_test.TestFoo\n"}
{"Time":"2020-07-16T12:57:46.365922+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper_test.go:739 +0x35\n"}
{"Time":"2020-07-16T12:57:46.365927+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.365931+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 1 [chan receive]:\n"}
{"Time":"2020-07-16T12:57:46.365937+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.(*T).Run(0xc0000cc5a0, 0x4cff19f, 0x7, 0x4d4d420, 0x408e301)\n"}
{"Time":"2020-07-16T12:57:46.365941+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:1043 +0x37e\n"}
{"Time":"2020-07-16T12:57:46.365946+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.runTests.func1(0xc0000cc900)\n"}
{"Time":"2020-07-16T12:57:46.365951+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:1284 +0x78\n"}
{"Time":"2020-07-16T12:57:46.365957+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.tRunner(0xc0000cc900, 0xc00054fe10)\n"}
{"Time":"2020-07-16T12:57:46.365961+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:991 +0xdc\n"}
{"Time":"2020-07-16T12:57:46.365968+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.runTests(0xc0005987c0, 0x565f000, 0x11, 0x11, 0x0)\n"}
{"Time":"2020-07-16T12:57:46.365972+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:1282 +0x2a7\n"}
{"Time":"2020-07-16T12:57:46.365977+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.(*M).Run(0xc0005d2300, 0x0)\n"}
{"Time":"2020-07-16T12:57:46.365981+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:1199 +0x15f\n"}
{"Time":"2020-07-16T12:57:46.365985+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"main.main()\n"}
{"Time":"2020-07-16T12:57:46.365988+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t_testmain.go:86 +0x135\n"}
{"Time":"2020-07-16T12:57:46.365992+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 6 [chan receive]:\n"}
{"Time":"2020-07-16T12:57:46.366006+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"github.com/cockroachdb/cockroach/pkg/util/log.flushDaemon()\n"}
{"Time":"2020-07-16T12:57:46.36601+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:72 +0x73\n"}
{"Time":"2020-07-16T12:57:46.366014+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"created by github.com/cockroachdb/cockroach/pkg/util/log.init.7\n"}
{"Time":"2020-07-16T12:57:46.366019+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:44 +0x35\n"}
{"Time":"2020-07-16T12:57:46.366024+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366027+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 7 [chan receive]:\n"}
{"Time":"2020-07-16T12:57:46.366032+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"github.com/cockroachdb/cockroach/pkg/util/log.signalFlusher()\n"}
{"Time":"2020-07-16T12:57:46.366043+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:99 +0x124\n"}
{"Time":"2020-07-16T12:57:46.366049+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"created by github.com/cockroachdb/cockroach/pkg/util/log.init.7\n"}
{"Time":"2020-07-16T12:57:46.366054+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:45 +0x4d\n"}
{"Time":"2020-07-16T12:57:46.366058+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366076+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 18 [syscall]:\n"}
{"Time":"2020-07-16T12:57:46.366081+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"os/signal.signal_recv(0x0)\n"}
{"Time":"2020-07-16T12:57:46.366085+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/runtime/sigqueue.go:144 +0x96\n"}
{"Time":"2020-07-16T12:57:46.36609+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"os/signal.loop()\n"}
{"Time":"2020-07-16T12:57:46.366094+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/os/signal/signal_unix.go:23 +0x22\n"}
{"Time":"2020-07-16T12:57:46.366099+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"created by os/signal.Notify.func1\n"}
{"Time":"2020-07-16T12:57:46.366104+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/os/signal/signal.go:127 +0x44\n"}
{"Time":"2020-07-16T12:57:46.366108+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366112+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"goroutine 198 [sleep]:\n"}
{"Time":"2020-07-16T12:57:46.366117+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"time.Sleep(0x3b9aca00)\n"}
{"Time":"2020-07-16T12:57:46.366121+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/runtime/time.go:188 +0xba\n"}
{"Time":"2020-07-16T12:57:46.366126+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"github.com/cockroachdb/cockroach/pkg/util/stop_test.TestFoo(0xc0000cc5a0)\n"}
{"Time":"2020-07-16T12:57:46.366131+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/Users/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper_test.go:742 +0x42\n"}
{"Time":"2020-07-16T12:57:46.366136+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"testing.tRunner(0xc0000cc5a0, 0x4d4d420)\n"}
{"Time":"2020-07-16T12:57:46.36614+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:991 +0xdc\n"}
{"Time":"2020-07-16T12:57:46.366144+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"created by testing.(*T).Run\n"}
{"Time":"2020-07-16T12:57:46.366149+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\t/usr/local/Cellar/go/1.14.3/libexec/src/testing/testing.go:1042 +0x357\n"}
{"Time":"2020-07-16T12:57:46.366154+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366162+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366168+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"ERROR: exit status 2\n"}
{"Time":"2020-07-16T12:57:46.366172+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"\n"}
{"Time":"2020-07-16T12:57:46.366177+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"1 runs completed, 1 failures, over 2s\n"}
{"Time":"2020-07-16T12:57:46.369811+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Test":"TestFoo","Output":"context canceled\n"}
{"Time":"2020-07-16T12:57:46.369836+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Output":"FAIL\n"}
{"Time":"2020-07-16T12:57:46.370392+02:00","Action":"output","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Output":"FAIL\tgithub.com/cockroachdb/cockroach/pkg/util/stop\t2.277s\n"}
{"Time":"2020-07-16T12:57:46.370411+02:00","Action":"fail","Package":"github.com/cockroachdb/cockroach/pkg/util/stop","Elapsed":2.277}
make: *** [stress] Error 1

@knz
Copy link
Contributor

knz commented Aug 31, 2020

fixed by #52200

@knz knz closed this as completed Aug 31, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@knz knz

Labels
A-logging In and around the logging infrastructure. A-testing Testing tools and infrastructure
Projects
None yet
Milestone
No milestone
2 participants
@knz @tbg