Log 'access: finish' line with metadata

internal/command/discover/discover.go

@@ -22,13 +22,18 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, fmt.Errorf("Failed to get username: %v", err)
 	}
 
+	metaData := config.MetaData{}
 	if response.IsAnonymous() {
+		metaData.Username = "Anonymous"
 		fmt.Fprintf(c.ReadWriter.Out, "Welcome to GitLab, Anonymous!\n")
 	} else {
+		metaData.Username = response.Username
 		fmt.Fprintf(c.ReadWriter.Out, "Welcome to GitLab, @%s!\n", response.Username)
 	}
 
-	return ctx, nil
+	ctxWithMetaData := context.WithValue(ctx, "metaData", metaData)
+
+	return ctxWithMetaData, nil
 }
 
 func (c *Command) getUserInfo(ctx context.Context) (*discover.Response, error) {

internal/command/discover/discover_test.go

@@ -6,6 +6,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"net/http"
+	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/require"
@@ -46,29 +47,29 @@ func TestExecute(t *testing.T) {
 	url := testserver.StartSocketHttpServer(t, requests)
 
 	testCases := []struct {
-		desc           string
-		arguments      *commandargs.Shell
-		expectedOutput string
+		desc             string
+		arguments        *commandargs.Shell
+		expectedUsername string
 	}{
 		{
-			desc:           "With a known username",
-			arguments:      &commandargs.Shell{GitlabUsername: "alex-doe"},
-			expectedOutput: "Welcome to GitLab, @alex-doe!\n",
+			desc:             "With a known username",
+			arguments:        &commandargs.Shell{GitlabUsername: "alex-doe"},
+			expectedUsername: "@alex-doe",
 		},
 		{
-			desc:           "With a known key id",
-			arguments:      &commandargs.Shell{GitlabKeyId: "1"},
-			expectedOutput: "Welcome to GitLab, @alex-doe!\n",
+			desc:             "With a known key id",
+			arguments:        &commandargs.Shell{GitlabKeyId: "1"},
+			expectedUsername: "@alex-doe",
 		},
 		{
-			desc:           "With an unknown key",
-			arguments:      &commandargs.Shell{GitlabKeyId: "-1"},
-			expectedOutput: "Welcome to GitLab, Anonymous!\n",
+			desc:             "With an unknown key",
+			arguments:        &commandargs.Shell{GitlabKeyId: "-1"},
+			expectedUsername: "Anonymous",
 		},
 		{
-			desc:           "With an unknown username",
-			arguments:      &commandargs.Shell{GitlabUsername: "unknown"},
-			expectedOutput: "Welcome to GitLab, Anonymous!\n",
+			desc:             "With an unknown username",
+			arguments:        &commandargs.Shell{GitlabUsername: "unknown"},
+			expectedUsername: "Anonymous",
 		},
 	}
 
@@ -81,10 +82,14 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			_, err := cmd.Execute(context.Background())
+			ctxWithMetaData, err := cmd.Execute(context.Background())
+
+			expectedOutput := fmt.Sprintf("Welcome to GitLab, %s!\n", tc.expectedUsername)
+			expectedUsername := strings.TrimLeft(tc.expectedUsername, "@")
 
 			require.NoError(t, err)
-			require.Equal(t, tc.expectedOutput, buffer.String())
+			require.Equal(t, expectedOutput, buffer.String())
+			require.Equal(t, expectedUsername, ctxWithMetaData.Value("metaData").(config.MetaData).Username)
 		})
 	}
 }

internal/command/receivepack/receivepack.go

@@ -30,6 +30,11 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
+	ctxWithMetaData := context.WithValue(ctx, "metaData", config.NewMetaData(
+		response.Gitaly.Repo.GlProjectPath,
+		response.Username,
+	))
+
 	if response.IsCustomAction() {
 		// When `geo_proxy_direct_to_primary` feature flag is enabled, a Git over HTTP direct request
 		// to primary repo is performed instead of proxying the request through Gitlab Rails.
@@ -42,7 +47,7 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 				Response:   response,
 			}
 
