diff options
author | Igor Drozdov <idrozdov@gitlab.com> | 2021-09-28 19:08:34 +0000 |
---|---|---|
committer | Igor Drozdov <idrozdov@gitlab.com> | 2021-09-28 19:08:34 +0000 |
commit | 6d146c217dc1ba78aa4a0c47c59b5b2e7be774d9 (patch) | |
tree | 0d70e3e65b0192089d6dd04b0ac8120341ba7de8 | |
parent | a1ae9e5ad2900d512a58ce64f4ad0f02769c3edd (diff) | |
parent | f40ddda89781aeb156f9b36bdb7d733c55b363c0 (diff) | |
download | gitlab-shell-6d146c217dc1ba78aa4a0c47c59b5b2e7be774d9.tar.gz |
Merge branch '499-log-me-more' into 'main'
Add more logging to gitlab-sshd
See merge request gitlab-org/gitlab-shell!531
-rw-r--r-- | README.md | 15 | ||||
-rw-r--r-- | cmd/gitlab-shell/command/command_test.go | 2 | ||||
-rw-r--r-- | internal/command/commandargs/shell.go | 13 | ||||
-rw-r--r-- | internal/sshd/connection.go | 10 | ||||
-rw-r--r-- | internal/sshd/session.go | 46 | ||||
-rw-r--r-- | internal/sshd/session_test.go | 4 | ||||
-rw-r--r-- | internal/sshd/sshd.go | 14 |
7 files changed, 75 insertions, 29 deletions
@@ -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") } |