diff --git a/classes/last_seen.go b/classes/last_seen.go new file mode 100644 index 0000000..9b85644 --- /dev/null +++ b/classes/last_seen.go @@ -0,0 +1,27 @@ +package classes + +import ( + "context" + "fmt" + + "gorm.io/gorm" +) + +// TouchLastSeen stamps users.last_seen with the current time, at most once +// per five minutes per user: it is one UPDATE that matches the row only when +// last_seen is NULL or older than five minutes, so a busy client costs one +// write per window. It does not touch updated_at, and it applies to a +// deactivated user too. Login and token refresh call it and ignore its +// error apart from logging it: authentication never depends on this write. +func TouchLastSeen(ctx context.Context, db *gorm.DB, userID uint) error { + if db == nil { + return fmt.Errorf("golem15.user: gorm handle is missing") + } + if userID == 0 { + return nil + } + return fresh(ctx, db).Exec( + `UPDATE users SET last_seen = NOW() WHERE id = ? AND (last_seen IS NULL OR last_seen < NOW() - INTERVAL '5 minutes')`, + userID, + ).Error +} diff --git a/controllers/api_controller.go b/controllers/api_controller.go index 4228893..69992d9 100644 --- a/controllers/api_controller.go +++ b/controllers/api_controller.go @@ -108,6 +108,10 @@ func Login(app *backpack.App) http.HandlerFunc { _ = gdb.WithContext(ctx).Model(user).Update("password", next).Error } } + // A failed last_seen write is logged and never fails the login. + if err := classes.TouchLastSeen(ctx, gdb, user.ID); err != nil { + slog.Default().Warn("golem15.user: stamp last_seen on login", "user_id", user.ID, "err", err) + } token, err := mintFor(app, secret, user, requestURL(r)) if err != nil { writeOpaque500(w) @@ -174,7 +178,7 @@ func Fetch(app *backpack.App) http.HandlerFunc { // Refresh slides a still-refreshable bearer token. func Refresh(app *backpack.App) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - _, secret, ok := sessionDeps(w, app) + gdb, secret, ok := sessionDeps(w, app) if !ok { return } @@ -195,6 +199,15 @@ func Refresh(app *backpack.App) http.HandlerFunc { }) return } + // The refresh never loads the user row: the subject comes from the + // new token. A failed last_seen write is logged and never fails it. + if sub, _, _, _, err := bouncer.VerifyClaims(next, secret); err == nil { + if id, err := strconv.ParseUint(sub, 10, 64); err == nil && id != 0 { + if err := classes.TouchLastSeen(r.Context(), gdb, uint(id)); err != nil { + slog.Default().Warn("golem15.user: stamp last_seen on refresh", "user_id", id, "err", err) + } + } + } writeJSON(w, http.StatusOK, map[string]any{"token": next}) } } diff --git a/last_seen_test.go b/last_seen_test.go new file mode 100644 index 0000000..a56f21a --- /dev/null +++ b/last_seen_test.go @@ -0,0 +1,231 @@ +package user + +import ( + "encoding/json" + "net/http" + "strings" + "testing" + "time" + + "git.golem15.com/golem15/sm-user-plugin/classes" + "git.golem15.com/golem15/sm-user-plugin/controllers" + "git.golem15.com/golem15/sm-user-plugin/models" + "gorm.io/gorm" +) + +// TestLastSeen covers users.last_seen (D-17, D-29): login and refresh stamp +// it at most once per five minutes, a failing write never fails them, and it +// never reaches a user API payload. +func TestLastSeen(t *testing.T) { + app, gdb := sessionApp(t, "0s") + user := insertUser(t, gdb, "last-seen@example.test", "correct-horse") + const credentials = `{"email":"last-seen@example.test","password":"correct-horse"}` + + lastSeen := func() *time.Time { + t.Helper() + var row struct{ LastSeen *time.Time } + if err := gdb.Raw(`SELECT last_seen FROM users WHERE id = ?`, user.ID).Scan(&row).Error; err != nil { + t.Fatal(err) + } + return row.LastSeen + } + setLastSeen := func(age time.Duration) time.Time { + t.Helper() + at := time.Now().Add(-age).Truncate(time.Microsecond) + if err := gdb.Exec(`UPDATE users SET last_seen = ? WHERE id = ?`, at, user.ID).Error; err != nil { + t.Fatal(err) + } + return at + } + login := func() (string, map[string]any, string) { + t.Helper() + rec := postJSON(t, controllers.Login(app), "/_user/api/v1/login", credentials) + if rec.Code != http.StatusOK { + t.Fatalf("login %d %s", rec.Code, rec.Body.String()) + } + var body struct { + Token string `json:"token"` + User map[string]any `json:"user"` + } + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatal(err) + } + if body.Token == "" || len(body.User) == 0 { + t.Fatalf("login body %s", rec.Body.String()) + } + return body.Token, body.User, rec.Body.String() + } + refresh := func(token string) (string, string) { + t.Helper() + rec := bearer(t, controllers.Refresh(app), http.MethodPost, "/_user/api/v1/refresh", token) + if rec.Code != http.StatusOK { + t.Fatalf("refresh %d %s", rec.Code, rec.Body.String()) + } + var body map[string]any + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatal(err) + } + next, _ := body["token"].(string) + if next == "" || len(body) != 1 { + t.Fatalf("refresh body %s", rec.Body.String()) + } + return next, rec.Body.String() + } + updatedAt := func() time.Time { + t.Helper() + var at time.Time + if err := gdb.Raw(`SELECT updated_at FROM users WHERE id = ?`, user.ID).Scan(&at).Error; err != nil { + t.Fatal(err) + } + return at + } + + if lastSeen() != nil { + t.Fatal("a new user already has last_seen") + } + stampedBefore := updatedAt() + + // A login stamps it. + started := time.Now().Add(-time.Second) + token, payload, raw := login() + first := lastSeen() + if first == nil || first.Before(started) || first.After(time.Now().Add(time.Second)) { + t.Fatalf("last_seen after the first login = %v", first) + } + if !updatedAt().Equal(stampedBefore) { + t.Fatal("stamping last_seen touched updated_at") + } + // A second login and a refresh inside five minutes leave it alone. + token2, _, _ := login() + if got := lastSeen(); got == nil || !got.Equal(*first) { + t.Fatalf("a second login inside five minutes moved last_seen: %v -> %v", first, got) + } + token, _ = refresh(token) + if got := lastSeen(); got == nil || !got.Equal(*first) { + t.Fatalf("a refresh inside five minutes moved last_seen: %v -> %v", first, got) + } + + // Six minutes later a refresh stamps it again, and so does a login. + old := setLastSeen(6 * time.Minute) + _, refreshRaw := refresh(token) + afterRefresh := lastSeen() + if afterRefresh == nil || !afterRefresh.After(old.Add(5*time.Minute)) { + t.Fatalf("a refresh after six minutes did not stamp last_seen: %v (was %v)", afterRefresh, old) + } + old = setLastSeen(6 * time.Minute) + login() + if got := lastSeen(); got == nil || !got.After(old.Add(5*time.Minute)) { + t.Fatalf("a login after six minutes did not stamp last_seen: %v", got) + } + // Four minutes is inside the window. + recent := setLastSeen(4 * time.Minute) + refresh(token2) + if got := lastSeen(); got == nil || !got.Equal(recent) { + t.Fatalf("a refresh after four minutes moved last_seen: %v -> %v", recent, got) + } + + // A failing write never fails authentication: with a trigger that + // refuses every last_seen update, login and refresh still answer 200 + // with the same body shape. + // last_seen is ten minutes old, so both handlers attempt the write. + blocked := setLastSeen(10 * time.Minute) + drop := func() { + gdb.Exec(`DROP TRIGGER IF EXISTS test_refuse_last_seen ON users`) + gdb.Exec(`DROP FUNCTION IF EXISTS test_refuse_last_seen()`) + } + t.Cleanup(drop) + for _, stmt := range []string{ + `CREATE OR REPLACE FUNCTION test_refuse_last_seen() RETURNS trigger AS $$ BEGIN RAISE EXCEPTION 'last_seen cannot be written in this test'; END $$ LANGUAGE plpgsql`, + `CREATE TRIGGER test_refuse_last_seen BEFORE UPDATE OF last_seen ON users FOR EACH ROW EXECUTE FUNCTION test_refuse_last_seen()`, + } { + if err := gdb.Exec(stmt).Error; err != nil { + t.Fatal(err) + } + } + if err := classes.TouchLastSeen(t.Context(), gdb, user.ID); err == nil { + t.Fatal("the test trigger does not refuse the write, or TouchLastSeen swallowed the failure") + } + failedToken, failedPayload, _ := login() + _, failedRefreshRaw := refresh(failedToken) + if got := lastSeen(); got == nil || !got.Equal(blocked) { + t.Fatalf("last_seen changed although the write is refused: %v -> %v", blocked, got) + } + if len(failedPayload) != len(payload) { + t.Fatalf("the login payload changed shape when the write failed: %v vs %v", failedPayload, payload) + } + for key := range payload { + if _, ok := failedPayload[key]; !ok { + t.Fatalf("the login payload lost %s when the write failed", key) + } + } + if !strings.HasPrefix(failedRefreshRaw, `{"token":"`) || !strings.HasPrefix(refreshRaw, `{"token":"`) { + t.Fatalf("refresh bodies: %s / %s", refreshRaw, failedRefreshRaw) + } + drop() + + // No user payload carries the admin columns; permissions stays null and + // groups an empty list. + current, _, _ := login() + fetch := bearer(t, controllers.Fetch(app), http.MethodGet, "/_user/api/v1/fetch", current) + if fetch.Code != http.StatusOK { + t.Fatalf("fetch %d %s", fetch.Code, fetch.Body.String()) + } + var fetched struct { + User map[string]any `json:"user"` + } + if err := json.Unmarshal(fetch.Body.Bytes(), &fetched); err != nil { + t.Fatal(err) + } + for name, body := range map[string]string{"login": raw, "fetch": fetch.Body.String(), "refresh": refreshRaw} { + for _, key := range []string{"last_seen", "created_at", "updated_at", "LastSeen", "CreatedAt", "UpdatedAt", "Permissions"} { + if strings.Contains(body, `"`+key+`"`) { + t.Fatalf("the %s body carries %s: %s", name, key, body) + } + } + } + for name, got := range map[string]map[string]any{"login": payload, "fetch": fetched.User} { + if value, ok := got["permissions"]; !ok || value != nil { + t.Fatalf("%s payload permissions = %v (%v)", name, value, ok) + } + if groups, ok := got["groups"].([]any); !ok || len(groups) != 0 { + t.Fatalf("%s payload groups = %v", name, got["groups"]) + } + } + + // The model itself never serializes them either. + now := time.Now() + marshalled, err := json.Marshal(models.User{ + ID: 1, Email: "marshal@example.test", LastSeen: &now, CreatedAt: now, UpdatedAt: now, + Permissions: models.PermissionSet{"blog.post": 1}, Groups: []models.UserGroup{{Name: "Admins"}}, + }) + if err != nil { + t.Fatal(err) + } + lower := strings.ToLower(string(marshalled)) + for _, key := range []string{"last_seen", "lastseen", "permissions", "created_at", "createdat", "updated_at", "updatedat", "groups", "blog.post", "admins"} { + if strings.Contains(lower, key) { + t.Fatalf("a marshalled user carries %s: %s", key, marshalled) + } + } + if strings.Contains(string(marshalled), `"Password"`) { + t.Fatalf("a marshalled user carries the password: %s", marshalled) + } + + // The helper itself: a deactivated user is stamped, an unknown id and a + // zero id are no error, a missing handle is. + if err := gdb.Exec(`UPDATE users SET last_seen = NULL, deleted_at = NOW() WHERE id = ?`, user.ID).Error; err != nil { + t.Fatal(err) + } + if err := classes.TouchLastSeen(t.Context(), gdb, user.ID); err != nil || lastSeen() == nil { + t.Fatalf("a deactivated user was not stamped: %v", err) + } + if err := classes.TouchLastSeen(t.Context(), gdb, 987654321); err != nil { + t.Fatal(err) + } + if err := classes.TouchLastSeen(t.Context(), gdb, 0); err != nil { + t.Fatal(err) + } + if err := classes.TouchLastSeen(t.Context(), (*gorm.DB)(nil), user.ID); err == nil { + t.Fatal("TouchLastSeen without a handle") + } +}