Fix a data race on the log data of concurrent gitlab-sshd sessions

What does this MR do and why?

Closes #884 (closed)

handleConn kept the context that holds a session's log data in one variable per connection (L240), and the channel handler of every session assigned to it (L261-262). Each session channel runs that handler in a goroutine of its own, and up to concurrent_sessions_limit sessions (10 by default) run at once on one connection, so the sessions of a client that multiplexes them, such as OpenSSH with ControlMaster, which Git LFS turns on for its SSH transfer protocol, wrote the variable concurrently. The read for the access: finish line (L267) was also unordered with a session still running when handleRequests stopped waiting for it, after EOFTimeout or at the end of a graceful shutdown. The issue has the details and a reproduction.

This MR has each session store its command.LogData in an atomic.Value when it ends, and the line reads it from there. The variable came in with !810 (merged), which replaced a channel because a send on it after it was closed panicked in production, so I kept the variable and made it atomic rather than going back to a channel. LogData holds only strings and integers, so the line gets a copy of it, and every store has the same type, as atomic.Value requires. connOutcome.serverError is atomic for the same reason: sessions write it from their own goroutines (connection.go#L80-83). I used atomic.Value rather than atomic.Pointer[command.LogData] because it keeps handleConn at the length it was: the pointer needs a nil check on the read, which takes the function over the funlen limit of 60 lines.

No behavior change: the line still logs the user, the project and the written bytes of the session that stored its data last, and an empty meta when no session ran. If you would rather the line described every session, with one line per session or written_bytes summed over them, I can follow up with that, but it changes what the line means, so I kept it out of this fix.

The tests:

  • TestAccessFinishWithConcurrentSessions runs ten git-receive-pack sessions at once on one connection and checks the line's gl_user_name and meta. Its access check holds every session until all ten have asked for one, so they end together, and fails the test if they have not all asked within five seconds, since the sessions would then no longer overlap. Gitaly is not reachable, so each command fails right after its access check, which still records the log data; the test Gitaly server is not used because SSHReceivePack writes ReceivedMD without a lock, and concurrent pushes would race there instead. The test logs through a handler that keeps only the access: finish lines: the JSON handler writes one line at a time, and the ordering that adds between the sessions hid the race in 2 of 120 runs when I counted.
  • The access check handler and the assertions of TestAccessFinishLogsCommandLogData move into accessCheckHandler and requireAccessFinishLogData, which both tests use.
  • setupServerWithContext sets ConcurrentSessionsLimit to 1 only when the caller passes a nil config or leaves the limit at zero, which every existing caller does.

How to set up and validate locally

  1. Run the tests under the race detector:

    go test -race -count=1 -run TestAccessFinish ./internal/sshd/

    With the tests on main's sshd.go, TestAccessFinishWithConcurrentSessions fails in nearly every run with WARNING: DATA RACE at sshd.go:262. With the change both tests pass. Without -race they pass on both, since only the race detector sees the race; the race job runs them through make test_race.

  2. To see it without this MR's tests, follow the steps in the issue.

What I ran

In registry.gitlab.com/gitlab-org/gitlab-build-images/debian-trixie-golang-1.25:latest (go1.25.14), the image the tests, race and lint jobs use, after the test job's make build and cp config.yml.example config.yml, without the Gitaly service (so the gitlab-sshd acceptance tests skip), on main at 16e5a730 and on this branch:

  • make verify test_fancy (the tests job), CGO_ENABLED=0 make verify test_fancy (tests_without_cgo) and make test_race (race): pass, 50 packages, none failing.
  • make lint (golangci-lint 2.12.2, no difference from the empty support/lint_last_known_acceptable.txt), golangci-lint fmt --diff, go vet ./..., go mod tidy (no diff) and make validate-log-fields: pass.
  • nilaway at the version .gitlab-ci.yml pins: no findings.

With Go 1.26.7 and Go 1.27.2, the other images of the job matrix, on this branch: the tests, tests_without_cgo and race commands above pass.

In ubi-9.6-golang-1.25 with FIPS_MODE=1 and GOLANG_FIPS=1, after the tests:fips job's dnf install -y git, on main and on this branch: make test_fancy passes.

TestAccessFinishWithConcurrentSessions under -race, each run in a process of its own, since the race detector reports a given race once per process:

Go main with the new tests this MR
1.25.14 60 of 60 fail 0 of 60 fail
1.26.7 60 of 60 fail 0 of 60 fail
1.27.2 59 of 60 fail 0 of 60 fail

The race detector does not report every race in every run, so on main the test passed in 1 of those 60 runs with Go 1.27.2, and in 2 of 20 in an earlier count with Go 1.26.7.

go test -race -count=1 -run TestAccessFinish -v ./internal/sshd/ with Go 1.25.14, with the tests on main's sshd.go:

=== RUN   TestAccessFinishLogsCommandLogData
=== RUN   TestAccessFinishLogsCommandLogData/the_command_succeeds
=== RUN   TestAccessFinishLogsCommandLogData/the_command_fails_after_its_access_check
--- PASS: TestAccessFinishLogsCommandLogData (0.09s)
    --- PASS: TestAccessFinishLogsCommandLogData/the_command_succeeds (0.05s)
    --- PASS: TestAccessFinishLogsCommandLogData/the_command_fails_after_its_access_check (0.04s)
=== RUN   TestAccessFinishWithConcurrentSessions
==================
WARNING: DATA RACE
Write at 0x00c0001a89b0 by goroutine 205:
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).handleConn.func3()
      internal/sshd/sshd.go:262 +0x724
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handleRequests.func1()
      internal/sshd/connection.go:224 +0x302

