feat: stamp users.last_seen on login and token refresh

One conditional UPDATE writes it at most once per five minutes per
user. A failed write is logged and never fails authentication, and no
user payload carries the column.

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
+}

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})
 	}
 }

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")
+	}
+}