From 857c73a66a60480c8acfb425a4389055f532a06e Mon Sep 17 00:00:00 2001 From: Lemon-miaow Date: Thu, 24 Sep 2026 16:02:44 +0800 Subject: [PATCH] =?UTF-8?q?fix(audit):=20=E5=AE=A1=E8=AE=A1=E6=8C=89?= =?UTF-8?q?=E8=B4=A6=E5=8F=B7=20id=20=E5=BD=92=E5=B1=9E=E5=B9=B6=E8=AE=B0?= =?UTF-8?q?=E5=BD=95=E6=9D=A5=E6=BA=90=20IP/UA=EF=BC=8C=E7=99=BB=E5=BD=95?= =?UTF-8?q?=E5=A4=B1=E8=B4=A5=E4=B8=8E=E9=99=90=E9=80=9F=E5=85=A5=E5=AE=A1?= =?UTF-8?q?=E8=AE=A1=E5=92=8C=E6=8C=87=E6=A0=87=EF=BC=8C=E5=86=99=E5=85=A5?= =?UTF-8?q?=E5=A4=B1=E8=B4=A5=E8=AE=A1=E6=95=B0=E5=91=8A=E8=AD=A6?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- deploy/alerts/felis-alerts.yaml | 26 ++- deploy/alerts/felis-alerts_test.yml | 55 ++++++ deploy/alerts/felis-prometheusrule.yaml | 22 +++ docs/troubleshooting.md | 35 +++- internal/api/api_test.go | 7 +- internal/api/audit.go | 172 +++++++++++++++++ internal/api/audit_test.go | 177 ++++++++++++++++++ internal/api/auth.go | 5 +- internal/api/handlers_access.go | 10 +- internal/api/handlers_account.go | 2 +- internal/api/handlers_account_migrate.go | 29 +-- internal/api/handlers_auth.go | 16 +- internal/api/handlers_auth_email.go | 7 +- internal/api/handlers_backups.go | 13 +- internal/api/handlers_console.go | 2 +- internal/api/handlers_email_otp.go | 19 +- internal/api/handlers_files.go | 3 +- internal/api/handlers_internal.go | 9 +- internal/api/handlers_logstream.go | 2 +- internal/api/handlers_onboard.go | 6 +- internal/api/handlers_op_login.go | 25 ++- internal/api/handlers_op_login_test.go | 30 +-- internal/api/handlers_passkey.go | 11 +- internal/api/handlers_passkey_discoverable.go | 8 +- internal/api/handlers_player_reclaim.go | 10 +- internal/api/handlers_setup.go | 3 +- internal/api/handlers_updates.go | 2 +- internal/api/handlers_user.go | 24 +-- internal/api/handlers_users.go | 29 ++- internal/api/images.go | 12 +- internal/api/otp_lock.go | 7 +- internal/api/pgrepo.go | 16 +- internal/api/ratelimit.go | 27 ++- internal/api/repo.go | 22 ++- internal/api/session.go | 1 + internal/api/submissions.go | 15 +- internal/metrics/metrics.go | 29 +++ internal/pgint/pgint_test.go | 51 +++++ .../migrations/0023_audit_attribution.sql | 16 ++ 39 files changed, 794 insertions(+), 161 deletions(-) create mode 100644 internal/api/audit.go create mode 100644 internal/api/audit_test.go create mode 100644 internal/store/migrations/0023_audit_attribution.sql diff --git a/deploy/alerts/felis-alerts.yaml b/deploy/alerts/felis-alerts.yaml index 929ae9f..11c472b 100644 --- a/deploy/alerts/felis-alerts.yaml +++ b/deploy/alerts/felis-alerts.yaml @@ -6,7 +6,9 @@ # - felis-operator pod :8080/metrics → felis_servers_total, felis_start_duration_seconds # - felis-api internal :8081/metrics → felis_image_build_failures_total, # felis_mail_total, felis_rate_limited_total, -# felis_auth_otp_lockouts_total +# felis_auth_otp_lockouts_total, +# felis_auth_failures_total, +# felis_audit_write_failures_total # - node-exporter textfile collector → felis_db_backup_* (felis-db-backup.timer) # node_* / kube_* series come from node-exporter / kube-state-metrics. groups: @@ -142,3 +144,25 @@ groups: The audit log names the account (action auth.otp.locked); the owner was mailed. Unless they fumbled codes, someone is guessing at it (troubleshooting §17). + - alert: FelisSignInFailures + expr: sum(increase(felis_auth_failures_total[15m])) > 30 + for: 5m + labels: + severity: warning + annotations: + summary: "over 30 refused sign-ins in 15 minutes" + description: >- + Wrong codes, unknown addresses or bad passkey assertions well above people + mistyping: someone is guessing or enumerating. `sum by (door, reason) + (increase(felis_auth_failures_total[15m]))` shows where; the audit rows + (action auth..failed) carry each caller's client_ip (troubleshooting §17). + - alert: FelisAuditWriteFailing + expr: increase(felis_audit_write_failures_total[15m]) > 0 + labels: + severity: warning + annotations: + summary: "felis-api failed to write audit rows" + description: >- + The actions went through but their audit rows were lost. The felis-api log + names each lost row (`audit: lost ...`); the usual cause is PostgreSQL + being unreachable or out of disk. diff --git a/deploy/alerts/felis-alerts_test.yml b/deploy/alerts/felis-alerts_test.yml index 322ae22..4a47e25 100644 --- a/deploy/alerts/felis-alerts_test.yml +++ b/deploy/alerts/felis-alerts_test.yml @@ -236,3 +236,58 @@ tests: - eval_time: 90m alertname: FelisOTPAccountLocked exp_alerts: [] + - name: sign-in failure rate + interval: 1m + input_series: + # Two doors failing at 3/min between them from t=0. + - series: 'felis_auth_failures_total{door="login_email",reason="bad_code",job="felis-api"}' + values: '0+2x40' + - series: 'felis_auth_failures_total{door="op_login",reason="no_account",job="felis-api"}' + values: '0+1x40' + alert_rule_test: + - eval_time: 8m + alertname: FelisSignInFailures + exp_alerts: [] + - eval_time: 25m + alertname: FelisSignInFailures + exp_alerts: + - exp_labels: + severity: warning + exp_annotations: + summary: "over 30 refused sign-ins in 15 minutes" + description: >- + Wrong codes, unknown addresses or bad passkey assertions well above people + mistyping: someone is guessing or enumerating. `sum by (door, reason) + (increase(felis_auth_failures_total[15m]))` shows where; the audit rows + (action auth..failed) carry each caller's client_ip (troubleshooting §17). + - name: people mistyping stays quiet + interval: 1m + input_series: + - series: 'felis_auth_failures_total{door="login_email",reason="bad_code",job="felis-api"}' + values: '0 0 1 1 2 2 3 3 4 4 5x30' + alert_rule_test: + - eval_time: 30m + alertname: FelisSignInFailures + exp_alerts: [] + - name: audit rows lost + interval: 1m + input_series: + - series: 'felis_audit_write_failures_total{job="felis-api",instance="api-0"}' + values: '0 0 0 2x20' + alert_rule_test: + - eval_time: 2m + alertname: FelisAuditWriteFailing + exp_alerts: [] + - eval_time: 5m + alertname: FelisAuditWriteFailing + exp_alerts: + - exp_labels: + severity: warning + job: felis-api + instance: api-0 + exp_annotations: + summary: "felis-api failed to write audit rows" + description: >- + The actions went through but their audit rows were lost. The felis-api log + names each lost row (`audit: lost ...`); the usual cause is PostgreSQL + being unreachable or out of disk. diff --git a/deploy/alerts/felis-prometheusrule.yaml b/deploy/alerts/felis-prometheusrule.yaml index 0b68db9..556ef4e 100644 --- a/deploy/alerts/felis-prometheusrule.yaml +++ b/deploy/alerts/felis-prometheusrule.yaml @@ -144,3 +144,25 @@ spec: The audit log names the account (action auth.otp.locked); the owner was mailed. Unless they fumbled codes, someone is guessing at it (troubleshooting §17). + - alert: FelisSignInFailures + expr: sum(increase(felis_auth_failures_total[15m])) > 30 + for: 5m + labels: + severity: warning + annotations: + summary: "over 30 refused sign-ins in 15 minutes" + description: >- + Wrong codes, unknown addresses or bad passkey assertions well above people + mistyping: someone is guessing or enumerating. `sum by (door, reason) + (increase(felis_auth_failures_total[15m]))` shows where; the audit rows + (action auth..failed) carry each caller's client_ip (troubleshooting §17). + - alert: FelisAuditWriteFailing + expr: increase(felis_audit_write_failures_total[15m]) > 0 + labels: + severity: warning + annotations: + summary: "felis-api failed to write audit rows" + description: >- + The actions went through but their audit rows were lost. The felis-api log + names each lost row (`audit: lost ...`); the usual cause is PostgreSQL + being unreachable or out of disk. diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 538cdcc..1192337 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -933,7 +933,9 @@ The series come from two processes: - `felis-api` internal face `:8081/metrics` (Service `felis-api-internal`) — `felis_image_build_failures_total`, and the sign-in series of §17 (`felis_mail_total`, `felis_rate_limited_total`, - `felis_auth_otp_lockouts_total`). Unauthenticated like the probes; + `felis_auth_otp_lockouts_total`, `felis_auth_failures_total`, + `felis_sessions_revoked_total`, `felis_audit_write_failures_total`). + Unauthenticated like the probes; ClusterIP-only, and the external face never serves it. - `felis_reaper_worlds_deleted_total` is produced inside the one-shot reaper CronJob, which exits long before any scrape interval — without a pushgateway @@ -945,8 +947,8 @@ The series come from two processes: `deploy/alerts/` ships ready-made rules: build failures, slow starts, node disk/memory thresholds, the kubelet `DiskPressure` condition, control-plane database backup freshness (§16; needs node-exporter's textfile collector), and -sign-in abuse: the mail budget, relay failures, throttled floods and account -code locks (§17). +sign-in abuse: the mail budget, relay failures, throttled floods, account +code locks and the refused sign-in rate, plus lost audit rows (§17). - Plain Prometheus: add `felis-alerts.yaml` to `rule_files`. Check and unit-test it standalone with `promtool check rules felis-alerts.yaml` and @@ -1171,7 +1173,7 @@ Skips the pre-migration snapshot (`migrate up -no-backup`). The installer warns loudly when it is set. Use it only when the snapshot cannot work and you have another backup, e.g. an external database newer than the host's `pg_dump`. -## 17. Sign-in refused with 429, mail budget, account code locks +## 17. Sign-in refused with 429, mail budget, account code locks, failed sign-ins The public sign-in doors (`/api/v1/auth/*` except logout and the op-login status poll) have three limits of their own. Each answers 429 with a @@ -1232,6 +1234,29 @@ sudo -u postgres psql felis -c \ "DELETE FROM otp_failure_windows WHERE user_id = (SELECT id FROM users WHERE username = '');" ``` +### Who tried: the audit trail + +Every refused sign-in writes an `auth..failed` row (payload `reason`: +`bad_code`, `no_account`, `staff_account`, `not_staff`, `bad_assertion`, ...) +and counts in `felis_auth_failures_total{door,reason}`; `FelisSignInFailures` +fires above 30 in 15 minutes. The first refusal of each throttled burst writes +`auth.rate_limited` with the source address. Rows carry `actor_user_id` (the +account, the column to attribute by), `client_ip` (the same address the limit +keys on) and `user_agent`. `actor` is display text: a verified email or the +username, never an address the caller set without verifying. + +```sh +sudo -u postgres psql felis -c " + SELECT created_at, action, actor, client_ip, payload->>'reason' AS reason + FROM audit_logs + WHERE action LIKE 'auth.%' AND created_at > now() - interval '1 hour' + ORDER BY created_at DESC LIMIT 50;" +``` + +A failed audit write does not fail the action; it logs `audit: lost ...` in +`felis-api` and counts in `felis_audit_write_failures_total` +(`FelisAuditWriteFailing`). The cause is almost always PostgreSQL (§16). + ### Optional: a Cloudflare rate limiting rule in front The limits above live in the API, so they hold on any edge. Behind Cloudflare @@ -1274,3 +1299,5 @@ for 10 seconds (the Free plan's limits). | Sign-in 429 `rate_limited` for everyone at once | §17 | | 429 `mail_rate_limited` / `FelisMailBudgetExhausted` | §17 | | Right code refused; `otp_account_locked` / `FelisOTPAccountLocked` | §17 | +| `FelisSignInFailures` / who is guessing, from where | §17 | +| `FelisAuditWriteFailing` | §17 | diff --git a/internal/api/api_test.go b/internal/api/api_test.go index c0531ff..7fa5297 100644 --- a/internal/api/api_test.go +++ b/internal/api/api_test.go @@ -47,6 +47,7 @@ type fakeRepo struct { serverResources map[string]ResourceSpec resourceUpdates map[string]ResourceSpec audits []AuditEntry + failAudit error // Audit fails with it (a store outage) joins []string // create-server seeding (spec §15) seeded map[string]bool // name -> servers row exists @@ -745,6 +746,9 @@ func (f *fakeRepo) SeedServer(_ context.Context, name, subdomain string, _, _, _ } func (f *fakeRepo) Ping(_ context.Context) error { return f.pingErr } func (f *fakeRepo) Audit(_ context.Context, e AuditEntry) error { + if f.failAudit != nil { + return f.failAudit + } f.audits = append(f.audits, e) return nil } @@ -857,7 +861,8 @@ func (f *fakeRepo) SessionUser(_ context.Context, tokenHash string, now time.Tim return nil, ErrNotFound } return &SessionedUser{ - ID: u.ID, Email: u.Email, Role: u.Role, + ID: u.ID, Username: u.Username, Email: u.Email, Role: u.Role, + EmailVerified: u.EmailVerified, }, nil } } diff --git a/internal/api/audit.go b/internal/api/audit.go new file mode 100644 index 0000000..db08bf3 --- /dev/null +++ b/internal/api/audit.go @@ -0,0 +1,172 @@ +package api + +import ( + "cmp" + "context" + "encoding/json" + "errors" + "log" + "net/http" + "strings" + "time" + "unicode/utf8" + + "felis.lolicon.best/internal/metrics" +) + +// Audit rows (audit_logs, spec §6). +// +// Every row an HTTP request writes carries the acting account's id +// (actor_user_id), the caller's address (the one the sign-in limit keys on) and +// user agent; actor is display text. A failed write never fails the operation +// it records, which already happened, but it is logged and counted +// (felis_audit_write_failures_total, FelisAuditWriteFailing): a silent drop is +// how a database blip erases the trail. + +const ( + // auditWriteTimeout bounds one audit insert. The write outlives the caller's + // request context, so a client that hangs up right after the action cannot + // cancel its own audit row. + auditWriteTimeout = 5 * time.Second + // auditUserAgentMax bounds the stored user agent; the header is the caller's + // to write. + auditUserAgentMax = 256 + // anonymousActor names a caller no account was resolved for. + anonymousActor = "anonymous" +) + +// auditActor is the display name for a principal: an email only when something +// vouches for it (an Access JWT, or a session whose address was verified), else +// the username. A player can set their address to anyone's before verifying it, +// so an unverified email would let them sign rows as that person. +func auditActor(p *Principal) string { + switch { + case p == nil: + return anonymousActor + case p.Email != "" && (p.EmailVerified || !p.ViaSession): + return p.Email + case p.Username != "": + return p.Username + case p.UserID != "": + return p.UserID + } + return anonymousActor +} + +// audit records an action by the signed-in caller. target is the object acted +// on (a server name, a user or credential id) and lands in server_name. +func (a *API) audit(r *http.Request, action, target string) { + p := principalFromContext(r.Context()) + e := AuditEntry{Actor: auditActor(p), Action: action, ServerName: target} + if p != nil { + e.ActorUserID = p.UserID + } + a.auditEntry(r, e) +} + +// auditAccount records an action a pre-session door took for the account it +// resolved (u nil: none was). The username is the actor: the door has not yet +// proven anything about the address. +func (a *API) auditAccount(r *http.Request, u *StaffUser, action, target string) { + e := AuditEntry{Actor: anonymousActor, Action: action, ServerName: target} + if u != nil { + e.Actor, e.ActorUserID = u.Username, u.ID + } + a.auditEntry(r, e) +} + +// auditEntry fills the request detail into e and writes it. Source defaults to +// external; internal callers set it and the component actor themselves. +func (a *API) auditEntry(r *http.Request, e AuditEntry) { + if e.Source == "" { + e.Source = "external" + } + e.RequestID = requestIDFromContext(r.Context()) + if e.Source == "external" { + if ip := a.clientIP(r); ip.IsValid() { + e.ClientIP = ip.String() + } + e.UserAgent = truncateUTF8(r.UserAgent(), auditUserAgentMax) + } + a.writeAudit(r.Context(), e) +} + +// writeAudit inserts e, logging and counting a failure. +func (a *API) writeAudit(ctx context.Context, e AuditEntry) { + ctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), auditWriteTimeout) + defer cancel() + if err := a.Repo.Audit(ctx, e); err != nil { + metrics.AuditWriteFailuresTotal.Inc() + log.Printf("audit: lost %s by %s (user %q, request_id=%s): %v", + e.Action, e.Actor, e.ActorUserID, e.RequestID, err) + } +} + +// authFailure records one refused sign-in attempt: felis_auth_failures_total +// by door and reason, and an auth..failed row naming the account when +// the door resolved one (u nil: the signed-in caller if any, else anonymous). +// The doors keep their answers uniform so a prober learns nothing; the reason +// is for the operator. +func (a *API) authFailure(r *http.Request, door, reason string, u *StaffUser) { + metrics.AuthFailuresTotal.WithLabelValues(door, reason).Inc() + e := AuditEntry{Action: "auth." + door + ".failed", Payload: auditPayload(map[string]any{"reason": reason})} + switch p := principalFromContext(r.Context()); { + case u != nil: + e.Actor, e.ActorUserID = cmp.Or(u.Username, u.ID), u.ID + case p != nil: + e.Actor, e.ActorUserID = auditActor(p), p.UserID + default: + e.Actor = anonymousActor + } + a.auditEntry(r, e) +} + +// passkeyCloneRejected records an assertion refused for a regressed signature +// counter. It keeps its own action so a cloned authenticator stands out from +// ordinary failures, and counts as a failure of its door. u nil: a signed-in +// step-up, attributed to the caller. +func (a *API) passkeyCloneRejected(r *http.Request, door string, u *StaffUser, credentialID string) { + metrics.AuthFailuresTotal.WithLabelValues(door, "clone_rejected").Inc() + if u == nil { + a.audit(r, "auth.passkey_clone_rejected", credentialID) + return + } + a.auditAccount(r, u, "auth.passkey_clone_rejected", credentialID) +} + +// isOTPRefusal reports whether err is a refused code (wrong, spent, or the +// account's budget locked), as opposed to a fault. +func isOTPRefusal(err error) bool { + return errors.Is(err, ErrOTPInvalid) || errors.Is(err, ErrOTPLocked) || errors.Is(err, ErrOTPAccountLocked) +} + +// otpFailureReason names a refused code for authFailure. +func otpFailureReason(err error) string { + switch { + case errors.Is(err, ErrOTPAccountLocked): + return "account_locked" + case errors.Is(err, ErrOTPLocked): + return "code_locked" + } + return "bad_code" +} + +// auditPayload marshals a small detail map for AuditEntry.Payload. +func auditPayload(v map[string]any) []byte { + b, _ := json.Marshal(v) + return b +} + +// truncateUTF8 makes s valid UTF-8 (a header may carry any byte, a text +// column refuses invalid sequences) and cuts it to at most n bytes on a rune +// boundary. +func truncateUTF8(s string, n int) string { + s = strings.ToValidUTF8(s, "\uFFFD") + if len(s) <= n { + return s + } + for n > 0 && !utf8.RuneStart(s[n]) { + n-- + } + return s[:n] +} diff --git a/internal/api/audit_test.go b/internal/api/audit_test.go new file mode 100644 index 0000000..2552d1b --- /dev/null +++ b/internal/api/audit_test.go @@ -0,0 +1,177 @@ +package api + +import ( + "errors" + "net/http" + "strings" + "testing" + "time" + + "github.com/prometheus/client_golang/prometheus/testutil" + + "felis.lolicon.best/internal/metrics" +) + +// Audit attribution: a row names the acting account by id and never by an +// address the caller merely asserted; refused sign-ins, throttling and logouts +// leave rows; a failed write is counted instead of vanishing. + +func TestAuditActorIgnoresUnverifiedEmail(t *testing.T) { + cases := []struct { + name string + p *Principal + want string + }{ + {"verified session email", &Principal{UserID: "u1", Username: "alice", Email: "alice@example.net", EmailVerified: true, ViaSession: true}, "alice@example.net"}, + {"unverified session email", &Principal{UserID: "u2", Username: "mallory", Email: "owner@example.net", ViaSession: true}, "mallory"}, + {"access jwt email", &Principal{UserID: "sub", Email: "ops@example.net"}, "ops@example.net"}, + {"no email", &Principal{UserID: "u3", Username: "bob", ViaSession: true}, "bob"}, + {"id only", &Principal{UserID: "u4", ViaSession: true}, "u4"}, + {"nobody", nil, anonymousActor}, + } + for _, c := range cases { + if got := auditActor(c.p); got != c.want { + t.Errorf("%s: auditActor = %q, want %q", c.name, got, c.want) + } + } +} + +// A player who sets their address to the owner's still signs every row as +// themselves, by username and by id. +func TestAuditCannotBeSignedWithAnotherPersonsEmail(t *testing.T) { + repo := newFakeRepo() + repo.settings[LocalAuthEnabledKey] = []byte("true") + repo.staff["owner"] = &StaffUser{ID: "u1", Username: "owner", Email: "owner@example.net", Role: "owner", EmailVerified: true} + repo.staff["mallory"] = &StaffUser{ID: "u2", Username: "mallory", Email: "mallory@example.net", Role: "user", EmailVerified: true} + repo.sessions[hashCookie("tok")] = &fakeSession{userID: "u2", expiresAt: time.Unix(1_700_000_000, 0).Add(time.Hour)} + api := newTestAPI(repo, newFakeCluster()) + api.External = SessionAuth{Repo: repo, RootDomain: testRoot, Now: api.now} + api.ClientIPHeader = "CF-Connecting-IP" + eh := api.ExternalHandler() + hdr := map[string]string{ + "Content-Type": "application/json", "Cookie": sessionCookieName + "=tok", + "CF-Connecting-IP": "203.0.113.5", "User-Agent": "probe/1.0", + } + for _, email := range []string{"owner@example.net", "owner@example.net"} { + if w := do(eh, "POST", "/api/v1/account/email", `{"email":"`+email+`"}`, hdr); w.Code != http.StatusOK { + t.Fatalf("set email = %d (%s)", w.Code, w.Body.String()) + } + } + // The first write ran while the address was still verified; the second + // ran with the owner's address set and unverified. + last := repo.audits[len(repo.audits)-1] + if last.Actor != "mallory" || last.ActorUserID != "u2" { + t.Fatalf("audit after spoofing = actor %q user %q, want mallory/u2", last.Actor, last.ActorUserID) + } + if last.ClientIP != "203.0.113.5" || last.UserAgent != "probe/1.0" || last.RequestID == "" { + t.Fatalf("audit request detail = %+v", last) + } +} + +func TestSignInFailuresAreAuditedAndCounted(t *testing.T) { + api, repo, mailer := seedLoginEmailAPI(t) + eh := api.ExternalHandler() + noAccount := metrics.AuthFailuresTotal.WithLabelValues("login_email", "no_account") + badCode := metrics.AuthFailuresTotal.WithLabelValues("login_email", "bad_code") + n0, b0 := testutil.ToFloat64(noAccount), testutil.ToFloat64(badCode) + + do(eh, "POST", "/api/v1/auth/email/verify", `{"email":"ghost@example.net","code":"123456"}`, jsonHeader) + if w := do(eh, "POST", "/api/v1/auth/email/start", `{"email":"player@example.net"}`, jsonHeader); w.Code != http.StatusAccepted { + t.Fatalf("start = %d", w.Code) + } + wrong := "000000" + if mailer.code == wrong { + wrong = "111111" + } + do(eh, "POST", "/api/v1/auth/email/verify", `{"email":"player@example.net","code":"`+wrong+`"}`, jsonHeader) + + if got := testutil.ToFloat64(noAccount) - n0; got != 1 { + t.Errorf("no_account failures counted %v, want 1", got) + } + if got := testutil.ToFloat64(badCode) - b0; got != 1 { + t.Errorf("bad_code failures counted %v, want 1", got) + } + var failed []AuditEntry + for _, e := range repo.audits { + if e.Action == "auth.login_email.failed" { + failed = append(failed, e) + } + } + if len(failed) != 2 { + t.Fatalf("failure audits = %+v, want 2", failed) + } + if failed[0].Actor != anonymousActor || failed[0].ActorUserID != "" || !strings.Contains(string(failed[0].Payload), "no_account") { + t.Errorf("unknown-address failure = %+v", failed[0]) + } + if failed[1].Actor != "player" || failed[1].ActorUserID != "u1" || !strings.Contains(string(failed[1].Payload), "bad_code") { + t.Errorf("wrong-code failure = %+v", failed[1]) + } +} + +func TestThrottleAuditsOncePerEpisode(t *testing.T) { + api, repo, _ := seedLoginEmailAPI(t) + api.AuthDoorLimit = RateLimit{Burst: 1, PerMinute: 1} + clock := time.Unix(1_700_000_000, 0) + api.Now = func() time.Time { return clock } + eh := api.ExternalHandler() + options := func() int { + return do(eh, "POST", "/api/v1/auth/options", `{"email":"x@example.net"}`, jsonHeader).Code + } + throttled := func() int { + n := 0 + for _, e := range repo.audits { + if e.Action == "auth.rate_limited" { + n++ + } + } + return n + } + options() + for i := 0; i < 5; i++ { + if c := options(); c != http.StatusTooManyRequests { + t.Fatalf("call %d = %d, want 429", i+2, c) + } + } + if n := throttled(); n != 1 { + t.Fatalf("5 refusals left %d audit rows, want 1", n) + } + clock = clock.Add(time.Minute) + options() + options() + if n := throttled(); n != 2 { + t.Fatalf("a second episode left %d rows in total, want 2", n) + } +} + +func TestAuditWriteFailureIsCountedNotFatal(t *testing.T) { + api, repo, _ := seedLoginEmailAPI(t) + repo.failAudit = errors.New("db down") + before := testutil.ToFloat64(metrics.AuditWriteFailuresTotal) + if w := do(api.ExternalHandler(), "POST", "/api/v1/auth/email/start", `{"email":"player@example.net"}`, jsonHeader); w.Code != http.StatusAccepted { + t.Fatalf("start with the audit store down = %d, want 202", w.Code) + } + if got := testutil.ToFloat64(metrics.AuditWriteFailuresTotal) - before; got != 1 { + t.Fatalf("audit write failures counted %v, want 1", got) + } +} + +func TestLogoutAuditsTheLiveSession(t *testing.T) { + api, repo, _ := seedLoginEmailAPI(t) + repo.sessions[hashCookie("tok")] = &fakeSession{userID: "u1", expiresAt: time.Unix(1_700_000_000, 0).Add(time.Hour)} + eh := api.ExternalHandler() + cookie := map[string]string{"Content-Type": "application/json", "Cookie": sessionCookieName + "=tok"} + do(eh, "POST", "/api/v1/auth/logout", "", cookie) + do(eh, "POST", "/api/v1/auth/logout", "", cookie) // already revoked: no second row + if len(repo.audits) != 1 || repo.audits[0].Action != "auth.logout" || repo.audits[0].ActorUserID != "u1" || repo.audits[0].Actor != "player" { + t.Fatalf("logout audits = %+v, want one auth.logout by player/u1", repo.audits) + } +} + +func TestTruncateUTF8KeepsRunesWhole(t *testing.T) { + if got := truncateUTF8("ab\xffc", 10); got != "ab�c" { + t.Errorf("invalid byte = %q", got) + } + if got := truncateUTF8("猫猫", 4); got != "猫" { + t.Errorf("cut mid-rune = %q, want 猫", got) + } +} diff --git a/internal/api/auth.go b/internal/api/auth.go index 62912bc..270c351 100644 --- a/internal/api/auth.go +++ b/internal/api/auth.go @@ -15,7 +15,10 @@ import ( type Principal struct { // UserID is the stable web identity (SSO subject → users.id). UserID string - // Email is the audited actor identity (spec §14: audit actor = Access email). + // Username is the account's login name; empty for an Access-JWT caller. + Username string + // Email is the account's address. Only an Access JWT or EmailVerified vouches + // for it: a player can set any address before verifying it (auditActor). Email string // Role is "owner", "admin", or "user" (mirrors users.role). Role string diff --git a/internal/api/handlers_access.go b/internal/api/handlers_access.go index 8468b0f..9b6ca0d 100644 --- a/internal/api/handlers_access.go +++ b/internal/api/handlers_access.go @@ -159,7 +159,7 @@ func (a *API) handleAccessWhitelist(w http.ResponseWriter, r *http.Request) { if !ok { return } - a.audit(r, principalFromContext(r.Context()).Email, "access.whitelist."+body.Action, name) + a.audit(r, "access.whitelist."+body.Action, name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "action": body.Action, "player": body.Player, "output": out, }) @@ -249,7 +249,7 @@ func (a *API) handleAccessBan(w http.ResponseWriter, r *http.Request) { if !ok { return } - a.audit(r, principalFromContext(r.Context()).Email, "access.ban."+body.Action, name) + a.audit(r, "access.ban."+body.Action, name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "action": body.Action, "player": body.Player, "output": out, }) @@ -282,7 +282,7 @@ func (a *API) handleAccessKick(w http.ResponseWriter, r *http.Request) { if !ok { return } - a.audit(r, principalFromContext(r.Context()).Email, "access.kick", name) + a.audit(r, "access.kick", name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "player": body.Player, "output": out, }) @@ -354,7 +354,7 @@ func (a *API) handleAccessPermission(w http.ResponseWriter, r *http.Request) { if !ok { return } - a.audit(r, principalFromContext(r.Context()).Email, "access.permission."+body.Action, name) + a.audit(r, "access.permission."+body.Action, name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "action": body.Action, "player": body.Player, "node": body.Node, "output": out, @@ -397,7 +397,7 @@ func (a *API) handleAccessGroup(w http.ResponseWriter, r *http.Request) { if !ok { return } - a.audit(r, principalFromContext(r.Context()).Email, "access.group."+body.Action, name) + a.audit(r, "access.group."+body.Action, name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "action": body.Action, "player": body.Player, "group": body.Group, "output": out, }) diff --git a/internal/api/handlers_account.go b/internal/api/handlers_account.go index 13d7b88..61fdb73 100644 --- a/internal/api/handlers_account.go +++ b/internal/api/handlers_account.go @@ -229,7 +229,7 @@ func (a *API) handleLinkVerify(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, p.Email, "account.link", "") + a.audit(r, "account.link", "") writeJSON(w, http.StatusOK, map[string]any{ "linked": true, "mc_uuid": mcUUID, "auth_source": authSource, }) diff --git a/internal/api/handlers_account_migrate.go b/internal/api/handlers_account_migrate.go index 2e490cd..ba7f7b8 100644 --- a/internal/api/handlers_account_migrate.go +++ b/internal/api/handlers_account_migrate.go @@ -114,11 +114,10 @@ func (a *API) handleMigrateStart(w http.ResponseWriter, r *http.Request) { return } // Internal-face event: attribute to the in-game initiator, Source 'internal'. - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: "mc:" + mcUUID, - Source: "internal", - Action: "account.migrate.start", - RequestID: requestIDFromContext(r.Context()), + a.auditEntry(r, AuditEntry{ + Actor: "mc:" + mcUUID, + Source: "internal", + Action: "account.migrate.start", }) writeJSON(w, http.StatusCreated, map[string]any{"started": true, "state": "initiated"}) } @@ -247,7 +246,7 @@ func (a *API) handleMigrateConfirmOTPStart(w http.ResponseWriter, r *http.Reques return } committed = true - a.audit(r, auditActor(p), "account.migrate.confirm_otp_sent", "") + a.audit(r, "account.migrate.confirm_otp_sent", "") writeJSON(w, http.StatusAccepted, map[string]any{"sent": true, "expires_at": expiresAt.UTC()}) } @@ -275,7 +274,11 @@ func (a *API) handleMigrateConfirmOTPVerify(w http.ResponseWriter, r *http.Reque return } var lock *OTPAccountLockedError - switch err := a.Repo.ConsumeLoginEmailOTP(r.Context(), p.UserID, otpPurposeMigrate, otpCodeHash(code), a.now()); { + err := a.Repo.ConsumeLoginEmailOTP(r.Context(), p.UserID, otpPurposeMigrate, otpCodeHash(code), a.now()) + if isOTPRefusal(err) { + a.authFailure(r, "migrate_confirm", otpFailureReason(err), nil) + } + switch { case errors.As(err, &lock): a.noteOTPLock(r, err, p.UserID, otpPurposeMigrate) writeOTPAccountLocked(w, r, lock.Until, a.now()) @@ -300,7 +303,7 @@ func (a *API) handleMigrateConfirmOTPVerify(w http.ResponseWriter, r *http.Reque writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.migrate.confirmed", "") + a.audit(r, "account.migrate.confirmed", "") writeJSON(w, http.StatusOK, map[string]any{"confirmed": true}) } @@ -387,6 +390,7 @@ func (a *API) handleMigrateConfirmPasskeyFinish(w http.ResponseWriter, r *http.R sessionData, err := a.Repo.ConsumePasskeyChallengeByUser(r.Context(), p.UserID, passkeyPurposeMigrate, a.now()) if err != nil { if errors.Is(err, ErrPasskeyChallengeInvalid) { + a.authFailure(r, "migrate_passkey", "challenge_invalid", nil) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey confirmation could not be completed; begin again")) return @@ -401,6 +405,7 @@ func (a *API) handleMigrateConfirmPasskeyFinish(w http.ResponseWriter, r *http.R } va, err := a.Passkey.FinishLogin(migratePasskeyUser(p, creds), sessionData, bytes.NewReader(req.Assertion)) if err != nil { + a.authFailure(r, "migrate_passkey", "bad_assertion", nil) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey confirmation could not be completed; begin again")) return @@ -412,7 +417,7 @@ func (a *API) handleMigrateConfirmPasskeyFinish(w http.ResponseWriter, r *http.R // next login. if err := a.applyAssertionCounter(r.Context(), va); err != nil { if errors.Is(err, errPasskeyClonedAuthenticator) { - a.audit(r, auditActor(p), "auth.passkey_clone_rejected", va.CredentialID) + a.passkeyCloneRejected(r, "migrate_passkey", nil, va.CredentialID) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey confirmation could not be completed; begin again")) return @@ -429,7 +434,7 @@ func (a *API) handleMigrateConfirmPasskeyFinish(w http.ResponseWriter, r *http.R writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.migrate.confirmed", "") + a.audit(r, "account.migrate.confirmed", "") writeJSON(w, http.StatusOK, map[string]any{"confirmed": true}) } @@ -506,7 +511,7 @@ func (a *API) handleMigrateIssueCode(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.migrate.code_issued", targetID) + a.audit(r, "account.migrate.code_issued", targetID) writeJSON(w, http.StatusCreated, map[string]any{"code": code, "expires_at": expiresAt.UTC()}) } @@ -544,7 +549,7 @@ func (a *API) handleMigrateRedeem(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.migrate.redeemed", sourceUserID) + a.audit(r, "account.migrate.redeemed", sourceUserID) writeJSON(w, http.StatusOK, map[string]any{ "migrated": true, "servers_moved": len(moved), diff --git a/internal/api/handlers_auth.go b/internal/api/handlers_auth.go index 30d7595..58e3ad3 100644 --- a/internal/api/handlers_auth.go +++ b/internal/api/handlers_auth.go @@ -1,6 +1,10 @@ package api -import "net/http" +import ( + "net/http" + + "felis.lolicon.best/internal/metrics" +) // Passwordless auth handlers (spec §B). Staff (Owner/Operator) authenticate via // email-OTP / passkey + in-game approve on op.console; players via bind code or @@ -10,10 +14,16 @@ import "net/http" // handleLogout revokes the presented session and clears the cookie (spec §B). It // is mounted Public and idempotent: it reads the cookie directly, so it works even -// when the session has already expired and never errors on a missing one. +// when the session has already expired and never errors on a missing one. Ending +// a live session is audited under its account; a dead cookie leaves no row. func (a *API) handleLogout(w http.ResponseWriter, r *http.Request) { if c, err := r.Cookie(sessionCookieName); err == nil && c.Value != "" { - _ = a.Repo.RevokeSession(r.Context(), hashCookie(c.Value)) + hash := hashCookie(c.Value) + u, uerr := a.Repo.SessionUser(r.Context(), hash, a.now()) + if err := a.Repo.RevokeSession(r.Context(), hash); err == nil && uerr == nil { + metrics.SessionsRevokedTotal.WithLabelValues("logout").Inc() + a.auditEntry(r, AuditEntry{Actor: u.Username, ActorUserID: u.ID, Action: "auth.logout"}) + } } clearSessionCookie(w) writeJSON(w, http.StatusOK, map[string]any{"ok": true}) diff --git a/internal/api/handlers_auth_email.go b/internal/api/handlers_auth_email.go index ce1f9e9..f7eba01 100644 --- a/internal/api/handlers_auth_email.go +++ b/internal/api/handlers_auth_email.go @@ -167,7 +167,7 @@ func (a *API) handleLoginEmailStart(w http.ResponseWriter, r *http.Request) { return } committed = true - a.audit(r, u.Username, "auth.login_email.otp_sent", "") + a.auditAccount(r, u, "auth.login_email.otp_sent", "") writeJSON(w, http.StatusAccepted, map[string]any{"sent": true, "expires_at": expiresAt.UTC()}) } @@ -219,6 +219,7 @@ func (a *API) handleLoginEmailVerify(w http.ResponseWriter, r *http.Request) { // Uniform with a wrong code: a caller probing whether an address has an account // gets the same invalid_code either way. (The /auth/options oracle is the // sanctioned place to learn existence; this door does not double as one.) + a.authFailure(r, "login_email", "no_account", nil) writeError(w, r, newError(http.StatusBadRequest, "invalid_code", "email code is invalid or expired")) return case err != nil: @@ -240,6 +241,7 @@ func (a *API) handleLoginEmailVerify(w http.ResponseWriter, r *http.Request) { case errors.Is(err, ErrOTPInvalid), errors.Is(err, ErrOTPLocked), errors.Is(err, ErrOTPAccountLocked): // The account lock answers the same way; its owner hears about it by mail. a.noteOTPLock(r, err, u.ID, otpPurposeLogin) + a.authFailure(r, "login_email", otpFailureReason(err), u) // Both a wrong/expired code and an attempt-exhausted one return the SAME 400 // invalid_code, byte-identical to the unknown-account branch above. Surfacing // otp_locked as a distinct 429 (as the authenticated onboarding door does) would @@ -263,6 +265,7 @@ func (a *API) handleLoginEmailVerify(w http.ResponseWriter, r *http.Request) { // Staff means anything above role=user: an admin OR the role=owner identity. The // player door must yield only player sessions. if u.Role != "user" { + a.authFailure(r, "login_email", "staff_account", u) writeError(w, r, newError(http.StatusForbidden, "staff_account", "that account is staff; sign in at the operator console")) return @@ -279,7 +282,7 @@ func (a *API) handleLoginEmailVerify(w http.ResponseWriter, r *http.Request) { return } setSessionCookie(w, token, expires) - a.audit(r, u.Username, "auth.login_email", "") + a.auditAccount(r, u, "auth.login_email", "") writeJSON(w, http.StatusOK, map[string]any{ "user_id": u.ID, "role": u.Role, diff --git a/internal/api/handlers_backups.go b/internal/api/handlers_backups.go index 840c001..c57a013 100644 --- a/internal/api/handlers_backups.go +++ b/internal/api/handlers_backups.go @@ -208,7 +208,7 @@ func (a *API) handleRestoreBackup(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "backup.restore", name) + a.audit(r, "backup.restore", name) writeJSON(w, http.StatusAccepted, map[string]any{ "name": name, "status": "restoring", @@ -256,7 +256,7 @@ func (a *API) handleBackupNow(w http.ResponseWriter, r *http.Request) { return } - a.enqueueBackup(w, r, name, rec, p.Email, "external") + a.enqueueBackup(w, r, name, rec, auditActor(p), "external") } // handleInternalBackup is the internal-face backup trigger. The break-glass console @@ -360,10 +360,11 @@ func (a *API) enqueueBackup(w http.ResponseWriter, r *http.Request, name string, return } - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: actor, Source: source, Action: "backup.create", - ServerName: name, RequestID: requestIDFromContext(r.Context()), - }) + e := AuditEntry{Actor: actor, Source: source, Action: "backup.create", ServerName: name} + if p := principalFromContext(r.Context()); p != nil { + e.ActorUserID = p.UserID + } + a.auditEntry(r, e) writeJSON(w, http.StatusAccepted, map[string]any{ "name": name, "status": "backing_up", diff --git a/internal/api/handlers_console.go b/internal/api/handlers_console.go index 2c32e29..e85f479 100644 --- a/internal/api/handlers_console.go +++ b/internal/api/handlers_console.go @@ -117,6 +117,6 @@ func (a *API) handleCommand(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "console.command", name) + a.audit(r, "console.command", name) writeJSON(w, http.StatusOK, map[string]any{"name": name, "output": output}) } diff --git a/internal/api/handlers_email_otp.go b/internal/api/handlers_email_otp.go index 1b9502c..64ae8d8 100644 --- a/internal/api/handlers_email_otp.go +++ b/internal/api/handlers_email_otp.go @@ -192,7 +192,7 @@ func (a *API) handleEmailOTPStart(w http.ResponseWriter, r *http.Request) { // The send succeeded: keep both reservations (the deferred rollback becomes a // no-op) so the cooldown windows stand. committed = true - a.audit(r, auditActor(p), "account.email.otp_sent", "") + a.audit(r, "account.email.otp_sent", "") writeJSON(w, http.StatusAccepted, map[string]any{ "sent": true, "expires_at": expiresAt.UTC(), @@ -224,6 +224,9 @@ func (a *API) handleEmailOTPVerify(w http.ResponseWriter, r *http.Request) { return } email, err := a.Repo.VerifyEmailOTP(r.Context(), p.UserID, otpPurposeOnboard, otpCodeHash(code), a.now()) + if isOTPRefusal(err) { + a.authFailure(r, "onboard_email", otpFailureReason(err), nil) + } var lock *OTPAccountLockedError switch { case errors.As(err, &lock): @@ -245,7 +248,7 @@ func (a *API) handleEmailOTPVerify(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.email.verified", "") + a.audit(r, "account.email.verified", "") writeJSON(w, http.StatusOK, map[string]any{"verified": true, "email": email}) } @@ -316,16 +319,6 @@ func (a *API) handleSetEmail(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.email.set", "") + a.audit(r, "account.email.set", "") writeJSON(w, http.StatusOK, map[string]any{"email": email}) } - -// auditActor picks the most identifying actor string for a principal: the audited -// Access email when present, else the stable user id. A player mid-onboarding may -// not have a verified email yet, so the id keeps the audit row attributable. -func auditActor(p *Principal) string { - if p.Email != "" { - return p.Email - } - return p.UserID -} diff --git a/internal/api/handlers_files.go b/internal/api/handlers_files.go index 9d58754..fcf710e 100644 --- a/internal/api/handlers_files.go +++ b/internal/api/handlers_files.go @@ -164,8 +164,7 @@ func (a *API) handleWriteFile(w http.ResponseWriter, r *http.Request) { return } - p := principalFromContext(r.Context()) - a.audit(r, p.Email, "file.write", name+":"+path) + a.audit(r, "file.write", name+":"+path) writeJSON(w, http.StatusOK, map[string]any{"path": path, "status": "written"}) } diff --git a/internal/api/handlers_internal.go b/internal/api/handlers_internal.go index 1347d12..5d4f6ae 100644 --- a/internal/api/handlers_internal.go +++ b/internal/api/handlers_internal.go @@ -51,9 +51,8 @@ func (a *API) handleReady(w http.ResponseWriter, r *http.Request) { writeError(w, r, newError(http.StatusBadRequest, "bad_name", "invalid server name: %v", err)) return } - _ = a.Repo.Audit(r.Context(), AuditEntry{ + a.auditEntry(r, AuditEntry{ Actor: "backend", Source: "internal", Action: "ready", ServerName: name, - RequestID: requestIDFromContext(r.Context()), }) w.WriteHeader(http.StatusNoContent) } @@ -163,9 +162,8 @@ func (a *API) handleInternalWake(w http.ResponseWriter, r *http.Request) { // the cap held with 503 (or a SetDesiredState error) leaves the cooldown // untouched and the next join attempt is not also throttled. a.limiter().record(name) - _ = a.Repo.Audit(r.Context(), AuditEntry{ + a.auditEntry(r, AuditEntry{ Actor: "velocity", Source: "internal", Action: "wake", ServerName: name, - RequestID: requestIDFromContext(r.Context()), }) writeJSON(w, http.StatusAccepted, map[string]any{ "name": name, "desiredState": "Running", @@ -256,9 +254,8 @@ func (a *API) handleInternalClaim(w http.ResponseWriter, r *http.Request) { return } - _ = a.Repo.Audit(r.Context(), AuditEntry{ + a.auditEntry(r, AuditEntry{ Actor: "velocity", Source: "internal", Action: "claim", ServerName: name, - RequestID: requestIDFromContext(r.Context()), }) writeJSON(w, http.StatusOK, map[string]any{"name": name, "claimed": true}) } diff --git a/internal/api/handlers_logstream.go b/internal/api/handlers_logstream.go index 5cef7d0..412c4bd 100644 --- a/internal/api/handlers_logstream.go +++ b/internal/api/handlers_logstream.go @@ -98,6 +98,6 @@ func (a *API) handleServerConsole(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "console.attach", name) + a.audit(r, "console.attach", name) relayLogStream(w, r, src) } diff --git a/internal/api/handlers_onboard.go b/internal/api/handlers_onboard.go index 5f9662e..5fb5700 100644 --- a/internal/api/handlers_onboard.go +++ b/internal/api/handlers_onboard.go @@ -103,13 +103,16 @@ func (a *API) handleBindRedeem(w http.ResponseWriter, r *http.Request) { userID, mcUUID, authSource, err := a.Repo.RedeemPlayerBindCode(r.Context(), uid, code, a.now()) switch { case errors.Is(err, ErrLinkCodeInvalid): + a.authFailure(r, "bind_redeem", "bad_code", nil) writeError(w, r, newError(http.StatusBadRequest, "invalid_code", "bind code is invalid or expired")) return case errors.Is(err, ErrPlayerBindForbidden): + a.authFailure(r, "bind_redeem", "staff_account", nil) writeError(w, r, newError(http.StatusForbidden, "staff_account", "that Minecraft account belongs to staff; sign in at the operator console")) return case errors.Is(err, ErrPlayerAccountRetired): + a.authFailure(r, "bind_redeem", "account_retired", nil) // The linked Felis account is disabled or soft-deleted: the door refuses to // reuse it, because minting a session here would resurrect the account the // owner just retired (audit #33). The code survives, so re-enabling the @@ -133,7 +136,8 @@ func (a *API) handleBindRedeem(w http.ResponseWriter, r *http.Request) { return } setSessionCookie(w, token, expires) - a.audit(r, userID, "account.bind_redeem", "") + // The in-game code proved the Minecraft account; it names the actor. + a.auditEntry(r, AuditEntry{Actor: "mc:" + mcUUID, ActorUserID: userID, Action: "account.bind_redeem"}) writeJSON(w, http.StatusOK, map[string]any{ "user_id": userID, "linked": true, "mc_uuid": mcUUID, "auth_source": authSource, }) diff --git a/internal/api/handlers_op_login.go b/internal/api/handlers_op_login.go index 35c5110..bda5ed1 100644 --- a/internal/api/handlers_op_login.go +++ b/internal/api/handlers_op_login.go @@ -136,6 +136,7 @@ func (a *API) handleOpLoginStart(w http.ResponseWriter, r *http.Request) { u, err := a.Repo.UserByEmail(r.Context(), email) switch { case errors.Is(err, ErrNotFound): + a.authFailure(r, "op_login", "no_account", nil) neutral() return case err != nil: @@ -148,6 +149,7 @@ func (a *API) handleOpLoginStart(w http.ResponseWriter, r *http.Request) { // on console.) gets the neutral response, never a request or a code. // Staff means admin OR owner — the Owner is the primary op.console user. if !staffRole(u.Role) { + a.authFailure(r, "op_login", "not_staff", u) neutral() return } @@ -191,7 +193,7 @@ func (a *API) handleOpLoginStart(w http.ResponseWriter, r *http.Request) { return } committed = true - a.audit(r, u.Username, "auth.op_login.otp_sent", "") + a.auditAccount(r, u, "auth.op_login.otp_sent", "") writeJSON(w, http.StatusAccepted, map[string]any{ "request_id": id, "expires_at": expiresAt.UTC(), }) @@ -271,6 +273,7 @@ func (a *API) handleOpLoginFinish(w http.ResponseWriter, r *http.Request) { loginReq, err := a.Repo.OpLoginRequestByID(r.Context(), requestID) switch { case errors.Is(err, ErrNotFound): + a.authFailure(r, "op_login", "unknown_request", nil) writeError(w, r, invalid) return case err != nil: @@ -281,6 +284,7 @@ func (a *API) handleOpLoginFinish(w http.ResponseWriter, r *http.Request) { // code before an admin approved) must not consume the code. Not-approved collapses // into the same uniform failure as a bad code, so the ordering leaks nothing. if loginReq.Status != "approved" || loginReq.Consumed || !loginReq.ExpiresAt.After(now) { + a.authFailure(r, "op_login", "not_approved", a.opLoginAccount(r, loginReq.UserID)) writeError(w, r, invalid) return } @@ -290,6 +294,7 @@ func (a *API) handleOpLoginFinish(w http.ResponseWriter, r *http.Request) { switch err := a.Repo.ConsumeLoginEmailOTP(r.Context(), loginReq.UserID, otpPurposeOpLogin, otpCodeHash(code), now); { case errors.Is(err, ErrOTPInvalid), errors.Is(err, ErrOTPLocked), errors.Is(err, ErrOTPAccountLocked): a.noteOTPLock(r, err, loginReq.UserID, otpPurposeOpLogin) + a.authFailure(r, "op_login", otpFailureReason(err), a.opLoginAccount(r, loginReq.UserID)) writeError(w, r, invalid) return case err != nil: @@ -317,6 +322,7 @@ func (a *API) handleOpLoginFinish(w http.ResponseWriter, r *http.Request) { return } if !staffRole(u.Role) { + a.authFailure(r, "op_login", "not_staff", u) writeError(w, r, newError(http.StatusForbidden, "staff_account", "that account is not an operator")) return } @@ -331,10 +337,19 @@ func (a *API) handleOpLoginFinish(w http.ResponseWriter, r *http.Request) { return } setSessionCookie(w, token, expires) - a.audit(r, u.Username, "auth.op_login", "") + a.auditAccount(r, u, "auth.op_login", "") writeJSON(w, http.StatusOK, map[string]any{"user_id": u.ID, "role": u.Role}) } +// opLoginAccount loads the account a login request belongs to for a failure's +// audit row, falling back to the bare id. +func (a *API) opLoginAccount(r *http.Request, userID string) *StaffUser { + if u, err := a.Repo.UserByID(r.Context(), userID); err == nil { + return u + } + return &StaffUser{ID: userID} +} + // handleOpLoginPending lists live pending staff login requests, oldest first (internal // face). Today no plugin consumes it: the approver learns the request id out-of-band // (the op.console start screen shows it to the person logging in) and runs @@ -421,9 +436,9 @@ func (a *API) handleOpLoginApprove(w http.ResponseWriter, r *http.Request) { return } payload, _ := json.Marshal(map[string]string{"request_id": id, "approver_user_id": approverID}) - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: approver.Username, Source: "internal", Action: "auth.op_login.approved", - RequestID: requestIDFromContext(r.Context()), Payload: payload, + a.auditEntry(r, AuditEntry{ + Actor: approver.Username, ActorUserID: approverID, Source: "internal", + Action: "auth.op_login.approved", Payload: payload, }) writeJSON(w, http.StatusOK, map[string]any{"approved": true}) } diff --git a/internal/api/handlers_op_login_test.go b/internal/api/handlers_op_login_test.go index cde1a36..2bf6b34 100644 --- a/internal/api/handlers_op_login_test.go +++ b/internal/api/handlers_op_login_test.go @@ -3,6 +3,7 @@ package api import ( "net/http" "net/http/httptest" + "strings" "testing" "time" ) @@ -149,13 +150,14 @@ func TestOpLoginVertical(t *testing.T) { t.Fatalf("session row for the cookie = %+v (ok=%v), want userID a1", s, ok) } - // Three audits by "op": otp_sent (start), approved (in-game vouch), op_login (finish). - if n := len(repo.audits); n != 3 { - t.Fatalf("want 3 audits, got %d: %+v", n, repo.audits) + // Four audits by "op": otp_sent (start), the early finish refused before + // approval, approved (in-game vouch), op_login (finish). + if n := len(repo.audits); n != 4 { + t.Fatalf("want 4 audits, got %d: %+v", n, repo.audits) } - wantActions := []string{"auth.op_login.otp_sent", "auth.op_login.approved", "auth.op_login"} + wantActions := []string{"auth.op_login.otp_sent", "auth.op_login.failed", "auth.op_login.approved", "auth.op_login"} for i, want := range wantActions { - if repo.audits[i].Action != want || repo.audits[i].Actor != "op" { + if repo.audits[i].Action != want || repo.audits[i].Actor != "op" || repo.audits[i].ActorUserID != "a1" { t.Errorf("audit[%d] = %+v, want action %q by op", i, repo.audits[i], want) } } @@ -213,7 +215,7 @@ func TestOpLoginOwnerAdmitted(t *testing.T) { // a request_id + expires_at, mint/mail nothing, and still burn the per-recipient // cooldown — so neither the response nor the throttle tells a caller who is staff. func TestOpLoginStartNeutral(t *testing.T) { - check := func(t *testing.T, seed func(*fakeRepo), email string) { + check := func(t *testing.T, seed func(*fakeRepo), email, wantReason, wantUser string) { t.Helper() repo := newFakeRepo() repo.settings[LocalAuthEnabledKey] = []byte("true") @@ -236,9 +238,15 @@ func TestOpLoginStartNeutral(t *testing.T) { if s, _ := b["expires_at"].(string); s == "" { t.Error("neutral start must still return expires_at") } - if len(repo.opLogins) != 0 || len(repo.otps) != 0 || mailer.calls != 0 || len(repo.audits) != 0 { - t.Errorf("neutral start must mint/mail/audit nothing: reqs=%d otps=%d mails=%d audits=%d", - len(repo.opLogins), len(repo.otps), mailer.calls, len(repo.audits)) + if len(repo.opLogins) != 0 || len(repo.otps) != 0 || mailer.calls != 0 { + t.Errorf("neutral start must mint/mail nothing: reqs=%d otps=%d mails=%d", + len(repo.opLogins), len(repo.otps), mailer.calls) + } + // The response is neutral; the operator's record is not. + if len(repo.audits) != 1 || repo.audits[0].Action != "auth.op_login.failed" || + !strings.Contains(string(repo.audits[0].Payload), `"reason":"`+wantReason+`"`) || + repo.audits[0].ActorUserID != wantUser { + t.Errorf("neutral start audits = %+v, want one auth.op_login.failed %s by %q", repo.audits, wantReason, wantUser) } // The reservation is KEPT: re-probing the same address is throttled like a resend. if w := startOp(eh, email); w.Code != http.StatusTooManyRequests || decodeErr(t, w) != "otp_resend_cooldown" { @@ -247,12 +255,12 @@ func TestOpLoginStartNeutral(t *testing.T) { } t.Run("unknown address", func(t *testing.T) { - check(t, nil, "ghost@example.net") + check(t, nil, "ghost@example.net", "no_account", "") }) t.Run("non-staff (role=user) address is ignored by the staff door", func(t *testing.T) { check(t, func(repo *fakeRepo) { repo.staff["p"] = &StaffUser{ID: "u9", Username: "p", Email: "player@example.net", Role: "user", EmailVerified: true} - }, "player@example.net") + }, "player@example.net", "not_staff", "u9") }) } diff --git a/internal/api/handlers_passkey.go b/internal/api/handlers_passkey.go index d64f05a..f3657b4 100644 --- a/internal/api/handlers_passkey.go +++ b/internal/api/handlers_passkey.go @@ -355,7 +355,7 @@ func (a *API) handlePasskeyRegisterFinish(w http.ResponseWriter, r *http.Request writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.passkey.registered", cred.ID) + a.audit(r, "account.passkey.registered", cred.ID) writeJSON(w, http.StatusCreated, passkeyView(cred)) } @@ -415,7 +415,7 @@ func (a *API) handlePasskeyDelete(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, auditActor(p), "account.passkey.removed", id) + a.audit(r, "account.passkey.removed", id) w.WriteHeader(http.StatusNoContent) } @@ -593,6 +593,7 @@ func (a *API) handlePasskeyLoginFinish(w http.ResponseWriter, r *http.Request) { u, err := a.Repo.UserByEmail(r.Context(), email) if err != nil { if errors.Is(err, ErrNotFound) { + a.authFailure(r, "passkey", "no_account", nil) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -604,6 +605,7 @@ func (a *API) handlePasskeyLoginFinish(w http.ResponseWriter, r *http.Request) { sessionData, err := a.Repo.ConsumePasskeyChallengeByUser(r.Context(), u.ID, passkeyPurposeLogin, a.now()) if err != nil { if errors.Is(err, ErrPasskeyChallengeInvalid) { + a.authFailure(r, "passkey", "challenge_invalid", u) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -625,6 +627,7 @@ func (a *API) handlePasskeyLoginFinish(w http.ResponseWriter, r *http.Request) { } va, err := a.Passkey.FinishLogin(user, sessionData, bytes.NewReader(req.Assertion)) if err != nil { + a.authFailure(r, "passkey", "bad_assertion", u) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -634,7 +637,7 @@ func (a *API) handlePasskeyLoginFinish(w http.ResponseWriter, r *http.Request) { // distinctly; a successful assertion advances the stored counter and stamps last_used_at. if err := a.applyAssertionCounter(r.Context(), va); err != nil { if errors.Is(err, errPasskeyClonedAuthenticator) { - a.audit(r, u.Username, "auth.passkey_clone_rejected", va.CredentialID) + a.passkeyCloneRejected(r, "passkey", u, va.CredentialID) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -654,7 +657,7 @@ func (a *API) handlePasskeyLoginFinish(w http.ResponseWriter, r *http.Request) { return } setSessionCookie(w, token, expires) - a.audit(r, u.Username, "auth.passkey_login", "") + a.auditAccount(r, u, "auth.passkey_login", "") writeJSON(w, http.StatusOK, map[string]any{ "user_id": u.ID, "role": u.Role, diff --git a/internal/api/handlers_passkey_discoverable.go b/internal/api/handlers_passkey_discoverable.go index db0c178..ab53489 100644 --- a/internal/api/handlers_passkey_discoverable.go +++ b/internal/api/handlers_passkey_discoverable.go @@ -128,6 +128,7 @@ func (a *API) handlePasskeyLoginDiscoverableFinish(w http.ResponseWriter, r *htt sessionData, err := a.Repo.ConsumeDiscoverableChallenge(r.Context(), req.LoginID, a.now()) if err != nil { if errors.Is(err, ErrPasskeyChallengeInvalid) { + a.authFailure(r, "passkey_discoverable", "challenge_invalid", nil) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -166,6 +167,9 @@ func (a *API) handlePasskeyLoginDiscoverableFinish(w http.ResponseWriter, r *htt } va, err := a.Passkey.FinishDiscoverableLogin(resolve, sessionData, bytes.NewReader(req.Assertion)) if err != nil { + // resolved is set when the credential named a live account and only the + // signature (or the credential's binding) failed. + a.authFailure(r, "passkey_discoverable", "bad_assertion", resolved) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -184,7 +188,7 @@ func (a *API) handlePasskeyLoginDiscoverableFinish(w http.ResponseWriter, r *htt // resolved account; a successful assertion advances the stored counter and stamps last_used_at. if err := a.applyAssertionCounter(r.Context(), va); err != nil { if errors.Is(err, errPasskeyClonedAuthenticator) { - a.audit(r, resolved.Username, "auth.passkey_clone_rejected", va.CredentialID) + a.passkeyCloneRejected(r, "passkey_discoverable", resolved, va.CredentialID) writeError(w, r, newError(http.StatusBadRequest, "passkey_login_invalid", "passkey login could not be completed; begin again")) return @@ -204,7 +208,7 @@ func (a *API) handlePasskeyLoginDiscoverableFinish(w http.ResponseWriter, r *htt return } setSessionCookie(w, token, expires) - a.audit(r, resolved.Username, "auth.passkey_login_discoverable", "") + a.auditAccount(r, resolved, "auth.passkey_login_discoverable", "") writeJSON(w, http.StatusOK, map[string]any{ "user_id": resolved.ID, "role": resolved.Role, diff --git a/internal/api/handlers_player_reclaim.go b/internal/api/handlers_player_reclaim.go index 29216db..02eefc5 100644 --- a/internal/api/handlers_player_reclaim.go +++ b/internal/api/handlers_player_reclaim.go @@ -98,9 +98,8 @@ func (a *API) handleReclaimUsername(w http.ResponseWriter, r *http.Request) { // accountability record shows the reclaim was declined, and why. payload, _ := json.Marshal(map[string]string{ "username": req.Username, "squatter_uuid": req.SquatterUUID, "reason": "protected_admin"}) - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: "velocity", Source: "internal", Action: "player.reclaim.refused", - RequestID: requestIDFromContext(r.Context()), Payload: payload, + a.auditEntry(r, AuditEntry{ + Actor: "velocity", Source: "internal", Action: "player.reclaim.refused", Payload: payload, }) writeError(w, r, newError(http.StatusConflict, "protected_admin", "that username belongs to a linked administrator on the login server and cannot be reclaimed")) @@ -126,9 +125,8 @@ func (a *API) handleReclaimUsername(w http.ResponseWriter, r *http.Request) { // payload (the flat columns model a server op, not this), keyed by Source // internal since velocity, not a human, drives it. payload, _ := json.Marshal(map[string]string{"username": req.Username, "squatter_uuid": req.SquatterUUID}) - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: "velocity", Source: "internal", Action: "player.reclaim", - RequestID: requestIDFromContext(r.Context()), Payload: payload, + a.auditEntry(r, AuditEntry{ + Actor: "velocity", Source: "internal", Action: "player.reclaim", Payload: payload, }) writeJSON(w, http.StatusOK, map[string]any{ "blacklisted": true, diff --git a/internal/api/handlers_setup.go b/internal/api/handlers_setup.go index 8ce8229..a134571 100644 --- a/internal/api/handlers_setup.go +++ b/internal/api/handlers_setup.go @@ -67,6 +67,7 @@ func (a *API) handleSetupRedeem(w http.ResponseWriter, r *http.Request) { if err != nil { // Unknown, already-consumed, or expired — uniform 400 so the token cannot // be used as an oracle. + a.authFailure(r, "setup_redeem", "bad_token", nil) writeError(w, r, newError(http.StatusBadRequest, "setup_token_invalid", "this setup link is invalid or has already been used")) return @@ -96,7 +97,7 @@ func (a *API) handleSetupRedeem(w http.ResponseWriter, r *http.Request) { creds, _ := a.Repo.PasskeyCredentialsForUser(r.Context(), u.ID) hasPasskey := len(creds) > 0 - a.audit(r, u.Username, "auth.setup_redeem", "") + a.auditAccount(r, u, "auth.setup_redeem", "") writeJSON(w, http.StatusOK, map[string]any{ "user_id": u.ID, "username": u.Username, diff --git a/internal/api/handlers_updates.go b/internal/api/handlers_updates.go index dbc35ed..28e5812 100644 --- a/internal/api/handlers_updates.go +++ b/internal/api/handlers_updates.go @@ -113,6 +113,6 @@ func (a *API) handleSetUpdateWindow(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, principalFromContext(r.Context()).Email, "updates.window_set", "") + a.audit(r, "updates.window_set", "") writeJSON(w, http.StatusOK, body) } diff --git a/internal/api/handlers_user.go b/internal/api/handlers_user.go index c1c62f5..136102f 100644 --- a/internal/api/handlers_user.go +++ b/internal/api/handlers_user.go @@ -67,7 +67,7 @@ func (a *API) handleWake(w http.ResponseWriter, r *http.Request) { // held at capacity should retry the instant a slot frees, not wait out a // cooldown their refused wake never earned). a.limiter().record(name) - a.audit(r, p.Email, "wake", name) + a.audit(r, "wake", name) writeJSON(w, http.StatusAccepted, map[string]any{"name": name, "desiredState": "Running"}) } @@ -95,7 +95,7 @@ func (a *API) handleStop(w http.ResponseWriter, r *http.Request) { writeError(w, r, err) return } - a.audit(r, p.Email, "stop", name) + a.audit(r, "stop", name) writeJSON(w, http.StatusAccepted, map[string]any{"name": name, "desiredState": "Stopped"}) } @@ -160,7 +160,7 @@ func (a *API) handleClaim(w http.ResponseWriter, r *http.Request) { } // ④ audit. Allowlist population happens on first successful join (spec §9.4). - a.audit(r, p.Email, "claim", name) + a.audit(r, "claim", name) writeJSON(w, http.StatusOK, map[string]any{"name": name, "claimed": true}) } @@ -321,7 +321,6 @@ func (a *API) handleCreateServer(w http.ResponseWriter, r *http.Request) { writeError(w, r, errBuildUnavailable) return } - p := principalFromContext(r.Context()) var body createServerRequest if err := decodeJSON(w, r, &body); err != nil { @@ -449,7 +448,7 @@ func (a *API) handleCreateServer(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "server.create", body.Name) + a.audit(r, "server.create", body.Name) writeJSON(w, http.StatusCreated, map[string]any{ "name": body.Name, "subdomain": body.Subdomain, @@ -634,7 +633,6 @@ type patchServerRequest struct { // (Postgres) is untouched, so the two never desync (spec §22). The admin gate is // the adminOnly wrapper in routing — every caller here is already an admin. func (a *API) handlePatchServer(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) name := r.PathValue("name") if err := naming.ValidateServerName(name); err != nil { writeError(w, r, newError(http.StatusBadRequest, "bad_name", "invalid server name: %v", err)) @@ -794,7 +792,7 @@ func (a *API) handlePatchServer(w http.ResponseWriter, r *http.Request) { } } - a.audit(r, p.Email, "server.patch", name) + a.audit(r, "server.patch", name) writeJSON(w, http.StatusOK, map[string]any{ "name": name, "patched": changed, @@ -838,18 +836,6 @@ func (a *API) isOwnerOrAdmin(p *Principal, rec *ServerRecord) bool { return rec != nil && rec.OwnerID != "" && rec.OwnerID == p.UserID } -// audit writes a best-effort audit row; a logging failure must not fail the -// underlying operation, which already succeeded. -func (a *API) audit(r *http.Request, actor, action, server string) { - _ = a.Repo.Audit(r.Context(), AuditEntry{ - Actor: actor, - Source: "external", - Action: action, - ServerName: server, - RequestID: requestIDFromContext(r.Context()), - }) -} - // quantityToMilli converts a K8s resource.Quantity to millicores (e.g. "2"→2000, // "500m"→500). A zero/unset quantity returns 0. func quantityToMilli(q resource.Quantity) int { diff --git a/internal/api/handlers_users.go b/internal/api/handlers_users.go index 80f62c5..d3c28f6 100644 --- a/internal/api/handlers_users.go +++ b/internal/api/handlers_users.go @@ -5,6 +5,8 @@ import ( "net/http" "strconv" "strings" + + "felis.lolicon.best/internal/metrics" ) // ---- user CRUD ---- @@ -99,7 +101,7 @@ func (a *API) handleCreateUser(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.create", u.ID) + a.audit(r, "user.create", u.ID) writeJSON(w, http.StatusCreated, u) } @@ -179,7 +181,7 @@ func (a *API) handlePatchUser(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.patch", id) + a.audit(r, "user.patch", id) writeJSON(w, http.StatusOK, u) } @@ -215,7 +217,7 @@ func (a *API) handleDeleteUser(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.delete", id) + a.audit(r, "user.delete", id) writeJSON(w, http.StatusOK, map[string]any{"deleted": true}) } @@ -266,7 +268,7 @@ func (a *API) handleDisableUser(w http.ResponseWriter, r *http.Request) { if body.Disabled { action = "user.disable" } - a.audit(r, p.Email, action, id) + a.audit(r, action, id) writeJSON(w, http.StatusOK, map[string]any{"id": id, "disabled": body.Disabled}) } @@ -323,7 +325,7 @@ func (a *API) handleSetQuotas(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.set_quotas", id) + a.audit(r, "user.set_quotas", id) writeJSON(w, http.StatusOK, v) } @@ -350,7 +352,6 @@ func (a *API) handleListUserSessions(w http.ResponseWriter, r *http.Request) { // handleRevokeUserSessions revokes every live session of a user // (DELETE /users/{id}/sessions). func (a *API) handleRevokeUserSessions(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) id := r.PathValue("id") if id == "" { writeError(w, r, errBadRequest) @@ -362,14 +363,14 @@ func (a *API) handleRevokeUserSessions(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.revoke_sessions", id) + metrics.SessionsRevokedTotal.WithLabelValues("admin").Inc() + a.audit(r, "user.revoke_sessions", id) writeJSON(w, http.StatusOK, map[string]any{"ok": true}) } // handleRevokeUserSession revokes a single session of a user // (DELETE /users/{id}/sessions/{hash}). func (a *API) handleRevokeUserSession(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) id := r.PathValue("id") tokenHash := r.PathValue("hash") if id == "" || tokenHash == "" { @@ -382,7 +383,8 @@ func (a *API) handleRevokeUserSession(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.revoke_session", id) + metrics.SessionsRevokedTotal.WithLabelValues("admin").Inc() + a.audit(r, "user.revoke_session", id) writeJSON(w, http.StatusOK, map[string]any{"ok": true}) } @@ -397,7 +399,6 @@ func (a *API) handleRevokeUserSession(w http.ResponseWriter, r *http.Request) { // DeleteAllPasskeyCredentialsForUser treats removing zero rows as success, so // unbinding an account that holds no passkeys is a 200 no-op, not a 404. func (a *API) handleUnbindUserPasskeys(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) id := r.PathValue("id") if id == "" { writeError(w, r, errBadRequest) @@ -409,7 +410,7 @@ func (a *API) handleUnbindUserPasskeys(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.unbind_passkeys", id) + a.audit(r, "user.unbind_passkeys", id) writeJSON(w, http.StatusOK, map[string]any{"ok": true}) } @@ -418,7 +419,6 @@ func (a *API) handleUnbindUserPasskeys(w http.ResponseWriter, r *http.Request) { // handleUnlinkAccount removes a single (user_id, mc_uuid) binding // (DELETE /users/{id}/links/{mc_uuid}). func (a *API) handleUnlinkAccount(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) userID := r.PathValue("id") mcUUID := r.PathValue("mc_uuid") if userID == "" || mcUUID == "" { @@ -436,14 +436,13 @@ func (a *API) handleUnlinkAccount(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.unlink_account", userID) + a.audit(r, "user.unlink_account", userID) writeJSON(w, http.StatusOK, map[string]any{"ok": true, "mc_uuid": mcUUID}) } // handleLinkAccount force-binds a UUID to a user // (POST /users/{id}/links). func (a *API) handleLinkAccount(w http.ResponseWriter, r *http.Request) { - p := principalFromContext(r.Context()) userID := r.PathValue("id") if userID == "" { writeError(w, r, errBadRequest) @@ -489,7 +488,7 @@ func (a *API) handleLinkAccount(w http.ResponseWriter, r *http.Request) { return } - a.audit(r, p.Email, "user.link_account", userID) + a.audit(r, "user.link_account", userID) writeJSON(w, http.StatusOK, map[string]any{ "ok": true, "mc_uuid": body.MCUUID, diff --git a/internal/api/images.go b/internal/api/images.go index 3ec81f9..d1274d7 100644 --- a/internal/api/images.go +++ b/internal/api/images.go @@ -73,7 +73,7 @@ func (a *API) handleBuildImage(w http.ResponseWriter, r *http.Request) { writeBuildError(w, r, err) return } - a.audit(r, p.Email, "image.build", bld.ImageRef) + a.audit(r, "image.build", bld.ImageRef) writeJSON(w, http.StatusAccepted, bld) } @@ -151,7 +151,7 @@ func (a *API) handleBuildLogs(w http.ResponseWriter, r *http.Request) { "could not open build logs")) return } - a.audit(r, p.Email, "image.build.logs", id) + a.audit(r, "image.build.logs", id) relayLogStream(w, r, src) } @@ -162,14 +162,13 @@ func (a *API) handleCancelBuild(w http.ResponseWriter, r *http.Request) { writeError(w, r, errBuildUnavailable) return } - p := principalFromContext(r.Context()) id := r.PathValue("id") bld, err := a.Builder.Cancel(r.Context(), id) if err != nil { writeBuildError(w, r, err) return } - a.audit(r, p.Email, "image.build.cancel", bld.ImageRef) + a.audit(r, "image.build.cancel", bld.ImageRef) writeJSON(w, http.StatusOK, bld) } @@ -206,7 +205,7 @@ func (a *API) handleAddImage(w http.ResponseWriter, r *http.Request) { writeBuildError(w, r, err) return } - a.audit(r, p.Email, "image.admit", img.ImageRef) + a.audit(r, "image.admit", img.ImageRef) writeJSON(w, http.StatusCreated, img) } @@ -218,7 +217,6 @@ func (a *API) handleRemoveImage(w http.ResponseWriter, r *http.Request) { writeError(w, r, errBuildUnavailable) return } - p := principalFromContext(r.Context()) ref := r.URL.Query().Get("ref") if ref == "" { writeError(w, r, newError(http.StatusBadRequest, "bad_request", @@ -229,7 +227,7 @@ func (a *API) handleRemoveImage(w http.ResponseWriter, r *http.Request) { writeBuildError(w, r, err) return } - a.audit(r, p.Email, "image.remove", ref) + a.audit(r, "image.remove", ref) w.WriteHeader(http.StatusNoContent) } diff --git a/internal/api/otp_lock.go b/internal/api/otp_lock.go index 7189955..7365c76 100644 --- a/internal/api/otp_lock.go +++ b/internal/api/otp_lock.go @@ -61,12 +61,7 @@ func (a *API) noteOTPLock(r *http.Request, err error, userID, purpose string) { payload, _ := json.Marshal(map[string]any{ "user_id": userID, "purpose": purpose, "until": lock.Until.UTC(), "failures": otpFailureBudget, }) - if aerr := a.Repo.Audit(ctx, AuditEntry{ - Actor: actor, Source: "external", Action: "auth.otp.locked", - RequestID: requestIDFromContext(ctx), Payload: payload, - }); aerr != nil { - log.Printf("auth: audit of otp lock for user %s failed: %v", userID, aerr) - } + a.auditEntry(r, AuditEntry{Actor: actor, ActorUserID: userID, Action: "auth.otp.locked", Payload: payload}) door, notify := otpDoorName[purpose] if !notify || uerr != nil || u.Email == "" { diff --git a/internal/api/pgrepo.go b/internal/api/pgrepo.go index 6cd3a58..1785d09 100644 --- a/internal/api/pgrepo.go +++ b/internal/api/pgrepo.go @@ -747,10 +747,16 @@ func (p *PGRepo) Audit(ctx context.Context, e AuditEntry) error { if len(e.Payload) > 0 { payload = string(e.Payload) } + // actor_user_id goes through a lookup so an id with no users row (an + // Access-JWT subject, a purged account) lands as NULL instead of failing + // the foreign key and losing the row. _, err := p.db.ExecContext(ctx, - `INSERT INTO audit_logs (actor, source, action, server_name, request_id, payload) - VALUES ($1, $2, $3, NULLIF($4, ''), NULLIF($5, ''), $6)`, - e.Actor, e.Source, e.Action, e.ServerName, e.RequestID, payload) + `INSERT INTO audit_logs (actor, source, action, server_name, request_id, payload, + actor_user_id, client_ip, user_agent) + VALUES ($1, $2, $3, NULLIF($4, ''), NULLIF($5, ''), $6, + (SELECT id FROM users WHERE id = NULLIF($7, '')), NULLIF($8, '')::inet, NULLIF($9, ''))`, + e.Actor, e.Source, e.Action, e.ServerName, e.RequestID, payload, + e.ActorUserID, e.ClientIP, e.UserAgent) return err } @@ -1086,13 +1092,13 @@ func (p *PGRepo) SessionUser(ctx context.Context, tokenHash string, now time.Tim // minted for an account that was alive a moment ago stops authenticating the // instant the account is disabled or soft-deleted, so every authenticated route // is fail-closed regardless of which door minted the cookie (audit #33). - const q = `SELECT u.id, COALESCE(u.email, ''), u.role::text, COALESCE(u.email_verified, false) + const q = `SELECT u.id, u.username, COALESCE(u.email, ''), u.role::text, COALESCE(u.email_verified, false) FROM sessions s JOIN users u ON u.id = s.user_id WHERE s.token_hash = $1 AND s.revoked_at IS NULL AND s.expires_at > $2 AND u.disabled = false AND u.deleted_at IS NULL` var u SessionedUser switch err := p.db.QueryRowContext(ctx, q, tokenHash, now).Scan( - &u.ID, &u.Email, &u.Role, &u.EmailVerified); { + &u.ID, &u.Username, &u.Email, &u.Role, &u.EmailVerified); { case errors.Is(err, sql.ErrNoRows): return nil, ErrNotFound case err != nil: diff --git a/internal/api/ratelimit.go b/internal/api/ratelimit.go index d5a50c7..5675e13 100644 --- a/internal/api/ratelimit.go +++ b/internal/api/ratelimit.go @@ -54,6 +54,9 @@ const ( type tokenBucket struct { tokens float64 at time.Time + // refusing is set from a refusal until the next admission, so one episode + // of refusals can be recorded once. + refusing bool } // bucketSet is a set of token buckets keyed by caller. A missing key is a full @@ -121,8 +124,16 @@ func (s *bucketSet) bucket(key string, now time.Time) *tokenBucket { // take spends one token from key's bucket. When none is left it reports how // long until one is. A disabled limit always admits. func (s *bucketSet) take(key string) (bool, time.Duration) { + ok, wait, _ := s.admit(key) + return ok, wait +} + +// admit is take that also reports whether a refusal is the first since key was +// last admitted, so a flood leaves one audit row per episode instead of one +// per refused request. +func (s *bucketSet) admit(key string) (ok bool, wait time.Duration, first bool) { if s == nil || !s.limit.enabled() { - return true, 0 + return true, 0, false } s.mu.Lock() defer s.mu.Unlock() @@ -130,9 +141,12 @@ func (s *bucketSet) take(key string) (bool, time.Duration) { b := s.bucket(key, now) if b.tokens >= 1 { b.tokens-- - return true, 0 + b.refusing = false + return true, 0, false } - return false, s.wait(b) + first = !b.refusing + b.refusing = true + return false, s.wait(b), first } // peek reports whether key's bucket holds a token, without spending it. @@ -176,9 +190,14 @@ const mailGateKey = "mail" // throttleAuthDoor applies the per-source bucket to one public auth door. func (a *API) throttleAuthDoor(h http.HandlerFunc) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - ok, wait := a.authDoorGate().take(sourceKey(a.clientIP(r))) + key := sourceKey(a.clientIP(r)) + ok, wait, first := a.authDoorGate().admit(key) if !ok { metrics.RateLimitedTotal.WithLabelValues("auth_door").Inc() + if first { + a.auditEntry(r, AuditEntry{Actor: anonymousActor, Action: "auth.rate_limited", + Payload: auditPayload(map[string]any{"source": key, "door": r.URL.Path})}) + } writeError(w, r, newError(http.StatusTooManyRequests, "rate_limited", "too many sign-in requests from this network; try again shortly").retryAfter(wait)) return diff --git a/internal/api/repo.go b/internal/api/repo.go index 3a55a78..3e56788 100644 --- a/internal/api/repo.go +++ b/internal/api/repo.go @@ -32,14 +32,21 @@ type MyServerView struct { PlayersMax int32 `json:"playersMax"` } -// AuditEntry is one row written to audit_logs (spec §6). The actor is the Access -// email for human callers and the component name for internal callers. +// AuditEntry is one row written to audit_logs (spec §6). Actor is display text: +// a verified email or the username for people (auditActor), the component name +// for internal callers. ActorUserID is the account that acted, the column to +// attribute by: an unverified email proves nothing, so only the id is binding. type AuditEntry struct { - Actor string - Source string - Action string - ServerName string - RequestID string + Actor string + ActorUserID string + Source string + Action string + ServerName string + RequestID string + // ClientIP and UserAgent say where an external call came from; empty for + // internal callers. ClientIP is the address the sign-in limit keys on. + ClientIP string + UserAgent string // Payload is an optional structured detail blob stored in the audit_logs.payload // jsonb column. It MUST be valid JSON or nil; nil (the zero value) is stored as // SQL NULL, so existing callers that leave it unset are unaffected. The @@ -125,6 +132,7 @@ type PasskeyCredential struct { // accounts without a second DB read. type SessionedUser struct { ID string + Username string Email string Role string EmailVerified bool diff --git a/internal/api/session.go b/internal/api/session.go index ac1a91b..33c0708 100644 --- a/internal/api/session.go +++ b/internal/api/session.go @@ -167,6 +167,7 @@ func (s SessionAuth) Authenticate(r *http.Request) (*Principal, error) { } return &Principal{ UserID: u.ID, + Username: u.Username, Email: u.Email, Role: u.Role, ViaAdminAccess: staffRole(u.Role) && hostIsAdminConsole(r, s.RootDomain, s.AdminHostname), diff --git a/internal/api/submissions.go b/internal/api/submissions.go index c551f58..575ca21 100644 --- a/internal/api/submissions.go +++ b/internal/api/submissions.go @@ -124,7 +124,7 @@ func (a *API) handleCreateSubmission(w http.ResponseWriter, r *http.Request) { return } committed = true - a.audit(r, p.Email, "submission.create", sub.ID) + a.audit(r, "submission.create", sub.ID) writeJSON(w, http.StatusCreated, sub) } @@ -172,7 +172,7 @@ func (a *API) handleUploadSubmissionContext(w http.ResponseWriter, r *http.Reque return } committed = true - a.audit(r, p.Email, "submission.upload", sub.ID) + a.audit(r, "submission.upload", sub.ID) writeJSON(w, http.StatusOK, sub) } @@ -274,7 +274,7 @@ func (a *API) handleApproveSubmission(w http.ResponseWriter, r *http.Request) { writeSubmitError(w, r, err) return } - a.audit(r, p.Email, "submission.approve", sub.ID) + a.audit(r, "submission.approve", sub.ID) writeJSON(w, http.StatusOK, sub) } @@ -297,7 +297,7 @@ func (a *API) handleRejectSubmission(w http.ResponseWriter, r *http.Request) { writeSubmitError(w, r, err) return } - a.audit(r, p.Email, "submission.reject", sub.ID) + a.audit(r, "submission.reject", sub.ID) writeJSON(w, http.StatusOK, sub) } @@ -318,7 +318,7 @@ func (a *API) handleWithdrawSubmission(w http.ResponseWriter, r *http.Request) { writeSubmitError(w, r, err) return } - a.audit(r, p.Email, "submission.withdraw", sub.ID) + a.audit(r, "submission.withdraw", sub.ID) writeJSON(w, http.StatusOK, sub) } @@ -333,13 +333,12 @@ func (a *API) handleDeleteSubmission(w http.ResponseWriter, r *http.Request) { writeError(w, r, errSubmissionsUnavailable) return } - p := principalFromContext(r.Context()) sub, err := a.Submissions.Delete(r.Context(), r.PathValue("id")) if err != nil { writeSubmitError(w, r, err) return } - a.audit(r, p.Email, "submission.delete", sub.ID) + a.audit(r, "submission.delete", sub.ID) writeJSON(w, http.StatusOK, sub) } @@ -412,7 +411,7 @@ func (a *API) handleAdminSubmissionContext(w http.ResponseWriter, r *http.Reques } w.Header().Set("Content-Disposition", `attachment; filename="context.tar.gz"`) w.Header().Set("X-Content-Type-Options", "nosniff") - a.audit(r, principalFromContext(r.Context()).Email, "submission.context.download", r.PathValue("id")) + a.audit(r, "submission.context.download", r.PathValue("id")) streamSubmissionContext(w, rc) } diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 5a4d5b7..d8bb69a 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -81,6 +81,32 @@ var ( Name: "rate_limited_total", Help: "Requests refused by a volumetric rate limit, by scope.", }, []string{"scope"}) + + // AuthFailuresTotal counts refused sign-in attempts by door (login_email, + // op_login, passkey, passkey_discoverable, setup_redeem, bind_redeem) and + // reason (bad_code, no_account, staff_account, bad_credential, ...). A few a + // day is people mistyping; a steady stream is guessing or enumeration. + AuthFailuresTotal = prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: namespace, + Name: "auth_failures_total", + Help: "Refused sign-in attempts, by door and reason.", + }, []string{"door", "reason"}) + + // SessionsRevokedTotal counts sessions ended before expiry, by who ended + // them: logout (the holder) or admin (the owner revoking a user's sessions). + SessionsRevokedTotal = prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: namespace, + Name: "sessions_revoked_total", + Help: "Sessions revoked before expiry, by who revoked them.", + }, []string{"by"}) + + // AuditWriteFailuresTotal counts audit rows the API failed to write. The + // action went through; only its record was lost. + AuditWriteFailuresTotal = prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: namespace, + Name: "audit_write_failures_total", + Help: "Audit rows the API failed to write.", + }) ) // OTPPurposes are the email-code doors OTPLockoutsTotal is labelled by. @@ -135,6 +161,9 @@ func Collectors() []prometheus.Collector { OTPLockoutsTotal, MailTotal, RateLimitedTotal, + AuthFailuresTotal, + SessionsRevokedTotal, + AuditWriteFailuresTotal, } } diff --git a/internal/pgint/pgint_test.go b/internal/pgint/pgint_test.go index 38dc90d..81a53d0 100644 --- a/internal/pgint/pgint_test.go +++ b/internal/pgint/pgint_test.go @@ -327,6 +327,57 @@ func TestConsumeLoginEmailOTPContract(t *testing.T) { // The account-level wrong-code budget must survive supersede: minting a fresh // code resets the per-code attempts, and the public login door can mint one a // minute, so only a counter outside email_otps bounds guessing per account. +// TestAuditAttributionContract pins migration 0023: actor_user_id is filled +// from a real account id and falls to NULL (never a failed insert) for an id +// with no users row; client_ip and user_agent land when given. +func TestAuditAttributionContract(t *testing.T) { + ctx := context.Background() + u := newUser(t, "user", "audit") + action := "pgint.audit." + suffix(t) + for _, e := range []api.AuditEntry{ + {Actor: u.Username, ActorUserID: u.ID, Action: action, ClientIP: "2001:db8::7", UserAgent: "pgint/1"}, + {Actor: "sso-subject", ActorUserID: "not-a-user-" + suffix(t), Action: action}, + {Actor: "anonymous", Action: action, ClientIP: "203.0.113.9"}, + } { + e.Source = "external" + if err := repo.Audit(ctx, e); err != nil { + t.Fatalf("Audit(%s): %v", e.Actor, err) + } + } + rows, err := db.QueryContext(ctx, `SELECT actor, COALESCE(actor_user_id, ''), COALESCE(host(client_ip), ''), COALESCE(user_agent, '') + FROM audit_logs WHERE action = $1 ORDER BY id`, action) + if err != nil { + t.Fatalf("select: %v", err) + } + defer rows.Close() + var got []string + for rows.Next() { + var actor, uid, ip, ua string + if err := rows.Scan(&actor, &uid, &ip, &ua); err != nil { + t.Fatalf("scan: %v", err) + } + got = append(got, strings.Join([]string{actor, uid, ip, ua}, "|")) + } + want := []string{ + u.Username + "|" + u.ID + "|2001:db8::7|pgint/1", + "sso-subject|||", + "anonymous||203.0.113.9|", + } + if strings.Join(got, "\n") != strings.Join(want, "\n") { + t.Fatalf("audit rows:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n")) + } + + // The session principal carries the username the rows are signed with. + hash := "audit-sess-" + suffix(t) + if err := repo.CreateSession(ctx, hash, u.ID, mustNow().Add(time.Hour)); err != nil { + t.Fatalf("CreateSession: %v", err) + } + su, err := repo.SessionUser(ctx, hash, mustNow()) + if err != nil || su.Username != u.Username { + t.Fatalf("SessionUser = %+v, %v; want username %q", su, err, u.Username) + } +} + func TestOTPFailureBudgetContract(t *testing.T) { ctx := context.Background() u := newUser(t, "user", "otp-budget") diff --git a/internal/store/migrations/0023_audit_attribution.sql b/internal/store/migrations/0023_audit_attribution.sql new file mode 100644 index 0000000..70c8ab3 --- /dev/null +++ b/internal/store/migrations/0023_audit_attribution.sql @@ -0,0 +1,16 @@ +-- Audit attribution. actor is display text, and for a signed-in caller it used +-- to be the account's email, which a player can set to any unverified address, +-- so a row could name someone else. actor_user_id is the account that acted, +-- taken from the session (NULL for component actors and anonymous callers), and +-- client_ip / user_agent say where the call came from (client_ip is the +-- address the sign-in rate limit keys on: the edge's header when configured). +-- Users are soft-deleted, so the SET NULL only runs on a hard purge; actor +-- still names the account then. +ALTER TABLE audit_logs + ADD COLUMN actor_user_id text REFERENCES users(id) ON DELETE SET NULL, + ADD COLUMN client_ip inet, + ADD COLUMN user_agent text; + +CREATE INDEX audit_logs_actor_user_id_idx ON audit_logs (actor_user_id, created_at DESC) + WHERE actor_user_id IS NOT NULL; +CREATE INDEX audit_logs_created_at_idx ON audit_logs (created_at DESC);