Merge branch '648-gitlab-sshd-should-include-data-transfer-bytes-in-logs-2' into 'main'

Log 'access: finish' line with additional metadata

See merge request https://gitlab.com/gitlab-org/gitlab-shell/-/merge_requests/783



Merged-by: Patrick Bajao <ebajao@gitlab.com>
Approved-by: Alejandro Rodríguez <alejandro@gitlab.com>
Approved-by: Patrick Bajao <ebajao@gitlab.com>
Reviewed-by: Alejandro Rodríguez <alejandro@gitlab.com>
Reviewed-by: Patrick Bajao <ebajao@gitlab.com>
Reviewed-by: Ash McKenzie <amckenzie@gitlab.com>
Co-authored-by: Ash McKenzie <amckenzie@gitlab.com>

cmd/check/main.go

@@ -43,7 +43,7 @@ func main() {
 	ctx, finished := command.Setup(executable.Name, config)
 	defer finished()
 
-	if err = cmd.Execute(ctx); err != nil {
+	if ctx, err = cmd.Execute(ctx); err != nil {
 		fmt.Fprintf(readWriter.ErrOut, "%v\n", err)
 		os.Exit(1)
 	}

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

@@ -46,7 +46,7 @@ func main() {
 	ctx, finished := command.Setup(executable.Name, config)
 	defer finished()
 
-	if err = cmd.Execute(ctx); err != nil {
+	if ctx, err = cmd.Execute(ctx); err != nil {
 		console.DisplayWarningMessage(err.Error(), readWriter.ErrOut)
 		os.Exit(1)
 	}

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

@@ -46,7 +46,7 @@ func main() {
 	ctx, finished := command.Setup(executable.Name, config)
 	defer finished()
 
-	if err = cmd.Execute(ctx); err != nil {
+	if ctx, err = cmd.Execute(ctx); err != nil {
 		console.DisplayWarningMessage(err.Error(), readWriter.ErrOut)
 		os.Exit(1)
 	}

cmd/gitlab-shell/main.go

@@ -76,7 +76,7 @@ func main() {
 	ctxlog.WithFields(log.Fields{"env": env, "command": cmdName}).Info("gitlab-shell: main: executing command")
 	fips.Check()
 
-	if err := cmd.Execute(ctx); err != nil {
+	if _, err := cmd.Execute(ctx); err != nil {
 		ctxlog.WithError(err).Warn("gitlab-shell: main: command execution failed")
 		if grpcstatus.Convert(err).Code() != grpccodes.Internal {
 			console.DisplayWarningMessage(err.Error(), readWriter.ErrOut)

internal/command/authorizedkeys/authorized_keys.go

@@ -18,21 +18,21 @@ type Command struct {
 	ReadWriter *readwriter.ReadWriter
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	// Do and return nothing when the expected and actual user don't match.
 	// This can happen when the user in sshd_config doesn't match the user
 	// trying to login. When nothing is printed, the user will be denied access.
 	if c.Args.ExpectedUser != c.Args.ActualUser {
 		// TODO: Log this event once we have a consistent way to log in Go.
 		// See https://gitlab.com/gitlab-org/gitlab-shell/issues/192 for more info.
-		return nil
+		return ctx, nil
 	}
 
 	if err := c.printKeyLine(ctx); err != nil {
-		return err
+		return ctx, err
 	}
 
-	return nil
+	return ctx, nil
 }
 
 func (c *Command) printKeyLine(ctx context.Context) error {

internal/command/authorizedkeys/authorized_keys_test.go

@@ -84,7 +84,7 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			err := cmd.Execute(context.Background())
+			_, err := cmd.Execute(context.Background())
 
 			require.NoError(t, err)
 			require.Equal(t, tc.expectedOutput, buffer.String())

internal/command/authorizedprincipals/authorized_principals.go

@@ -16,12 +16,12 @@ type Command struct {
 	ReadWriter *readwriter.ReadWriter
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	if err := c.printPrincipalLines(); err != nil {
-		return err
+		return ctx, err
 	}
 
-	return nil
+	return ctx, nil
 }
 
 func (c *Command) printPrincipalLines() error {

internal/command/authorizedprincipals/authorized_principals_test.go

@@ -42,7 +42,7 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			err := cmd.Execute(context.Background())
+			_, err := cmd.Execute(context.Background())
 
 			require.NoError(t, err)
 			require.Equal(t, tc.expectedOutput, buffer.String())

internal/command/command.go

@@ -2,6 +2,7 @@ package command
 
 import (
 	"context"
+	"strings"
 
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
 	"gitlab.com/gitlab-org/labkit/correlation"
@@ -9,7 +10,13 @@ import (
 )
 
 type Command interface {
-	Execute(ctx context.Context) error
+	Execute(ctx context.Context) (context.Context, error)
+}
+
+type LogMetadata struct {
+	Username      string `json:"username"`
+	Project       string `json:"project,omitempty"`
+	RootNamespace string `json:"root_namespace,omitempty"`
 }
 
 // Setup() initializes tracing from the configuration file and generates a
@@ -47,3 +54,23 @@ func Setup(serviceName string, config *config.Config) (context.Context, func())
 		closer.Close()
 	}
 }
+
+func NewLogMetadata(project, username string) LogMetadata {
+	rootNameSpace := ""
+
+	if len(project) > 0 {
+		splitFn := func(c rune) bool {
+			return c == '/'
+		}
+		m := strings.FieldsFunc(project, splitFn)
+		if len(m) > 0 {
+			rootNameSpace = m[0]
+		}
+	}
+
+	return LogMetadata{
+		Username:      username,
+		Project:       project,
+		RootNamespace: rootNameSpace,
+	}
+}

internal/command/command_test.go

@@ -77,3 +77,40 @@ func addAdditionalEnv(envMap map[string]string) func() {
 
 	}
 }
+
+func TestNewLogMetadata(t *testing.T) {
+	testCases := []struct {
+		desc                  string
+		project               string
+		username              string
+		expectedRootNamespace string
+	}{
+		{
+			desc:                  "Project under single namespace",
+			project:               "flightjs/Flight",
+			username:              "alex-doe",
+			expectedRootNamespace: "flightjs",
+		},
+		{
+			desc:                  "Project under single odd namespace",
+			project:               "flightjs///Flight",
+			username:              "alex-doe",
+			expectedRootNamespace: "flightjs",
+		},
+		{
+			desc:                  "Project under deeper namespace",
+			project:               "flightjs/one/Flight",
+			username:              "alex-doe",
+			expectedRootNamespace: "flightjs",
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.desc, func(t *testing.T) {
+			metadata := NewLogMetadata(tc.project, tc.username)
+			require.Equal(t, tc.project, metadata.Project)
+			require.Equal(t, tc.username, metadata.Username)
+			require.Equal(t, tc.expectedRootNamespace, metadata.RootNamespace)
+		})
+	}
+}

internal/command/discover/discover.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 
+	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
@@ -16,19 +17,24 @@ type Command struct {
 	ReadWriter *readwriter.ReadWriter
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	response, err := c.getUserInfo(ctx)
 	if err != nil {
-		return fmt.Errorf("Failed to get username: %v", err)
+		return ctx, fmt.Errorf("Failed to get username: %v", err)
 	}
 
+	metadata := command.LogMetadata{}
 	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 nil
+	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+
+	return ctxWithLogMetadata, nil
 }
 
 func (c *Command) getUserInfo(ctx context.Context) (*discover.Response, error) {

internal/command/discover/discover_test.go

@@ -6,11 +6,13 @@ import (
 	"encoding/json"
 	"fmt"
 	"net/http"
+	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/require"
 
 	"gitlab.com/gitlab-org/gitlab-shell/v14/client/testserver"
+	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
@@ -46,29 +48,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 +83,14 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			err := cmd.Execute(context.Background())
+			ctxWithLogMetadata, 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, ctxWithLogMetadata.Value("metadata").(command.LogMetadata).Username)
 		})
 	}
 }
@@ -123,7 +129,7 @@ func TestFailingExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			err := cmd.Execute(context.Background())
+			_, err := cmd.Execute(context.Background())
 
 			require.Empty(t, buffer.String())
 			require.EqualError(t, err, tc.expectedError)

internal/command/healthcheck/healthcheck.go

@@ -19,20 +19,20 @@ type Command struct {
 	ReadWriter *readwriter.ReadWriter
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	response, err := c.runCheck(ctx)
 	if err != nil {
-		return fmt.Errorf("%v: FAILED - %v", apiMessage, err)
+		return ctx, fmt.Errorf("%v: FAILED - %v", apiMessage, err)
 	}
 
 	fmt.Fprintf(c.ReadWriter.Out, "%v: OK\n", apiMessage)
 
 	if !response.Redis {
-		return fmt.Errorf("%v: FAILED", redisMessage)
+		return ctx, fmt.Errorf("%v: FAILED", redisMessage)
 	}
 
 	fmt.Fprintf(c.ReadWriter.Out, "%v: OK\n", redisMessage)
-	return nil
+	return ctx, nil
 }
 
 func (c *Command) runCheck(ctx context.Context) (*healthcheck.Response, error) {

internal/command/healthcheck/healthcheck_test.go

@@ -53,7 +53,7 @@ func TestExecute(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{Out: buffer},
 	}
 
-	err := cmd.Execute(context.Background())
+	_, err := cmd.Execute(context.Background())
 
 	require.NoError(t, err)
 	require.Equal(t, "Internal API available: OK\nRedis available via internal API: OK\n", buffer.String())
@@ -68,7 +68,7 @@ func TestFailingRedisExecute(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{Out: buffer},
 	}
 
-	err := cmd.Execute(context.Background())
+	_, err := cmd.Execute(context.Background())
 	require.Error(t, err, "Redis available via internal API: FAILED")
 	require.Equal(t, "Internal API available: OK\n", buffer.String())
 }
@@ -82,7 +82,7 @@ func TestFailingAPIExecute(t *testing.T) {
 		ReadWriter: &readwriter.ReadWriter{Out: buffer},
 	}
 
-	err := cmd.Execute(context.Background())
+	_, err := cmd.Execute(context.Background())
 	require.Empty(t, buffer.String())
 	require.EqualError(t, err, "Internal API available: FAILED - Internal API unreachable")
 }

internal/command/lfsauthenticate/lfsauthenticate.go

@@ -8,6 +8,7 @@ import (
 
 	"gitlab.com/gitlab-org/labkit/log"
 
+	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/shared/accessverifier"
@@ -37,10 +38,10 @@ type Payload struct {
 	ExpiresIn int           `json:"expires_in,omitempty"`
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	args := c.Args.SshArgs
 	if len(args) < 3 {
-		return disallowedcommand.Error
+		return ctx, disallowedcommand.Error
 	}
 
 	// e.g. git-lfs-authenticate user/repo.git download
@@ -49,14 +50,20 @@ func (c *Command) Execute(ctx context.Context) error {
 
 	action, err := actionFromOperation(operation)
 	if err != nil {
-		return err
+		return ctx, err
 	}
 
 	accessResponse, err := c.verifyAccess(ctx, action, repo)
 	if err != nil {
-		return err
+		return ctx, err
 	}
 
+	metadata := command.NewLogMetadata(
+		accessResponse.Gitaly.Repo.GlProjectPath,
+		accessResponse.Username,
+	)
+	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+
 	payload, err := c.authenticate(ctx, operation, repo, accessResponse.UserId)
 	if err != nil {
 		// return nothing just like Ruby's GitlabShell#lfs_authenticate does
@@ -65,12 +72,12 @@ func (c *Command) Execute(ctx context.Context) error {
 			log.Fields{"operation": operation, "repo": repo, "user_id": accessResponse.UserId},
 		).WithError(err).Debug("lfsauthenticate: execute: LFS authentication failed")
 
-		return nil
+		return ctxWithLogMetadata, nil
 	}
 
 	fmt.Fprintf(c.ReadWriter.Out, "%s\n", payload)
 
-	return nil
+	return ctxWithLogMetadata, nil
 }
 
 func actionFromOperation(operation string) (commandargs.CommandType, error) {

internal/command/lfsauthenticate/lfsauthenticate_test.go

@@ -11,6 +11,7 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"gitlab.com/gitlab-org/gitlab-shell/v14/client/testserver"
+	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/config"
@@ -54,7 +55,7 @@ func TestFailedRequests(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output},
 			}
 
-			err := cmd.Execute(context.Background())
+			_, err := cmd.Execute(context.Background())
 			require.Error(t, err)
 
 			require.Equal(t, tc.expectedOutput, err.Error())
@@ -109,8 +110,14 @@ func TestLfsAuthenticateRequests(t *testing.T) {
 				}
 
 				body := map[string]interface{}{
-					"gl_id":  glId,
-					"status": true,
+					"gl_id":       glId,
+					"status":      true,
+					"gl_username": "alex-doe",
+					"gitaly": map[string]interface{}{
+						"repository": map[string]interface{}{
+							"gl_project_path": "group/project-path",
+						},
+					},
 				}
 				require.NoError(t, json.NewEncoder(w).Encode(body))
 			},
@@ -145,10 +152,15 @@ func TestLfsAuthenticateRequests(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output},
 			}
 
-			err := cmd.Execute(context.Background())
-			require.NoError(t, err)
+			ctxWithLogMetadata, err := cmd.Execute(context.Background())
 
+			require.NoError(t, err)
 			require.Equal(t, tc.expectedOutput, output.String())
+
+			metadata := ctxWithLogMetadata.Value("metadata").(command.LogMetadata)
+			require.Equal(t, "alex-doe", metadata.Username)
+			require.Equal(t, "group/project-path", metadata.Project)
+			require.Equal(t, "group", metadata.RootNamespace)
 		})
 	}
 }

internal/command/personalaccesstoken/personalaccesstoken.go

@@ -34,10 +34,10 @@ type tokenArgs struct {
 	ExpiresDate string // Calculated, a TTL is passed from command-line.
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	err := c.parseTokenArgs()
 	if err != nil {
-		return err
+		return ctx, err
 	}
 
 	log.WithContextFields(ctx, log.Fields{
@@ -46,13 +46,14 @@ func (c *Command) Execute(ctx context.Context) error {
 
 	response, err := c.getPersonalAccessToken(ctx)
 	if err != nil {
-		return err
+		return ctx, err
 	}
 
 	fmt.Fprint(c.ReadWriter.Out, "Token:   "+response.Token+"\n")
 	fmt.Fprint(c.ReadWriter.Out, "Scopes:  "+strings.Join(response.Scopes, ",")+"\n")
 	fmt.Fprint(c.ReadWriter.Out, "Expires: "+response.ExpiresAt+"\n")
-	return nil
+
+	return ctx, nil
 }
 
 func (c *Command) parseTokenArgs() error {

internal/command/personalaccesstoken/personalaccesstoken_test.go

@@ -167,7 +167,7 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: output, In: input},
 			}
 
-			err := cmd.Execute(context.Background())
+			_, err := cmd.Execute(context.Background())
 
 			if tc.expectedError == "" {
 				require.NoError(t, err)

internal/command/receivepack/gitalycall_test.go

@@ -72,7 +72,7 @@ func TestReceivePack(t *testing.T) {
 				ctx := correlation.ContextWithCorrelation(context.Background(), "a-correlation-id")
 				ctx = correlation.ContextWithClientName(ctx, "gitlab-shell-tests")
 
-				err := cmd.Execute(ctx)
+				_, err := cmd.Execute(ctx)
 				require.NoError(t, err)
 
 				if tc.username != "" {

internal/command/receivepack/receivepack.go

@@ -3,6 +3,7 @@ package receivepack
 import (
 	"context"
 
+	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/commandargs"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/githttp"
 	"gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/readwriter"
@@ -18,18 +19,23 @@ type Command struct {
 	ReadWriter *readwriter.ReadWriter
 }
 
-func (c *Command) Execute(ctx context.Context) error {
+func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 	args := c.Args.SshArgs
 	if len(args) != 2 {
-		return disallowedcommand.Error
+		return ctx, disallowedcommand.Error
 	}
 
 	repo := args[1]
 	response, err := c.verifyAccess(ctx, repo)
 	if err != nil {
-		return err
+		return ctx, err
 	}
 
+	ctxWithLogMetadata := context.WithValue(ctx, "metadata", command.NewLogMetadata(
+		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 +48,7 @@ func (c *Command) Execute(ctx context.Context) error {
 				Response:   response,
 			}
 
-			return cmd.Execute(ctx)
+			return ctxWithLogMetadata, cmd.Execute(ctx)
 		}
 
 		customAction := customaction.Command{
@@ -50,10 +56,10 @@ func (c *Command) Execute(ctx context.Context) error {
 			ReadWriter: c.ReadWriter,
 			EOFSent:    true,
 		}
-		return customAction.Execute(ctx, response)
+		return ctxWithLogMetadata, customAction.Execute(ctx, response)
 	}
 
-	return c.performGitalyCall(ctx, response)
+	return ctxWithLogMetadata, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {