fix(lagoon): warn on after-commit work registered after lagoon:after_commit; correct the OnDatabase example and pivot read guidance (quick-261028-r16)

- flushStatementAfterCommit marks the statement; AfterCommit logs a warning
  when work is buffered on a flushed statement that no longer holds GORM's
  transaction. Log-only: the work still never runs, the write succeeds
- subtests pin the late callback warning, a callback between commit and
  flush, and a reused chained statement staying silent
- README OnDatabase example registers After(gorm:create).Before(commit),
  matching docs/database/transactions.md
- RegisterJoinTable: pivot-ordered reads join the pivot table explicitly;
  a Preload cannot be ordered by a pivot column

docs/database/transactions.md

@@ -84,7 +84,7 @@ return lagoon.OnDatabase(app, func(_ *sql.DB, gdb *gorm.DB) error {
 ```
 
 > [!WARNING]
-> Register such a callback with a `Before("gorm:commit_or_rollback_transaction")` constraint, as above. lagoon runs a single-statement write's after-commit work from its own callback right after that commit step; a callback that GORM sorts after it buffers work that is never run, without an error.
+> Register such a callback with a `Before("gorm:commit_or_rollback_transaction")` constraint, as above. lagoon runs a single-statement write's after-commit work from its own callback right after that commit step; a callback that GORM sorts after it buffers work that is never run. The write still succeeds, and lagoon logs a warning when that happens.
 
 ## Boot-time work that needs the database
 

modules/lagoon/README.md

@@ -26,7 +26,7 @@ Use cases:
 
 - One shared pool: `lagoon.Open`, `lagoon.Use` and `lagoon.OpenFromApp` return a `*sql.DB` and a `*gorm.DB` built on that same pool; `lagoon.Publish` makes both available on the `backpack.App`.
 - Database-ready hooks: `lagoon.OnDatabase` runs a callback with the pool and GORM handle as soon as the database is published, immediately when it already is, otherwise when `lagoon.Publish` runs. Plugins register GORM callbacks through it from Boot, which runs before the `serve` command publishes the database.
-- After-commit work: `lagoon.Transaction` runs a function in a transaction and then the callbacks registered with `lagoon.AfterCommit`, in order, only after the commit succeeds; a nested `lagoon.Transaction` is a savepoint whose callbacks are dropped with it when it fails. A nested `lagoon.Transaction` must be given the outer transaction's handle: given a root handle it returns an error without running its function, rather than open an independent transaction whose callbacks would wait on the outer one. A single-statement write for which GORM opens its own implicit transaction runs its callbacks from `lagoon:after_commit` once GORM commits, and never when the write fails. A callback registered inside a foreign plain GORM transaction is unsafe because Lagoon cannot observe its commit, so `lagoon.AfterCommit` warns and skips it. Outside a transaction, callbacks run immediately. The handle a supported callback receives always has an empty statement on the connection its work belongs to. A panicking callback is logged and never turns a committed write into an error.
+- After-commit work: `lagoon.Transaction` runs a function in a transaction and then the callbacks registered with `lagoon.AfterCommit`, in order, only after the commit succeeds; a nested `lagoon.Transaction` is a savepoint whose callbacks are dropped with it when it fails. A nested `lagoon.Transaction` must be given the outer transaction's handle: given a root handle it returns an error without running its function, rather than open an independent transaction whose callbacks would wait on the outer one. A single-statement write for which GORM opens its own implicit transaction runs its callbacks from `lagoon:after_commit` once GORM commits, and never when the write fails. A GORM callback that runs after `lagoon:after_commit` on the same write registers its work too late: the work never runs, and `lagoon.AfterCommit` logs a warning. A callback registered inside a foreign plain GORM transaction is unsafe because Lagoon cannot observe its commit, so `lagoon.AfterCommit` warns and skips it. Outside a transaction, callbacks run immediately. The handle a supported callback receives always has an empty statement on the connection its work belongs to. A panicking callback is logged and never turns a committed write into an error.
 - Per-plugin migrations: `lagoon.Migrate` runs the framework's `system_files` set (`attach.Migrations`), backend admin identity set (`lagoon.BackendAdminMigrations`), `deferred_bindings` set (`lagoon.DeferredBindingMigrations`, under the `lagoon.DeferredHistoryID` history) and job-queue set (`lagoon.QueueMigrations`: River's schema pinned at `lagoon.RiverSchemaVersion`, then the `lagoon.JobsTable` record table, under the `lagoon.QueueHistoryID` history), then every `pact.HasMigrations` set in plugin activation order, each in its own `summer_migrations_<plugin_id>` history table (`lagoon.HistoryTableName`). `lagoon.RollbackLast` and `lagoon.Status` cover rollback and history.
 - Mass assignment: `lagoon.Fill` copies only allow-listed keys onto a model by GORM column name and silently drops the rest, logging each dropped key once outside production. A `json.Number` (from a decoder using `UseNumber`) fills integer, unsigned and float fields. A value that does not fit its column (a fraction, an exponent or an overflow for an integer field, or a value of the wrong type) is a `lagoon.FillTypeError` naming the key, so a caller can answer it as a validation failure on that field. `lagoon.HasFillable` and `lagoon.HasHidden` are the Go forms of `$fillable` and `$hidden`.
 - Validation: `lagoon.Validate` (where `required` fails on a zero date or time) accepts Laravel-style rule strings (`required`, `nullable`, `integer`, `numeric`, `between`, `min`, `max`, `in`, `unique`, `boolean`, `email`, `confirmed`, `different`, `mimes`) and returns a field-to-messages map, translated through phrasebook when a translator is given. Unknown rule tokens are an error. A failed numeric range reports the bound that failed: the `min` message below the lower bound, the `max` message above the upper one, and the numeric `between` message when the bound came from `between`.
@@ -81,12 +81,12 @@ func createPost(ctx context.Context, gdb *gorm.DB, tr *phrasebook.Translator, in
 }
 ```
 
-A plugin registers its GORM callbacks from Boot through `lagoon.OnDatabase`, so they are installed whenever the database is published, and defers side effects until the write commits:
+A plugin registers its GORM callbacks from Boot through `lagoon.OnDatabase`, so they are installed whenever the database is published, and defers side effects until the write commits. Register the callback before GORM's `gorm:commit_or_rollback_transaction` step: lagoon runs a single-statement write's after-commit work from `lagoon:after_commit` right after that step, so work buffered by a callback GORM sorts later never runs, and `lagoon.AfterCommit` logs a warning for it (see [Callbacks registered at boot](../../docs/database/transactions.md#callbacks-registered-at-boot)):
 
 ```go
 func (p *Plugin) Boot(app *backpack.App) error {
 	return lagoon.OnDatabase(app, func(_ *sql.DB, gdb *gorm.DB) error {
-		return gdb.Callback().Create().After("gorm:after_create").Register("acme:post_created", func(db *gorm.DB) {
+		return gdb.Callback().Create().After("gorm:create").Before("gorm:commit_or_rollback_transaction").Register("acme:post_created", func(db *gorm.DB) {
 			if db.Error != nil {
 				return
 			}
@@ -191,7 +191,7 @@ func (p *Plugin) Migrations() []*gormigrate.Migration {
 | `lagoon.OrderOption` | Option type accepted by `lagoon.OrderBy`. |
 | `lagoon.Paginate` | Builds a `lagoon.Page` with `lagoon.PageMeta`. |
 | `lagoon.WithSoftDeleteCascade` | Runs a cascade inside the parent delete transaction. |
-| `lagoon.RegisterJoinTable` | Registers a custom pivot model for a many-to-many field. |
+| `lagoon.RegisterJoinTable` | Registers a custom pivot model for a many-to-many field. Reads in pivot order join the pivot table explicitly, because a Preload of the field cannot be ordered by a pivot column. |
 | `lagoon.DecryptLaravelPayload` | Decrypts a Laravel AES-256-CBC payload for data imports. |
 | `attach.File` | The `system_files` row model; `attach.File.URL` is the public URL of the original. |
 | `attach.PublicURL` | Public URL of a blob key: under `storage.uploads.public_url` when set, else under `storage.uploads.public_path_prefix`. |

modules/lagoon/relations.go

@@ -15,8 +15,13 @@ import (
 // Association Mode has no documented path to set those columns. Writes go
 // through an explicit delete-then-bulk-insert (or ON CONFLICT DO UPDATE)
 // against the join table directly, in the same transaction as the parent
-// save. Reads use Preload(field) plus .Order(...) on the pivot's own
+// save.
-// columns once RegisterJoinTable has run.
+//
+// Reads in pivot order join the pivot table explicitly: Joins on the join
+// table plus Order on its columns. A Preload of the field still loads the
+// targets through the pivot model once RegisterJoinTable has run, but GORM
+// issues that query without the join table, so ordering it by a pivot
+// column fails with a missing FROM-clause entry.
 func RegisterJoinTable(db *gorm.DB, owner any, field string, joinModel any) error {
 	if db == nil {
 		return fmt.Errorf("lagoon: register join table: db is nil")

modules/lagoon/transaction.go

@@ -14,6 +14,9 @@ const AfterCommitCallback = "lagoon:after_commit"
 
 const statementBufferKey = "lagoon:after_commit"
 
+// statementFlushedKey marks a statement whose AfterCommitCallback has run.
+const statementFlushedKey = "lagoon:after_commit_flushed"
+
 type afterCommitKey struct{}
 
 // afterCommitBuffer holds the callbacks registered inside one transaction.
@@ -95,6 +98,14 @@ func Transaction(ctx context.Context, gdb *gorm.DB, fn func(ctx context.Context,
 // run, because Lagoon cannot know whether that transaction will commit.
 // Anywhere else, fn runs immediately on db's connection.
 //
+// Called from a GORM callback that runs after AfterCommitCallback on the
+// same write, fn is registered too late and never runs; AfterCommit logs a
+// warning for it. Register such callbacks
+// Before("gorm:commit_or_rollback_transaction"). The warning also requires
+// that the statement no longer holds GORM's transaction, so a statement
+// reused across writes does not warn for a correctly ordered callback in a
+// later write.
+//
 // The handle fn receives always has an empty statement on the connection
 // the work belongs to, whatever handle AfterCommit was called with. Queries
 // through it never continue from the written model's
@@ -115,6 +126,10 @@ func AfterCommit(ctx context.Context, db *gorm.DB, fn func(ctx context.Context,
 	}
 	if db != nil && db.Statement != nil {
 		if _, started := db.InstanceGet("gorm:started_transaction"); started {
+			if _, flushed := db.InstanceGet(statementFlushedKey); flushed && !transactionalHandle(db) {
+				moduleLog.Warn("lagoon: after-commit callback registered after lagoon:after_commit ran; it will not run",
+					"hint", "register the GORM callback before gorm:commit_or_rollback_transaction")
+			}
 			buf := &afterCommitBuffer{}
 			if existing, ok := db.InstanceGet(statementBufferKey); ok {
 				if b, ok := existing.(*afterCommitBuffer); ok && b != nil {
@@ -155,8 +170,11 @@ func bufferFrom(ctx context.Context, db *gorm.DB) *afterCommitBuffer {
 
 // flushStatementAfterCommit is the AfterCommitCallback GORM callback: it
 // runs the statement's buffered callbacks once GORM's own transaction has
-// committed, on a fresh session over the pool.
+// committed, on a fresh session over the pool. It first marks the
+// statement as flushed, on every write that passes through it, so that
+// AfterCommit can warn about work registered after this point.
 func flushStatementAfterCommit(db *gorm.DB) {
+	db.InstanceSet(statementFlushedKey, true)
 	raw, ok := db.InstanceGet(statementBufferKey)
 	if !ok {
 		return

modules/lagoon/transaction_test.go

@@ -227,6 +227,114 @@ func TestTransactionAfterCommit(t *testing.T) {
 		}
 	})
 
+	// A callback GORM sorts after lagoon:after_commit registers its work too
+	// late: the write succeeds, the work never runs, and AfterCommit warns.
+	t.Run("late_callback_warns", func(t *testing.T) {
+		g, err := Use(ctx, db)
+		if err != nil {
+			t.Fatal(err)
+		}
+		var logs bytes.Buffer
+		previous := slog.Default()
+		slog.SetDefault(slog.New(slog.NewTextHandler(&logs, &slog.HandlerOptions{Level: slog.LevelWarn})))
+		defer slog.SetDefault(previous)
+		var r recorder
+		if err := g.Callback().Create().After(AfterCommitCallback).Register("lagoon_test:late", func(stmt *gorm.DB) {
+			item, ok := stmt.Statement.Dest.(*acItem)
+			if !ok {
+				return
+			}
+			name := item.Name
+			AfterCommit(stmt.Statement.Context, stmt, func(context.Context, *gorm.DB) { r.add(name) })
+		}); err != nil {
+			t.Fatal(err)
+		}
+		if err := g.WithContext(ctx).Create(&acItem{Name: "flush-late"}).Error; err != nil {
+			t.Fatal(err)
+		}
+		if n := committedCount(t, db, "flush-late"); n != 1 {
+			t.Fatalf("committed rows = %d, want 1", n)
+		}
+		if got := r.names(); len(got) != 0 {
+			t.Fatalf("callbacks = %v, want none", got)
+		}
+		if !strings.Contains(logs.String(), "registered after lagoon:after_commit ran") {
+			t.Fatalf("warning = %q", logs.String())
+		}
+	})
+
+	// A callback between GORM's commit step and lagoon:after_commit is in
+	// time: its work runs once and nothing is logged.
+	t.Run("callback_between_commit_and_flush_runs", func(t *testing.T) {
+		g, err := Use(ctx, db)
+		if err != nil {
+			t.Fatal(err)
+		}
+		var logs bytes.Buffer
+		previous := slog.Default()
+		slog.SetDefault(slog.New(slog.NewTextHandler(&logs, &slog.HandlerOptions{Level: slog.LevelWarn})))
+		defer slog.SetDefault(previous)
+		var r recorder
+		if err := g.Callback().Create().After("gorm:commit_or_rollback_transaction").Before(AfterCommitCallback).Register("lagoon_test:between", func(stmt *gorm.DB) {
+			item, ok := stmt.Statement.Dest.(*acItem)
+			if !ok {
+				return
+			}
+			name := item.Name
+			AfterCommit(stmt.Statement.Context, stmt, func(context.Context, *gorm.DB) { r.add(name) })
+		}); err != nil {
+			t.Fatal(err)
+		}
+		if err := g.WithContext(ctx).Create(&acItem{Name: "flush-between"}).Error; err != nil {
+			t.Fatal(err)
+		}
+		if got := r.names(); !reflect.DeepEqual(got, []string{"flush-between"}) {
+			t.Fatalf("callbacks = %v, want [flush-between]", got)
+		}
+		if strings.Contains(logs.String(), "registered after lagoon:after_commit ran") {
+			t.Fatalf("unexpected warning %q", logs.String())
+		}
+	})
+
+	// A chained handle reuses one statement across writes, so the flushed
+	// marker of the first write is still set during the second. A correctly
+	// ordered callback must stay silent there, because the statement holds
+	// GORM's transaction again.
+	t.Run("reused_statement_no_false_warning", func(t *testing.T) {
+		g, err := Use(ctx, db)
+		if err != nil {
+			t.Fatal(err)
+		}
+		var logs bytes.Buffer
+		previous := slog.Default()
+		slog.SetDefault(slog.New(slog.NewTextHandler(&logs, &slog.HandlerOptions{Level: slog.LevelWarn})))
+		defer slog.SetDefault(previous)
+		var r recorder
+		if err := g.Callback().Create().Before("gorm:create").Register("lagoon_test:reuse", func(stmt *gorm.DB) {
+			item, ok := stmt.Statement.Dest.(*acItem)
+			if !ok {
+				return
+			}
+			name := item.Name
+			AfterCommit(stmt.Statement.Context, stmt, func(context.Context, *gorm.DB) { r.add(name) })
+		}); err != nil {
+			t.Fatal(err)
+		}
+		q := g.WithContext(ctx).Table("lagoon_ac_items")
+		if err := q.Create(&acItem{Name: "flush-reuse-1"}).Error; err != nil {
+			t.Fatal(err)
+		}
+		if err := q.Create(&acItem{Name: "flush-reuse-2"}).Error; err != nil {
+			t.Fatal(err)
+		}
+		if got := r.names(); !reflect.DeepEqual(got, []string{"flush-reuse-1", "flush-reuse-2"}) {
+			t.Fatalf("callbacks = %v, want [flush-reuse-1 flush-reuse-2]", got)
+		}
+		if strings.Contains(logs.String(), "registered after lagoon:after_commit ran") {
+			t.Fatalf("unexpected warning %q", logs.String())
+		}
+	})
+
 	t.Run("plain_gorm_transaction_is_refused", func(t *testing.T) {
 		var logs bytes.Buffer
 		previous := slog.Default()