golem15/summercms
4
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(conga,lagoon): River and GORM log through diary components

Browse Source 
- 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
This commit is contained in:
Jakub Zych
2026-10-21 11:51:57 +02:00
parent 5b09b32512
commit e6b20e2cb6
8 changed files with 142 additions and 10 deletions
Download Patch File Download Diff File Expand all files Collapse all files

5
modules/conga/README.md
View File

@@ -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 `<plugin id>[<index>]:<command>`. 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.

33
modules/conga/client.go
View File

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

2
modules/conga/conga.go
View File

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

45
modules/conga/logger_smoke_test.go Normal file
View File

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

2
modules/conga/worker.go
View File

@@ -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

5
modules/lagoon/README.md
View File

@@ -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.

23
modules/lagoon/connection.go
View File

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

37
modules/lagoon/logger_smoke_test.go Normal file
View File

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