Merge branch '499-log-me-more' into 'main'

Add more logging to gitlab-sshd

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

7 files changed, 75 insertions, 29 deletions

diff --git a/README.md b/README.md
index 7847377..a45b30d 100644
--- a/README.md
+++ b/README.md
@@ -98,6 +98,21 @@ environment.
 
 Starting with GitLab 8.12, GitLab supports Git LFS authentication through SSH.
 
+## Logging Guidelines
+
+In general, it should be possible to determine the structure, but not content,
+of a gitlab-shell or gitlab-sshd session just from inspecting the logs. Some
+guidelines:
+
+- We use [`gitlab.com/gitlab-org/labkit/log`](https://pkg.go.dev/gitlab.com/gitlab-org/labkit/log)
+  for logging functionality
+- **Always** include a correlation ID
+- Log messages should be invariant and unique. Include accessory information in
+  fields, using `log.WithField`, `log.WithFields`, or `log.WithError`.
+- Log success cases as well as error cases
+- Logging too much is better than not logging enough. If a message seems too
+  verbose, consider reducing the log level before removing the message.
+
 ## Releasing
 
 See [PROCESS.md](./PROCESS.md)
diff --git a/cmd/gitlab-shell/command/command_test.go b/cmd/gitlab-shell/command/command_test.go
index 2db644b..2aeee59 100644
--- a/cmd/gitlab-shell/command/command_test.go
+++ b/cmd/gitlab-shell/command/command_test.go
@@ -267,7 +267,7 @@ func TestParseFailure(t *testing.T) {
 			executable:    &executable.Executable{Name: executable.GitlabShell},
 			env:           sshenv.Env{IsSSHConnection: true, OriginalCommand: `git receive-pack "`},
 			arguments:     []string{},
-			expectedError: "Invalid SSH command",
+			expectedError: "Invalid SSH command: invalid command line string",
 		},
 	}
 
