Log internal 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

cmd/check/main.go

@@ -8,6 +8,7 @@ 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/executable"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 )
 
 func main() {
@@ -29,6 +30,8 @@ func main() {
 		os.Exit(1)
 	}
 
+	logger.Configure(config)
+
 	cmd, err := command.New(executable, os.Args[1:], config, readWriter)
 	if err != nil {
 		fmt.Fprintf(readWriter.ErrOut, "%v\n", err)

cmd/gitlab-shell-authorized-keys-check/main.go

@@ -9,6 +9,7 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/console"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 )
 
 func main() {
@@ -30,6 +31,8 @@ func main() {
 		os.Exit(1)
 	}
 
+	logger.Configure(config)
+
 	cmd, err := command.New(executable, os.Args[1:], config, readWriter)
 	if err != nil {
 		// For now this could happen if `SSH_CONNECTION` is not set on

cmd/gitlab-shell-authorized-principals-check/main.go

@@ -9,6 +9,7 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/console"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 )
 
 func main() {
@@ -30,6 +31,8 @@ func main() {
 		os.Exit(1)
 	}
 
+	logger.Configure(config)
+
 	cmd, err := command.New(executable, os.Args[1:], config, readWriter)
 	if err != nil {
 		// For now this could happen if `SSH_CONNECTION` is not set on

cmd/gitlab-shell/main.go

@@ -9,6 +9,7 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/console"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/logger"
 )
 
 func main() {
@@ -30,6 +31,8 @@ func main() {
 		os.Exit(1)
 	}
 
+	logger.Configure(config)
+
 	cmd, err := command.New(executable, os.Args[1:], config, readWriter)
 	if err != nil {
 		// For now this could happen if `SSH_CONNECTION` is not set on

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.ElapsedTimeMs(start, time.Now()),
+	}
+
 	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
 }
 

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"))
 	})
 }
 

internal/logger/logger.go

@@ -3,10 +3,13 @@ package logger
 import (
 	"fmt"
 	"io"
+	"io/ioutil"
 	golog "log"
 	"log/syslog"
+	"math"
 	"os"
 	"sync"
+	"time"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 
@@ -26,13 +29,19 @@ func Configure(cfg *config.Config) error {
 	defer mutex.Unlock()
 
 	pid = os.Getpid()
+	ProgName, _ = os.Executable()
 
-	var err error
-	logWriter, err = os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND, 0)
+	// Avoid leaking output if we can't set up the logging output
+	log.SetOutput(ioutil.Discard)
+
+	output, err := os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 	if err != nil {
+		setupBootstrapLogger()
+		logPrint("Unable to configure logging", err)
 		return err
 	}
 
+	logWriter = output
 	log.SetOutput(logWriter)
 	if cfg.LogFormat == "json" {
 		log.SetFormatter(&log.JSONFormatter{})
@@ -41,12 +50,14 @@ func Configure(cfg *config.Config) error {
 	return nil
 }
 
+// If our log file is not available we want to log somewhere else, but
+// not to standard error because that leaks information to the user. This
+// function attempts to log to syslog.
 func logPrint(msg string, err error) {
-	mutex.Lock()
-	defer mutex.Unlock()
-
 	if logWriter == nil {
-		bootstrapLogPrint(msg, err)
+		if bootstrapLogger != nil {
+			bootstrapLogger.Print(ProgName+":", msg+":", err)
+		}
 		return
 	}
 
@@ -56,6 +67,10 @@ func logPrint(msg string, err error) {
 }
 
 func Fatal(msg string, err error) {
+	mutex.Lock()
+	defer mutex.Unlock()
+	setupBootstrapLogger()
+
 	logPrint(msg, err)
 	// We don't show the error to the end user because it can leak
 	// information that is private to the GitLab server.
@@ -63,20 +78,23 @@ func Fatal(msg string, err error) {
 	os.Exit(1)
 }
 
-// If our log file is not available we want to log somewhere else, but
-// not to standard error because that leaks information to the user. This
-// function attempts to log to syslog.
-//
 // We assume the logging mutex is already locked.
-func bootstrapLogPrint(msg string, err error) {
+func setupBootstrapLogger() {
 	if bootstrapLogger == nil {
-		var err error
-		bootstrapLogger, err = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
-		if err != nil {
-			// The message will not be logged.
-			return
-		}
+		bootstrapLogger, _ = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
 	}
+}
+
+func ElapsedTimeMs(start time.Time, end time.Time) float64 {
+	// Later versions of Go support Milliseconds directly:
+	// https://go-review.googlesource.com/c/go/+/167387/
+	return roundFloat(end.Sub(start).Seconds() * 1e3)
+}
+
+func roundFloat(x float64) float64 {
+	return round(x, 1000)
+}
 
-	bootstrapLogger.Print(ProgName+":", msg+":", err)
+func round(x, unit float64) float64 {
+	return math.Round(x*unit) / unit
 }

internal/logger/logger_test.go

+package logger
+
+import (
+	"fmt"
+	"io/ioutil"
+	"os"
+	"strings"
+	"testing"
+	"time"
+
+	log "github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
+)
+
+func TestConfigure(t *testing.T) {
+	tmpFile, err := ioutil.TempFile(os.TempDir(), "logtest-")
+	require.NoError(t, err)
+	defer tmpFile.Close()
+
+	config := config.Config{
+		LogFile:   tmpFile.Name(),
+		LogFormat: "json",
+	}
+
+	err = Configure(&config)
+
+	require.NoError(t, err)
+
+	log.Info("this is a test")
+
+	tmpFile.Close()
+
+	data, err := ioutil.ReadFile(tmpFile.Name())
+	require.NoError(t, err)
+	require.True(t, strings.Contains(string(data), `msg":"this is a test"`))
+}
+
+func TestElapsedTimeMs(t *testing.T) {
+	testCases := []struct {
+		delta    float64
+		expected float64
+	}{
+		{
+			delta:    123.0,
+			expected: 123.0,
+		},
+		{
+			delta:    123.4,
+			expected: 123.4,
+		},
+		{
+			delta:    123.45,
+			expected: 123.45,
+		},
+		{
+			delta:    123.456,
+			expected: 123.456,
+		},
+
+		{
+			delta:    123.4567,
+			expected: 123.457,
+		},
+		{
+			delta:    123.4564,
+			expected: 123.456,
+		},
+	}
+
+	for _, tc := range testCases {
+		duration := fmt.Sprintf("%fms", tc.delta)
+
+		t.Run(duration, func(t *testing.T) {
+			delta, _ := time.ParseDuration(duration)
+			start := time.Now()
+			end := start.Add(delta)
+			require.Equal(t, tc.expected, ElapsedTimeMs(start, end))
+			require.InDelta(t, tc.expected, ElapsedTimeMs(start, end), 0.001)
+		})
+	}
+}

internal/testhelper/testhelper.go

@@ -8,6 +8,8 @@ import (
 	"runtime"
 
 	"github.com/otiai10/copy"
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
 )
 
 var (
@@ -91,3 +93,10 @@ 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
+}

spec/support/gitlab_shell_setup.rb

 require 'yaml'
+require 'tempfile'
 
 RSpec.shared_context 'gitlab shell', shared_context: :metadata do
   def original_root_path
@@ -10,6 +11,8 @@ RSpec.shared_context 'gitlab shell', shared_context: :metadata do
   end
 
   def write_config(config)
+    config['log_file'] ||= Tempfile.new.path
+
     File.open(config_path, 'w') do |f|
       f.write(config.to_yaml)
     end