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:

  1. The fields go on the existing API log line instead of a new line, as suggested in the review.
  2. The returned error is unchanged, so gitlab-sshd's error metrics count these failures exactly as before.
  3. krb5_principal is a new field name, because LabKit has no field for it. gl_key_id and gl_user_name reuse the existing names.
  4. Certificate logins get no extra fields here, because gitlab-sshd already logs the certificate during authentication.
  5. 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:

  1. Add public_key_fingerprint to the public key authentication log line as a follow-up commit here?
  2. 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.029s

gofmt -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.

Edited by Hamza Hassanain

Merge request reports

Loading
Loading