diff --git a/internal/command/commandargs/shell.go b/internal/command/commandargs/shell.go
index 589f58d..7a76be5 100644
--- a/internal/command/commandargs/shell.go
+++ b/internal/command/commandargs/shell.go
@@ -1,7 +1,7 @@
 package commandargs
 
 import (
-	"errors"
+	"fmt"
 	"regexp"
 
 	"github.com/mattn/go-shellwords"
@@ -49,21 +49,16 @@ func (s *Shell) GetArguments() []string {
 
 func (s *Shell) validate() error {
 	if !s.Env.IsSSHConnection {
-		return errors.New("Only SSH allowed")
+		return fmt.Errorf("Only SSH allowed")
 	}
 
-	if !s.isValidSSHCommand() {
-		return errors.New("Invalid SSH command")
+	if err := s.ParseCommand(s.Env.OriginalCommand); err != nil {
+		return fmt.Errorf("Invalid SSH command: %w", err)
 	}
 
 	return nil
 }
 
-func (s *Shell) isValidSSHCommand() bool {
-	err := s.ParseCommand(s.Env.OriginalCommand)
-	return err == nil
-}
-
 func (s *Shell) parseWho() {
 	for _, argument := range s.Arguments {
 		if keyId := tryParseKeyId(argument); keyId != "" {
diff --git a/internal/sshd/connection.go b/internal/sshd/connection.go
index 1d91a6c..c8f5c00 100644
--- a/internal/sshd/connection.go
+++ b/internal/sshd/connection.go
@@ -29,21 +29,26 @@ func newConnection(maxSessions int64, remoteAddr string) *connection {
 }
 
 func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, handler channelHandler) {
+	ctxlog := log.WithContextFields(ctx, log.Fields{"remote_addr": c.remoteAddr})
+
 	defer metrics.SshdConnectionDuration.Observe(time.Since(c.begin).Seconds())
 
 	for newChannel := range chans {
+		ctxlog.WithField("channel_type", newChannel.ChannelType).Info("connection: handle: new channel requested")
 		if newChannel.ChannelType() != "session" {
+			ctxlog.Info("connection: handle: unknown channel type")
 			newChannel.Reject(ssh.UnknownChannelType, "unknown channel type")
 			continue
 		}
 		if !c.concurrentSessions.TryAcquire(1) {
+			ctxlog.Info("connection: handle: too many concurrent sessions")
 			newChannel.Reject(ssh.ResourceShortage, "too many concurrent sessions")
 			metrics.SshdHitMaxSessions.Inc()
 			continue
 		}
 		channel, requests, err := newChannel.Accept()
 		if err != nil {
-			log.WithError(err).Info("could not accept channel")
+			ctxlog.WithError(err).Error("connection: handle: accepting channel failed")
 			c.concurrentSessions.Release(1)
 			continue
 		}
@@ -54,11 +59,12 @@ func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, ha
 			// Prevent a panic in a single session from taking out the whole server
 			defer func() {
 				if err := recover(); err != nil {
-					log.WithContextFields(ctx, log.Fields{"recovered_error": err, "address": c.remoteAddr}).Warn("panic handling session")
+					ctxlog.WithField("recovered_error", err).Warn("panic handling session")
 				}
 			}()
 
 			handler(ctx, channel, requests)
+			ctxlog.Info("connection: handle: done")
 		}()
 	}
 }
diff --git a/internal/sshd/session.go b/internal/sshd/session.go
index d5a0174..b26edc5 100644
--- a/internal/sshd/session.go
+++ b/internal/sshd/session.go
@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 
+	"gitlab.com/gitlab-org/labkit/log"
 	"golang.org/x/crypto/ssh"
 
 	shellCmd "gitlab.com/gitlab-org/gitlab-shell/cmd/gitlab-shell/command"
@@ -40,16 +41,27 @@ type exitStatusReq struct {
 }
 
 func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) {
+	ctxlog := log.ContextLogger(ctx)
+
+	ctxlog.Debug("session: handle: entering request loop")
+
 	for req := range requests {
+		sessionLog := ctxlog.WithFields(log.Fields{
+			"bytesize":   len(req.Payload),
+			"type":       req.Type,
+			"want_reply": req.WantReply,
+		})
+		sessionLog.Debug("session: handle: request received")
+
 		var shouldContinue bool
 		switch req.Type {
 		case "env":
-			shouldContinue = s.handleEnv(req)
+			shouldContinue = s.handleEnv(ctx, req)
 		case "exec":
 			shouldContinue = s.handleExec(ctx, req)
 		case "shell":
 			shouldContinue = false
-			s.exit(s.handleShell(ctx, req))
+			s.exit(ctx, s.handleShell(ctx, req))
 		default:
 			// Ignore unknown requests but don't terminate the session
 			shouldContinue = true
@@ -58,18 +70,23 @@ func (s *session) handle(ctx context.Context, requests <-chan *ssh.Request) {
 			}
 		}
 
+		sessionLog.WithField("should_continue", shouldContinue).Debug("session: handle: request processed")
+
 		if !shouldContinue {
 			s.channel.Close()
 			break
 		}
 	}
+
+	ctxlog.Debug("session: handle: exiting request loop")
 }
 
-func (s *session) handleEnv(req *ssh.Request) bool {
+func (s *session) handleEnv(ctx context.Context, req *ssh.Request) bool {
 	var accepted bool
 	var envRequest envRequest
 
 	if err := ssh.Unmarshal(req.Payload, &envRequest); err != nil {
+		log.ContextLogger(ctx).WithError(err).Error("session: handleEnv: failed to unmarshal request")
 		return false
 	}
 
@@ -85,6 +102,10 @@ func (s *session) handleEnv(req *ssh.Request) bool {
 		req.Reply(accepted, []byte{})
 	}
 
+	log.WithContextFields(
+		ctx, log.Fields{"accepted": accepted, "env_request": envRequest},
+	).Debug("session: handleEnv: processed")
+
 	return true
 }
 
@@ -96,7 +117,8 @@ func (s *session) handleExec(ctx context.Context, req *ssh.Request) bool {
 
 	s.execCmd = execRequest.Command
 
-	s.exit(s.handleShell(ctx, req))
+	s.exit(ctx, s.handleShell(ctx, req))
+
 	return false
 }
 
@@ -119,28 +141,30 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) uint32 {
 	}
 
 	cmd, err := shellCmd.NewWithKey(s.gitlabKeyId, env, s.cfg, rw)
-
 	if err != nil {
 		if !errors.Is(err, disallowedcommand.Error) {
-			s.toStderr("Failed to parse command: %v\n", err.Error())
+			s.toStderr(ctx, "Failed to parse command: %v\n", err.Error())
 		}
-		s.toStderr("Unknown command: %v\n", s.execCmd)
+		s.toStderr(ctx, "Unknown command: %v\n", s.execCmd)
 		return 128
 	}
 
 	if err := cmd.Execute(ctx); err != nil {
-		s.toStderr("remote: ERROR: %v\n", err.Error())
+		s.toStderr(ctx, "remote: ERROR: %v\n", err.Error())
 		return 1
 	}
 
 	return 0
 }
 
-func (s *session) toStderr(format string, args ...interface{}) {
-	fmt.Fprintf(s.channel.Stderr(), format, args...)
+func (s *session) toStderr(ctx context.Context, format string, args ...interface{}) {
+	out := fmt.Sprintf(format, args...)
+	log.WithContextFields(ctx, log.Fields{"stderr": out}).Debug("session: toStderr: output")
+	fmt.Fprint(s.channel.Stderr(), out)
 }
 
-func (s *session) exit(status uint32) {
+func (s *session) exit(ctx context.Context, status uint32) {
+	log.WithContextFields(ctx, log.Fields{"exit_status": status}).Info("session: exit: exiting")
 	req := exitStatusReq{ExitStatus: status}
 
 	s.channel.CloseWrite()
diff --git a/internal/sshd/session_test.go b/internal/sshd/session_test.go
index b014c0c..f135825 100644
--- a/internal/sshd/session_test.go
+++ b/internal/sshd/session_test.go
@@ -86,7 +86,7 @@ func TestHandleEnv(t *testing.T) {
 			s := &session{gitProtocolVersion: "1"}
 			r := &ssh.Request{Payload: tc.payload}
 
-			require.Equal(t, s.handleEnv(r), tc.expectedResult)
+			require.Equal(t, s.handleEnv(context.Background(), r), tc.expectedResult)
 			require.Equal(t, s.gitProtocolVersion, tc.expectedProtocolVersion)
 		})
 	}
@@ -145,7 +145,7 @@ func TestHandleShell(t *testing.T) {
 		{
 			desc:             "fails to parse command",
 			cmd:              `\`,
-			errMsg:           "Failed to parse command: Invalid SSH command\nUnknown command: \\\n",
+			errMsg:           "Failed to parse command: Invalid SSH command: invalid command line string\nUnknown command: \\\n",
 			gitlabKeyId:      "root",
 			expectedExitCode: 128,
 		}, {
diff --git a/internal/sshd/sshd.go b/internal/sshd/sshd.go
index 92a9c2b..19fa661 100644
--- a/internal/sshd/sshd.go
+++ b/internal/sshd/sshd.go
@@ -149,19 +149,23 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 	defer s.wg.Done()
 	defer nconn.Close()
 
+	ctx, cancel := context.WithCancel(correlation.ContextWithCorrelation(ctx, correlation.SafeRandomID()))
+	defer cancel()
+
+	ctxlog := log.WithContextFields(ctx, log.Fields{"remote_addr": remoteAddr})
+
 	// Prevent a panic in a single connection from taking out the whole server
 	defer func() {
 		if err := recover(); err != nil {
-			log.WithContextFields(ctx, log.Fields{"recovered_error": err, "address": remoteAddr}).Warn("panic handling session")
+			ctxlog.Warn("panic handling session")
 		}
 	}()
 
-	ctx, cancel := context.WithCancel(correlation.ContextWithCorrelation(ctx, correlation.SafeRandomID()))
-	defer cancel()
+	ctxlog.Info("server: handleConn: start")
 
 	sconn, chans, reqs, err := ssh.NewServerConn(nconn, s.serverConfig.get(ctx))
 	if err != nil {
-		log.ContextLogger(ctx).WithError(err).Info("Failed to initialize SSH connection")
+		ctxlog.WithError(err).Error("server: handleConn: failed to initialize SSH connection")
 		return
 	}
 
@@ -178,4 +182,6 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 
 		session.handle(ctx, requests)
 	})
+
+	ctxlog.Info("server: handleConn: done")
 }