diff --git a/cmd/summer/docs.go b/cmd/summer/docs.go index de0223d0..3fb47768 100644 --- a/cmd/summer/docs.go +++ b/cmd/summer/docs.go @@ -89,6 +89,14 @@ func docsServeCommand() bonfire.Command { return bonfire.Command{ Name: "docs:serve", Description: "Build the documentation site and preview it on a local address", + Long: `Builds the documentation site like docs:build into a temporary directory and +serves it on a loopback address. It watches the docs sources and the files +their src= references point to, and rebuilds on change; a failed rebuild keeps +the last good site. Ctrl+C stops the server and exits 0.`, + Examples: []bonfire.Example{ + {Command: "docs:serve", Description: "Preview the docs of the current repository on " + docsite.DefaultServeAddr}, + {Command: "docs:serve --addr 127.0.0.1:4100", Description: "Use another port"}, + }, Flags: []bonfire.Flag{ {Name: "root", Description: "Repository root; src= paths and modules/ resolve against it", Default: "."}, {Name: "src", Description: "Docs source directory (default /docs)"}, diff --git a/cmd/summer/main.go b/cmd/summer/main.go index 8a9556fc..b40b2517 100644 --- a/cmd/summer/main.go +++ b/cmd/summer/main.go @@ -4,7 +4,9 @@ import ( "context" "fmt" "os" + "os/signal" "strings" + "syscall" "git.golem15.com/golem15/summercms/internal/build" "git.golem15.com/golem15/summercms/internal/dev" @@ -256,12 +258,27 @@ func devCommand() bonfire.Command { return bonfire.Command{ Name: "dev", Description: "Watch sources and rebuild the app binary", + Long: `Builds the application in the current directory, runs bin/ serve and +watches the application's Go, YAML, go.mod, go.work, summer.yaml and .env +files (bin/, tmp/, .git/, main.go and plugins.gen.go excluded). After a change +it rebuilds and restarts serve; a failed build keeps the running server. + +The global options summer dev was given (-v, -q, --ansi, --no-ansi, -n, +--env) are passed on to serve. Ctrl+C stops serve, which prints its own +shutdown report, then prints the dev report (rebuilds, failed builds, +restarts, uptime) and exits 0.`, + Examples: []bonfire.Example{ + {Command: "dev", Description: "Build, serve and rebuild on every change"}, + {Command: "dev -v", Description: "Pass -v on to serve: per-plugin summary lines and info logs of every component"}, + }, Run: func(ctx context.Context, in bonfire.Input, out bonfire.Output) error { dir, err := os.Getwd() if err != nil { return err } - return dev.Watch(ctx, dir, out) + ctx, stop := signal.NotifyContext(ctx, os.Interrupt, syscall.SIGTERM) + defer stop() + return dev.Watch(ctx, dir, out, bonfire.GlobalsOf(out).Args()) }, } } diff --git a/docs/console/scaffolding.md b/docs/console/scaffolding.md index a59e54a3..5b17c554 100644 --- a/docs/console/scaffolding.md +++ b/docs/console/scaffolding.md @@ -13,13 +13,15 @@ The `summer` tool creates and builds applications and generates the files a plug | Command | Purpose | |---------|---------| | `summer build` | Reads `summer.yaml`, generates `plugins.gen.go` and `main.go`, and builds the binary into `bin/`, passing the manifest's `build.tags` to `go build` as `-tags`. Run it from the application directory or any directory below it. | -| `summer dev` | Builds the application as `summer build` does (build tags included), starts the binary, and rebuilds and restarts it whenever a Go or YAML source, `go.mod`, `go.work`, `.env` or `summer.yaml` changes. | +| `summer dev` | Builds the application as `summer build` does (build tags included), runs `bin/ serve`, and rebuilds and restarts it whenever a Go or YAML source, `go.mod`, `go.work`, `.env` or `summer.yaml` changes. A failed build keeps the running server. | ```sh summer build summer dev ``` +`summer dev` passes its global options on to `serve`: `summer dev -v` shows the per-plugin lines of the startup summary and every component's info logs, `summer dev -q` only warnings and errors. Ctrl+C stops `serve`, which prints its shutdown report, then `summer dev` prints its own report (rebuilds, failed builds, restarts, uptime) and exits 0. + Do not edit `main.go` or `plugins.gen.go`: `summer build` rewrites them from the manifest. ## Creating an application diff --git a/docs/console/setup-and-maintenance.md b/docs/console/setup-and-maintenance.md index 02849fcc..19927bcc 100644 --- a/docs/console/setup-and-maintenance.md +++ b/docs/console/setup-and-maintenance.md @@ -132,9 +132,9 @@ When the admin is mounted and the `backend_users` table is empty, `serve` prints | Command | Arguments and flags | Purpose | |---------|---------------------|---------| -| `queue:work` | `--queue `, repeatable | Runs a job worker in the foreground on the named queues (default: every known queue) until SIGINT or SIGTERM. An unknown queue is an error that lists the known ones. | +| `queue:work` | `--queue `, repeatable | Runs a job worker in the foreground on the named queues (default: every known queue) until SIGINT or SIGTERM, with a startup summary and a shutdown report. An unknown queue is an error that lists the known ones. | | `queue:clear` | `[queue]` (default `default`) | Deletes the waiting, scheduled and retryable jobs of one queue and prints how many it cleared. Running jobs are never touched. | -| `schedule:run` | `--once` | Without `--once`, runs a scheduler-only worker until stopped. With `--once`, runs the entries due in the current minute and exits, for system cron. | +| `schedule:run` | `--once` | Without `--once`, runs a scheduler-only worker until stopped, with a startup summary and a shutdown report. With `--once`, runs the entries due in the current minute, prints `Ran N due entries (M failed)` and exits, for system cron. | ```sh ./bin/acme queue:work --queue default --queue imports @@ -142,6 +142,8 @@ When the admin is mounted and the `backend_users` table is empty, `serve` prints ./bin/acme schedule:run --once ``` +`queue:work` prints a startup summary on a terminal: the environment, each queue with its concurrency, the database host and whether the `scheduled` queue runs in this worker. `schedule:run` prints the number of schedule entries and the next one due. Off a terminal they log the same facts as a `startup summary` record (components `queue` and `schedule`). On Ctrl+C or SIGTERM both stop within 10 seconds and print a shutdown report: jobs done, failed and handed back to the queue (jobs still running at the deadline are cancelled and River retries them), the uptime and any stop error. They exit 0 after a clean stop and 1 when the worker fails to stop. + `serve` runs a job worker in the same process unless `queue.work_in_serve` is `false`; set it to `false` when you run `queue:work` separately. [Task scheduling](../plugins/scheduling.md) explains the scheduler, and [conga](../../modules/conga/README.md) the queue settings. ## Realtime and push diff --git a/docs/console/utilities.md b/docs/console/utilities.md index a261a183..b90b14f1 100644 --- a/docs/console/utilities.md +++ b/docs/console/utilities.md @@ -35,7 +35,7 @@ These docs are Markdown files under `docs/`, plus every module README, built int |---------|-------|---------| | `summer docs:build` | `--root` (default `.`), `--src`, `--out`, `--base-url`, `--site-url`, `--site-label`, `--check` | Checks every page and writes the site to `site/` (or `--out`): HTML pages, a raw `.md` copy of each page, `llms.txt`, `llms-full.txt` and the search index. With `--check` it only reports problems and writes nothing. | | `summer docs:sync` | `--root` (default `.`), `--src` | Rewrites every code block that has a `src=` reference from its source file. | -| `summer docs:serve` | `--root` (default `.`), `--src`, `--base-url`, `--site-url`, `--site-label`, `--addr` (default `127.0.0.1:8088`), `--allow-remote` | Builds the site into a temporary directory, serves it and rebuilds when a page, a module or a referenced source changes. A failed rebuild prints its problems and keeps serving the last good build. | +| `summer docs:serve` | `--root` (default `.`), `--src`, `--base-url`, `--site-url`, `--site-label`, `--addr` (default `127.0.0.1:8088`), `--allow-remote` | Builds the site into a temporary directory, serves it and rebuilds when a page, a module or a referenced source changes. A failed rebuild prints its problems and keeps serving the last good build. Ctrl+C stops it and exits 0. | `docs/site.yaml` accepts two optional keys, `site_url` and `site_label`, that add a link back to the main site to every page header. With `site_url: https://acme.example/` the link reads "acme.example". Without `site_label` the label is the URL's host, or Home when `site_url` is a path such as `/`. `site_url` must be an `http://` or `https://` URL with a host, or a path starting with a single `/`. The `--site-url` and `--site-label` flags override the two keys the way `--base-url` overrides `base_url`. diff --git a/internal/dev/watch.go b/internal/dev/watch.go index 253b726d..794a8d4c 100644 --- a/internal/dev/watch.go +++ b/internal/dev/watch.go @@ -14,23 +14,44 @@ import ( "github.com/fsnotify/fsnotify" "git.golem15.com/golem15/summercms/internal/build" + "git.golem15.com/golem15/summercms/modules/bonfire" ) const defaultDebounce = 200 * time.Millisecond // Options customizes the watch loop. Tests inject Build and Start. type Options struct { - Build func(ctx context.Context, appDir string, out io.Writer) error - Start func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) + Build func(ctx context.Context, appDir string, out io.Writer) error + // Start runs binPath with args ("serve" followed by the forwarded + // global options). + Start func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) Debounce time.Duration } -// Watch rebuilds the app on source changes and restarts the child binary. -func Watch(ctx context.Context, appDir string, out io.Writer) error { - return watch(ctx, appDir, out, Options{}) +// Watch builds the app, runs bin/ serve with args (the global +// options summer dev was given, such as -v) and rebuilds and restarts it on +// source changes. When ctx ends it stops the child with SIGTERM (serve +// prints its own shutdown report), prints the dev report (rebuilds, failed +// builds, restarts, uptime) and returns nil. +func Watch(ctx context.Context, appDir string, out bonfire.Output, args []string) error { + return watch(ctx, appDir, out, args, Options{}) } -func watch(ctx context.Context, appDir string, out io.Writer, opts Options) error { +// devReport counts what a watch session did. +type devReport struct { + rebuilds, failed, restarts int + started time.Time +} + +func (r devReport) details() []bonfire.Detail { + return []bonfire.Detail{ + {Label: "Rebuilds", Value: fmt.Sprintf("%d (%d failed)", r.rebuilds+r.failed, r.failed), Warn: r.failed > 0}, + {Label: "Restarts", Value: fmt.Sprint(r.restarts)}, + {Label: "Uptime", Value: time.Since(r.started).Round(time.Second).String()}, + } +} + +func watch(ctx context.Context, appDir string, out bonfire.Output, args []string, opts Options) error { if appDir == "" { return fmt.Errorf("dev: app directory is empty") } @@ -40,7 +61,7 @@ func watch(ctx context.Context, appDir string, out io.Writer, opts Options) erro } appDir = abs if out == nil { - out = os.Stdout + out = bonfire.NewOutput(os.Stdin, os.Stdout, os.Stderr) } if opts.Build == nil { opts.Build = build.App @@ -57,6 +78,14 @@ func watch(ctx context.Context, appDir string, out io.Writer, opts Options) erro return err } binPath := filepath.Join(appDir, "bin", m.Binary) + childArgs := append([]string{"serve"}, args...) + // On a terminal the child gets the process's own stdout and stderr, so + // serve sees a terminal and prints its styled summary and report. + childOut, childErr := io.Writer(out), io.Writer(out) + if bonfire.IsTerminal(out) { + childOut, childErr = os.Stdout, os.Stderr + } + report := devReport{started: time.Now()} watcher, err := fsnotify.NewWatcher() if err != nil { @@ -70,26 +99,35 @@ func watch(ctx context.Context, appDir string, out io.Writer, opts Options) erro var current *child defer func() { current.stop() }() + out.Info(fmt.Sprintf("Watching %s; running bin/%s %s", appDir, m.Binary, strings.Join(childArgs, " "))) rebuild := func() { if ctx.Err() != nil { return } start := time.Now() if err := opts.Build(ctx, appDir, out); err != nil { - fmt.Fprintf(out, "build error: %v\n", err) + report.failed++ + out.Error(fmt.Sprintf("Build failed: %v", err)) return } - fmt.Fprintf(out, "rebuild: %s\n", time.Since(start).Round(time.Millisecond)) + report.rebuilds++ + out.Success(fmt.Sprintf("Rebuilt in %s", time.Since(start).Round(time.Millisecond))) if ctx.Err() != nil { return } - next, err := startChild(ctx, opts, binPath, out) + restart := current != nil + current.stop() + current = nil + next, err := startChild(ctx, opts, binPath, childArgs, childOut, childErr) if err != nil { - fmt.Fprintf(out, "start error: %v\n", err) + out.Error(fmt.Sprintf("Start failed: %v", err)) return } - current.stop() current = next + if restart { + report.restarts++ + out.Info("Restarted bin/" + m.Binary) + } } rebuild() @@ -145,9 +183,10 @@ func watch(ctx context.Context, appDir string, out io.Writer, opts Options) erro case <-ctx.Done(): current.stop() current = nil - return ctx.Err() + bonfire.Details(out, "Dev report", report.details()) + return nil case err := <-watchErrs: - fmt.Fprintf(out, "watch error: %v\n", err) + out.Warning(fmt.Sprintf("Watch error: %v", err)) case <-events: if timer == nil { timer = time.NewTimer(opts.Debounce) @@ -172,8 +211,8 @@ type child struct { wait <-chan error } -func startChild(ctx context.Context, opts Options, binPath string, out io.Writer) (*child, error) { - cmd, err := opts.Start(ctx, binPath, out, out) +func startChild(ctx context.Context, opts Options, binPath string, args []string, stdout, stderr io.Writer) (*child, error) { + cmd, err := opts.Start(ctx, binPath, args, stdout, stderr) if err != nil { return nil, err } @@ -198,8 +237,10 @@ func (c *child) stop() { } } -func startBin(_ context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { - cmd := exec.Command(binPath) +// startBin runs binPath with args, which watch builds as "serve" followed +// by the forwarded global options. +func startBin(_ context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { + cmd := exec.Command(binPath, args...) cmd.Stdout = stdout cmd.Stderr = stderr cmd.Stdin = os.Stdin diff --git a/internal/dev/watch_test.go b/internal/dev/watch_test.go index f09221a7..d73e84ec 100644 --- a/internal/dev/watch_test.go +++ b/internal/dev/watch_test.go @@ -16,6 +16,7 @@ import ( "time" "git.golem15.com/golem15/summercms/internal/build" + "git.golem15.com/golem15/summercms/modules/bonfire" ) type safeBuffer struct { @@ -35,6 +36,11 @@ func (s *safeBuffer) String() string { return s.b.String() } +// testOutput is a non-terminal bonfire console writing to w. +func testOutput(w io.Writer) bonfire.Output { + return bonfire.NewOutput(strings.NewReader(""), w, w) +} + func TestWatchRebuildsOnSourceEdit(t *testing.T) { dir := t.TempDir() writeWatchApp(t, dir) @@ -53,7 +59,10 @@ func TestWatchRebuildsOnSourceEdit(t *testing.T) { fmt.Fprintln(w, "built hello in 1ms") return nil }, - Start: func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { + Start: func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { + if got := strings.Join(args, " "); got != "serve -v --env staging" { + return nil, fmt.Errorf("start args = %q, want serve and the forwarded globals", got) + } starts.Add(1) cmd := exec.Command("sleep", "30") if err := cmd.Start(); err != nil { @@ -64,7 +73,7 @@ func TestWatchRebuildsOnSourceEdit(t *testing.T) { } done := make(chan error, 1) - go func() { done <- watch(ctx, dir, &out, opts) }() + go func() { done <- watch(ctx, dir, testOutput(&out), []string{"-v", "--env", "staging"}, opts) }() waitUntil(t, "initial start", func() bool { return starts.Load() == 1 }) if builds.Load() != 1 { @@ -91,15 +100,18 @@ func TestWatchRebuildsOnSourceEdit(t *testing.T) { } got := out.String() - if strings.Count(got, "rebuild:") != 2 { + if strings.Count(got, "Rebuilt in ") != 2 { t.Fatalf("want 2 rebuild latency lines, got %q", got) } cancel() select { case err := <-done: - if err != nil && err != context.Canceled { - t.Fatalf("watch exit: %v", err) + if err != nil { + t.Fatalf("watch returned %v after Ctrl+C, want nil (exit 0)", err) + } + if !strings.Contains(out.String(), "Dev report") || !strings.Contains(out.String(), "Restarts 1") { + t.Fatalf("missing dev report:\n%s", out.String()) } case <-time.After(3 * time.Second): t.Fatal("watch did not exit on cancel") @@ -127,7 +139,7 @@ func TestWatchKeepsChildOnBuildFailure(t *testing.T) { } return nil }, - Start: func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { + Start: func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { starts.Add(1) cmd := exec.Command("sleep", "30") if err := cmd.Start(); err != nil { @@ -139,7 +151,7 @@ func TestWatchKeepsChildOnBuildFailure(t *testing.T) { } done := make(chan error, 1) - go func() { done <- watch(ctx, dir, &out, opts) }() + go func() { done <- watch(ctx, dir, testOutput(&out), nil, opts) }() waitUntil(t, "initial start", func() bool { return starts.Load() == 1 }) if err := os.WriteFile(filepath.Join(dir, "plugin.go"), []byte("package p\n// bad\n"), 0o644); err != nil { @@ -192,7 +204,7 @@ func TestWatchDebouncesRapidEdits(t *testing.T) { builds.Add(1) return nil }, - Start: func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { + Start: func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { cmd := exec.Command("sleep", "30") if err := cmd.Start(); err != nil { return nil, err @@ -201,7 +213,7 @@ func TestWatchDebouncesRapidEdits(t *testing.T) { }, } done := make(chan error, 1) - go func() { done <- watch(ctx, dir, &out, opts) }() + go func() { done <- watch(ctx, dir, testOutput(&out), nil, opts) }() waitUntil(t, "initial build", func() bool { return builds.Load() == 1 }) for i := 0; i < 5; i++ { @@ -243,7 +255,7 @@ func TestWatchIgnoresBinAndTmp(t *testing.T) { builds.Add(1) return nil }, - Start: func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { + Start: func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { cmd := exec.Command("sleep", "30") if err := cmd.Start(); err != nil { return nil, err @@ -252,7 +264,7 @@ func TestWatchIgnoresBinAndTmp(t *testing.T) { }, } done := make(chan error, 1) - go func() { done <- watch(ctx, dir, &out, opts) }() + go func() { done <- watch(ctx, dir, testOutput(&out), nil, opts) }() waitUntil(t, "initial build", func() bool { return builds.Load() == 1 }) if err := os.WriteFile(filepath.Join(dir, "bin", "hello.go"), []byte("package main\n"), 0o644); err != nil { @@ -290,7 +302,7 @@ func TestWatchHelloWorkspaceRebuildLatency(t *testing.T) { } return nil }, - Start: func(ctx context.Context, binPath string, stdout, stderr io.Writer) (*exec.Cmd, error) { + Start: func(ctx context.Context, binPath string, args []string, stdout, stderr io.Writer) (*exec.Cmd, error) { starts.Add(1) cmd := exec.Command("sleep", "30") if err := cmd.Start(); err != nil { @@ -301,7 +313,7 @@ func TestWatchHelloWorkspaceRebuildLatency(t *testing.T) { } done := make(chan error, 1) - go func() { done <- watch(ctx, dir, &out, opts) }() + go func() { done <- watch(ctx, dir, testOutput(&out), nil, opts) }() waitUntilTimeout(t, 60*time.Second, "initial real rebuild", func() bool { return starts.Load() == 1 }) if builds.Load() != 1 { t.Fatalf("initial builds = %d", builds.Load()) @@ -320,7 +332,7 @@ func TestWatchHelloWorkspaceRebuildLatency(t *testing.T) { } waitUntilTimeout(t, 60*time.Second, "rebuild after source edit", func() bool { return starts.Load() == 2 }) got := out.String() - if strings.Count(got, "rebuild:") < 2 { + if strings.Count(got, "Rebuilt in ") < 2 { t.Fatalf("want rebuild latency lines after restart, got %q", got) } if !rebuildLinePresent(got) { @@ -352,7 +364,7 @@ func TestWatchHelloWorkspaceRebuildLatency(t *testing.T) { func rebuildLinePresent(s string) bool { for _, line := range strings.Split(s, "\n") { line = strings.TrimSpace(line) - if strings.HasPrefix(line, "rebuild:") && len(strings.TrimSpace(strings.TrimPrefix(line, "rebuild:"))) > 0 { + if _, d, ok := strings.Cut(line, "Rebuilt in "); ok && strings.TrimSpace(d) != "" { return true } } diff --git a/modules/conga/README.md b/modules/conga/README.md index b71b7326..278ca26e 100644 --- a/modules/conga/README.md +++ b/modules/conga/README.md @@ -224,8 +224,8 @@ queues: | Command | Arguments and flags | Description | |---------|---------------------|-------------| -| `queue:work` | `--queue `, repeatable | Runs a job worker in the foreground on the named queues (default: every known queue) until SIGINT or SIGTERM, then stops it within 10 seconds. An unknown queue is an error that lists the known ones. | -| `schedule:run` | `--once` (bare) | Without `--once`: runs a worker on the `scheduled` queue that carries every plugin's periodic jobs, prints `scheduler started` and runs until SIGINT or SIGTERM, then stops within 10 seconds. With `--once`: runs, in-process and without River, every entry due in the current minute of `app.timezone` (a daily entry at its hour and minute; `Every(d)` of a minute or less on every run, a longer one when the minutes since midnight are a multiple of `d`), printing `Running scheduled command: ` per entry or `No scheduled commands are ready to run.`. An unregistered command prints a warning and is skipped. The exit status is the first command error, after every due entry ran. There is no overlap lock: two runs in one minute run the due entries twice, as Laravel does. System cron: `* * * * * cd /app && ./bin/app schedule:run --once`. | +| `queue:work` | `--queue `, repeatable | Runs a job worker in the foreground on the named queues (default: every known queue) until SIGINT or SIGTERM. It prints a startup summary on a terminal (environment, queues with their concurrency, database host, whether the `scheduled` queue runs here) and logs it as a `startup summary` record of component `queue` otherwise. On a signal it stops the worker within 10 seconds, prints and logs a `shutdown report` (jobs done, failed and handed back to the queue, uptime, stop errors) and exits 0, or 1 when the worker fails to stop. An unknown queue is an error that lists the known ones. | +| `schedule:run` | `--once` (bare) | Without `--once`: runs a worker on the `scheduled` queue that carries every plugin's periodic jobs, prints a startup summary (entry count and the next due entry; a `startup summary` record of component `schedule` off a terminal) and runs until SIGINT or SIGTERM, then stops within 10 seconds, prints a shutdown report (scheduled commands run and failed, uptime) and exits 0. With `--once`: runs, in-process and without River, every entry due in the current minute of `app.timezone` (a daily entry at its hour and minute; `Every(d)` of a minute or less on every run, a longer one when the minutes since midnight are a multiple of `d`), printing `Running scheduled command: ` per entry or `No scheduled commands are ready to run.`. An unregistered command prints a warning and is skipped. It ends with `Ran N due entries (M failed)`; the exit status is the first command error, after every due entry ran. There is no overlap lock: two runs in one minute run the due entries twice, as Laravel does. System cron: `* * * * * cd /app && ./bin/app schedule:run --once`. | | `queue:clear` | `[queue]` (default `default`) | Deletes the available, scheduled and retryable jobs of one queue in batches until none are left and prints `Cleared N jobs`. Running jobs are never touched. | ## Dependencies diff --git a/modules/conga/commands.go b/modules/conga/commands.go index a0e9ce5e..d87a08f6 100644 --- a/modules/conga/commands.go +++ b/modules/conga/commands.go @@ -3,8 +3,10 @@ package conga import ( "context" "fmt" + "log/slog" "os" "os/signal" + "slices" "strconv" "strings" "syscall" @@ -12,6 +14,7 @@ import ( "git.golem15.com/golem15/summercms/modules/backpack" "git.golem15.com/golem15/summercms/modules/bonfire" + "git.golem15.com/golem15/summercms/modules/diary" "git.golem15.com/golem15/summercms/modules/lagoon" "git.golem15.com/golem15/summercms/modules/pact" "git.golem15.com/golem15/summercms/modules/party" @@ -30,6 +33,23 @@ func RuntimeCommands(app *backpack.App, plugins []party.Plugin) []bonfire.Comman { Name: "queue:work", Description: "Run background job workers in the foreground", + Long: `Starts one River worker on the shared database pool for every known queue, or +for the queues named with --queue, and runs jobs until Ctrl+C or SIGTERM. It +prints a startup summary (environment, queues with their concurrency, database +host, whether the scheduled queue runs here) on a terminal, and logs it as a +"startup summary" record of component queue otherwise. + +On a signal it stops fetching jobs and waits up to 10 seconds for running +ones; jobs still running then are cancelled and River retries them later. +It prints a shutdown report (jobs done, failed, handed back to the queue, +uptime) and exits 0, or 1 when the worker fails to stop. + +serve runs the same worker in-process unless queue.work_in_serve is false; +run queue:work as a separate process when it is.`, + Examples: []bonfire.Example{ + {Command: "queue:work", Description: "Work every known queue"}, + {Command: "queue:work --queue mail --queue default", Description: "Work only the mail and default queues"}, + }, Flags: []bonfire.Flag{{ Name: "queue", Description: "Queue to work (repeatable; default all known queues)", @@ -44,6 +64,19 @@ func RuntimeCommands(app *backpack.App, plugins []party.Plugin) []bonfire.Comman { Name: "schedule:run", Description: "Run the scheduler in the foreground (or once for system cron)", + Long: `Without --once it runs a worker on the scheduled queue that also enqueues every +plugin's schedule entries, prints a startup summary (entry count, the next +due entry) and runs until Ctrl+C or SIGTERM, then prints a report (scheduled +commands run and failed, uptime) and exits 0. + +With --once it runs the entries due in the current minute in app.timezone, +one after another, ends with "Ran N due entries (M failed)" and exits 1 when +any of them failed. Use it from system cron when no worker runs the +scheduled queue.`, + Examples: []bonfire.Example{ + {Command: "schedule:run", Description: "Run the scheduler in the foreground"}, + {Command: "schedule:run --once", Description: "From cron, every minute: run the entries due now and exit"}, + }, Flags: []bonfire.Flag{{ Name: "once", Description: "Run the entries due this minute and exit (for system cron)", @@ -81,40 +114,151 @@ func RuntimeCommands(app *backpack.App, plugins []party.Plugin) []bonfire.Comman } } +// conga's console loggers: the startup summaries and shutdown reports of +// queue:work and schedule:run. +var ( + queueLog = diary.For("queue") + scheduleLog = diary.For("schedule") +) + +// announce prints rows as a block on a terminal (not under -q) and logs them +// as one record msg; the record is hidden from a terminal console when the +// block was printed (diary.HideOnTTY). +func announce(ctx context.Context, out bonfire.Output, log *slog.Logger, level slog.Level, title, msg string, rows []bonfire.Detail, attrs []slog.Attr) { + if bonfire.IsTerminal(out) && !bonfire.IsQuiet(out) { + bonfire.Details(out, title, rows) + ctx = diary.HideOnTTY(ctx) + } + log.LogAttrs(ctx, level, msg, attrs...) +} + +// workerReport is the shutdown report of a worker: its job counters, the +// uptime and the stop error. +func workerReport(w *Worker, started time.Time, stopErr error) ([]bonfire.Detail, []slog.Attr, slog.Level) { + st := w.Stats() + errText := "none" + level := slog.LevelInfo + if stopErr != nil { + errText = stopErr.Error() + level = slog.LevelError + } + up := time.Since(started).Round(time.Second) + rows := []bonfire.Detail{ + {Label: "Jobs", Value: fmt.Sprintf("%d done, %d failed, %d handed back to the queue", st.Done, st.Failed, st.HandedBack+st.InFlight), Warn: st.Failed > 0}, + {Label: "Uptime", Value: up.String()}, + {Label: "Errors", Value: errText, Warn: stopErr != nil}, + } + attrs := []slog.Attr{ + slog.Int64("jobs_done", st.Done), + slog.Int64("jobs_failed", st.Failed), + slog.Int64("jobs_handed_back", st.HandedBack+st.InFlight), + slog.Int64("uptime_ms", time.Since(started).Milliseconds()), + } + if stopErr != nil { + attrs = append(attrs, slog.String("errors", errText)) + } + return rows, attrs, level +} + +// queueList is "default (10), mail (2)": each queue with its MaxWorkers. +func queueList(w *Worker) string { + parts := make([]string, 0, len(w.queues)) + for _, q := range w.queues { + parts = append(parts, fmt.Sprintf("%s (%d)", q, w.concurrency[q])) + } + return strings.Join(parts, ", ") +} + func work(ctx context.Context, app *backpack.App, plugins []party.Plugin, queues []string, out bonfire.Output) error { + started := time.Now() ctx, stop := signal.NotifyContext(ctx, os.Interrupt, syscall.SIGTERM) defer stop() w, err := StartWorker(ctx, app, plugins, WorkerOptions{Queues: queues}) if err != nil { return err } - out.Info("worker started on queues: " + strings.Join(w.Queues(), ", ")) + scheduler := "not in this worker (the " + QueueScheduled + " queue is not selected)" + if slices.Contains(w.queues, QueueScheduled) { + scheduler = "included (the " + QueueScheduled + " queue runs scheduled commands)" + } + env := "unknown" + if app.Config != nil && app.Config.Environment() != "" { + env = app.Config.Environment() + } + db := lagoon.DatabaseLabel(lagoon.DSN(app.Config)) + announce(ctx, out, queueLog, slog.LevelInfo, "Worker started", "startup summary", []bonfire.Detail{ + {Label: "Environment", Value: env}, + {Label: "Queues", Value: queueList(w)}, + {Label: "Database", Value: db}, + {Label: "Scheduler", Value: scheduler}, + }, []slog.Attr{ + slog.String("environment", env), + slog.String("queues", strings.Join(w.queues, ",")), + slog.String("database", db), + slog.String("scheduler", scheduler), + }) <-ctx.Done() stopCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() - return w.Stop(stopCtx) + stopErr := w.Stop(stopCtx) + rows, attrs, level := workerReport(w, started, stopErr) + announce(context.WithoutCancel(ctx), out, queueLog, level, "Shutdown report", "shutdown report", rows, attrs) + return stopErr +} + +// nextDue is the earliest next run of entries after now, and its command. +func nextDue(entries []scheduleEntry, now time.Time) (time.Time, string) { + var at time.Time + var cmd string + for _, e := range entries { + if e.schedule == nil { + continue + } + if n := e.schedule.Next(now); at.IsZero() || n.Before(at) { + at, cmd = n, e.cmd.Command + } + } + return at, cmd } // runScheduler runs a scheduler-only worker (the scheduled queue plus every // plugin's periodic jobs) until SIGINT or SIGTERM. func runScheduler(ctx context.Context, app *backpack.App, plugins []party.Plugin, out bonfire.Output) error { + started := time.Now() ctx, stop := signal.NotifyContext(ctx, os.Interrupt, syscall.SIGTERM) defer stop() w, err := StartWorker(ctx, app, plugins, WorkerOptions{Queues: []string{QueueScheduled}}) if err != nil { return err } - out.Info("scheduler started") + entries, _ := scheduleEntries(app, plugins) + next := "none" + if at, cmd := nextDue(entries, time.Now()); cmd != "" { + next = cmd + " at " + at.Format("2006-01-02 15:04 MST") + } + announce(ctx, out, scheduleLog, slog.LevelInfo, "Scheduler started", "startup summary", []bonfire.Detail{ + {Label: "Entries", Value: fmt.Sprint(len(entries))}, + {Label: "Next", Value: next}, + }, []slog.Attr{ + slog.Int("entries", len(entries)), + slog.String("next", next), + }) <-ctx.Done() stopCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() - return w.Stop(stopCtx) + stopErr := w.Stop(stopCtx) + st := w.Stats() + rows, attrs, level := workerReport(w, started, stopErr) + rows[0] = bonfire.Detail{Label: "Runs", Value: fmt.Sprintf("%d scheduled commands (%d failed)", st.Done+st.Failed, st.Failed), Warn: st.Failed > 0} + announce(context.WithoutCancel(ctx), out, scheduleLog, level, "Shutdown report", "shutdown report", rows, attrs) + return stopErr } // scheduleRunOnce runs, without River, every schedule entry due in the // minute of now in app.timezone (Laravel schedule:run for system cron). An // unregistered command is warned about and skipped; the returned error is the -// first command error, after every due entry ran. +// first command error, after every due entry ran. It ends with "Ran N due +// entries (M failed)". func scheduleRunOnce(ctx context.Context, app *backpack.App, plugins []party.Plugin, now time.Time, out bonfire.Output) error { entries, err := scheduleEntries(app, plugins) if err != nil { @@ -138,16 +282,22 @@ func scheduleRunOnce(ctx context.Context, app *backpack.App, plugins []party.Plu return withAppDB(ctx, app, func() error { log := loggerFromApp(app) var first error + ran, failed := 0, 0 for _, e := range due { if _, ok := scheduledCatalog(app, log, e.cmd.Command); !ok { out.Warning(fmt.Sprintf("Scheduled command %s is not registered; skipping", e.cmd.Command)) continue } out.Printf("Running scheduled command: %s\n", strings.Join(append([]string{e.cmd.Command}, e.cmd.Args...), " ")) - if _, err := callScheduled(ctx, app, log, e.cmd.Command, e.cmd.Args, out); err != nil && first == nil { - first = err + ran++ + if _, err := callScheduled(ctx, app, log, e.cmd.Command, e.cmd.Args, out); err != nil { + failed++ + if first == nil { + first = err + } } } + out.Info(fmt.Sprintf("Ran %d due entries (%d failed)", ran, failed)) return first }) } diff --git a/modules/conga/worker.go b/modules/conga/worker.go index 09158196..a2f6c36a 100644 --- a/modules/conga/worker.go +++ b/modules/conga/worker.go @@ -40,6 +40,8 @@ type Worker struct { listener *pgxpool.Pool queues []string counters *workerCounters + // concurrency is each queue's MaxWorkers, for the startup summary. + concurrency map[string]int } // WorkerStats counts the job attempts a worker ran since it started. @@ -195,7 +197,7 @@ func StartWorker(ctx context.Context, app *backpack.App, plugins []party.Plugin, m.worker = client m.schedule = table m.counters.Store(counters) - return &Worker{m: m, client: client, listener: listener, queues: sortedQueueNames(queues), counters: counters}, nil + return &Worker{m: m, client: client, listener: listener, queues: sortedQueueNames(queues), counters: counters, concurrency: queues}, nil } // StartServeWorker starts the in-process worker of the serve command on diff --git a/modules/lagoon/README.md b/modules/lagoon/README.md index b17862f9..06eebe0b 100644 --- a/modules/lagoon/README.md +++ b/modules/lagoon/README.md @@ -136,6 +136,7 @@ func (p *Plugin) Migrations() []*gormigrate.Migration { | `lagoon.Migrate` | Runs framework and plugin migrations in order. | | `lagoon.RollbackLast` | Rolls back the last migration of one plugin. | | `lagoon.Status` | Lists applied migration IDs per plugin as `lagoon.StatusRow` values. | +| `lagoon.DatabaseLabel` | Describes a DSN for a person as `host:port/name` (parsed with `pgconn.ParseConfig`), never the user or password; `not configured` when empty, `configured` when it does not parse. Used by the startup summaries of `serve` and `queue:work`. | | `lagoon.PendingMigrations` | Lists the migrations `lagoon.Migrate` would apply, as `lagoon.MigrationRef` values (`Plugin`, `ID`): the framework sets first, then each plugin in order, each in declaration order. A missing history table means the whole set is pending. Read-only; `serve` reports the count in its startup summary. | | `lagoon.HistoryTableName` | Returns the gormigrate history table for a plugin ID. | | `lagoon.BackendAdminMigrations` | Creates the backend user, role and admin token blacklist tables, the `backend_api_tokens` table for personal API tokens, seeds the system roles, adds a case-insensitive unique index on `backend_users.email` and adds WinterCMS's nullable jsonable `backend_users.metadata` column (TEXT; the admin subtitle lives under its `subtitle` key). The index migration refuses to run while emails differ only in case and names the clashing logins. Rolling back the metadata migration drops only that column. | @@ -264,7 +265,7 @@ storage: ## Dependencies - 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: `gorm.io/gorm`, `gorm.io/driver/postgres`, `github.com/jackc/pgx/v5` (stdlib driver; `pgconn` for `lagoon.DatabaseLabel`), `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. diff --git a/modules/lagoon/connection.go b/modules/lagoon/connection.go index 69749c4f..d12fc76d 100644 --- a/modules/lagoon/connection.go +++ b/modules/lagoon/connection.go @@ -4,12 +4,14 @@ import ( "context" "database/sql" "fmt" + "strconv" "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/pgconn" _ "github.com/jackc/pgx/v5/stdlib" "gorm.io/driver/postgres" "gorm.io/gorm" @@ -122,6 +124,33 @@ func DSN(cfg *compass.Config) string { return strings.TrimSpace(cfg.String("database.dsn")) } +// DatabaseLabel describes dsn for a person without its secrets: host:port/name +// parsed with pgconn.ParseConfig (a Unix socket directory reads "socket +// "), never the user or password. An empty DSN is "not configured", one +// that does not parse "configured". serve and queue:work print it in their +// startup summaries. +func DatabaseLabel(dsn string) string { + dsn = strings.TrimSpace(dsn) + if dsn == "" { + return "not configured" + } + cfg, err := pgconn.ParseConfig(dsn) + if err != nil || cfg.Host == "" { + return "configured" + } + host := cfg.Host + if strings.HasPrefix(host, "/") { + host = "socket " + host + } else if strings.Contains(host, ":") { + host = "[" + host + "]" + } + label := host + ":" + strconv.Itoa(int(cfg.Port)) + if cfg.Database != "" { + label += "/" + cfg.Database + } + return label +} + // Publish stores the shared SQL pool and GORM handle on the app. Both // handles refer to the same *sql.DB. It then runs the callbacks queued by // OnDatabase and returns the first error. diff --git a/modules/surf/README.md b/modules/surf/README.md index 022ee21d..6a2b6e7a 100644 --- a/modules/surf/README.md +++ b/modules/surf/README.md @@ -202,7 +202,7 @@ The `serve` command also opens the database through [lagoon](../lagoon/README.md ## Dependencies - SummerCMS modules: [backpack](../backpack/README.md), [bonfire](../bonfire/README.md), [bouncer](../bouncer/README.md), [cabana](../cabana/README.md), [compass](../compass/README.md), [conga](../conga/README.md) (the in-process job worker of `serve`), [cooler](../cooler/README.md) (the shared rate-limit store `serve` installs), [diary](../diary/README.md) (the `http` and `serve` component loggers), [lagoon](../lagoon/README.md) (including `lagoon/attach`), [pact](../pact/README.md), [party](../party/README.md), [towel](../towel/README.md), [wire](../wire/README.md). -- Third-party: `gocloud.dev/blob` (uploads bucket opened by `serve`), `github.com/goccy/go-yaml` (api-docs spec conversion), `github.com/jackc/pgx/v5/pgconn` (the database host and name in the startup summary). +- Third-party: `gocloud.dev/blob` (uploads bucket opened by `serve`), `github.com/goccy/go-yaml` (api-docs spec conversion). - Standard library: `bytes`, `context`, `crypto/rand`, `embed`, `encoding/base64`, `encoding/json`, `errors`, `fmt`, `html/template`, `log/slog`, `math`, `mime`, `net`, `net/http`, `net/netip`, `net/url`, `os`, `os/signal`, `path/filepath`, `regexp`, `sort`, `strconv`, `strings`, `sync`, `sync/atomic`, `syscall`, `time`, `unicode/utf8`. - Tests additionally use `github.com/testcontainers/testcontainers-go` (Redis and Postgres containers). diff --git a/modules/surf/serve_summary_smoke_test.go b/modules/surf/serve_summary_smoke_test.go index 67212f3d..727c0b4b 100644 --- a/modules/surf/serve_summary_smoke_test.go +++ b/modules/surf/serve_summary_smoke_test.go @@ -155,11 +155,11 @@ func TestServeSummarySmoke(t *testing.T) { t.Fatalf("summary leaks %q:\n%s\n%s", secret, got, logs.String()) } } - if databaseFact("host=db port=5432 dbname=acme user=u password=p") != "db:5432/acme" { - t.Errorf("keyword DSN = %q", databaseFact("host=db port=5432 dbname=acme user=u password=p")) + if lagoon.DatabaseLabel("host=db port=5432 dbname=acme user=u password=p") != "db:5432/acme" { + t.Errorf("keyword DSN = %q", lagoon.DatabaseLabel("host=db port=5432 dbname=acme user=u password=p")) } - if databaseFact("postgres://u:p@[::1:bad") != "configured" { - t.Errorf("unparsable DSN = %q, want configured", databaseFact("postgres://u:p@[::1:bad")) + if lagoon.DatabaseLabel("postgres://u:p@[::1:bad") != "configured" { + t.Errorf("unparsable DSN = %q, want configured", lagoon.DatabaseLabel("postgres://u:p@[::1:bad")) } probe := []bonfire.Command{{ diff --git a/modules/surf/summary.go b/modules/surf/summary.go index 7473cc1f..ccfff1da 100644 --- a/modules/surf/summary.go +++ b/modules/surf/summary.go @@ -18,7 +18,6 @@ import ( "git.golem15.com/golem15/summercms/modules/diary" "git.golem15.com/golem15/summercms/modules/lagoon" "git.golem15.com/golem15/summercms/modules/party" - "github.com/jackc/pgx/v5/pgconn" ) // serveLog is the logger of serve's startup summary and shutdown report. @@ -108,7 +107,7 @@ func buildFacts(app *backpack.App, in factInputs) summaryFacts { Environment: "unknown", Addr: in.addr, URL: serveURL(in.addr), - Database: databaseFact(configString(app, "database.dsn")), + Database: lagoon.DatabaseLabel(configString(app, "database.dsn")), Pending: len(in.pending), MigrateCmd: in.bin + " migrate", Mail: driverFact(app, "mail.driver", "memory"), @@ -155,31 +154,6 @@ func driverFact(app *backpack.App, key, def string) string { return def } -// databaseFact is host:port/name parsed from dsn with pgconn.ParseConfig, -// never the user or password. A DSN that does not parse is "configured", -// an empty one "not configured". -func databaseFact(dsn string) string { - dsn = strings.TrimSpace(dsn) - if dsn == "" { - return "not configured" - } - cfg, err := pgconn.ParseConfig(dsn) - if err != nil || cfg.Host == "" { - return "configured" - } - host := cfg.Host - if strings.HasPrefix(host, "/") { - host = "socket " + host - } else if strings.Contains(host, ":") { - host = "[" + host + "]" - } - fact := host + ":" + strconv.Itoa(int(cfg.Port)) - if cfg.Database != "" { - fact += "/" + cfg.Database - } - return fact -} - // migrations is the migration line: "up to date", "N pending — run ..." or // "unknown". func (f summaryFacts) migrations() (string, bool) {