Merge branch 'sh-add-http-status-code' into 'master'

Add HTTP status code to internal API logs

Closes #450

See merge request gitlab-org/gitlab-shell!376

client/client_test.go

@@ -7,7 +7,6 @@ import (
 	"io/ioutil"
 	"net/http"
 	"path"
-	"strings"
 	"testing"
 
 	"github.com/sirupsen/logrus"
@@ -124,10 +123,12 @@ func testSuccessfulGet(t *testing.T, client *GitlabNetClient) {
 		assert.NoError(t, err)
 		assert.Equal(t, string(responseBody), "Hello")
 
-		assert.Equal(t, 1, len(hook.Entries))
-		assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "method=GET"))
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "Finished HTTP request"))
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=GET")
+		assert.Contains(t, entries[0].Message, "status=200")
+		assert.Contains(t, entries[0].Message, "Finished HTTP request")
 	})
 }
 
@@ -146,10 +147,12 @@ func testSuccessfulPost(t *testing.T, client *GitlabNetClient) {
 		assert.NoError(t, err)
 		assert.Equal(t, "Echo: {\"key\":\"value\"}", string(responseBody))
 
-		assert.Equal(t, 1, len(hook.Entries))
-		assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "method=POST"))
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "Finished HTTP request"))
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=POST")
+		assert.Contains(t, entries[0].Message, "status=200")
+		assert.Contains(t, entries[0].Message, "Finished HTTP request")
 	})
 }
 
@@ -160,10 +163,12 @@ func testMissing(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API error (404)")
 		assert.Nil(t, response)
 
-		assert.Equal(t, 1, len(hook.Entries))
-		assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "method=GET"))
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "Internal API error"))
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=GET")
+		assert.Contains(t, entries[0].Message, "status=404")
+		assert.Contains(t, entries[0].Message, "Internal API error")
 	})
 
 	t.Run("Missing error for POST", func(t *testing.T) {
@@ -172,10 +177,12 @@ func testMissing(t *testing.T, client *GitlabNetClient) {
 		assert.EqualError(t, err, "Internal API error (404)")
 		assert.Nil(t, response)
 
-		assert.Equal(t, 1, len(hook.Entries))
-		assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "method=POST"))
-		assert.True(t, strings.Contains(hook.LastEntry().Message, "Internal API error"))
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=POST")
+		assert.Contains(t, entries[0].Message, "status=404")
+		assert.Contains(t, entries[0].Message, "Internal API error")
 	})
 }
 
@@ -195,15 +202,33 @@ 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("/broken")
 		assert.EqualError(t, err, "Internal API unreachable")
 		assert.Nil(t, response)
+
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=GET")
+		assert.NotContains(t, entries[0].Message, "status=")
+		assert.Contains(t, entries[0].Message, "Internal API unreachable")
 	})
 
 	t.Run("Broken request for POST", func(t *testing.T) {
+		hook := testhelper.SetupLogger()
+
 		response, err := client.Post("/broken", map[string]string{})
 		assert.EqualError(t, err, "Internal API unreachable")
 		assert.Nil(t, response)
+
+		entries := hook.AllEntries()
+		assert.Equal(t, 1, len(entries))
+		assert.Equal(t, logrus.InfoLevel, entries[0].Level)
+		assert.Contains(t, entries[0].Message, "method=POST")
+		assert.NotContains(t, entries[0].Message, "status=")
+		assert.Contains(t, entries[0].Message, "Internal API unreachable")
 	})
 }
 

client/gitlabnet.go

@@ -123,18 +123,22 @@ func (c *GitlabNetClient) DoRequest(method, path string, data interface{}) (*htt
 		"url":         request.URL.String(),
 		"duration_ms": time.Since(start) / time.Millisecond,
 	}
+	logger := log.WithFields(fields)
 
 	if err != nil {
-		log.WithError(err).WithFields(fields).Error("Internal API unreachable")
+		logger.WithError(err).Error("Internal API unreachable")
 		return nil, fmt.Errorf("Internal API unreachable")
 	}
 
+	if response != nil {
+		logger = logger.WithField("status", response.StatusCode)
+	}
 	if err := parseError(response); err != nil {
-		log.WithError(err).WithFields(fields).Error("Internal API error")
+		logger.WithError(err).Error("Internal API error")
 		return nil, err
 	}
 
-	log.WithFields(fields).Info("Finished HTTP request")
+	logger.Info("Finished HTTP request")
 
 	return response, nil
 }

internal/command/receivepack/gitalycall_test.go

@@ -2,7 +2,6 @@ package receivepack
 
 import (
 	"bytes"
-	"strings"
 	"testing"
 
 	"github.com/sirupsen/logrus"
@@ -43,7 +42,10 @@ func TestReceivePack(t *testing.T) {
 	require.NoError(t, err)
 
 	require.Equal(t, "ReceivePack: "+userId+" "+repo, output.String())
-	require.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-	require.True(t, strings.Contains(hook.LastEntry().Message, "executing git command"))
-	require.True(t, strings.Contains(hook.LastEntry().Message, "command=git-receive-pack"))
+
+	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")
 }

internal/command/uploadarchive/gitalycall_test.go

@@ -2,7 +2,6 @@ package uploadarchive
 
 import (
 	"bytes"
-	"strings"
 	"testing"
 
 	"github.com/sirupsen/logrus"
@@ -43,7 +42,9 @@ func TestUploadPack(t *testing.T) {
 	require.NoError(t, err)
 
 	require.Equal(t, "UploadArchive: "+repo, output.String())
-	require.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-	require.True(t, strings.Contains(hook.LastEntry().Message, "executing git command"))
-	require.True(t, strings.Contains(hook.LastEntry().Message, "command=git-upload-archive"))
+	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")
 }

internal/command/uploadpack/gitalycall_test.go

@@ -2,11 +2,8 @@ package uploadpack
 
 import (
 	"bytes"
-	"strings"
 	"testing"
 
-	"github.com/sirupsen/logrus"
-
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -44,9 +41,10 @@ func TestUploadPack(t *testing.T) {
 	require.NoError(t, err)
 
 	require.Equal(t, "UploadPack: "+repo, output.String())
-	require.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
-	require.True(t, strings.Contains(hook.LastEntry().Message, "executing git command"))
-	require.True(t, strings.Contains(hook.LastEntry().Message, "command=git-upload-pack"))
+	entries := hook.AllEntries()
+	assert.Equal(t, 2, len(entries))
+	require.Contains(t, entries[1].Message, "executing git command")
+	require.Contains(t, entries[1].Message, "command=git-upload-pack")
 
 	for k, v := range map[string]string{
 		"gitaly-feature-cache_invalidator":        "true",