Merge branch 'ashmckenzie/log-metadata-refactor' into 'main'

Log metadata refactor

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



Merged-by: Ash McKenzie <amckenzie@gitlab.com>
Approved-by: Alejandro Rodríguez <alejandro@gitlab.com>
Approved-by: Igor Drozdov <idrozdov@gitlab.com>

internal/command/command.go

@@ -17,11 +17,15 @@ type Command interface {
 }
 
 type LogMetadata struct {
-	Username      string `json:"username"`
 	Project       string `json:"project,omitempty"`
 	RootNamespace string `json:"root_namespace,omitempty"`
 }
 
+type LogData struct {
+	Username string      `json:"username"`
+	Meta     LogMetadata `json:"meta"`
+}
+
 func CheckForVersionFlag(osArgs []string, version, buildTime string) {
 	// We can't use the flag library because gitlab-shell receives other arguments
 	// that confuse the parser.
@@ -69,7 +73,7 @@ func Setup(serviceName string, config *config.Config) (context.Context, func())
 	}
 }
 
-func NewLogMetadata(project, username string) LogMetadata {
+func NewLogData(project, username string) LogData {
 	rootNameSpace := ""
 
 	if len(project) > 0 {
@@ -82,9 +86,11 @@ func NewLogMetadata(project, username string) LogMetadata {
 		}
 	}
 
-	return LogMetadata{
-		Username:      username,
-		Project:       project,
-		RootNamespace: rootNameSpace,
+	return LogData{
+		Username: username,
+		Meta: LogMetadata{
+			Project:       project,
+			RootNamespace: rootNameSpace,
+		},
 	}
 }

internal/command/command_test.go

@@ -78,7 +78,7 @@ func addAdditionalEnv(envMap map[string]string) func() {
 	}
 }
 
-func TestNewLogMetadata(t *testing.T) {
+func TestNewLogData(t *testing.T) {
 	testCases := []struct {
 		desc                  string
 		project               string
@@ -107,10 +107,10 @@ func TestNewLogMetadata(t *testing.T) {
 
 	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)
+			data := NewLogData(tc.project, tc.username)
+			require.Equal(t, tc.username, data.Username)
+			require.Equal(t, tc.project, data.Meta.Project)
+			require.Equal(t, tc.expectedRootNamespace, data.Meta.RootNamespace)
 		})
 	}
 }

internal/command/discover/discover.go

@@ -23,18 +23,18 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, fmt.Errorf("Failed to get username: %v", err)
 	}
 
-	metadata := command.LogMetadata{}
+	logData := command.LogData{}
 	if response.IsAnonymous() {
-		metadata.Username = "Anonymous"
+		logData.Username = "Anonymous"
 		fmt.Fprintf(c.ReadWriter.Out, "Welcome to GitLab, Anonymous!\n")
 	} else {
-		metadata.Username = response.Username
+		logData.Username = response.Username
 		fmt.Fprintf(c.ReadWriter.Out, "Welcome to GitLab, @%s!\n", response.Username)
 	}
 
-	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+	ctxWithLogData := context.WithValue(ctx, "logData", logData)
 
-	return ctxWithLogMetadata, nil
+	return ctxWithLogData, nil
 }
 
 func (c *Command) getUserInfo(ctx context.Context) (*discover.Response, error) {

internal/command/discover/discover_test.go

@@ -83,14 +83,14 @@ func TestExecute(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{Out: buffer},
 			}
 
-			ctxWithLogMetadata, err := cmd.Execute(context.Background())
+			ctxWithLogData, 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, expectedOutput, buffer.String())
-			require.Equal(t, expectedUsername, ctxWithLogMetadata.Value("metadata").(command.LogMetadata).Username)
+			require.Equal(t, expectedUsername, ctxWithLogData.Value("logData").(command.LogData).Username)
 		})
 	}
 }

internal/command/lfsauthenticate/lfsauthenticate.go

