Log internal HTTP requestssh-log-http-requests

This restores the previous behavior of logging the success and failures
of internal HTTP requests.

Part of https://gitlab.com/gitlab-org/gitlab/issues/207916

2 files changed, 41 insertions, 0 deletions

diff --git a/internal/gitlabnet/client.go b/internal/gitlabnet/client.go
index bb8655a..7c8f431 100644
--- a/internal/gitlabnet/client.go
+++ b/internal/gitlabnet/client.go
@@ -8,8 +8,11 @@ import (
 	"io"
 	"net/http"
 	"strings"
+	"time"
 
+	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 )
 
 const (
@@ -111,15 +114,26 @@ func (c *GitlabClient) DoRequest(method, path string, data interface{}) (*http.R
 	request.Header.Add("Content-Type", "application/json")
 	request.Close = true
 
+	start := time.Now()
 	response, err := c.httpClient.Do(request)
+	fields := log.Fields{
+		"method":      method,
+		"url":         request.URL.String(),
+		"duration_ms": logger.ElapsedTime(start),
+	}
+
 	if err != nil {
+		log.WithError(err).WithFields(fields).Error("Internal API unreachable")
 		return nil, fmt.Errorf("Internal API unreachable")
 	}
 
 	if err := parseError(response); err != nil {
+		log.WithError(err).WithFields(fields).Error("Internal API error")
 		return nil, err
 	}
 
+	log.WithFields(fields).Info("Finished HTTP request")
+
 	return response, nil
 }
 
diff --git a/internal/gitlabnet/client_test.go b/internal/gitlabnet/client_test.go
index 3f96b41..d6ca91d 100644
--- a/internal/gitlabnet/client_test.go
+++ b/internal/gitlabnet/client_test.go
@@ -7,8 +7,11 @@ import (
 	"io/ioutil"
 	"net/http"
 	"path"
+	"strings"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -116,6 +119,7 @@ func TestClients(t *testing.T) {
 
 func testSuccessfulGet(t *testing.T, client *GitlabClient) {
 	t.Run("Successful get", func(t *testing.T) {
+		hook := testhelper.SetupLogger()
 		response, err := client.Get("/hello")
 		require.NoError(t, err)
 		require.NotNil(t, response)
@@ -125,11 +129,17 @@ func testSuccessfulGet(t *testing.T, client *GitlabClient) {
 		responseBody, err := ioutil.ReadAll(response.Body)
 		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"))
 	})
 }
 
 func testSuccessfulPost(t *testing.T, client *GitlabClient) {
 	t.Run("Successful Post", func(t *testing.T) {
+		hook := testhelper.SetupLogger()
 		data := map[string]string{"key": "value"}
 
 		response, err := client.Post("/post_endpoint", data)
@@ -141,20 +151,37 @@ func testSuccessfulPost(t *testing.T, client *GitlabClient) {
 		responseBody, err := ioutil.ReadAll(response.Body)
 		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"))
 	})
 }
 
 func testMissing(t *testing.T, client *GitlabClient) {
 	t.Run("Missing error for GET", func(t *testing.T) {
+		hook := testhelper.SetupLogger()
 		response, err := client.Get("/missing")
 		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"))
 	})
 
 	t.Run("Missing error for POST", func(t *testing.T) {
+		hook := testhelper.SetupLogger()
 		response, err := client.Post("/missing", map[string]string{})
 		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"))
 	})
 }