## Summary When a connection ends, gitlab-sshd logs an `access: finish` line next to `duration_s` and `written_bytes`. That line is meant to say who did what, but it carries neither the user nor the project: `meta` is always `{}` and there is no username field at all. That holds for every command: clone, fetch, push, `git archive --remote`, `git-lfs-authenticate`, `git-lfs-transfer` and a plain `ssh git@host`. Only `written_bytes` gets through, because gitlab-sshd sets it itself. ## Steps to reproduce From a clean checkout of `main`, save the test below as `internal/sshd/access_finish_repro_test.go` and run: ```shell go test ./internal/sshd/ -run TestAccessFinishRepro -count=1 -v ``` The test only uses the package's own test helpers. It runs `git-receive-pack` through gitlab-sshd for a user (`alex-doe`) and a project (`flightjs/Flight`) that `/api/v4/internal/allowed` returns, then prints the `access: finish` line the connection logs. <details> <summary><code>internal/sshd/access_finish_repro_test.go</code></summary> ```go package sshd import ( "bytes" "context" "encoding/json" "fmt" "log/slog" "net/http" "path" "testing" "time" "github.com/stretchr/testify/require" "golang.org/x/crypto/ssh" "gitlab.com/gitlab-org/gitlab-shell/v14/client/testserver" "gitlab.com/gitlab-org/gitlab-shell/v14/internal/config" "gitlab.com/gitlab-org/gitlab-shell/v14/internal/testhelper" ) // Runs git-receive-pack through gitlab-sshd for a user and a project the // internal API names, and prints the "access: finish" line the connection // logs. func TestAccessFinishRepro(t *testing.T) { buf := &syncBuffer{} originalDefault := slog.Default() slog.SetDefault(slog.New(slog.NewJSONHandler(buf, nil))) t.Cleanup(func() { slog.SetDefault(originalDefault) }) testRoot := testhelper.PrepareTestRootDir(t) gitalyAddress, _ := testserver.StartGitalyServer(t, "unix") requests := []testserver.TestRequestHandler{ { Path: authorizedKeysAPIPath, Handler: func(w http.ResponseWriter, _ *http.Request) { fmt.Fprint(w, `{"id": 1000, "key": "key"}`) }, }, { Path: "/api/v4/internal/allowed", Handler: func(w http.ResponseWriter, _ *http.Request) { fmt.Fprintf(w, `{"status": true, "gl_id": "user-1", "gl_username": "alex-doe", "gl_project_id": 1, "gl_root_namespace_id": 2, "gitaly": {"repository": {"storage_name": "default", "relative_path": "repo.git", "gl_repository": "project-1", "gl_project_path": "flightjs/Flight"}, "address": %q, "token": "token"}}`, gitalyAddress) }, }, } cfg := &config.Config{GitlabURL: testserver.StartSocketHTTPServer(t, requests), RootDir: "/tmp", User: user} cfg.Server.Listen = "127.0.0.1:0" cfg.Server.ConcurrentSessionsLimit = 1 cfg.Server.HostKeyFiles = []string{path.Join(testRoot, "certs/valid/server.key")} cfg.GitalyClient.InitSidechannelRegistry(context.Background()) s, err := NewServer(cfg) require.NoError(t, err) go func() { s.ListenAndServe(context.Background()) }() t.Cleanup(func() { s.Shutdown() }) verifyStatus(t, s, StatusReady) client, err := ssh.Dial("tcp", s.Addr(), clientConfig(t, testRoot)) require.NoError(t, err) session, err := client.NewSession() require.NoError(t, err) session.Stdin = &bytes.Buffer{} require.NoError(t, session.Run("git-receive-pack flightjs/Flight")) require.NoError(t, client.Close()) require.Eventually(t, func() bool { return bytes.Contains(buf.Bytes(), []byte(`"msg":"access: finish"`)) }, 5*time.Second, 10*time.Millisecond) for _, line := range bytes.Split(buf.Bytes(), []byte("\n")) { var entry map[string]any if json.Unmarshal(line, &entry) == nil && entry["msg"] == "access: finish" { t.Logf("%s", line) } } } ``` </details> ## What is the current bug behavior? On `main` at fcd1db8e the test prints: ```json {"time":"2026-10-12T14:28:09.875251996Z","level":"INFO","msg":"access: finish","correlation_id":"01M4R87309AD5WZSRX2JWWNCD2","remote_addr":"127.0.0.1:37844","duration_s":0.009347557,"written_bytes":31,"meta":{}} ``` ## What is the expected correct behavior? The line carries the user and the project the command found, whether the command then succeeds or fails: ```json {"time":"...","level":"INFO","msg":"access: finish","correlation_id":"...","remote_addr":"...","duration_s":...,"gl_user_name":"alex-doe","written_bytes":31,"meta":{"project":"flightjs/Flight","root_namespace":"flightjs","project_id":1,"root_namespace_id":2}} ``` ## Possible fixes There are three causes. **The context keys do not match.** Each command stores its `command.LogData` in the context it returns from `Execute`, under a key type of its own: | Command | Key type | |---------|----------| | discover | [`logDataKey{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/discover/discover.go#L42) | | `git-upload-pack` | [`logDataKey{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/uploadpack/uploadpack.go#L46) | | `git-receive-pack` | [`logData{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/receivepack/receivepack.go#L39) | | `git-upload-archive` | [`logInfo{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/uploadarchive/uploadarchive.go#L43) | | `git-lfs-authenticate` | [`logInfo{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/lfsauthenticate/lfsauthenticate.go#L75) | | `git-lfs-transfer` | [`command.LogDataKey`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/lfstransfer/lfstransfer.go#L55) | gitlab-sshd reads the value back under [`sshd.logInfo{}`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/sshd/sshd.go#L303-304), yet another type, and stores it again under that type once it has counted the written bytes ([`session.go` L203](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/sshd/session.go#L203)). A context lookup only matches a key of the identical type, so gitlab-sshd never finds what a command stored, not even for `git-lfs-transfer`. The per-package key types replaced a shared `"logData"` string key during the 2024 golangci-lint clean-up. An exported key for this already exists, [`command.LogDataKey`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/command/command.go#L47-48), but only `git-lfs-transfer` uses it, and gitlab-sshd does not read it. **The line does not log the username.** [`access: finish`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/sshd/sshd.go#L269-274) logs `written_bytes` and `meta`. The username was `meta.username` when !783 added it, as part of #648; !832 moved it to `LogData.Username` and nothing added it back to the line, so even with matching keys the line would still have no username. **A command that fails loses it.** When `Execute` returns an error, [`handleShell`](https://gitlab.com/gitlab-org/gitlab-shell/-/blob/fcd1db8e533949ae9a1d0cdfbfae92f5fa9a352e/internal/sshd/session.go#L205-212) returns the context it was given rather than the one holding the log data, so a command that gets past its access check and then fails, for example because its Gitaly call fails, logs no user, no project and `written_bytes` 0 even with matching keys. The fix I have in mind: read and store the log data in gitlab-sshd under `command.LogDataKey`, have every command store it there too and drop the per-package key types, log the username on the line as `gl_user_name`, the LabKit field gitlab-shell already uses for the username on its other log lines, and have `handleShell` return the context holding the log data when the command fails as well. I'd like to work on this.