From 07972b56cf175c06df3eb0d8fe0eadf9ca19af46 Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Sun, 26 Mar 2023 17:05:12 -0700 Subject: [PATCH] fix(ci): fixed test race condition due to logging (#2852) --- .../api_server_repository_test.go | 9 ++-- tests/testenv/cli_test_env.go | 51 +++++++++++++------ 2 files changed, 39 insertions(+), 21 deletions(-) diff --git a/tests/end_to_end_test/api_server_repository_test.go b/tests/end_to_end_test/api_server_repository_test.go index 62d1ffaef..d4292387f 100644 --- a/tests/end_to_end_test/api_server_repository_test.go +++ b/tests/end_to_end_test/api_server_repository_test.go @@ -108,8 +108,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al var sp testutil.ServerParameters - e.LogOutput = true - e.LogOutputPrefix = " " + e.SetLogOutput(true, " ") t.Logf("******** first server startup ********") @@ -174,8 +173,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al defer rep.Close(ctx) - e.LogOutput = true - e.LogOutputPrefix = " " + e.SetLogOutput(true, " ") // start the server again, using the same address & TLS key+cert, so existing connection // should be re-established. @@ -219,8 +217,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al runner2 := testenv.NewInProcRunner(t) e2 := testenv.NewCLITest(t, testenv.RepoFormatNotImportant, runner2) - e2.LogOutput = true - e2.LogOutputPrefix = "client2 " + e2.SetLogOutput(true, "") defer e2.RunAndExpectSuccess(t, "repo", "disconnect") diff --git a/tests/testenv/cli_test_env.go b/tests/testenv/cli_test_env.go index 4dd721b62..fb435d568 100644 --- a/tests/testenv/cli_test_env.go +++ b/tests/testenv/cli_test_env.go @@ -42,13 +42,14 @@ type CLITest struct { Runner CLIRunner - LogOutput bool - LogOutputPrefix string - fixedArgs []string Environment map[string]string DefaultRepositoryCreateFlags []string + + logMu sync.RWMutex + logOutputEnabled bool + logOutputPrefix string } // RepoFormatNotImportant chooses arbitrary format version where it's not important to the test. @@ -143,6 +144,21 @@ func (e *CLITest) TweakFile(t *testing.T, dirn, fglob string) { require.NoError(t, err) } +func (e *CLITest) SetLogOutput(enable bool, prefix string) { + e.logMu.Lock() + defer e.logMu.Unlock() + + e.logOutputEnabled = enable + e.logOutputPrefix = prefix +} + +func (e *CLITest) getLogOutputPrefix() (string, bool) { + e.logMu.RLock() + defer e.logMu.RUnlock() + + return e.logOutputPrefix, os.Getenv("KOPIA_TEST_LOG_OUTPUT") != "" || e.logOutputEnabled +} + // RunAndProcessStderr runs the given command, and streams its output line-by-line to a given function until it returns false. func (e *CLITest) RunAndProcessStderr(t *testing.T, callback func(line string) bool, args ...string) (wait func() error, kill func()) { t.Helper() @@ -152,12 +168,14 @@ func (e *CLITest) RunAndProcessStderr(t *testing.T, callback func(line string) b go func() { scanner := bufio.NewScanner(stdout) for scanner.Scan() { - if os.Getenv("KOPIA_TEST_LOG_OUTPUT") != "" || e.LogOutput { - t.Logf("[%vstdout] %v", e.LogOutputPrefix, scanner.Text()) + if prefix, ok := e.getLogOutputPrefix(); ok { + t.Logf("[%vstdout] %v", prefix, scanner.Text()) } } - t.Logf("[%vstdout] EOF", e.LogOutputPrefix) + if prefix, ok := e.getLogOutputPrefix(); ok { + t.Logf("[%vstdout] EOF", prefix) + } }() scanner := bufio.NewScanner(stderr) @@ -170,12 +188,14 @@ func (e *CLITest) RunAndProcessStderr(t *testing.T, callback func(line string) b // complete the scan in background without processing lines. go func() { for scanner.Scan() { - if os.Getenv("KOPIA_TEST_LOG_OUTPUT") != "" || e.LogOutput { - t.Logf("[%vstderr] %v", e.LogOutputPrefix, scanner.Text()) + if prefix, ok := e.getLogOutputPrefix(); ok { + t.Logf("[%vstderr] %v", prefix, scanner.Text()) } } - t.Logf("[%vstderr] EOF", e.LogOutputPrefix) + if prefix, ok := e.getLogOutputPrefix(); ok { + t.Logf("[%vstderr] EOF", prefix) + } }() return wait, kill @@ -236,7 +256,8 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, t.Helper() args = e.cmdArgs(args) - t.Logf("%vrunning 'kopia %v' with %v", e.LogOutputPrefix, strings.Join(args, " "), e.Environment) + outputPrefix, logOutput := e.getLogOutputPrefix() + t.Logf("%vrunning 'kopia %v' with %v", outputPrefix, strings.Join(args, " "), e.Environment) timer := timetrack.StartTimer() @@ -251,8 +272,8 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, scanner := bufio.NewScanner(stdoutReader) for scanner.Scan() { - if os.Getenv("KOPIA_TEST_LOG_OUTPUT") != "" || e.LogOutput { - t.Logf("[%vstdout] %v", e.LogOutputPrefix, scanner.Text()) + if logOutput { + t.Logf("[%vstdout] %v", outputPrefix, scanner.Text()) } stdout = append(stdout, scanner.Text()) @@ -266,8 +287,8 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, scanner := bufio.NewScanner(stderrReader) for scanner.Scan() { - if os.Getenv("KOPIA_TEST_LOG_OUTPUT") != "" || e.LogOutput { - t.Logf("[%vstderr] %v", e.LogOutputPrefix, scanner.Text()) + if logOutput { + t.Logf("[%vstderr] %v", outputPrefix, scanner.Text()) } stderr = append(stderr, scanner.Text()) @@ -285,7 +306,7 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, } //nolint:forbidigo - t.Logf("%vfinished in %v: 'kopia %v'", e.LogOutputPrefix, timer.Elapsed().Milliseconds(), strings.Join(args, " ")) + t.Logf("%vfinished in %v: 'kopia %v'", outputPrefix, timer.Elapsed().Milliseconds(), strings.Join(args, " ")) return stdout, stderr, gotErr }