Ensure log entries have time formatted as UTC

Use a formatter with logrus logs so all log entries have the time field
as UTC. Also fixed a few places that weren't using the configured
logger.

Changelog: fixed

4 files changed, 70 insertions, 14 deletions

diff --git a/internal/blackbox/blackbox.go b/internal/blackbox/blackbox.go
index 5a77ff69d..82f2e707c 100644
--- a/internal/blackbox/blackbox.go
+++ b/internal/blackbox/blackbox.go
@@ -8,9 +8,9 @@ import (
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
-	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/git/stats"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/version"
 	"gitlab.com/gitlab-org/labkit/monitoring"
 )
@@ -140,7 +140,7 @@ func (b Blackbox) Run() error {
 func (b Blackbox) runProbes() {
 	for ; ; time.Sleep(b.cfg.sleepDuration) {
 		for _, probe := range b.cfg.Probes {
-			entry := log.WithFields(map[string]interface{}{
+			entry := log.Default().WithFields(map[string]interface{}{
 				"probe": probe.Name,
 				"type":  probe.Type,
 			})
diff --git a/internal/log/hook.go b/internal/log/hook.go
index d9a995f3e..36a6c848d 100644
--- a/internal/log/hook.go
+++ b/internal/log/hook.go
@@ -31,6 +31,8 @@ func NewHookLogger() *HookLogger {
 		logger.SetOutput(logFile)
 	}
 
+	logger.SetFormatter(UTCTextFormatter())
+
 	return &HookLogger{logger: logger}
 }
 
diff --git a/internal/log/log.go b/internal/log/log.go
index 21171758e..99381418d 100644
--- a/internal/log/log.go
+++ b/internal/log/log.go
@@ -10,9 +10,32 @@ const (
 	// GitalyLogDirEnvKey defines the environment variable used to specify the Gitaly log directory
 	GitalyLogDirEnvKey = "GITALY_LOG_DIR"
 	// LogTimestampFormat defines the timestamp format in log files
-	LogTimestampFormat = "2006-01-02T15:04:05.000Z"
+	LogTimestampFormat = "2006-01-02T15:04:05.000"
+	// LogTimestampFormatUTC defines the utc timestamp format in log files
+	LogTimestampFormatUTC = "2006-01-02T15:04:05.000Z"
 )
 
+type utcFormatter struct {
+	logrus.Formatter
+}
+
+func (u utcFormatter) Format(e *logrus.Entry) ([]byte, error) {
+	e.Time = e.Time.UTC()
+	return u.Formatter.Format(e)
+}
+
+// UTCJsonFormatter returns a Formatter that formats a logrus Entry's as json and converts the time
+// field into UTC
+func UTCJsonFormatter() logrus.Formatter {
+	return &utcFormatter{Formatter: &logrus.JSONFormatter{TimestampFormat: LogTimestampFormatUTC}}
+}
+
+// UTCTextFormatter returns a Formatter that formats a logrus Entry's as text and converts the time
+// field into UTC
+func UTCTextFormatter() logrus.Formatter {
+	return &utcFormatter{Formatter: &logrus.TextFormatter{TimestampFormat: LogTimestampFormatUTC}}
+}
+
 var (
 	defaultLogger = logrus.StandardLogger()
 	grpcGo        = logrus.New()
@@ -37,11 +60,9 @@ func Configure(loggers []*logrus.Logger, format string, level string) {
 	var formatter logrus.Formatter
 	switch format {
 	case "json":
-		formatter = &logrus.JSONFormatter{TimestampFormat: LogTimestampFormat}
-	case "text":
-		formatter = &logrus.TextFormatter{TimestampFormat: LogTimestampFormat}
-	case "":
-		// Just stick with the default
+		formatter = UTCJsonFormatter()
+	case "", "text":
+		formatter = UTCTextFormatter()
 	default:
 		logrus.WithField("format", format).Fatal("invalid logger format")
 	}
diff --git a/internal/log/log_test.go b/internal/log/log_test.go
index d51f6da3c..5be348027 100644
--- a/internal/log/log_test.go
+++ b/internal/log/log_test.go
@@ -1,9 +1,12 @@
 package log
 
 import (
+	"bytes"
 	"testing"
+	"time"
 
 	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
@@ -18,7 +21,7 @@ func TestConfigure(t *testing.T) {
 			desc:   "json format with info level",
 			format: "json",
 			logger: &logrus.Logger{
-				Formatter: &logrus.JSONFormatter{TimestampFormat: LogTimestampFormat},
+				Formatter: &utcFormatter{&logrus.JSONFormatter{TimestampFormat: LogTimestampFormatUTC}},
 				Level:     logrus.InfoLevel,
 			},
 		},
@@ -26,14 +29,15 @@ func TestConfigure(t *testing.T) {
 			desc:   "text format with info level",
 			format: "text",
 			logger: &logrus.Logger{
-				Formatter: &logrus.TextFormatter{TimestampFormat: LogTimestampFormat},
+				Formatter: &utcFormatter{&logrus.TextFormatter{TimestampFormat: LogTimestampFormatUTC}},
 				Level:     logrus.InfoLevel,
 			},
 		},
 		{
 			desc: "empty format with info level",
 			logger: &logrus.Logger{
-				Level: logrus.InfoLevel,
+				Formatter: &utcFormatter{&logrus.TextFormatter{TimestampFormat: LogTimestampFormatUTC}},
+				Level:     logrus.InfoLevel,
 			},
 		},
 		{
@@ -41,7 +45,7 @@ func TestConfigure(t *testing.T) {
 			format: "text",
 			level:  "debug",
 			logger: &logrus.Logger{
-				Formatter: &logrus.TextFormatter{TimestampFormat: LogTimestampFormat},
+				Formatter: &utcFormatter{&logrus.TextFormatter{TimestampFormat: LogTimestampFormatUTC}},
 				Level:     logrus.DebugLevel,
 			},
 		},
@@ -50,15 +54,44 @@ func TestConfigure(t *testing.T) {
 			format: "text",
 			level:  "invalid-level",
 			logger: &logrus.Logger{
-				Formatter: &logrus.TextFormatter{TimestampFormat: LogTimestampFormat},
+				Formatter: &utcFormatter{&logrus.TextFormatter{TimestampFormat: LogTimestampFormatUTC}},
 				Level:     logrus.InfoLevel,
 			},
 		},
 	} {
 		t.Run(tc.desc, func(t *testing.T) {
-			loggers := []*logrus.Logger{{}, {}}
+			loggers := []*logrus.Logger{{Formatter: &logrus.TextFormatter{}}, {Formatter: &logrus.TextFormatter{}}}
 			Configure(loggers, tc.format, tc.level)
 			require.Equal(t, []*logrus.Logger{tc.logger, tc.logger}, loggers)
+
+			now := time.Now()
+			nowUTCFormatted := now.UTC().Format(LogTimestampFormatUTC)
+
+			message := "this is a logging message."
+			var out bytes.Buffer
+
+			// both loggers are the same, so no need to test both the same way
+			logger := loggers[0]
+			logger.Out = &out
+			entry := logger.WithTime(now)
+
+			switch tc.level {
+			case "debug":
+				entry.Debug(message)
+			case "warn":
+				entry.Warn(message)
+			case "error":
+				entry.Error(message)
+			case "", "info":
+				entry.Info(message)
+			default:
+				entry.Info(message)
+			}
+
+			if tc.format != "" {
+				assert.Contains(t, out.String(), nowUTCFormatted)
+			}
+			assert.Contains(t, out.String(), message)
 		})
 	}
 }