-			return ctx, cmd.Execute(ctx)
+			return ctxWithMetaData, cmd.Execute(ctx)
 		}
 
 		customAction := customaction.Command{
@@ -50,10 +55,10 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 			ReadWriter: c.ReadWriter,
 			EOFSent:    true,
 		}
-		return ctx, customAction.Execute(ctx, response)
+		return ctxWithMetaData, customAction.Execute(ctx, response)
 	}
 
-	return ctx, c.performGitalyCall(ctx, response)
+	return ctxWithMetaData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/receivepack/receivepack_test.go

@@ -14,6 +14,21 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/testhelper/requesthandlers"
 )
 
+func TestAllowedAccess(t *testing.T) {
+	gitalyAddress, _ := testserver.StartGitalyServer(t, "unix")
+	requests := requesthandlers.BuildAllowedWithGitalyHandlers(t, gitalyAddress)
+	cmd, _ := setup(t, "1", requests)
+	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
+
+	ctxWithMetaData, err := cmd.Execute(context.Background())
+
+	require.NoError(t, err)
+	metaData := ctxWithMetaData.Value("metaData").(config.MetaData)
+	require.Equal(t, "alex-doe", metaData.Username)
+	require.Equal(t, "group/project-path", metaData.Project)
+	require.Equal(t, "group", metaData.RootNamespace)
+}
+
 func TestForbiddenAccess(t *testing.T) {
 	requests := requesthandlers.BuildDisallowedByApiHandlers(t)
 	cmd, _ := setup(t, "disallowed", requests)

internal/command/uploadarchive/uploadarchive.go

@@ -28,7 +28,13 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
-	return ctx, c.performGitalyCall(ctx, response)
+	metaData := config.NewMetaData(
+		response.Gitaly.Repo.GlProjectPath,
+		response.Username,
+	)
+	ctxWithMetaData := context.WithValue(ctx, "metaData", metaData)
+
+	return ctxWithMetaData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/uploadarchive/uploadarchive_test.go

@@ -14,18 +14,41 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/testhelper/requesthandlers"
 )
 
+func TestAllowedAccess(t *testing.T) {
+	gitalyAddress, _ := testserver.StartGitalyServer(t, "unix")
+	requests := requesthandlers.BuildAllowedWithGitalyHandlers(t, gitalyAddress)
+	cmd, _ := setup(t, "1", requests)
+	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
+
+	ctxWithMetaData, err := cmd.Execute(context.Background())
+
+	require.NoError(t, err)
+	metaData := ctxWithMetaData.Value("metaData").(config.MetaData)
+	require.Equal(t, "alex-doe", metaData.Username)
+	require.Equal(t, "group/project-path", metaData.Project)
+	require.Equal(t, "group", metaData.RootNamespace)
+}
+
 func TestForbiddenAccess(t *testing.T) {
 	requests := requesthandlers.BuildDisallowedByApiHandlers(t)
+
+	cmd, _ := setup(t, "disallowed", requests)
+
+	_, err := cmd.Execute(context.Background())
+	require.Equal(t, "Disallowed by API call", err.Error())
+}
+
+func setup(t *testing.T, keyId string, requests []testserver.TestRequestHandler) (*Command, *bytes.Buffer) {
 	url := testserver.StartHttpServer(t, requests)
 
 	output := &bytes.Buffer{}
+	input := bytes.NewBufferString("input")
 
 	cmd := &Command{
 		Config:     &config.Config{GitlabUrl: url},
-		Args:       &commandargs.Shell{GitlabKeyId: "disallowed", SshArgs: []string{"git-upload-archive", "group/repo"}},
-		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output},
+		Args:       &commandargs.Shell{GitlabKeyId: keyId, SshArgs: []string{"git-upload-archive", "group/repo"}},
+		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
-	_, err := cmd.Execute(context.Background())
-	require.Equal(t, "Disallowed by API call", err.Error())
+	return cmd, output
 }

internal/command/uploadpack/uploadpack.go