Previous write at 0x00c0001a89b0 by goroutine 204:
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).handleConn.func3()
      internal/sshd/sshd.go:262 +0x724
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handleRequests.func1()
      internal/sshd/connection.go:224 +0x302

Goroutine 205 (running) created at:
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handleRequests()
      internal/sshd/connection.go:207 +0x6dc
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handle()
      internal/sshd/connection.go:150 +0x3b1
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).handleConn()
      internal/sshd/sshd.go:242 +0x607
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).serve.gowrap1()
      internal/sshd/sshd.go:173 +0x6b

Goroutine 204 (finished) created at:
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handleRequests()
      internal/sshd/connection.go:207 +0x6dc
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*connection).handle()
      internal/sshd/connection.go:150 +0x3b1
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).handleConn()
      internal/sshd/sshd.go:242 +0x607
  gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd.(*Server).serve.gowrap1()
      internal/sshd/sshd.go:173 +0x6b
==================
    testing.go:1617: race detected during execution of test
--- FAIL: TestAccessFinishWithConcurrentSessions (0.04s)
FAIL
FAIL	gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd	0.190s
FAIL

The same on this branch:

=== RUN   TestAccessFinishLogsCommandLogData
=== RUN   TestAccessFinishLogsCommandLogData/the_command_succeeds
=== RUN   TestAccessFinishLogsCommandLogData/the_command_fails_after_its_access_check
--- PASS: TestAccessFinishLogsCommandLogData (0.09s)
    --- PASS: TestAccessFinishLogsCommandLogData/the_command_succeeds (0.04s)
    --- PASS: TestAccessFinishLogsCommandLogData/the_command_fails_after_its_access_check (0.05s)
=== RUN   TestAccessFinishWithConcurrentSessions
--- PASS: TestAccessFinishWithConcurrentSessions (0.05s)
PASS
ok  	gitlab.com/gitlab-org/gitlab-shell/v14/internal/sshd	1.214s

The test in the issue, under -race with go1.25.14, failed in 20 runs of 20 on main and in none of 20 on this branch.

The branch sits on main at 16e5a730.

MR acceptance checklist

Evaluate this MR against the MR acceptance checklist. It helps you analyze changes to reduce risks in quality, performance, reliability, security, and maintainability.

Merge request reports

Loading
Loading