Remove some unreliable tests

Logrus buffers its output internally, which makes these tests fail
intermittently. They're also not a good example to follow generally.

We now have acceptance tests that exercise this functionality so I'm
pretty relaxed about losing the expectations. However, we can test
them by inspecting the server-received metadata too, so there's no loss
of coverage here.

The move from logrus to labkit for logging also makes these tests hard
to justify keeping.

5 files changed, 77 insertions, 136 deletions

diff --git a/client/client_test.go b/client/client_test.go
index 8c5599e..bf45181 100644
--- a/client/client_test.go
+++ b/client/client_test.go
@@ -11,8 +11,8 @@ import (
 	"strings"
 	"testing"
 
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
+
 	"gitlab.com/gitlab-org/gitlab-shell/client/testserver"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
 )
@@ -76,7 +76,6 @@ func TestClients(t *testing.T) {
 
 func testSuccessfulGet(t *testing.T, client *GitlabNetClient) {
 	t.Run("Successful get", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
 		response, err := client.Get(context.Background(), "/hello")
 		require.NoError(t, err)
 		require.NotNil(t, response)
@@ -86,22 +85,11 @@ func testSuccessfulGet(t *testing.T, client *GitlabNetClient) {
 		responseBody, err := ioutil.ReadAll(response.Body)
 		require.NoError(t, err)
 		require.Equal(t, string(responseBody), "Hello")
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=GET")
-		require.Contains(t, entries[0].Message, "status=200")
-		require.Contains(t, entries[0].Message, "content_length_bytes=")
-		require.Contains(t, entries[0].Message, "Finished HTTP request")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 }
 
 func testSuccessfulPost(t *testing.T, client *GitlabNetClient) {
 	t.Run("Successful Post", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
 		data := map[string]string{"key": "value"}
 
 		response, err := client.Post(context.Background(), "/post_endpoint", data)
@@ -113,50 +101,20 @@ func testSuccessfulPost(t *testing.T, client *GitlabNetClient) {
 		responseBody, err := ioutil.ReadAll(response.Body)
 		require.NoError(t, err)
 		require.Equal(t, "Echo: {\"key\":\"value\"}", string(responseBody))
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=POST")
-		require.Contains(t, entries[0].Message, "status=200")
-		require.Contains(t, entries[0].Message, "content_length_bytes=")
-		require.Contains(t, entries[0].Message, "Finished HTTP request")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 }
 
 func testMissing(t *testing.T, client *GitlabNetClient) {
 	t.Run("Missing error for GET", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
 		response, err := client.Get(context.Background(), "/missing")
 		require.EqualError(t, err, "Internal API error (404)")
 		require.Nil(t, response)
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=GET")
-		require.Contains(t, entries[0].Message, "status=404")
-		require.Contains(t, entries[0].Message, "Internal API error")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 
 	t.Run("Missing error for POST", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
 		response, err := client.Post(context.Background(), "/missing", map[string]string{})
 		require.EqualError(t, err, "Internal API error (404)")
 		require.Nil(t, response)
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=POST")
-		require.Contains(t, entries[0].Message, "status=404")
-		require.Contains(t, entries[0].Message, "Internal API error")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 }
 
@@ -176,37 +134,15 @@ func testErrorMessage(t *testing.T, client *GitlabNetClient) {
 
 func testBrokenRequest(t *testing.T, client *GitlabNetClient) {
 	t.Run("Broken request for GET", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
-
 		response, err := client.Get(context.Background(), "/broken")
 		require.EqualError(t, err, "Internal API unreachable")
 		require.Nil(t, response)
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=GET")
-		require.NotContains(t, entries[0].Message, "status=")
-		require.Contains(t, entries[0].Message, "Internal API unreachable")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 
 	t.Run("Broken request for POST", func(t *testing.T) {
-		hook := testhelper.SetupLogger()
-
 		response, err := client.Post(context.Background(), "/broken", map[string]string{})
 		require.EqualError(t, err, "Internal API unreachable")
 		require.Nil(t, response)
-
-		require.True(t, testhelper.WaitForLogEvent(hook))
-		entries := hook.AllEntries()
-		require.Equal(t, 1, len(entries))
-		require.Equal(t, logrus.InfoLevel, entries[0].Level)
-		require.Contains(t, entries[0].Message, "method=POST")
-		require.NotContains(t, entries[0].Message, "status=")
-		require.Contains(t, entries[0].Message, "Internal API unreachable")
-		require.Contains(t, entries[0].Message, "correlation_id=")
 	})
 }
 
diff --git a/internal/command/receivepack/gitalycall_test.go b/internal/command/receivepack/gitalycall_test.go
index 12c603d..4665366 100644
--- a/internal/command/receivepack/gitalycall_test.go
+++ b/internal/command/receivepack/gitalycall_test.go
@@ -5,7 +5,6 @@ import (
 	"context"
 	"testing"
 
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/labkit/correlation"
 
@@ -14,12 +13,11 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/sshenv"
-	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
 func TestReceivePack(t *testing.T) {
-	gitalyAddress, _ := testserver.StartGitalyServer(t)
+	gitalyAddress, testServer := testserver.StartGitalyServer(t)
 
 	requests := requesthandlers.BuildAllowedWithGitalyHandlers(t, gitalyAddress)
 	url := testserver.StartHttpServer(t, requests)
@@ -43,10 +41,15 @@ func TestReceivePack(t *testing.T) {
 
 		env := sshenv.Env{
 			IsSSHConnection: true,
-			OriginalCommand: "git-receive-pack group/repo",
+			OriginalCommand: "git-receive-pack " + repo,
 			RemoteAddr:      "127.0.0.1",
 		}
-		args := &commandargs.Shell{CommandType: commandargs.ReceivePack, SshArgs: []string{"git-receive-pack", repo}, Env: env}
+
+		args := &commandargs.Shell{
+			CommandType: commandargs.ReceivePack,
+			SshArgs:     []string{"git-receive-pack", repo},
+			Env:         env,
+		}
 
 		if tc.username != "" {
 			args.GitlabUsername = tc.username
@@ -60,7 +63,6 @@ func TestReceivePack(t *testing.T) {
 			ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 		}
 
-		hook := testhelper.SetupLogger()
 		ctx := correlation.ContextWithCorrelation(context.Background(), "a-correlation-id")
 		ctx = correlation.ContextWithClientName(ctx, "gitlab-shell-tests")
 
@@ -73,15 +75,20 @@ func TestReceivePack(t *testing.T) {
 			require.Equal(t, "ReceivePack: key-123 "+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)
-		require.Contains(t, entries[1].Message, "executing git command")
-		require.Contains(t, entries[1].Message, "command=git-receive-pack")
-		require.Contains(t, entries[1].Message, "remote_ip=127.0.0.1")
-		require.Contains(t, entries[1].Message, "gl_key_type=key")
-		require.Contains(t, entries[1].Message, "gl_key_id=123")
-		require.Contains(t, entries[1].Message, "correlation_id=a-correlation-id")
+		for k, v := range map[string]string{
+			"gitaly-feature-cache_invalidator":        "true",
+			"gitaly-feature-inforef_uploadpack_cache": "false",
+			"x-gitlab-client-name":                    "gitlab-shell-tests-git-receive-pack",
+			"key_id":                                  "123",
+			"user_id":                                 "1",
+			"remote_ip":                               "127.0.0.1",
+			"key_type":                                "key",
+		} {
+			actual := testServer.ReceivedMD[k]
+			require.Len(t, actual, 1)
+			require.Equal(t, v, actual[0])
+		}
+		require.Empty(t, testServer.ReceivedMD["some-other-ff"])
+		require.Equal(t, testServer.ReceivedMD["x-gitlab-correlation-id"][0], "a-correlation-id")
 	}
 }
diff --git a/internal/command/uploadarchive/gitalycall_test.go b/internal/command/uploadarchive/gitalycall_test.go
index 3ec1449..302b949 100644
--- a/internal/command/uploadarchive/gitalycall_test.go
+++ b/internal/command/uploadarchive/gitalycall_test.go
@@ -5,7 +5,6 @@ import (
 	"context"
 	"testing"
 
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/labkit/correlation"
 
@@ -13,12 +12,12 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
-	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/sshenv"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
-func TestUploadPack(t *testing.T) {
-	gitalyAddress, _ := testserver.StartGitalyServer(t)
+func TestUploadArchive(t *testing.T) {
+	gitalyAddress, testServer := testserver.StartGitalyServer(t)
 
 	requests := requesthandlers.BuildAllowedWithGitalyHandlers(t, gitalyAddress)
 	url := testserver.StartHttpServer(t, requests)
@@ -29,13 +28,25 @@ func TestUploadPack(t *testing.T) {
 	userId := "1"
 	repo := "group/repo"
 
+	env := sshenv.Env{
+		IsSSHConnection: true,
+		OriginalCommand: "git-upload-archive " + repo,
+		RemoteAddr:      "127.0.0.1",
+	}
+
+	args := &commandargs.Shell{
+		GitlabKeyId: userId,
+		CommandType: commandargs.UploadArchive,
+		SshArgs:     []string{"git-upload-archive", repo},
+		Env:         env,
+	}
+
 	cmd := &Command{
 		Config:     &config.Config{GitlabUrl: url},
-		Args:       &commandargs.Shell{GitlabKeyId: userId, CommandType: commandargs.UploadArchive, SshArgs: []string{"git-upload-archive", repo}},
+		Args:       args,
 		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
-	hook := testhelper.SetupLogger()
 	ctx := correlation.ContextWithCorrelation(context.Background(), "a-correlation-id")
 	ctx = correlation.ContextWithClientName(ctx, "gitlab-shell-tests")
 
@@ -44,13 +55,19 @@ func TestUploadPack(t *testing.T) {
 
 	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)
-	require.Contains(t, entries[1].Message, "executing git command")
-	require.Contains(t, entries[1].Message, "command=git-upload-archive")
-	require.Contains(t, entries[1].Message, "gl_key_type=key")
-	require.Contains(t, entries[1].Message, "gl_key_id=123")
-	require.Contains(t, entries[1].Message, "correlation_id=a-correlation-id")
+	for k, v := range map[string]string{
+		"gitaly-feature-cache_invalidator":        "true",
+		"gitaly-feature-inforef_uploadpack_cache": "false",
+		"x-gitlab-client-name":                    "gitlab-shell-tests-git-upload-archive",
+		"key_id":                                  "123",
+		"user_id":                                 "1",
+		"remote_ip":                               "127.0.0.1",
+		"key_type":                                "key",
+	} {
+		actual := testServer.ReceivedMD[k]
+		require.Len(t, actual, 1)
+		require.Equal(t, v, actual[0])
+	}
+	require.Empty(t, testServer.ReceivedMD["some-other-ff"])
+	require.Equal(t, testServer.ReceivedMD["x-gitlab-correlation-id"][0], "a-correlation-id")
 }
diff --git a/internal/command/uploadpack/gitalycall_test.go b/internal/command/uploadpack/gitalycall_test.go
index 6b4c6ba..926d2c9 100644
--- a/internal/command/uploadpack/gitalycall_test.go
+++ b/internal/command/uploadpack/gitalycall_test.go
@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"context"
 	"testing"
-	"time"
 
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/labkit/correlation"
@@ -13,7 +12,7 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
-	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/sshenv"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
@@ -29,13 +28,25 @@ func TestUploadPack(t *testing.T) {
 	userId := "1"
 	repo := "group/repo"
 
+	env := sshenv.Env{
+		IsSSHConnection: true,
+		OriginalCommand: "git-upload-pack " + repo,
+		RemoteAddr:      "127.0.0.1",
+	}
+
+	args := &commandargs.Shell{
+		GitlabKeyId: userId,
+		CommandType: commandargs.UploadPack,
+		SshArgs:     []string{"git-upload-pack", repo},
+		Env:         env,
+	}
+
 	cmd := &Command{
 		Config:     &config.Config{GitlabUrl: url},
-		Args:       &commandargs.Shell{GitlabKeyId: userId, CommandType: commandargs.UploadPack, SshArgs: []string{"git-upload-pack", repo}},
+		Args:       args,
 		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
-	hook := testhelper.SetupLogger()
 	ctx := correlation.ContextWithCorrelation(context.Background(), "a-correlation-id")
 	ctx = correlation.ContextWithClientName(ctx, "gitlab-shell-tests")
 
@@ -43,25 +54,20 @@ func TestUploadPack(t *testing.T) {
 	require.NoError(t, err)
 
 	require.Equal(t, "UploadPack: "+repo, output.String())
-	require.Eventually(t, func() bool {
-		entries := hook.AllEntries()
-
-		require.Equal(t, 2, len(entries))
-		require.Contains(t, entries[1].Message, "executing git command")
-		require.Contains(t, entries[1].Message, "command=git-upload-pack")
-		require.Contains(t, entries[1].Message, "gl_key_type=key")
-		require.Contains(t, entries[1].Message, "gl_key_id=123")
-		require.Contains(t, entries[1].Message, "correlation_id=a-correlation-id")
-		return true
-	}, time.Second, time.Millisecond)
 
 	for k, v := range map[string]string{
 		"gitaly-feature-cache_invalidator":        "true",
 		"gitaly-feature-inforef_uploadpack_cache": "false",
+		"x-gitlab-client-name":                    "gitlab-shell-tests-git-upload-pack",
+		"key_id":                                  "123",
+		"user_id":                                 "1",
+		"remote_ip":                               "127.0.0.1",
+		"key_type":                                "key",
 	} {
 		actual := testServer.ReceivedMD[k]
 		require.Len(t, actual, 1)
 		require.Equal(t, v, actual[0])
 	}
 	require.Empty(t, testServer.ReceivedMD["some-other-ff"])
+	require.Equal(t, testServer.ReceivedMD["x-gitlab-correlation-id"][0], "a-correlation-id")
 }
diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go
index 933da00..65fb975 100644
--- a/internal/testhelper/testhelper.go
+++ b/internal/testhelper/testhelper.go
@@ -7,11 +7,8 @@ import (
 	"path"
 	"runtime"
 	"testing"
-	"time"
 
 	"github.com/otiai10/copy"
-	"github.com/sirupsen/logrus"
-	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/require"
 )
 
@@ -75,25 +72,3 @@ func Setenv(key, value string) (func(), error) {
 	err := os.Setenv(key, value)
 	return func() { os.Setenv(key, oldValue) }, err
 }
-
-func SetupLogger() *test.Hook {
-	logger, hook := test.NewNullLogger()
-	logrus.SetOutput(logger.Writer())
-
-	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
-}