fix(ci): fixed test race condition due to logging (#2852)

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 = "<first> "
+	e.SetLogOutput(true, "<first> ")
 
 	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 = "<second> "
+	e.SetLogOutput(true, "<second> ")
 
 	// 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, "<client2>")
 
 	defer e2.RunAndExpectSuccess(t, "repo", "disconnect")
 

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
 }