Log identity when discover fails to get the username
Closes #873 (closed)
When gitlab-shell cannot look up an SSH user through the discover API, the user gets Failed to get username: .... Support could not match that error in the logs to a user. The only trace is the key ID inside the url of the client error line, which you cannot search or group by. With gitlab-sshd, the connection: session error line has no identity either.
Now the discover command adds gl_user_name, gl_key_id, or krb5_principal (depending on what it got) to its logger before it calls the API. So the existing Internal API returned a client error line carries the identity, and no new log line is added. The message the user sees does not change.
Decisions I made:
- The fields go on the existing API log line instead of a new line, as suggested in the review.
- The returned error is unchanged, so gitlab-sshd's error metrics count these failures exactly as before.
krb5_principalis a new field name, because LabKit has no field for it.gl_key_idandgl_user_namereuse the existing names.- Certificate logins get no extra fields here, because gitlab-sshd already logs the certificate during authentication.
- There is no project field, because this step runs before any repository is involved.
I left out the key fingerprint. It is only known while gitlab-sshd checks the public key, not at this step. Should I:
- Add
public_key_fingerprintto thepublic key authenticationlog line as a follow-up commit here? - Or leave it for a separate issue?
How I tested
I built gitlab-shell from main and from this branch. Both used a small local server that answers every API call with 403 {"message":"Forbidden!"}. I ran them the way OpenSSH does for key 2 (banner trimmed):
$ SSH_CONNECTION="127.0.0.1 50000 127.0.0.1 22" bin/gitlab-shell key-2
remote: Failed to get username: Forbidden!Both builds print the same message to the user. The log from main, without time and the first executing command line:
{"level":"INFO","msg":"Internal API returned a client error","correlation_id":"01M4K050DTNVFBV2TWKZ3PSFED","method":"GET","url":"http://127.0.0.1:8077/api/v4/internal/discover?key_id=2","duration_s":0.00079785,"status":403}
{"level":"WARN","msg":"gitlab-shell: main: command execution failed","error_message":"Failed to get username: Forbidden!"}The log from this branch has the same 2 lines, and the client error line now has gl_key_id:
{"level":"INFO","msg":"Internal API returned a client error","correlation_id":"01M4X3QDPW3M6DX8VM3EE9F9NT","gl_key_id":2,"method":"GET","url":"http://127.0.0.1:8078/api/v4/internal/discover?key_id=2","duration_s":0.000601372,"status":403}
{"level":"WARN","msg":"gitlab-shell: main: command execution failed","error_message":"Failed to get username: Forbidden!"}With username-alice instead of key-2, the client error line has "gl_user_name":"alice". I did not try a Kerberos login by hand, and I only ran the gitlab-shell binary, not gitlab-sshd.
The failure test table now covers a 403 for a username, a key ID and a Kerberos principal, plus a 500. For each case it checks the identity fields on the API log line and that the other identity fields are absent. If I stop adding the fields to the logger, the 4 API cases fail.
$ GOFLAGS=-p=2 go test -count=1 ./internal/command/discover/
ok gitlab.com/gitlab-org/gitlab-shell/v14/internal/command/discover 3.029sgofmt -s -l and go vet printed nothing, and golangci-lint run on the package exited 0. The rest runs in the pipeline.
Implemented with AI assistance; I reviewed and tested the changes.