forked from cadence-workflow/cadence
-
Notifications
You must be signed in to change notification settings - Fork 0
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Suppress test failures due to logs after tests complete (cadence-work…
…flow#6067) "Fixes" test failures like this, by sweeping them under the rug: ``` 2024/05/28 21:39:29 ----- Done ----- 2024/05/28 21:39:29 Schema setup complete PASS coverage: 27.3% of statements in github.com/uber/cadence/client/..., github.com/uber/cadence/common/..., github.com/uber/cadence/host/..., github.com/uber/cadence/service/..., github.com/uber/cadence/tools/... panic: Log in goroutine after TestIntegrationSuite has completed: 2024-05-28T21:39:39.501Z DEBUG Selected default store shard for tasklist {"store-shard": "NonShardedStore", "wf-task-list-name": "9985f719-4b6a-4f0a-97c7-41a9e00d2414", "logging-call-at": "sharding_policy.go:100"} goroutine 72245 [running]: testing.(*common).logDepth(0xc0016ee680, {0xc00695ae00, 0xd5}, 0x3) /usr/local/go/src/testing/testing.go:1028 +0x6d4 testing.(*common).log(...) /usr/local/go/src/testing/testing.go:1010 testing.(*common).Logf(0xc0016ee680, {0x4a884b4, 0x2}, {0xc0021324b0, 0x1, 0x1}) /usr/local/go/src/testing/testing.go:1061 +0xa5 go.uber.org/zap/zaptest.testingWriter.Write({{0x662be10?, 0xc0016ee680?}, 0xa0?}, {0xc003ecf400, 0xd6, 0x400}) /go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:130 +0x11e go.uber.org/zap/zapcore.(*ioCore).Write(0xc0030ad920, {0xff, {0xc18db1a6dddeef12, 0xa3b5c069bd, 0x8268f40}, {0x0, 0x0}, {0x4af6670, 0x29}, {0x0, ...}, ...}, ...) ... ``` When the test completes, it will simply log to stderr rather than the test logger: ``` ❯ go test -count 1 -v ./... === RUN TestLoggerShouldNotFailIfLoggedLate --- PASS: TestLoggerShouldNotFailIfLoggedLate (0.00s) PASS 2024-05-29T16:20:50.742-0500 INFO COULD FAIL TEST "TestLoggerShouldNotFailIfLoggedLate", logged too late: too late, orig{"logging-call-at": "testlogger_test.go:41", "log_stack": "github.com/uber/cadence/common/log/testlogger.(*fallbackTestCore).Write\n\t/User... 2024-05-29T16:20:50.742-0500 INFO COULD FAIL TEST "TestLoggerShouldNotFailIfLoggedLate", logged too late: too late, with{"actor-id": "testing", "logging-call-at": "testlogger_test.go:42", "log_stack": "github.com/uber/cadence/common/log/testlogger.(*fallbackTestCore).Write\n\t/User... ok github.com/uber/cadence/common/log/testlogger 0.586s ``` Ignoring the correctness part of the problem, this gives us the best of both worlds: - most logs are grouped by the test that produced them - logs produced due to incomplete shutdowns are still produced (as long as `-v` or some other test fails), but will not directly fail the test(s) I am not overly fond of this, but some of our largest tests are quite flaky due to these logs, and that really isn't helping anything. Seems like a reasonable tradeoff, and we can move to an opt-in model eventually instead of applying it everywhere like this PR does.
- Loading branch information
Showing
6 changed files
with
234 additions
and
12 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,116 @@ | ||
| // The MIT License (MIT) | ||
|
|
||
| // Copyright (c) 2017-2020 Uber Technologies Inc. | ||
|
|
||
| // Permission is hereby granted, free of charge, to any person obtaining a copy | ||
| // of this software and associated documentation files (the "Software"), to deal | ||
| // in the Software without restriction, including without limitation the rights | ||
| // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | ||
| // copies of the Software, and to permit persons to whom the Software is | ||
| // furnished to do so, subject to the following conditions: | ||
| // | ||
| // The above copyright notice and this permission notice shall be included in all | ||
| // copies or substantial portions of the Software. | ||
| // | ||
| // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | ||
| // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | ||
| // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | ||
| // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | ||
| // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | ||
| // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | ||
| // SOFTWARE. | ||
|
|
||
| package testlogger | ||
|
|
||
| import ( | ||
| "fmt" | ||
| "os" | ||
| "testing" | ||
| "time" | ||
|
|
||
| "github.com/uber/cadence/common/log" | ||
| "github.com/uber/cadence/common/log/tag" | ||
| ) | ||
|
|
||
| var ( | ||
| done = make(chan struct{}) | ||
| logged = make(chan struct{}) | ||
| ) | ||
|
|
||
| func TestMain(m *testing.M) { | ||
| code := m.Run() | ||
| // ensure synchronization between t.done and t.logf, else this test is extremely flaky. | ||
| // for details see: https://github.com/golang/go/issues/67701 | ||
| close(done) | ||
| select { | ||
| case <-logged: | ||
| os.Exit(code) | ||
| case <-time.After(time.Second): // should be MUCH faster | ||
| _, _ = fmt.Fprintln(os.Stderr, "timed out waiting for test to log") | ||
| os.Exit(1) | ||
| } | ||
| } | ||
|
|
||
| // Unfortunately a moderate hack, to work around our faulty lifecycle management, | ||
| // and some libraries with issues as well. | ||
| // Ideally this test WOULD fail, but that's much harder to assert "safely". | ||
| func TestLoggerShouldNotFailIfLoggedLate(t *testing.T) { | ||
| origLogger := New(t) | ||
| // if With does not defer core selection, this will fail the test | ||
| // by sending the logs to t.Logf | ||
| withLogger := origLogger.WithTags(tag.ActorID("testing")) // literally any tag | ||
| origLogger.Info("before is fine, orig") | ||
| withLogger.Info("before is fine, with") | ||
| go func() { | ||
| <-done | ||
| origLogger.Info("too late, orig") | ||
| withLogger.Info("too late, with") | ||
| close(logged) | ||
| }() | ||
| } | ||
|
|
||
| func TestSubtestShouldNotFail(t *testing.T) { | ||
| // when complete, a subtest's too-late logs just get pushed to the parent, | ||
| // and do not fail any tests. they only fail when no running parent exists. | ||
| // | ||
| // if Go changes this behavior, this test could fail, otherwise AFAICT it | ||
| // should be stable. | ||
| assertDoesNotFail := func(name string, setup, log func(t *testing.T)) { | ||
| // need to wrap in something that will out-live the "real" test, | ||
| // to ensure there is a running parent test to push logs toward. | ||
| t.Run(name, func(t *testing.T) { | ||
| // same setup as TestMain but contained within this sub-test | ||
| var ( | ||
| done = make(chan struct{}) | ||
| logged = make(chan struct{}) | ||
| ) | ||
| t.Run("inner", func(t *testing.T) { | ||
| setup(t) | ||
| go func() { | ||
| <-done | ||
| // despite being too late, the parent test is still running | ||
| // so this does not fail the test. | ||
| log(t) | ||
| close(logged) | ||
| }() | ||
| time.AfterFunc(10*time.Millisecond, func() { | ||
| close(done) | ||
| }) | ||
| }) | ||
| <-logged | ||
| }) | ||
| } | ||
|
|
||
| assertDoesNotFail("real", func(t *testing.T) { | ||
| // no setup needed | ||
| }, func(t *testing.T) { | ||
| t.Logf("too late but allowed") | ||
| }) | ||
|
|
||
| var l log.Logger | ||
| assertDoesNotFail("wrapped", func(t *testing.T) { | ||
| l = New(t) | ||
| }, func(t *testing.T) { | ||
| l.Info("too late but allowed") | ||
| }) | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters