feat(surf): serve startup summary, shutdown report and http request log
- serve prints a startup summary on a terminal (version, environment, URL, admin, database host and name, pending migrations, plugins, drivers) and logs it as a 'startup summary' record plus 'listening on <addr>' - on SIGINT/SIGTERM serve drains, prints and logs a shutdown report and returns nil (exit 0), or the drain errors (exit 1) - the request log is on by default under diary component http with request_id; the route pattern, never the path, is logged - lagoon.PendingMigrations, conga.Worker.Stats, diary.HideOnTTY, bonfire.IsTerminal and bonfire.Details back the summary and report
This commit is contained in:
Jakub Zych
382
modules/surf/summary.go
Normal file
382
modules/surf/summary.go
Normal file
@@ -0,0 +1,382 @@
|
||||
package surf
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"net/http"
|
||||
"strconv"
|
||||
"strings"
|
||||
"sync/atomic"
|
||||
"time"
|
||||
|
||||
"git.golem15.com/golem15/summercms/modules/backpack"
|
||||
"git.golem15.com/golem15/summercms/modules/bonfire"
|
||||
"git.golem15.com/golem15/summercms/modules/conga"
|
||||
"git.golem15.com/golem15/summercms/modules/cooler"
|
||||
"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.
|
||||
var serveLog = diary.For("serve")
|
||||
|
||||
// Messages of the records serve logs.
|
||||
const (
|
||||
summaryMessage = "startup summary"
|
||||
reportMessage = "shutdown report"
|
||||
listenPrefix = "listening on "
|
||||
)
|
||||
|
||||
// requestCounter wraps the compiled handler and counts requests in flight
|
||||
// and served, whatever http.access_log says, for the shutdown report.
|
||||
type requestCounter struct {
|
||||
next http.Handler
|
||||
inFlight atomic.Int64
|
||||
served atomic.Int64
|
||||
}
|
||||
|
||||
func newRequestCounter(next http.Handler) *requestCounter {
|
||||
return &requestCounter{next: next}
|
||||
}
|
||||
|
||||
func (c *requestCounter) ServeHTTP(w http.ResponseWriter, req *http.Request) {
|
||||
c.inFlight.Add(1)
|
||||
defer func() {
|
||||
c.inFlight.Add(-1)
|
||||
c.served.Add(1)
|
||||
}()
|
||||
c.next.ServeHTTP(w, req)
|
||||
}
|
||||
|
||||
// pluginFact is one plugin's line of the verbose summary.
|
||||
type pluginFact struct {
|
||||
ID string
|
||||
Requires []string
|
||||
Pending int
|
||||
}
|
||||
|
||||
// summaryFacts is what serve reports once it is listening. It holds no DSN,
|
||||
// user, password, key or token: the database is its host, port and name.
|
||||
type summaryFacts struct {
|
||||
Header string
|
||||
Environment string
|
||||
Addr string
|
||||
URL string
|
||||
Admin string
|
||||
AdminNotes []bannerLine
|
||||
Database string
|
||||
// Pending is the number of pending migrations; -1 when it could not
|
||||
// be read.
|
||||
Pending int
|
||||
MigrateCmd string
|
||||
Plugins []pluginFact
|
||||
Queue string
|
||||
Scheduler string
|
||||
Mail string
|
||||
Cache string
|
||||
Realtime string
|
||||
Search string
|
||||
}
|
||||
|
||||
// factInputs are the values serve learned while booting.
|
||||
type factInputs struct {
|
||||
addr string
|
||||
bin string
|
||||
plugins []party.Plugin
|
||||
queues []string
|
||||
worker bool
|
||||
adminPrefix string
|
||||
mounted bool
|
||||
admins adminPresence
|
||||
pending []lagoon.MigrationRef
|
||||
pendingErr error
|
||||
version bonfire.Version
|
||||
}
|
||||
|
||||
// buildFacts collects the summary from the app's config and in.
|
||||
func buildFacts(app *backpack.App, in factInputs) summaryFacts {
|
||||
name := strings.TrimSpace(configString(app, "app.name"))
|
||||
if name == "" {
|
||||
name = strings.TrimPrefix(in.bin, "bin/")
|
||||
}
|
||||
f := summaryFacts{
|
||||
Header: in.version.Header(name),
|
||||
Environment: "unknown",
|
||||
Addr: in.addr,
|
||||
URL: serveURL(in.addr),
|
||||
Database: databaseFact(configString(app, "database.dsn")),
|
||||
Pending: len(in.pending),
|
||||
MigrateCmd: in.bin + " migrate",
|
||||
Mail: driverFact(app, "mail.driver", "memory"),
|
||||
Cache: driverFact(app, cooler.CacheDriverKey, "memory"),
|
||||
Realtime: driverFact(app, "realtime.driver", "null"),
|
||||
Search: driverFact(app, "search.driver", "null"),
|
||||
}
|
||||
if app != nil && app.Config != nil && app.Config.Environment() != "" {
|
||||
f.Environment = app.Config.Environment()
|
||||
}
|
||||
if in.pendingErr != nil {
|
||||
f.Pending = -1
|
||||
}
|
||||
f.Admin, f.AdminNotes = adminStatus(f.URL, in.adminPrefix, in.mounted, in.admins)
|
||||
perPlugin := map[string]int{}
|
||||
for _, ref := range in.pending {
|
||||
perPlugin[ref.Plugin]++
|
||||
}
|
||||
for _, p := range in.plugins {
|
||||
f.Plugins = append(f.Plugins, pluginFact{ID: p.ID(), Requires: p.Requires(), Pending: perPlugin[p.ID()]})
|
||||
}
|
||||
if in.worker {
|
||||
f.Queue = strings.Join(in.queues, ", ") + " (worker in serve)"
|
||||
f.Scheduler = "in serve"
|
||||
} else {
|
||||
f.Queue = "off in serve (queue.work_in_serve is false; run queue:work)"
|
||||
f.Scheduler = "off in serve (run schedule:run)"
|
||||
}
|
||||
return f
|
||||
}
|
||||
|
||||
func configString(app *backpack.App, key string) string {
|
||||
if app == nil || app.Config == nil {
|
||||
return ""
|
||||
}
|
||||
return app.Config.String(key)
|
||||
}
|
||||
|
||||
// driverFact is the lower-cased driver named by key, or def when empty.
|
||||
func driverFact(app *backpack.App, key, def string) string {
|
||||
if v := strings.ToLower(strings.TrimSpace(configString(app, key))); v != "" {
|
||||
return v
|
||||
}
|
||||
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) {
|
||||
switch {
|
||||
case f.Pending < 0:
|
||||
return "unknown (the migration history could not be read)", true
|
||||
case f.Pending == 0:
|
||||
return "up to date", false
|
||||
default:
|
||||
return fmt.Sprintf("%d pending — run %s", f.Pending, f.MigrateCmd), true
|
||||
}
|
||||
}
|
||||
|
||||
func (f summaryFacts) pluginIDs() []string {
|
||||
ids := make([]string, 0, len(f.Plugins))
|
||||
for _, p := range f.Plugins {
|
||||
ids = append(ids, p.ID)
|
||||
}
|
||||
return ids
|
||||
}
|
||||
|
||||
// details is the block printed on a terminal; verbosity 1 or more adds one
|
||||
// line per plugin with its required plugins and pending migrations.
|
||||
func (f summaryFacts) details(verbosity int) []bonfire.Detail {
|
||||
url := f.URL
|
||||
if url == "" {
|
||||
url = f.Addr
|
||||
}
|
||||
migrations, warn := f.migrations()
|
||||
plugins := strconv.Itoa(len(f.Plugins))
|
||||
if len(f.Plugins) > 0 {
|
||||
plugins += " (" + strings.Join(f.pluginIDs(), ", ") + ")"
|
||||
}
|
||||
rows := []bonfire.Detail{
|
||||
{Label: "Environment", Value: f.Environment},
|
||||
{Label: "URL", Value: url},
|
||||
{Label: "Admin", Value: f.Admin},
|
||||
{Label: "Database", Value: f.Database},
|
||||
{Label: "Migrations", Value: migrations, Warn: warn},
|
||||
{Label: "Plugins", Value: plugins},
|
||||
}
|
||||
if verbosity >= 1 {
|
||||
for _, p := range f.Plugins {
|
||||
requires := "requires nothing"
|
||||
if len(p.Requires) > 0 {
|
||||
requires = "requires " + strings.Join(p.Requires, ", ")
|
||||
}
|
||||
rows = append(rows, bonfire.Detail{
|
||||
Label: " " + p.ID,
|
||||
Value: fmt.Sprintf("%s; %d pending migrations", requires, p.Pending),
|
||||
Warn: p.Pending > 0,
|
||||
})
|
||||
}
|
||||
}
|
||||
return append(rows,
|
||||
bonfire.Detail{Label: "Queue", Value: f.Queue},
|
||||
bonfire.Detail{Label: "Scheduler", Value: f.Scheduler},
|
||||
bonfire.Detail{Label: "Mail", Value: f.Mail},
|
||||
bonfire.Detail{Label: "Cache", Value: f.Cache},
|
||||
bonfire.Detail{Label: "Realtime", Value: f.Realtime},
|
||||
bonfire.Detail{Label: "Search", Value: f.Search},
|
||||
)
|
||||
}
|
||||
|
||||
// attrs are the attributes of the "startup summary" record.
|
||||
func (f summaryFacts) attrs() []slog.Attr {
|
||||
return []slog.Attr{
|
||||
slog.String("app", f.Header),
|
||||
slog.String("environment", f.Environment),
|
||||
slog.String("url", f.URL),
|
||||
slog.String("admin", f.Admin),
|
||||
slog.String("database", f.Database),
|
||||
slog.Int("migrations_pending", f.Pending),
|
||||
slog.Int("plugins", len(f.Plugins)),
|
||||
slog.String("plugin_ids", strings.Join(f.pluginIDs(), ",")),
|
||||
slog.String("queue", f.Queue),
|
||||
slog.String("scheduler", f.Scheduler),
|
||||
slog.String("mail", f.Mail),
|
||||
slog.String("cache", f.Cache),
|
||||
slog.String("realtime", f.Realtime),
|
||||
slog.String("search", f.Search),
|
||||
}
|
||||
}
|
||||
|
||||
// printSummary prints the block and the admin notes through out.
|
||||
func printSummary(out bonfire.Output, f summaryFacts) {
|
||||
bonfire.Details(out, f.Header, f.details(bonfire.VerbosityOf(out)))
|
||||
printBanner(out, f.AdminNotes)
|
||||
}
|
||||
|
||||
// logSummary logs one INFO record "startup summary" with every fact, one
|
||||
// whose message is exactly "listening on <addr>" (application smoke scripts
|
||||
// wait for it) and the admin notes (warnings at WARN).
|
||||
func logSummary(ctx context.Context, log *slog.Logger, f summaryFacts) {
|
||||
log.LogAttrs(ctx, slog.LevelInfo, summaryMessage, f.attrs()...)
|
||||
log.LogAttrs(ctx, slog.LevelInfo, listenPrefix+f.Addr, slog.String("url", f.URL))
|
||||
for _, n := range f.AdminNotes {
|
||||
level := slog.LevelInfo
|
||||
if n.warn {
|
||||
level = slog.LevelWarn
|
||||
}
|
||||
log.LogAttrs(ctx, level, n.text)
|
||||
}
|
||||
}
|
||||
|
||||
// shutdownReport is what serve did, printed and logged after a signal.
|
||||
type shutdownReport struct {
|
||||
// Draining is the number of requests in flight when the signal came.
|
||||
Draining int64
|
||||
// Aborted is the number still running at the drain deadline.
|
||||
Aborted int64
|
||||
Served int64
|
||||
Worker *conga.WorkerStats
|
||||
Uptime time.Duration
|
||||
Errors []error
|
||||
}
|
||||
|
||||
// Drained is the number of in-flight requests that finished in time.
|
||||
func (r shutdownReport) Drained() int64 {
|
||||
return max(0, r.Draining-r.Aborted)
|
||||
}
|
||||
|
||||
// Err joins the drain errors; nil means a clean stop (exit 0).
|
||||
func (r shutdownReport) Err() error {
|
||||
return errors.Join(r.Errors...)
|
||||
}
|
||||
|
||||
func (r shutdownReport) requestsLine() string {
|
||||
return fmt.Sprintf("%d served, %d drained, %d aborted", r.Served, r.Drained(), r.Aborted)
|
||||
}
|
||||
|
||||
func workerLine(s *conga.WorkerStats) string {
|
||||
if s == nil {
|
||||
return "not running in serve"
|
||||
}
|
||||
return fmt.Sprintf("%d done, %d failed, %d handed back to the queue", s.Done, s.Failed, s.HandedBack+s.InFlight)
|
||||
}
|
||||
|
||||
func errorsLine(errs []error) string {
|
||||
if len(errs) == 0 {
|
||||
return "none"
|
||||
}
|
||||
parts := make([]string, 0, len(errs))
|
||||
for _, e := range errs {
|
||||
parts = append(parts, e.Error())
|
||||
}
|
||||
return strings.Join(parts, "; ")
|
||||
}
|
||||
|
||||
// uptime rounds d for the report.
|
||||
func uptime(d time.Duration) string {
|
||||
switch {
|
||||
case d >= time.Minute:
|
||||
return d.Round(time.Second).String()
|
||||
case d >= time.Second:
|
||||
return d.Round(100 * time.Millisecond).String()
|
||||
default:
|
||||
return d.Round(time.Millisecond).String()
|
||||
}
|
||||
}
|
||||
|
||||
// details is the report as label/value lines.
|
||||
func (r shutdownReport) details() []bonfire.Detail {
|
||||
return []bonfire.Detail{
|
||||
{Label: "Requests", Value: r.requestsLine(), Warn: r.Aborted > 0},
|
||||
{Label: "Worker", Value: workerLine(r.Worker)},
|
||||
{Label: "Uptime", Value: uptime(r.Uptime)},
|
||||
{Label: "Errors", Value: errorsLine(r.Errors), Warn: len(r.Errors) > 0},
|
||||
}
|
||||
}
|
||||
|
||||
// attrs are the attributes of the "shutdown report" record.
|
||||
func (r shutdownReport) attrs() []slog.Attr {
|
||||
attrs := []slog.Attr{
|
||||
slog.Int64("served", r.Served),
|
||||
slog.Int64("drained", r.Drained()),
|
||||
slog.Int64("aborted", r.Aborted),
|
||||
slog.Int64("uptime_ms", r.Uptime.Milliseconds()),
|
||||
}
|
||||
if r.Worker != nil {
|
||||
attrs = append(attrs,
|
||||
slog.Int64("jobs_done", r.Worker.Done),
|
||||
slog.Int64("jobs_failed", r.Worker.Failed),
|
||||
slog.Int64("jobs_handed_back", r.Worker.HandedBack+r.Worker.InFlight),
|
||||
)
|
||||
}
|
||||
if len(r.Errors) > 0 {
|
||||
attrs = append(attrs, slog.String("errors", errorsLine(r.Errors)))
|
||||
}
|
||||
return attrs
|
||||
}
|
||||
|
||||
// logReport logs the report as one record: INFO, or ERROR with drain errors.
|
||||
func logReport(ctx context.Context, log *slog.Logger, r shutdownReport) {
|
||||
level := slog.LevelInfo
|
||||
if len(r.Errors) > 0 {
|
||||
level = slog.LevelError
|
||||
}
|
||||
log.LogAttrs(ctx, level, reportMessage, r.attrs()...)
|
||||
}
|
||||
Reference in New Issue
Block a user