Standardize Praefect and Gitaly timestamps

`grpc.start_time` and `grpc.request.deadline` are inserted and formatted
by go-grpc-middleware.  We pull in
https://github.com/grpc-ecosystem/go-grpc-middleware/pull/398 and
configure the timestamps with the Gitaly format.

Closes https://gitlab.com/gitlab-org/gitaly/-/issues/3451

7 files changed, 32 insertions, 11 deletions

diff --git a/changelogs/unreleased/sh-standardize-timestamp-formats.yml b/changelogs/unreleased/sh-standardize-timestamp-formats.yml
new file mode 100644
index 000000000..07936a147
--- /dev/null
+++ b/changelogs/unreleased/sh-standardize-timestamp-formats.yml
@@ -0,0 +1,5 @@
+---
+title: Standardize Praefect and Gitaly timestamps
+merge_request: 3133
+author:
+type: changed
diff --git a/go.mod b/go.mod
index fd3064e5b..1679bc584 100644
--- a/go.mod
+++ b/go.mod
@@ -17,7 +17,7 @@ require (
 	github.com/git-lfs/git-lfs v1.5.1-0.20200916154635-9ea4eed5b112
 	github.com/golang/protobuf v1.3.3
 	github.com/google/uuid v1.1.1
-	github.com/grpc-ecosystem/go-grpc-middleware v1.2.2
+	github.com/grpc-ecosystem/go-grpc-middleware v1.2.3-0.20210213123510-be4c235f9d1c
 	github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0
 	github.com/hashicorp/go-uuid v1.0.2 // indirect
 	github.com/hashicorp/golang-lru v0.5.4
@@ -39,6 +39,7 @@ require (
 	gitlab.com/gitlab-org/gitlab-shell v1.9.8-0.20201117050822-3f9890ef73dc
 	gitlab.com/gitlab-org/labkit v1.0.0
 	golang.org/x/crypto v0.0.0-20200820211705-5c72a883971a // indirect
+	golang.org/x/exp v0.0.0-20200331195152-e8c3332aa8e5 // indirect
 	golang.org/x/net v0.0.0-20200904194848-62affa334b73 // indirect
 	golang.org/x/sync v0.0.0-20200625203802-6e8e738ad208
 	golang.org/x/sys v0.0.0-20201015000850-e3ed0017c211
diff --git a/go.sum b/go.sum
index 60e64d9e8..2d6417b91 100644
--- a/go.sum
+++ b/go.sum
@@ -190,8 +190,8 @@ github.com/gopherjs/gopherjs v0.0.0-20181017120253-0766667cb4d1/go.mod h1:wJfORR
 github.com/gorilla/websocket v1.4.0/go.mod h1:E7qHFY5m1UJ88s3WnNqhKjPHQ0heANvMoAMk2YaljkQ=
 github.com/grpc-ecosystem/go-grpc-middleware v1.0.0 h1:Iju5GlWwrvL6UBg4zJJt3btmonfrMlCDdsejg4CZE7c=
 github.com/grpc-ecosystem/go-grpc-middleware v1.0.0/go.mod h1:FiyG127CGDf3tlThmgyCl78X/SZQqEOJBCDaAfeWzPs=
-github.com/grpc-ecosystem/go-grpc-middleware v1.2.2 h1:FlFbCRLd5Jr4iYXZufAvgWN6Ao0JrI5chLINnUXDDr0=
-github.com/grpc-ecosystem/go-grpc-middleware v1.2.2/go.mod h1:EaizFBKfUKtMIF5iaDEhniwNedqGo9FuLFzppDr3uwI=
+github.com/grpc-ecosystem/go-grpc-middleware v1.2.3-0.20210213123510-be4c235f9d1c h1:5xKmZgWe5pVbdz8m62CidLCGoe6Q+N535i3LVSOjpTQ=
+github.com/grpc-ecosystem/go-grpc-middleware v1.2.3-0.20210213123510-be4c235f9d1c/go.mod h1:RXwzibsL7UhPcEmGyGvXKJ8kyJsOCOEaLgGce4igMFs=
 github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0 h1:Ovs26xHkKqVztRpIrF/92BcuyuQ/YW4NSIpoGtfXNho=
 github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0/go.mod h1:8NvIoxWQoOIhqOTXgfV/d3M/q6VIi02HzZEHgUlZvzk=
 github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
diff --git a/internal/gitaly/server/server.go b/internal/gitaly/server/server.go
index 6472a8ccb..b8abe0416 100644
--- a/internal/gitaly/server/server.go
+++ b/internal/gitaly/server/server.go
@@ -108,7 +108,9 @@ func createNewServer(cfg config.Cfg, secure bool) (*grpc.Server, error) {
 			metadatahandler.StreamInterceptor,
 			grpc_prometheus.StreamServerInterceptor,
 			commandstatshandler.StreamInterceptor,
-			grpc_logrus.StreamServerInterceptor(logrusEntry, grpc_logrus.WithMessageProducer(commandstatshandler.CommandStatsMessageProducer)),
+			grpc_logrus.StreamServerInterceptor(logrusEntry,
+				grpc_logrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
+				grpc_logrus.WithMessageProducer(commandstatshandler.CommandStatsMessageProducer)),
 			sentryhandler.StreamLogHandler,
 			cancelhandler.Stream, // Should be below LogHandler
 			auth.StreamServerInterceptor(cfg.Auth),
@@ -125,7 +127,9 @@ func createNewServer(cfg config.Cfg, secure bool) (*grpc.Server, error) {
 			metadatahandler.UnaryInterceptor,
 			grpc_prometheus.UnaryServerInterceptor,
 			commandstatshandler.UnaryInterceptor,
-			grpc_logrus.UnaryServerInterceptor(logrusEntry, grpc_logrus.WithMessageProducer(commandstatshandler.CommandStatsMessageProducer)),
+			grpc_logrus.UnaryServerInterceptor(logrusEntry,
+				grpc_logrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
+				grpc_logrus.WithMessageProducer(commandstatshandler.CommandStatsMessageProducer)),
 			sentryhandler.UnaryLogHandler,
 			cancelhandler.Unary, // Should be below LogHandler
 			auth.UnaryServerInterceptor(cfg.Auth),
diff --git a/internal/middleware/commandstatshandler/commandstatshandler_test.go b/internal/middleware/commandstatshandler/commandstatshandler_test.go
index 3578458e4..732bd8014 100644
--- a/internal/middleware/commandstatshandler/commandstatshandler_test.go
+++ b/internal/middleware/commandstatshandler/commandstatshandler_test.go
@@ -14,6 +14,7 @@ import (
 	"gitlab.com/gitlab-org/gitaly/internal/git"
 	"gitlab.com/gitlab-org/gitaly/internal/gitaly/config"
 	"gitlab.com/gitlab-org/gitaly/internal/gitaly/service/ref"
+	"gitlab.com/gitlab-org/gitaly/internal/log"
 	"gitlab.com/gitlab-org/gitaly/internal/metadata/featureflag"
 	"gitlab.com/gitlab-org/gitaly/internal/testhelper"
 	"gitlab.com/gitlab-org/gitaly/proto/go/gitalypb"
@@ -28,11 +29,15 @@ func createNewServer(t *testing.T) *grpc.Server {
 	opts := []grpc.ServerOption{
 		grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
 			StreamInterceptor,
-			grpc_logrus.StreamServerInterceptor(logrusEntry, grpc_logrus.WithMessageProducer(CommandStatsMessageProducer)),
+			grpc_logrus.StreamServerInterceptor(logrusEntry,
+				grpc_logrus.WithTimestampFormat(log.LogTimestampFormat),
+				grpc_logrus.WithMessageProducer(CommandStatsMessageProducer)),
 		)),
 		grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
 			UnaryInterceptor,
-			grpc_logrus.UnaryServerInterceptor(logrusEntry, grpc_logrus.WithMessageProducer(CommandStatsMessageProducer)),
+			grpc_logrus.UnaryServerInterceptor(logrusEntry,
+				grpc_logrus.WithTimestampFormat(log.LogTimestampFormat),
+				grpc_logrus.WithMessageProducer(CommandStatsMessageProducer)),
 		)),
 	}
 
diff --git a/internal/praefect/server.go b/internal/praefect/server.go
index c15859c9b..0ad23f242 100644
--- a/internal/praefect/server.go
+++ b/internal/praefect/server.go
@@ -12,6 +12,7 @@ import (
 	"github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/internal/gitaly/server/auth"
 	"gitlab.com/gitlab-org/gitaly/internal/helper/fieldextractors"
+	"gitlab.com/gitlab-org/gitaly/internal/log"
 	"gitlab.com/gitlab-org/gitaly/internal/middleware/cancelhandler"
 	"gitlab.com/gitlab-org/gitaly/internal/middleware/metadatahandler"
 	"gitlab.com/gitlab-org/gitaly/internal/middleware/panichandler"
@@ -59,7 +60,8 @@ func NewGRPCServer(
 		middleware.MethodTypeStreamInterceptor(registry),
 		metadatahandler.StreamInterceptor,
 		grpc_prometheus.StreamServerInterceptor,
-		grpc_logrus.StreamServerInterceptor(logger),
+		grpc_logrus.StreamServerInterceptor(logger,
+			grpc_logrus.WithTimestampFormat(log.LogTimestampFormat)),
 		sentryhandler.StreamLogHandler,
 		cancelhandler.Stream, // Should be below LogHandler
 		grpctracing.StreamServerTracingInterceptor(),
@@ -82,7 +84,8 @@ func NewGRPCServer(
 			middleware.MethodTypeUnaryInterceptor(registry),
 			metadatahandler.UnaryInterceptor,
 			grpc_prometheus.UnaryServerInterceptor,
-			grpc_logrus.UnaryServerInterceptor(logger),
+			grpc_logrus.UnaryServerInterceptor(logger,
+				grpc_logrus.WithTimestampFormat(log.LogTimestampFormat)),
 			sentryhandler.UnaryLogHandler,
 			cancelhandler.Unary, // Should be below LogHandler
 			grpctracing.UnaryServerTracingInterceptor(),
diff --git a/internal/testhelper/testserver.go b/internal/testhelper/testserver.go
index 119e387f4..79aefccae 100644
--- a/internal/testhelper/testserver.go
+++ b/internal/testhelper/testserver.go
@@ -32,6 +32,7 @@ import (
 	gitalylog "gitlab.com/gitlab-org/gitaly/internal/gitaly/config/log"
 	serverauth "gitlab.com/gitlab-org/gitaly/internal/gitaly/server/auth"
 	"gitlab.com/gitlab-org/gitaly/internal/helper/fieldextractors"
+	gitalyinternallog "gitlab.com/gitlab-org/gitaly/internal/log"
 	praefectconfig "gitlab.com/gitlab-org/gitaly/internal/praefect/config"
 	grpccorrelation "gitlab.com/gitlab-org/labkit/correlation/grpc"
 	"google.golang.org/grpc"
@@ -296,13 +297,15 @@ func NewServerWithLogger(tb testing.TB, logger *log.Logger, streamInterceptors [
 	streamInterceptors = append([]grpc.StreamServerInterceptor{
 		grpc_ctxtags.StreamServerInterceptor(ctxTagger),
 		grpccorrelation.StreamServerCorrelationInterceptor(),
-		grpc_logrus.StreamServerInterceptor(logrusEntry),
+		grpc_logrus.StreamServerInterceptor(logrusEntry,
+			grpc_logrus.WithTimestampFormat(gitalyinternallog.LogTimestampFormat)),
 	}, streamInterceptors...)
 
 	unaryInterceptors = append([]grpc.UnaryServerInterceptor{
 		grpc_ctxtags.UnaryServerInterceptor(ctxTagger),
 		grpccorrelation.UnaryServerCorrelationInterceptor(),
-		grpc_logrus.UnaryServerInterceptor(logrusEntry),
+		grpc_logrus.UnaryServerInterceptor(logrusEntry,
+			grpc_logrus.WithTimestampFormat(gitalyinternallog.LogTimestampFormat)),
 	}, unaryInterceptors...)
 
 	return NewTestServer(