Merge branch 'sh-log-git-upload-receive-pack' into 'master'

Log git-{upload-pack,receive-pack} requests

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

7 files changed, 50 insertions, 0 deletions

diff --git a/internal/command/receivepack/gitalycall.go b/internal/command/receivepack/gitalycall.go
index 529b296..ffe0b6f 100644
--- a/internal/command/receivepack/gitalycall.go
+++ b/internal/command/receivepack/gitalycall.go
@@ -35,6 +35,8 @@ func (c *Command) performGitalyCall(response *accessverifier.Response) error {
 		ctx, cancel := context.WithCancel(ctx)
 		defer cancel()
 
+		gc.LogExecution(request.Repository, response, request.GitProtocol)
+
 		rw := c.ReadWriter
 		return client.ReceivePack(ctx, conn, rw.In, rw.Out, rw.ErrOut, request)
 	})
diff --git a/internal/command/receivepack/gitalycall_test.go b/internal/command/receivepack/gitalycall_test.go
index de20bfd..ece9f1e 100644
--- a/internal/command/receivepack/gitalycall_test.go
+++ b/internal/command/receivepack/gitalycall_test.go
@@ -2,14 +2,18 @@ package receivepack
 
 import (
 	"bytes"
+	"strings"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/stretchr/testify/require"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/testserver"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
@@ -33,8 +37,13 @@ func TestReceivePack(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
+	hook := testhelper.SetupLogger()
+
 	err := cmd.Execute()
 	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"))
 }
diff --git a/internal/command/uploadarchive/gitalycall.go b/internal/command/uploadarchive/gitalycall.go
index 269a8e2..1b792cb 100644
--- a/internal/command/uploadarchive/gitalycall.go
+++ b/internal/command/uploadarchive/gitalycall.go
@@ -27,6 +27,8 @@ func (c *Command) performGitalyCall(response *accessverifier.Response) error {
 		ctx, cancel := context.WithCancel(ctx)
 		defer cancel()
 
+		gc.LogExecution(request.Repository, response, "")
+
 		rw := c.ReadWriter
 		return client.UploadArchive(ctx, conn, rw.In, rw.Out, rw.ErrOut, request)
 	})
diff --git a/internal/command/uploadarchive/gitalycall_test.go b/internal/command/uploadarchive/gitalycall_test.go
index 5345119..6e67571 100644
--- a/internal/command/uploadarchive/gitalycall_test.go
+++ b/internal/command/uploadarchive/gitalycall_test.go
@@ -2,14 +2,18 @@ package uploadarchive
 
 import (
 	"bytes"
+	"strings"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/stretchr/testify/require"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/testserver"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
@@ -33,8 +37,13 @@ func TestUploadPack(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
+	hook := testhelper.SetupLogger()
+
 	err := cmd.Execute()
 	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"))
 }
diff --git a/internal/command/uploadpack/gitalycall.go b/internal/command/uploadpack/gitalycall.go
index 26f87f8..c15ef38 100644
--- a/internal/command/uploadpack/gitalycall.go
+++ b/internal/command/uploadpack/gitalycall.go
@@ -32,6 +32,8 @@ func (c *Command) performGitalyCall(response *accessverifier.Response) error {
 		ctx, cancel := context.WithCancel(ctx)
 		defer cancel()
 
+		gc.LogExecution(request.Repository, response, request.GitProtocol)
+
 		rw := c.ReadWriter
 		return client.UploadPack(ctx, conn, rw.In, rw.Out, rw.ErrOut, request)
 	})
diff --git a/internal/command/uploadpack/gitalycall_test.go b/internal/command/uploadpack/gitalycall_test.go
index 8c74212..e5fe8b2 100644
--- a/internal/command/uploadpack/gitalycall_test.go
+++ b/internal/command/uploadpack/gitalycall_test.go
@@ -2,8 +2,11 @@ package uploadpack
 
 import (
 	"bytes"
+	"strings"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -11,6 +14,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/gitlabnet/testserver"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/testhelper/requesthandlers"
 )
 
@@ -34,10 +38,15 @@ func TestUploadPack(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
+	hook := testhelper.SetupLogger()
+
 	err := cmd.Execute()
 	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"))
 
 	for k, v := range map[string]string{
 		"gitaly-feature-cache_invalidator":        "true",
diff --git a/internal/handler/exec.go b/internal/handler/exec.go
index 19621fa..3af0925 100644
--- a/internal/handler/exec.go
+++ b/internal/handler/exec.go
@@ -6,10 +6,14 @@ import (
 	"os"
 	"strings"
 
+	log "github.com/sirupsen/logrus"
+
 	"gitlab.com/gitlab-org/gitaly/auth"
 	"gitlab.com/gitlab-org/gitaly/client"
+	pb "gitlab.com/gitlab-org/gitaly/proto/go/gitalypb"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/gitlabnet/accessverifier"
 	"gitlab.com/gitlab-org/labkit/tracing"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/metadata"
@@ -51,6 +55,19 @@ func (gc *GitalyCommand) RunGitalyCommand(handler GitalyHandlerFunc) error {
 	return err
 }
 
+func (gc *GitalyCommand) LogExecution(repository *pb.Repository, response *accessverifier.Response, protocol string) {
+	fields := log.Fields{
+		"command":         gc.ServiceName,
+		"gl_project_path": repository.GlProjectPath,
+		"gl_repository":   repository.GlRepository,
+		"user_id":         response.UserId,
+		"username":        response.Username,
+		"git_protocol":    protocol,
+	}
+
+	log.WithFields(fields).Info("executing git command")
+}
+
 func withOutgoingMetadata(ctx context.Context, features map[string]string) context.Context {
 	md := metadata.New(nil)
 	for k, v := range features {