Currently, what we log to `gitlab-shell.log`, especially in `gitlab-sshd`, is haphazard. We need to audit the logs and ensure that they provide all the information we need to support an instance running in production. In particular, we want to be able to track the lifecycle of individual SSH connections and channels,from looking up the SSH key to the command(s) that are run, and the Gitaly RPCs they invoke. - [x] Using `log.ContextLogger` everywhere it's appropriate: https://gitlab.com/gitlab-org/labkit/-/blob/master/log/logger.go - [x] Replacing all `Infof/Warnf/Debugf` calls with `Info/Warn/Debug`, moving the variable component into `WithField[s]` instead - [x] Audit all code paths and ensure that the logging is sufficient for us to debug them in production - [x] Add request/response size to gitlab-shell logs https://gitlab.com/gitlab-org/gitlab/-/issues/338497 ## Code path audit For `gitlab-sshd`, these are the files we principally have to be interested in: ``` / ├cmd/ [OK] ├── gitlab-sshd/ [OK] │ └── main.go [OK] ├internal/ ├── command/ │   ├── commandargs/ │   │   ├── command_args.go [OK] │   │   └── shell.go [!!] │   ├── command.go [OK] │   ├── lfsauthenticate/ │   │   ├── lfsauthenticate.go [!!] │   ├── personalaccesstoken/ │   │   ├── personalaccesstoken.go [!!] │   ├── readwriter/ [OK] │   │   └── readwriter.go [OK] │   ├── receivepack/ │   │   ├── gitalycall.go [OK] - can be done in `gc.RunGitalyCommand` │   │   ├── receivepack.go [!!] │   ├── shared/ │   │   ├── accessverifier/ │   │   │   ├── accessverifier.go [??] - probably fine if everything calling Verify already logs │   │   ├── customaction/ │   │   │   ├── customaction.go [!!] │   │   └── disallowedcommand/ [OK] │   │   └── disallowedcommand.go [OK] │   ├── twofactorrecover/ │   │   ├── twofactorrecover.go [!!] │   ├── twofactorverify/ │   │   ├── twofactorverify.go [!!] │   ├── uploadarchive/ │   │   ├── gitalycall.go [OK] - can be done in `gc.RunGitalyCommand` │   │   ├── uploadarchive.go [!!] │   └── uploadpack/ │   ├── gitalycall.go [OK] - can be done in `gc.RunGitalyCommand` │   ├── uploadpack.go [!!] ├── config/ │   ├── config.go [!!] - one thing we could improve but unsure about order dependency ├── console/ │   ├── console.go [OK] ├── gitlabnet/ │   ├── client.go [!!] │ ├── */ [OK] - no errors swallowed here ├── handler/ │   ├── exec.go [!!] ├── keyline/ │   ├── key_line.go [OK] ├── logger/ │   ├── logger.go [OK] ├── metrics/ │   └── metrics.go [OK] ├── pktline/ │   ├── pktline.go [OK] ├── sshd/ [!!] │   ├── connection.go │   ├── server_config.go │   ├── session.go │   ├── sshd.go ├── sshenv/ [OK] │   ├── sshenv.go [OK] ``` I suppose I'll start by going through each one and adding any logging that seems missing. Since each connection gets its own correlation-id, we don't need to worry so much about logging data like client IP in every log message; just the initial message for the connection. Problems noted: - [x] `internal/command/commandargs/shell.go` - `validate` method swallows the actual error by using `isValidSSHCommand` - [x] `internal/command/lfsauthenticate/lfsauthenticate.go` - [x] Errors from `authenticate` method are swallowed. - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] `internal/command/personalaccesstoken/personalaccesstoken.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] Errors & outcomes need to be evident in the logs as well as in the user's console output - [x] `internal/command/receivepack/receivepack.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] Need to log custom-action status - [x] `internal/command/shared/customaction/customaction.go` - [x] Some logging, but could do with fleshing out - [x] `internal/command/twofactorrecover/twofactorrecover.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] Errors & outcomes need to be evident in the logs as well as in the user's console output - [x] `internal/command/twofactorverify/twofactorverify.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] Errors & outcomes need to be evident in the logs as well as in the user's console output - [x] `internal/command/uploadarchive/uploadarchive.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] `internal/command/uploadpack/uploadpack.go` - [x] No around-command logging; will need fixing if not addressed systematically a level up - [x] No intra-command logging - [x] Need to log custom-action status - [x] `internal/config/config.go` - [x] Would be nice to log when we're applying `SSL_CERT_DIR` - [x] Logging interceptors as well as tracing interceptors for HTTP? - [x] `internal/gitlabnet/client.go` - [x] Swallows actual JSON parser error in `client.ParseJSON` https://gitlab.com/gitlab-org/gitlab-shell/-/issues/533 - [x] `internal/handler/exec.go` - [x] Needs to log what's happening in `RunGitalyCommand` - [x] Logging interceptors as well as tracing interceptors for gRPC? - [x] `internal/sshd/*.go` - [x] `connection.go` - [x] `session.go` - [x] `server_config.go` - [x] `sshd.go`