@@ -58,11 +58,11 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
-	metadata := command.NewLogMetadata(
+	logData := command.NewLogData(
 		accessResponse.Gitaly.Repo.GlProjectPath,
 		accessResponse.Username,
 	)
-	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+	ctxWithLogData := context.WithValue(ctx, "logData", logData)
 
 	payload, err := c.authenticate(ctx, operation, repo, accessResponse.UserId)
 	if err != nil {
@@ -72,12 +72,12 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 			log.Fields{"operation": operation, "repo": repo, "user_id": accessResponse.UserId},
 		).WithError(err).Debug("lfsauthenticate: execute: LFS authentication failed")
 
-		return ctxWithLogMetadata, nil
+		return ctxWithLogData, nil
 	}
 
 	fmt.Fprintf(c.ReadWriter.Out, "%s\n", payload)
 
-	return ctxWithLogMetadata, nil
+	return ctxWithLogData, nil
 }
 
 func actionFromOperation(operation string) (commandargs.CommandType, error) {

internal/command/lfsauthenticate/lfsauthenticate_test.go

@@ -152,15 +152,15 @@ func TestLfsAuthenticateRequests(t *testing.T) {
 				ReadWriter: &readwriter.ReadWriter{ErrOut: output, Out: output},
 			}
 
-			ctxWithLogMetadata, err := cmd.Execute(context.Background())
+			ctxWithLogData, 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)
+			data := ctxWithLogData.Value("logData").(command.LogData)
+			require.Equal(t, "alex-doe", data.Username)
+			require.Equal(t, "group/project-path", data.Meta.Project)
+			require.Equal(t, "group", data.Meta.RootNamespace)
 		})
 	}
 }

internal/command/receivepack/receivepack.go

@@ -31,7 +31,7 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
-	ctxWithLogMetadata := context.WithValue(ctx, "metadata", command.NewLogMetadata(
+	ctxWithLogData := context.WithValue(ctx, "logData", command.NewLogData(
 		response.Gitaly.Repo.GlProjectPath,
 		response.Username,
 	))
@@ -48,7 +48,7 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 				Response:   response,
 			}
 
-			return ctxWithLogMetadata, cmd.Execute(ctx)
+			return ctxWithLogData, cmd.Execute(ctx)
 		}
 
 		customAction := customaction.Command{
@@ -56,10 +56,10 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 			ReadWriter: c.ReadWriter,
 			EOFSent:    true,
 		}
-		return ctxWithLogMetadata, customAction.Execute(ctx, response)
+		return ctxWithLogData, customAction.Execute(ctx, response)
 	}
 
-	return ctxWithLogMetadata, c.performGitalyCall(ctx, response)
+	return ctxWithLogData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/receivepack/receivepack_test.go