@@ -29,16 +29,22 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
+	metaData := config.NewMetaData(
+		response.Gitaly.Repo.GlProjectPath,
+		response.Username,
+	)
+	ctxWithMetaData := context.WithValue(ctx, "metaData", metaData)
+
 	if response.IsCustomAction() {
 		customAction := customaction.Command{
 			Config:     c.Config,
 			ReadWriter: c.ReadWriter,
 			EOFSent:    false,
 		}
-		return ctx, customAction.Execute(ctx, response)
+		return ctxWithMetaData, customAction.Execute(ctx, response)
 	}
 
-	return ctx, c.performGitalyCall(ctx, response)
+	return ctxWithMetaData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/uploadpack/uploadpack_test.go

@@ -14,18 +14,41 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/testhelper/requesthandlers"
 )
 
+func TestAllowedAccess(t *testing.T) {
+	gitalyAddress, _ := testserver.StartGitalyServer(t, "unix")
+	requests := requesthandlers.BuildAllowedWithGitalyHandlers(t, gitalyAddress)
+	cmd, _ := setup(t, "1", requests)
+	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
+
+	ctxWithMetaData, err := cmd.Execute(context.Background())
+
+	require.NoError(t, err)
+	metaData := ctxWithMetaData.Value("metaData").(config.MetaData)
+	require.Equal(t, "alex-doe", metaData.Username)
+	require.Equal(t, "group/project-path", metaData.Project)
+	require.Equal(t, "group", metaData.RootNamespace)
+}
+
 func TestForbiddenAccess(t *testing.T) {
 	requests := requesthandlers.BuildDisallowedByApiHandlers(t)
+
+	cmd, _ := setup(t, "disallowed", requests)
+
+	_, err := cmd.Execute(context.Background())
+	require.Equal(t, "Disallowed by API call", err.Error())
+}
+
+func setup(t *testing.T, keyId string, requests []testserver.TestRequestHandler) (*Command, *bytes.Buffer) {
 	url := testserver.StartHttpServer(t, requests)
 
 	output := &bytes.Buffer{}
+	input := bytes.NewBufferString("input")
 
 	cmd := &Command{
 		Config:     &config.Config{GitlabUrl: url},
-		Args:       &commandargs.Shell{GitlabKeyId: "disallowed", SshArgs: []string{"git-upload-pack", "group/repo"}},
-		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output},
+		Args:       &commandargs.Shell{GitlabKeyId: keyId, SshArgs: []string{"git-upload-pack", "group/repo"}},
+		ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output, In: input},
 	}
 
-	_, err := cmd.Execute(context.Background())
-	require.Equal(t, "Disallowed by API call", err.Error())
+	return cmd, output
 }

internal/sshd/connection.go

@@ -50,12 +50,12 @@ func newConnection(cfg *config.Config, nconn net.Conn) *connection {
 	}
 }
 
