Fix race conditions with logrus testingsh-fix-logrus-race

logrus fires a Goroutine to write logs, so the tests could fail if they
checked the event queue before the logrus have fired.  Since there isn't
an easy way to flush all outstanding hooks, we just retry every 100 ms
for up to a second for log to arrive in the queue.

Closes https://gitlab.com/gitlab-org/gitlab-shell/-/issues/450

4 files changed, 25 insertions, 0 deletions

diff --git a/client/client_test.go b/client/client_test.go
index 5e852dc..5c5fda8 100644
--- a/client/client_test.go
+++ b/client/client_test.go
@@ -123,6 +123,7 @@ func testSuccessfulGet(t *testing.T, client *GitlabNetClient) {
 		assert.NoError(t, err)
 		assert.Equal(t, string(responseBody), "Hello")
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
@@ -147,6 +148,7 @@ func testSuccessfulPost(t *testing.T, client *GitlabNetClient) {
 		assert.NoError(t, err)
 		assert.Equal(t, "Echo: {\"key\":\"value\"}", string(responseBody))
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
@@ -163,6 +165,7 @@ func testMissing(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API error (404)")
 		assert.Nil(t, response)
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
@@ -177,6 +180,7 @@ func testMissing(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API error (404)")
 		assert.Nil(t, response)
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
@@ -208,6 +212,7 @@ func testBrokenRequest(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API unreachable")
 		assert.Nil(t, response)
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
@@ -223,6 +228,7 @@ func testBrokenRequest(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API unreachable")
 		assert.Nil(t, response)
 
+		require.True(t, testhelper.WaitForLogEvent(hook))
 		entries := hook.AllEntries()
 		assert.Equal(t, 1, len(entries))
 		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
diff --git a/internal/command/receivepack/gitalycall_test.go b/internal/command/receivepack/gitalycall_test.go
index fd062b2..0cfbf5c 100644
--- a/internal/command/receivepack/gitalycall_test.go
+++ b/internal/command/receivepack/gitalycall_test.go
@@ -43,6 +43,7 @@ func TestReceivePack(t *testing.T) {
 
 	require.Equal(t, "ReceivePack: "+userId+" "+repo, output.String())
 
+	require.True(t, testhelper.WaitForLogEvent(hook))
 	entries := hook.AllEntries()
 	require.Equal(t, 2, len(entries))
 	require.Equal(t, logrus.InfoLevel, entries[1].Level)
diff --git a/internal/command/uploadarchive/gitalycall_test.go b/internal/command/uploadarchive/gitalycall_test.go
index 8b60e11..488c390 100644
--- a/internal/command/uploadarchive/gitalycall_test.go
+++ b/internal/command/uploadarchive/gitalycall_test.go
@@ -42,6 +42,8 @@ func TestUploadPack(t *testing.T) {
 	require.NoError(t, err)
 
 	require.Equal(t, "UploadArchive: "+repo, output.String())
+
+	require.True(t, testhelper.WaitForLogEvent(hook))
 	entries := hook.AllEntries()
 	require.Equal(t, 2, len(entries))
 	require.Equal(t, logrus.InfoLevel, entries[1].Level)
diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go
index da781ce..5e98c1c 100644
--- a/internal/testhelper/testhelper.go
+++ b/internal/testhelper/testhelper.go
@@ -6,6 +6,7 @@ import (
 	"os"
 	"path"
 	"runtime"
+	"time"
 
 	"github.com/otiai10/copy"
 	"github.com/sirupsen/logrus"
@@ -100,3 +101,18 @@ func SetupLogger() *test.Hook {
 
 	return hook
 }
+
+// logrus fires a Goroutine to write the output log, but there's no way to
+// flush all outstanding hooks to fire. We just wait up to a second
+// for an event to appear.
+func WaitForLogEvent(hook *test.Hook) bool {
+	for i := 0; i < 10; i++ {
+		if entry := hook.LastEntry(); entry != nil {
+			return true
+		}
+
+		time.Sleep(100*time.Millisecond)
+	}
+
+	return false
+}