@@ -21,13 +21,13 @@ func TestAllowedAccess(t *testing.T) {
 	cmd, _ := setup(t, "1", requests)
 	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
 
-	ctxWithLogMetadata, err := cmd.Execute(context.Background())
+	ctxWithLogData, err := cmd.Execute(context.Background())
 
 	require.NoError(t, err)
-	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)
+	data := ctxWithLogData.Value("logData").(command.LogData)
+	require.Equal(t, "alex-doe", data.Username)
+	require.Equal(t, "group/project-path", data.Meta.Project)
+	require.Equal(t, "group", data.Meta.RootNamespace)
 }
 
 func TestForbiddenAccess(t *testing.T) {

internal/command/uploadarchive/uploadarchive.go

@@ -29,13 +29,13 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
-	metadata := command.NewLogMetadata(
+	logData := command.NewLogData(
 		response.Gitaly.Repo.GlProjectPath,
 		response.Username,
 	)
-	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+	ctxWithLogData := context.WithValue(ctx, "logData", logData)
 
-	return ctxWithLogMetadata, c.performGitalyCall(ctx, response)
+	return ctxWithLogData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/uploadarchive/uploadarchive_test.go

@@ -21,13 +21,13 @@ func TestAllowedAccess(t *testing.T) {
 	cmd, _ := setup(t, "1", requests)
 	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
 
-	ctxWithLogMetadata, err := cmd.Execute(context.Background())
+	ctxWithLogData, err := cmd.Execute(context.Background())
 
 	require.NoError(t, err)
-	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)
+	data := ctxWithLogData.Value("logData").(command.LogData)
+	require.Equal(t, "alex-doe", data.Username)
+	require.Equal(t, "group/project-path", data.Meta.Project)
+	require.Equal(t, "group", data.Meta.RootNamespace)
 }
 
 func TestForbiddenAccess(t *testing.T) {

internal/command/uploadpack/uploadpack.go

@@ -30,11 +30,11 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 		return ctx, err
 	}
 
-	metadata := command.NewLogMetadata(
+	logData := command.NewLogData(
 		response.Gitaly.Repo.GlProjectPath,
 		response.Username,
 	)
-	ctxWithLogMetadata := context.WithValue(ctx, "metadata", metadata)
+	ctxWithLogData := context.WithValue(ctx, "logData", logData)
 
 	if response.IsCustomAction() {
 		customAction := customaction.Command{
@@ -42,10 +42,10 @@ func (c *Command) Execute(ctx context.Context) (context.Context, error) {
 			ReadWriter: c.ReadWriter,
 			EOFSent:    false,
 		}
-		return ctxWithLogMetadata, customAction.Execute(ctx, response)
+		return ctxWithLogData, customAction.Execute(ctx, response)
 	}
 
-	return ctxWithLogMetadata, c.performGitalyCall(ctx, response)
+	return ctxWithLogData, c.performGitalyCall(ctx, response)
 }
 
 func (c *Command) verifyAccess(ctx context.Context, repo string) (*accessverifier.Response, error) {

internal/command/uploadpack/uploadpack_test.go

@@ -21,13 +21,13 @@ func TestAllowedAccess(t *testing.T) {
 	cmd, _ := setup(t, "1", requests)
 	cmd.Config.GitalyClient.InitSidechannelRegistry(context.Background())
 
-	ctxWithLogMetadata, err := cmd.Execute(context.Background())
+	ctxWithLogData, err := cmd.Execute(context.Background())
 
 	require.NoError(t, err)
-	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)
+	data := ctxWithLogData.Value("logData").(command.LogData)
+	require.Equal(t, "alex-doe", data.Username)
+	require.Equal(t, "group/project-path", data.Meta.Project)
+	require.Equal(t, "group", data.Meta.RootNamespace)
 }
 
 func TestForbiddenAccess(t *testing.T) {

internal/sshd/session.go

@@ -52,7 +52,7 @@ type exitStatusReq struct {
 }
 
 func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) (context.Context, error) {
-	ctxWithLogMetadata := ctx
+	ctxWithLogData := ctx
 	ctxlog := log.ContextLogger(ctx)
 
 	ctxlog.Debug("session: handle: entering request loop")
@@ -73,13 +73,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
-			ctxWithLogMetadata, shouldContinue, err = s.handleExec(ctx, req)
+			ctxWithLogData, 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
-			ctxWithLogMetadata, status, err = s.handleShell(ctx, req)
+			ctxWithLogData, status, err = s.handleShell(ctx, req)
 			s.exit(ctx, status)
 		default:
 			// Ignore unknown requests but don't terminate the session
@@ -102,7 +102,7 @@ func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) (con
 
 	ctxlog.Debug("session: handle: exiting request loop")
 
-	return ctxWithLogMetadata, err
+	return ctxWithLogData, err
 }
 
 func (s *session) handleEnv(ctx context.Context, req *ssh.Request) (bool, error) {
@@ -144,10 +144,10 @@ func (s *session) handleExec(ctx context.Context, req *ssh.Request) (context.Con
 
 	s.execCmd = execRequest.Command
 
-	ctxWithLogMetadata, status, err := s.handleShell(ctx, req)
-	s.exit(ctxWithLogMetadata, status)
+	ctxWithLogData, status, err := s.handleShell(ctx, req)
+	s.exit(ctxWithLogData, status)
 
-	return ctxWithLogMetadata, false, err
+	return ctxWithLogData, false, err
 }
 
 func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Context, uint32, error) {
@@ -201,7 +201,7 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Co
 	}).Info("session: handleShell: executing command")
 	metrics.SshdSessionEstablishedDuration.Observe(establishSessionDuration)
 
-	ctxWithLogMetadata, err := cmd.Execute(ctx)
+	ctxWithLogData, err := cmd.Execute(ctx)
 	if err != nil {
 		grpcStatus := grpcstatus.Convert(err)
 		if grpcStatus.Code() != grpccodes.Internal {
@@ -213,7 +213,7 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) (context.Co
 
 	ctxlog.Info("session: handleShell: command executed successfully")
 
-	return ctxWithLogMetadata, 0, nil
+	return ctxWithLogData, 0, nil
 }
 
 func (s *session) toStderr(ctx context.Context, format string, args ...interface{}) {

internal/sshd/sshd.go

@@ -194,7 +194,7 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 	started := time.Now()
 	conn := newConnection(s.Config, nconn)
 
-	var ctxWithLogMetadata context.Context
+	var ctxWithLogData context.Context
 
 	conn.handle(ctx, s.serverConfig.get(ctx), func(ctx context.Context, sconn *ssh.ServerConn, channel ssh.Channel, requests <-chan *ssh.Request) error {
 		session := &session{
@@ -209,12 +209,17 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 		}
 
 		var err error
-		ctxWithLogMetadata, err = session.handle(ctx, requests)
+		ctxWithLogData, err = session.handle(ctx, requests)
 
 		return err
 	})
 
-	ctxlog.WithFields(log.Fields{"duration_s": time.Since(started).Seconds(), "meta": extractMetaDataFromContext(ctxWithLogMetadata)}).Info("access: finish")
+	logData := extractDataFromContext(ctxWithLogData)
+
+	ctxlog.WithFields(log.Fields{
+		"duration_s": time.Since(started).Seconds(),
+		"meta":       logData.Meta,
+	}).Info("access: finish")
 }
 
 func (s *Server) proxyPolicy() (proxyproto.PolicyFunc, error) {
@@ -236,18 +241,18 @@ func (s *Server) proxyPolicy() (proxyproto.PolicyFunc, error) {
 	}
 }
 
-func extractMetaDataFromContext(ctx context.Context) command.LogMetadata {
-	metadata := command.LogMetadata{}
+func extractDataFromContext(ctx context.Context) command.LogData {
+	logData := command.LogData{}
 
 	if ctx == nil {
-		return metadata
+		return logData
 	}
 
-	if ctx.Value("metadata") != nil {
-		metadata = ctx.Value("metadata").(command.LogMetadata)
+	if ctx.Value("logData") != nil {
+		logData = ctx.Value("logData").(command.LogData)
 	}
 
-	return metadata
+	return logData
 }
 
 func staticProxyPolicy(policy proxyproto.Policy) proxyproto.PolicyFunc {

internal/sshd/sshd_test.go

@@ -350,28 +350,28 @@ func TestLoginGraceTime(t *testing.T) {
 }
 
 func TestExtractMetaDataFromContext(t *testing.T) {
+	username := "alex-doe"
 	rootNameSpace := "flightjs"
 	project := fmt.Sprintf("%s/Flight", rootNameSpace)
-	username := "alex-doe"
-	ctx := context.WithValue(context.Background(), "metadata", command.NewLogMetadata(project, username))
+	ctx := context.WithValue(context.Background(), "logData", command.NewLogData(project, username))
 
-	metadata := extractMetaDataFromContext(ctx)
+	data := extractDataFromContext(ctx)
 
-	require.Equal(t, command.LogMetadata{Project: project, Username: username, RootNamespace: rootNameSpace}, metadata)
+	require.Equal(t, command.LogData{Username: username, Meta: command.LogMetadata{Project: project, RootNamespace: rootNameSpace}}, data)
 }
 
 func TestExtractMetaDataFromContextWithoutMetaData(t *testing.T) {
-	metadata := extractMetaDataFromContext(context.Background())
+	data := extractDataFromContext(context.Background())
 
-	require.Equal(t, command.LogMetadata{}, metadata)
+	require.Equal(t, command.LogData{}, data)
 }
 
 func TestExtractMetaDataFromNilContext(t *testing.T) {
 	var ctx context.Context
 
-	metadata := extractMetaDataFromContext(ctx)
+	data := extractDataFromContext(ctx)
 
-	require.Equal(t, command.LogMetadata{}, metadata)
+	require.Equal(t, command.LogData{}, data)
 }
 
 func setupServer(t *testing.T) *Server {