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:
TestAccessFinishWithConcurrentSessionsruns tengit-receive-packsessions at once on one connection and checks the line'sgl_user_nameandmeta. 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 becauseSSHReceivePackwritesReceivedMDwithout a lock, and concurrent pushes would race there instead. The test logs through a handler that keeps only theaccess: finishlines: 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
TestAccessFinishLogsCommandLogDatamove intoaccessCheckHandlerandrequireAccessFinishLogData, which both tests use. setupServerWithContextsetsConcurrentSessionsLimitto 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
-
Run the tests under the race detector:
go test -race -count=1 -run TestAccessFinish ./internal/sshd/With the tests on
main'ssshd.go,TestAccessFinishWithConcurrentSessionsfails in nearly every run withWARNING: DATA RACEatsshd.go:262. With the change both tests pass. Without-racethey pass on both, since only the race detector sees the race; theracejob runs them throughmake test_race. -
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(thetestsjob),CGO_ENABLED=0 make verify test_fancy(tests_without_cgo) andmake test_race(race): pass, 50 packages, none failing.make lint(golangci-lint 2.12.2, no difference from the emptysupport/lint_last_known_acceptable.txt),golangci-lint fmt --diff,go vet ./...,go mod tidy(no diff) andmake validate-log-fields: pass.nilawayat the version.gitlab-ci.ymlpins: 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
FAILThe 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.214sThe 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.