From e6b20e2cb66a3e4c233997126edd0c4ae9fa70de Mon Sep 17 00:00:00 2001 From: Jakub Zych Date: Wed, 21 Oct 2026 11:51:57 +0200 Subject: [PATCH] feat(conga,lagoon): River and GORM log through diary components - River's logger is diary.For("river") (warn by default), conga's own lines diary.For("conga"); an app-published logger still wins - GORM logs through logger.NewSlogLogger(diary.For("db")): warn level, record-not-found ignored, parameterized SQL traces only at verbosity 3 - Smoke tests TestRiverLoggerUsesDiarySmoke and TestGormLoggerUsesDiarySmoke --- modules/conga/README.md | 5 ++-- modules/conga/client.go | 33 +++++++++++++++++++-- modules/conga/conga.go | 2 +- modules/conga/logger_smoke_test.go | 45 +++++++++++++++++++++++++++++ modules/conga/worker.go | 2 +- modules/lagoon/README.md | 5 ++-- modules/lagoon/connection.go | 23 ++++++++++++++- modules/lagoon/logger_smoke_test.go | 37 ++++++++++++++++++++++++ 8 files changed, 142 insertions(+), 10 deletions(-) create mode 100644 modules/conga/logger_smoke_test.go create mode 100644 modules/lagoon/logger_smoke_test.go diff --git a/modules/conga/README.md b/modules/conga/README.md index ff12e1dc..5b792a9c 100644 --- a/modules/conga/README.md +++ b/modules/conga/README.md @@ -38,6 +38,7 @@ Use cases: - Scheduled commands: every worker carries one River periodic job per `pact.HasSchedule` entry, in plugin activation order then declaration order, with the id `[]:`. Only the elected leader enqueues. Each run is a `conga.ScheduledCommandArgs` job on `conga.QueueScheduled` with one attempt (an interrupted run is not retried; the next period runs normally) and unique by args within its cadence period, so a leader failover cannot double-enqueue a period. The worker runs a job only when its entry exists in the compiled schedule and its command and arguments match that entry exactly, so a forged `river_job` row cannot run an arbitrary command. An unregistered command, or an app with no published `bonfire.Catalog`, is logged at Warn (`schedule: command not registered; skipping`) and skipped without failing the worker or other entries. Command output is logged line by line at Info with a `command` attribute; failures are logged with the duration. - Framework schedule entries: before the plugin entries, every worker carries the framework's own entries from `lagoon.FrameworkSchedule`, listed under the plugin id `lagoon.FrameworkScheduleID`. Today that is the daily `deferred:purge` at `database.deferred_bindings.purge_at` (default `03:00`), with the id `summercms.lagoon[0]:deferred:purge`; it runs, appears in `schedule:run --once` and is protected by the compiled entry table exactly like a plugin entry. An empty `purge_at` removes it, and a malformed one fails the worker start. - Wall-clock schedules: `conga.Daily` fires at the next `hh:mm` in its location and `conga.Every` at the next multiple of its interval since local midnight, so a restart never delays a daily run by up to a day the way `river.PeriodicInterval(24h)` would. On a DST day `conga.Daily` keeps the wall-clock time. A schedule entry with an empty command, a zero cadence, a daily time out of range, or an interval under one second or not dividing 24h fails the worker start with an error naming the plugin id and entry index. +- Logging: River logs through [diary](../diary/README.md) as component `river`, which the framework default `log.components.river: warn` keeps at warn, and conga's own lines (scheduled runs, job failures) log as component `conga`. An application that publishes its own `*slog.Logger` on the `backpack.App` gets both instead. - Commands: `conga.RuntimeCommands` adds `queue:work`, `schedule:run` and `queue:clear` to the application binary. `schedule:run` runs a scheduler-only worker in its own process, and `schedule:run --once` runs the entries due in the current minute without River, for system cron. ## Usage @@ -228,7 +229,7 @@ queues: ## Dependencies -- SummerCMS modules: [backpack](../backpack/README.md), [bonfire](../bonfire/README.md) (commands and the `bonfire.Catalog` scheduled runs call), [bouncer](../bouncer/README.md) (the dispatching principal), [lagoon](../lagoon/README.md) (the shared pool, `lagoon.JobsTable` and the migrations that create River's schema and `summer_jobs`), [pact](../pact/README.md), [party](../party/README.md). +- SummerCMS modules: [backpack](../backpack/README.md), [bonfire](../bonfire/README.md) (commands and the `bonfire.Catalog` scheduled runs call), [bouncer](../bouncer/README.md) (the dispatching principal), [diary](../diary/README.md) (the river and conga component loggers), [lagoon](../lagoon/README.md) (the shared pool, `lagoon.JobsTable` and the migrations that create River's schema and `summer_jobs`), [pact](../pact/README.md), [party](../party/README.md). - Third-party: `github.com/riverqueue/river` v0.47.0 with its `riverdriver/riverdatabasesql` and `rivertype` modules. River is the Postgres job queue the project stack names: it gives transactional inserts on the shared `*sql.DB`, retries, stuck-job rescue, leader election for periodic work and `LISTEN`/`NOTIFY` wake-ups. `github.com/jackc/pgx/v5/pgxpool` opens the listener pool; `gorm.io/gorm` writes the record rows. ## Testing @@ -237,4 +238,4 @@ queues: go test ./modules/conga/... ``` -The tests start a `postgres:16-alpine` container through testcontainers-go and migrate a fresh database per test with `lagoon.Migrate`, so they need a running Docker daemon. `TestListenPickupLatency` sets a 30-second poll interval and checks that a job committed by a separate client is picked up in under one second, while a poll-only worker does not pick it up within two. `TestScheduleRunsCommand` checks that an `Every(1s)` entry runs its command through a periodic job and that an unregistered command is skipped with a Warn log. `go test -short ./modules/conga/...` skips the database tests. +The tests start a `postgres:16-alpine` container through testcontainers-go and migrate a fresh database per test with `lagoon.Migrate`, so they need a running Docker daemon. `TestListenPickupLatency` sets a 30-second poll interval and checks that a job committed by a separate client is picked up in under one second, while a poll-only worker does not pick it up within two. `TestScheduleRunsCommand` checks that an `Every(1s)` entry runs its command through a periodic job and that an unregistered command is skipped with a Warn log. `go test -short ./modules/conga/...` skips the database tests; `TestRiverLoggerUsesDiarySmoke` runs without them and checks that River logs as component `river` unless the application publishes a logger. diff --git a/modules/conga/client.go b/modules/conga/client.go index c62961fa..c39ea500 100644 --- a/modules/conga/client.go +++ b/modules/conga/client.go @@ -8,6 +8,7 @@ import ( "time" "git.golem15.com/golem15/summercms/modules/backpack" + "git.golem15.com/golem15/summercms/modules/diary" "github.com/riverqueue/river" "github.com/riverqueue/river/riverdriver/riverdatabasesql" ) @@ -113,11 +114,37 @@ func newInsertClient(sqlDB *sql.DB, s settings, log *slog.Logger) (*river.Client return river.NewClient(riverdatabasesql.New(sqlDB), baseConfig(s, log)) } -func loggerFromApp(app *backpack.App) *slog.Logger { +// moduleLog is the logger of conga's own lines (component conga). +var moduleLog = diary.For("conga") + +// riverLog is River's logger (component river). The framework default +// log.components.river: warn keeps River's info lines out of the console. +var riverLog = diary.For("river") + +// publishedLogger returns the *slog.Logger the application published, if any. +func publishedLogger(app *backpack.App) (*slog.Logger, bool) { if app != nil { if log, ok := app.Lookup[*slog.Logger](); ok && log != nil { - return log + return log, true } } - return slog.Default() + return nil, false +} + +// loggerFromApp is the logger of conga's own lines: the logger the +// application published, else the conga component logger. +func loggerFromApp(app *backpack.App) *slog.Logger { + if log, ok := publishedLogger(app); ok { + return log + } + return moduleLog +} + +// riverLogger is the logger handed to River: the logger the application +// published, else diary.For("river"). +func riverLogger(app *backpack.App) *slog.Logger { + if log, ok := publishedLogger(app); ok { + return log + } + return riverLog } diff --git a/modules/conga/conga.go b/modules/conga/conga.go index b6c6b5b4..53ca1e7c 100644 --- a/modules/conga/conga.go +++ b/modules/conga/conga.go @@ -514,7 +514,7 @@ func (m *Manager) insertOnlyLocked() (*river.Client[*sql.Tx], error) { if !ok || sqlDB == nil { return nil, ErrNoDatabase } - c, err := newInsertClient(sqlDB, settingsFromApp(m.app), loggerFromApp(m.app)) + c, err := newInsertClient(sqlDB, settingsFromApp(m.app), riverLogger(m.app)) if err != nil { return nil, fmt.Errorf("conga: river client: %w", err) } diff --git a/modules/conga/logger_smoke_test.go b/modules/conga/logger_smoke_test.go new file mode 100644 index 00000000..837e6824 --- /dev/null +++ b/modules/conga/logger_smoke_test.go @@ -0,0 +1,45 @@ +package conga + +import ( + "bytes" + "log/slog" + "strings" + "testing" + + "git.golem15.com/golem15/summercms/modules/backpack" + "git.golem15.com/golem15/summercms/modules/bonfire" + "git.golem15.com/golem15/summercms/modules/compass" + "git.golem15.com/golem15/summercms/modules/diary" +) + +// TestRiverLoggerUsesDiarySmoke: River logs through the diary component +// river unless the application publishes its own logger, and conga's own +// lines use component conga. +func TestRiverLoggerUsesDiarySmoke(t *testing.T) { + var buf bytes.Buffer + t.Cleanup(diary.Reset) + diary.Bootstrap(&buf, diary.Options{Color: bonfire.ColorNever}) + + riverLogger(nil).Warn("probe") + if !strings.Contains(buf.String(), "component=river") { + t.Fatalf("River record lacks component=river:\n%s", buf.String()) + } + loggerFromApp(nil).Warn("own line") + if !strings.Contains(buf.String(), "component=conga") { + t.Fatalf("conga record lacks component=conga:\n%s", buf.String()) + } + + var capture bytes.Buffer + app := backpack.New(&compass.Config{}) + if err := app.Publish(slog.New(slog.NewTextHandler(&capture, nil))); err != nil { + t.Fatal(err) + } + buf.Reset() + riverLogger(app).Warn("published probe") + if !strings.Contains(capture.String(), "published probe") { + t.Fatalf("published logger did not receive the River record:\n%s", capture.String()) + } + if strings.Contains(buf.String(), "published probe") { + t.Fatalf("River record reached diary although the app published a logger:\n%s", buf.String()) + } +} diff --git a/modules/conga/worker.go b/modules/conga/worker.go index 7481e513..4d810e55 100644 --- a/modules/conga/worker.go +++ b/modules/conga/worker.go @@ -81,7 +81,7 @@ func StartWorker(ctx context.Context, app *backpack.App, plugins []party.Plugin, return nil, ErrNoDatabase } s := settingsFromApp(app) - log := loggerFromApp(app) + log := riverLogger(app) periodic, table, err := periodicJobs(app, plugins) if err != nil { return nil, err diff --git a/modules/lagoon/README.md b/modules/lagoon/README.md index c32d6277..addf9f5a 100644 --- a/modules/lagoon/README.md +++ b/modules/lagoon/README.md @@ -37,6 +37,7 @@ Use cases: - Column types: `lagoon.Encrypted` stores AES-256-GCM ciphertext under a key derived from `app.key`, decrypts with previous keys during rotation, and always redacts itself in JSON and string output; `lagoon.Jsonable` stores JSON as TEXT and keeps SQL NULL distinct from an empty value. - Lifecycle and relations: hook interfaces matching GORM's native method names (`lagoon.HasBeforeCreate`, `lagoon.HasBeforeSave`, `lagoon.HasBeforeDelete`, `lagoon.HasAfterDelete`) plus `lagoon.HasBeforeValidate`; `lagoon.WithSoftDeleteCascade` runs a cascade inside the parent delete; `lagoon.RegisterJoinTable` wires pivot models with business columns. - Deferred binding: WinterCMS's `deferred_bindings` table holds the uploads and related-record changes of a form whose record is not saved yet. Every operation takes a `lagoon.DeferredKey` (the form's session key, the owning backend admin's id and the master record's morph type from `lagoon.MorphType`) and never reads or changes another admin's rows, since each row stores `backend_user_id`. `lagoon.DeferredBind` and `lagoon.DeferredUnbind` port WinterCMS's duplicate and cancel rules: a repeated bind writes nothing, and an unbind of a slave with a pending bind deletes that bind and returns it so the caller can remove what it created. `lagoon.DeferredBindings` reads and locks a session's bindings for the save that commits them, `lagoon.DeferredForget` deletes them once applied, and `lagoon.DeferredSlaves` is the subquery a list uses to include pending rows. A child created under deferral carries the `lagoon.DeferredEnvelope` (`{"created":true,"pivot":{...},"upload_id":"..."}`) in `pivot_data`. `lagoon.PurgeDeferred` removes expired bindings: it deletes an unattached `system_files` row a bind points at, and its blobs only after the commit, deletes a child only when its binding carries the created envelope, keeps records that were only linked, and locks each batch with `FOR UPDATE SKIP LOCKED`. +- Logging: GORM's lines no longer go to stdout through GORM's own logger. They arrive through [diary](../diary/README.md) as component `db`: slow queries (over 200 ms) and errors at warn, while a missing record (`gorm.ErrRecordNotFound`) is no longer logged. At verbosity 3 (`-vvv`) every query is traced at info, with placeholders instead of the bound values. - Imports from Laravel: `lagoon.DecryptLaravelPayload` decrypts Laravel `encrypted` payloads with the old application key, for one-off data imports. - Attachments (`attach`): the `attach.File` model for `system_files` rows, WinterCMS-compatible partitioned storage keys (`attach.BlobKey`, `attach.PartitionDirectory`), an S3 bucket option behind the `attach.S3BuildTag` build tag (an untagged binary refuses an `s3://` bucket URL at boot with an error naming the tag), public URLs (`attach.PublicURL` for any key, under `storage.uploads.public_url` when a public bucket or CDN serves the files (`attach.PublicURLBase`), `attach.File.URL` for an original, matching WinterCMS's `File::getPath()` under the WinterCMS layout), on-demand thumbnails through `attach.File.Thumb` for JPEG, PNG, GIF and WebP originals (a WebP original's thumbnail is JPEG bytes under its `.webp` name, since WebP cannot be encoded; a missing, undecodable or oversized original gets WinterCMS's broken-image picture, `attach.BrokenImagePNG`, as its thumbnail, as `File::makeThumb` does), storing uploads through `attach.Store` (a server-generated disk name whose extension follows the sniffed content through `attach.DiskExtension`, so a PNG named `x.html` is stored as `.png`, an extension allow-list with `attach.DefaultImageExtensions` and `attach.DefaultFileExtensions` as defaults, a MIME filter, a size limit enforced while streaming, in image mode the `attach.IsAllowedImage` content guard, and the refusal of protected uploads while `storage.uploads.public_url` serves the bucket publicly, `attach.ErrProtectedNeedsPrivateBucket`), attachment relation declarations (`attach.Relation`, `attach.HasRelations`), static serving with an optional `is_public` gate (`attach.StaticHandlerPublic`), and a two-phase delete that removes blobs only after the database transaction commits (`attach.DeleteForOwner`, `attach.DeleteKeys`). @@ -261,7 +262,7 @@ storage: ## Dependencies -- SummerCMS modules: [backpack](../backpack/README.md), [bonfire](../bonfire/README.md), [compass](../compass/README.md), [pact](../pact/README.md), [party](../party/README.md), [phrasebook](../phrasebook/README.md) (validation messages). +- SummerCMS modules: [backpack](../backpack/README.md), [bonfire](../bonfire/README.md), [compass](../compass/README.md), [diary](../diary/README.md) (component loggers, GORM's logger), [pact](../pact/README.md), [party](../party/README.md), [phrasebook](../phrasebook/README.md) (validation messages). - Third-party: `gorm.io/gorm`, `gorm.io/driver/postgres`, `github.com/jackc/pgx/v5` (stdlib driver), `github.com/go-gormigrate/gormigrate/v2`, `github.com/go-playground/validator/v10`, `github.com/riverqueue/river` (its `rivermigrate` and `riverdriver/riverdatabasesql` packages, for the River schema in `lagoon.QueueMigrations`). - Third-party, `attach` only: `gocloud.dev/blob` (file and memory drivers; the S3 driver `gocloud.dev/blob/s3blob` and the AWS SDK v2 only under the `summercms_s3` build tag), `github.com/disintegration/imaging` (thumbnails), `golang.org/x/image/webp` (WebP decoding). - Standard library: `database/sql`, `crypto/aes`, `crypto/cipher`, `crypto/hkdf`, `log/slog`, `image`, among others. @@ -272,4 +273,4 @@ storage: go test ./modules/lagoon/... ``` -The database tests in `lagoon` and `lagoon/attach` start a `postgres:16-alpine` container through testcontainers-go, so they need a running Docker daemon. They are skipped by `go test -short ./modules/lagoon/...`, which runs only the unit tests. +The database tests in `lagoon` and `lagoon/attach` start a `postgres:16-alpine` container through testcontainers-go, so they need a running Docker daemon. They are skipped by `go test -short ./modules/lagoon/...`, which runs only the unit tests; `TestGormLoggerUsesDiarySmoke` among them checks that GORM logs as component `db` and traces SQL only at verbosity 3. diff --git a/modules/lagoon/connection.go b/modules/lagoon/connection.go index 6aea6fd1..41ce5ae5 100644 --- a/modules/lagoon/connection.go +++ b/modules/lagoon/connection.go @@ -5,12 +5,15 @@ import ( "database/sql" "fmt" "strings" + "time" "git.golem15.com/golem15/summercms/modules/backpack" "git.golem15.com/golem15/summercms/modules/compass" + "git.golem15.com/golem15/summercms/modules/diary" _ "github.com/jackc/pgx/v5/stdlib" "gorm.io/driver/postgres" "gorm.io/gorm" + "gorm.io/gorm/logger" ) // Open pings dsn through pgx stdlib and returns that exact *sql.DB plus a @@ -53,8 +56,26 @@ func Use(ctx context.Context, sqlDB *sql.DB) (*gorm.DB, error) { return gormFromSQL(sqlDB) } +// gormLogger routes GORM's lines through diary as component db instead of +// GORM's default stdout logger: slow queries (over 200ms) and errors at warn, +// record-not-found ignored, and SQL traces only at verbosity 3 (-vvv), with +// parameterized queries so bound values never reach a log line. +func gormLogger() logger.Interface { + level := logger.Warn + if diary.Verbosity() >= 3 { + level = logger.Info + } + return logger.NewSlogLogger(diary.For("db"), logger.Config{ + SlowThreshold: 200 * time.Millisecond, + LogLevel: level, + IgnoreRecordNotFoundError: true, + // Log SQL with placeholders, never with the bound values. + ParameterizedQueries: true, + }) +} + func gormFromSQL(sqlDB *sql.DB) (*gorm.DB, error) { - gdb, err := gorm.Open(postgres.New(postgres.Config{Conn: sqlDB}), &gorm.Config{}) + gdb, err := gorm.Open(postgres.New(postgres.Config{Conn: sqlDB}), &gorm.Config{Logger: gormLogger()}) if err != nil { return nil, fmt.Errorf("lagoon: gorm open: %w", err) } diff --git a/modules/lagoon/logger_smoke_test.go b/modules/lagoon/logger_smoke_test.go new file mode 100644 index 00000000..8d386f2d --- /dev/null +++ b/modules/lagoon/logger_smoke_test.go @@ -0,0 +1,37 @@ +package lagoon + +import ( + "bytes" + "context" + "strings" + "testing" + + "git.golem15.com/golem15/summercms/modules/bonfire" + "git.golem15.com/golem15/summercms/modules/diary" +) + +// TestGormLoggerUsesDiarySmoke: GORM logs through the diary component db, +// and only reports info lines (SQL traces) at verbosity 3. +func TestGormLoggerUsesDiarySmoke(t *testing.T) { + var buf bytes.Buffer + t.Cleanup(diary.Reset) + diary.Bootstrap(&buf, diary.Options{Color: bonfire.ColorNever}) + ctx := context.Background() + + gormLogger().Warn(ctx, "slow %s", "query") + if !strings.Contains(buf.String(), "component=db") { + t.Fatalf("GORM record lacks component=db:\n%s", buf.String()) + } + + buf.Reset() + gormLogger().Info(ctx, "trace at default verbosity") + if buf.Len() != 0 { + t.Fatalf("GORM info line logged at verbosity 0:\n%s", buf.String()) + } + + diary.SetVerbosity(3, false) + gormLogger().Info(ctx, "trace at verbosity 3") + if !strings.Contains(buf.String(), "trace at verbosity 3") { + t.Fatalf("GORM info line missing at verbosity 3:\n%s", buf.String()) + } +}