-func (c *connection) handle(ctx context.Context, srvCfg *ssh.ServerConfig, handler channelHandler) {
+func (c *connection) handle(ctx context.Context, srvCfg *ssh.ServerConfig, handler channelHandler) context.Context {
 	log.WithContextFields(ctx, log.Fields{}).Info("server: handleConn: start")
 
 	sconn, chans, err := c.initServerConn(ctx, srvCfg)
 	if err != nil {
-		return
+		return ctx
 	}
 
 	if c.cfg.Server.ClientAliveInterval > 0 {
@@ -64,10 +64,12 @@ func (c *connection) handle(ctx context.Context, srvCfg *ssh.ServerConfig, handl
 		go c.sendKeepAliveMsg(ctx, sconn, ticker)
 	}
 
-	c.handleRequests(ctx, sconn, chans, handler)
+	ctxWithMetaData := c.handleRequests(ctx, sconn, chans, handler)
 
 	reason := sconn.Wait()
 	log.WithContextFields(ctx, log.Fields{"reason": reason}).Info("server: handleConn: done")
+
+	return ctxWithMetaData
 }
 
 func (c *connection) initServerConn(ctx context.Context, srvCfg *ssh.ServerConfig) (*ssh.ServerConn, <-chan ssh.NewChannel, error) {
@@ -95,6 +97,7 @@ func (c *connection) initServerConn(ctx context.Context, srvCfg *ssh.ServerConfi
 }
 
 func (c *connection) handleRequests(ctx context.Context, sconn *ssh.ServerConn, chans <-chan ssh.NewChannel, handler channelHandler) context.Context {
+	ctxWithMetaData := ctx
 	ctxlog := log.WithContextFields(ctx, log.Fields{"remote_addr": c.remoteAddr})
 
 	for newChannel := range chans {
@@ -134,7 +137,8 @@ func (c *connection) handleRequests(ctx context.Context, sconn *ssh.ServerConn,
 			}()
 
 			metrics.SliSshdSessionsTotal.Inc()
-			ctx, err = handler(ctx, sconn, channel, requests)
+			ctxWithMetaData, err = handler(ctx, sconn, channel, requests)
+
 			if err != nil {
 				c.trackError(ctxlog, err)
 			}
@@ -149,7 +153,7 @@ func (c *connection) handleRequests(ctx context.Context, sconn *ssh.ServerConn,
 	defer cancel()
 	c.concurrentSessions.Acquire(ctx, c.maxSessions)
 
-	return ctx
+	return ctxWithMetaData
 }
 
 func (c *connection) sendKeepAliveMsg(ctx context.Context, sconn *ssh.ServerConn, ticker *time.Ticker) {

internal/sshd/connection_test.go

@@ -151,13 +151,14 @@ func TestAcceptSessionSucceeds(t *testing.T) {
 	ctx := context.Background()
 
 	channelHandled := false
-	conn.handleRequests(ctx, nil, chans, func(context.Context, *ssh.ServerConn, ssh.Channel, <-chan *ssh.Request) (context.Context, error) {
+	returnedCtx := conn.handleRequests(ctx, nil, chans, func(context.Context, *ssh.ServerConn, ssh.Channel, <-chan *ssh.Request) (context.Context, error) {
 		channelHandled = true
 		close(chans)
 		return ctx, nil
 	})
 
 	require.True(t, channelHandled)
+	require.NotNil(t, returnedCtx)
 }
 
 func TestAcceptSessionFails(t *testing.T) {

internal/sshd/session.go

@@ -50,6 +50,7 @@ type exitStatusReq struct {
 }
 
 func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) (context.Context, error) {
+	ctxWithMetaData := ctx
 	ctxlog := log.ContextLogger(ctx)
 
 	ctxlog.Debug("session: handle: entering request loop")
@@ -70,13 +71,13 @@ func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) (con
 		case "exec":
 			// The command has been executed as `ssh user@host command` or `exec` channel has been used
 			// in the app implementation
-			ctx, shouldContinue, err = s.handleExec(ctx, req)
+			ctxWithMetaData, shouldContinue, err = s.handleExec(ctx, req)
 		case "shell":
 			// The command has been entered into the shell or `shell` channel has been used
 			// in the app implementation
 			shouldContinue = false
 			var status uint32
-			ctx, status, err = s.handleShell(ctx, req)
+			ctxWithMetaData, status, err = s.handleShell(ctx, req)
 			s.exit(ctx, status)
 		default:
 			// Ignore unknown requests but don't terminate the session
@@ -99,7 +100,7 @@ func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) (con
 
 	ctxlog.Debug("session: handle: exiting request loop")
 
-	return ctx, err
+	return ctxWithMetaData, err
 }
 
 func (s *session) handleEnv(ctx context.Context, req *ssh.Request) (bool, error) {
@@ -141,10 +142,10 @@ func (s *session) handleExec(ctx context.Context, req *ssh.Request) (context.Con
 
 	s.execCmd = execRequest.Command
 
-	ctx, status, err := s.handleShell(ctx, req)
-	s.exit(ctx, status)
+	ctxWithMetaData, status, err := s.handleShell(ctx, req)
+	s.exit(ctxWithMetaData, status)
 
-	return ctx, false, err
+	return ctxWithMetaData, false, err
 }
 
 func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Context, uint32, error) {
@@ -195,7 +196,7 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Co
 	}).Info("session: handleShell: executing command")
 	metrics.SshdSessionEstablishedDuration.Observe(establishSessionDuration)
 
-	ctx, err = cmd.Execute(ctx)
+	ctxWithMetaData, err := cmd.Execute(ctx)
 	if err != nil {
 		grpcStatus := grpcstatus.Convert(err)
 		if grpcStatus.Code() != grpccodes.Internal {
@@ -207,7 +208,7 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Co
 
 	ctxlog.Info("session: handleShell: command executed successfully")
 
-	return ctx, 0, nil
+	return ctxWithMetaData, 0, nil
 }
 
 func (s *session) toStderr(ctx context.Context, format string, args ...interface{}) {

internal/sshd/sshd.go

@@ -193,7 +193,7 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 	started := time.Now()
 	conn := newConnection(s.Config, nconn)
 
-	conn.handle(ctx, s.serverConfig.get(ctx), func(ctx context.Context, sconn *ssh.ServerConn, channel ssh.Channel, requests <-chan *ssh.Request) (context.Context, error) {
+	ctxWithMetaData := conn.handle(ctx, s.serverConfig.get(ctx), func(ctx context.Context, sconn *ssh.ServerConn, channel ssh.Channel, requests <-chan *ssh.Request) (context.Context, error) {
 		session := &session{
 			cfg:                 s.Config,
 			channel:             channel,
@@ -206,7 +206,7 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 		return session.handle(ctx, requests)
 	})
 
-	ctxlog.WithFields(log.Fields{"duration_s": time.Since(started).Seconds()}).Info("access: finish")
+	ctxlog.WithFields(log.Fields{"duration_s": time.Since(started).Seconds(), "meta": extractMetaDataFromContext(ctxWithMetaData)}).Info("access: finish")
 }
 
 func (s *Server) proxyPolicy() (proxyproto.PolicyFunc, error) {
@@ -228,6 +228,16 @@ func (s *Server) proxyPolicy() (proxyproto.PolicyFunc, error) {
 	}
 }
 
+func extractMetaDataFromContext(ctx context.Context) config.MetaData {
+	metaData := config.MetaData{}
+
+	if ctx.Value("metaData") != nil {
+		metaData = ctx.Value("metaData").(config.MetaData)
+	}
+
+	return metaData
+}
+
 func staticProxyPolicy(policy proxyproto.Policy) proxyproto.PolicyFunc {
 	return func(_ net.Addr) (proxyproto.Policy, error) {
 		return policy, nil

internal/sshd/sshd_test.go

@@ -348,6 +348,25 @@ func TestLoginGraceTime(t *testing.T) {
 	verifyStatus(t, s, StatusClosed)
 }
 
+func TestExtractMetaDataFromContext(t *testing.T) {
+	rootNameSpace := "flightjs"
+	project := fmt.Sprintf("%s/Flight", rootNameSpace)
+	username := "alex-doe"
+	ctxWithMetaData := context.WithValue(context.Background(), "metaData", config.NewMetaData(project, username))
+
+	metaData := extractMetaDataFromContext(ctxWithMetaData)
+
+	require.Equal(t, config.MetaData{Project: project, Username: username, RootNamespace: rootNameSpace}, metaData)
+}
+
+func TestExtractMetaDataFromContextWithoutMetaData(t *testing.T) {
+	ctxWithMetaData := context.Background()
+
+	metaData := extractMetaDataFromContext(ctxWithMetaData)
+
+	require.Equal(t, config.MetaData{}, metaData)
+}
+
 func setupServer(t *testing.T) *Server {
 	t.Helper()
 

internal/testhelper/requesthandlers/requesthandlers.go

@@ -38,6 +38,7 @@ func BuildAllowedWithGitalyHandlers(t *testing.T, gitalyAddress string) []testse
 					"gl_id":       "1",
 					"gl_key_type": "key",
 					"gl_key_id":   123,
+					"gl_username": "alex-doe",
 					"gitaly": map[string]interface{}{
 						"repository": map[string]interface{}{
 							"storage_name":                     "storage_name",