From 0372634076cdfd7cda740cd040e16e629ea662e4 Mon Sep 17 00:00:00 2001
From: Stan Hu <stanhu@gmail.com>
Date: Mon, 11 May 2020 22:02:58 -0700
Subject: Fix race conditions with logrus testing

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
---
 client/client_test.go                             |  6 ++++++
 internal/command/receivepack/gitalycall_test.go   |  1 +
 internal/command/uploadarchive/gitalycall_test.go |  2 ++
 internal/testhelper/testhelper.go                 | 16 ++++++++++++++++
 4 files changed, 25 insertions(+)

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
+}
-- 
cgit v1.2.1