diff --git a/AGENTS.md b/AGENTS.md index 73eb13b..9741c1b 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -29,7 +29,7 @@ root. Three files split cleanly along "engine vs. two interchangeable front-ends": - **[engine.go](engine.go)** — `Engine`, the display-agnostic load-test runner. Owns launching - processes at `Config.Rate` up to `Config.MaxParallel`, honoring `MaxCount`/`TestDuration`, + processes at `Config.Rate` up to `Config.MaxParallel`, honouring `MaxCount`/`TestDuration`, and tracking results (counts, running-process set, duration history, a bounded activity feed). Exposes its state via `Snapshot()` (cheap, capped-sample percentiles — safe to poll every UI tick) and `FinalSnapshot()` (full-history percentiles, call once after `Run()` @@ -37,17 +37,21 @@ Three files split cleanly along "engine vs. two interchangeable front-ends": Finished`) driven by `StopLaunching()`/`KillRunning()` (first/second Ctrl-C) and observable via the `Stopping()`/`Finished()` channels. `OutputMode` (`Discard`/`Passthrough`/`Capture`) is decided by the caller, not the engine — see `outputMode()` in [main.go](main.go). -- **[plain.go](plain.go)** — non-interactive driver: prints a config header, overwrites a - status line on stderr once a second, streams "system" log lines (process errors) as they - occur, and prints `FormatSummary()` on exit. Used whenever stdout/stderr isn't a real - terminal, or `--no-tui` is passed. +- **[plain.go](plain.go)** — non-interactive driver: prints a config header, a status line on a + timer (each update on its own line, suppressed when unchanged except for a periodic + heartbeat), streams "system" log lines (process errors) as they occur, and prints a summary + on exit. Used whenever stdout/stderr isn't a real terminal, or `--non-interactive` is passed. + Rendering is behind the `plainReporter` interface (`plain_reporters.go`): `textReporter` is the + behaviour above; `jsonReporter` (selected via `-o json`) instead emits `status`/`log`/`summary` + events as JSON Lines on stdout and drops the header/notices, which have no place in that + schema. - **[tui.go](tui.go)** — interactive driver: a bubbletea `Model` with five panels (Status, Config, Latency, Running, Log) plus a recent-Activity sidebar, driven by `Engine.Snapshot()` on a tick and by `Engine.LogLines()` for the log panel. Panel sizing is recalculated from terminal dimensions in `recalcSizes()`; layout math is the trickiest part of this file if something looks off after a resize. - **[main.go](main.go)** — CLI flag definitions (`urfave/cli/v3`) and the interactive/plain - dispatch: `isInteractiveTerminal()` checks stdout *and* stderr are TTYs, `--no-tui` forces + dispatch: `isInteractiveTerminal()` checks stdout *and* stderr are TTYs, `--non-interactive` forces plain mode even in a terminal. `resolveLogDir()` turns `--log-dir`/`LOADER_LOG_DIR` (or the `.loader` default) into a fresh timestamped subfolder per run (UTC, colon-free so it's valid on filesystems like NTFS — see `logDirTimeFormat`); `--no-log` leaves @@ -63,7 +67,7 @@ Three files split cleanly along "engine vs. two interchangeable front-ends": Both drivers talk to `Engine` through the same public surface (`Run`, `Snapshot`, `FinalSnapshot`, `LogLines`, `StopLaunching`, `KillRunning`, `Stopping`, `Finished`) — there is -no driver-specific state inside `Engine`. When changing engine behavior, check that both +no driver-specific state inside `Engine`. When changing engine behaviour, check that both `plain.go` and `tui.go` still make sense against the new semantics. Key invariants worth knowing before touching `engine.go`: diff --git a/README.md b/README.md index 215433c..921da1c 100644 --- a/README.md +++ b/README.md @@ -40,8 +40,10 @@ loader [options] COMMAND [ARGS...] | `--max-parallel` | `-p` | `20` | Maximum number of simultaneous processes | | `--max-count` | `-n` | `0` | Total processes to launch before stopping (0 = unlimited) | | `--duration` | `-d` | `0` | Stop launching after this duration (0 = unlimited) | -| `--verbose` | | off | Show stdout/stderr from each process (non-TUI mode) | -| `--no-tui` | | off | Force plain-text output instead of the fullscreen TUI | +| `--verbose` | | off | Show stdout/stderr from each process (non-interactive mode) | +| `--non-interactive` | | off | Force plain-text output instead of the fullscreen TUI (for CI or agentic use) | +| `--status-interval` | | `5s` | Interval between status lines in non-interactive mode | +| `--output` | `-o` | `plain` | Output format in non-interactive mode: `plain` or `json` (JSON Lines on stdout) | | `--log-dir` | | `.loader` | Directory to write per-run log files into (gets its own timestamped subfolder); also settable via `LOADER_LOG_DIR` | | `--no-log` | | off | Disable writing per-run log files | | `--log-env` | | none | Env var name to record in `environment.log` (can be specified multiple times); also settable via `LOADER_LOG_ENV_VARS` or a config file | @@ -130,12 +132,17 @@ Once the run finishes, the dashboard stays open showing the final results — pr ## Output -A live status line is printed to stderr during the run: +A status line is printed to stderr on a timer during the run (one per line, not overwritten in +place — so this mode's output stays readable in CI logs or piped to a file): ``` -launched=42 running=8 completed=34 failed=0 +[5s] launched=42 running=8 completed=34 failed=0 ``` +A line is only printed when the counters changed since the last one, except every 6th tick, which +is always printed so a log/agent watching for liveness still sees regular output even once nothing +is changing (e.g. while a handful of stragglers finish). + A summary is printed on exit: ``` @@ -144,11 +151,47 @@ Launched: 100 Completed: 100 Successes: 98 Failures: 2 -Duration: +Duration (OK): min: 142ms avg: 187ms p50: 183ms p95: 241ms p99: 267ms max: 312ms +Duration (FAIL): + min: 95ms + avg: 101ms + p50: 101ms + p95: 108ms + p99: 108ms + max: 108ms +``` + +### JSON output (`-o json`) + +With `-o json`, non-interactive mode emits [JSON Lines](https://jsonlines.org/) on stdout instead +of the text above: one self-contained JSON object per line, each with a `type` field. The config +header and signal-handling notices ("Stopping launch loop...", "Waiting for running +processes...") are text-only concepts with no place in that schema, so they're suppressed +entirely — stdout is a clean stream a script or agent can parse directly. + +A `status` line is emitted on the same timer, and with the same change-suppression/heartbeat +rules, as the plain status line: + +```json +{"type":"status","elapsed_seconds":5.02,"launched":42,"running":8,"completed":34,"failed":0} +``` + +A `log` line is emitted for each process error, as it occurs (the same events the plain driver +prints as `[procID] text`): + +```json +{"type":"log","elapsed_seconds":4.31,"proc_id":37,"text":"error after 812ms: exit status 1"} +``` + +A single `summary` line is emitted once at the end. `duration_ok`/`duration_fail` are omitted +when there's no data for that bucket (e.g. no failures): + +```json +{"type":"summary","launched":100,"completed":100,"successes":98,"failures":2,"duration_ok":{"count":98,"min_ms":142,"avg_ms":187,"p50_ms":183,"p95_ms":241,"p99_ms":267,"max_ms":312},"duration_fail":{"count":2,"min_ms":95,"avg_ms":101,"p50_ms":101,"p95_ms":108,"p99_ms":108,"max_ms":108}} ``` diff --git a/engine.go b/engine.go index 0b98f42..d0bab6b 100644 --- a/engine.go +++ b/engine.go @@ -385,7 +385,7 @@ func (w *lineWriter) Flush() { } // Engine runs a load test: launching cfg.Args repeatedly in parallel at -// cfg.Rate, up to cfg.MaxParallel concurrent processes, honoring +// cfg.Rate, up to cfg.MaxParallel concurrent processes, honouring // cfg.MaxCount/cfg.TestDuration, and tracking results. It is display-agnostic // — plain.go and tui.go both drive it the same way. type Engine struct { @@ -548,6 +548,15 @@ func (e *Engine) emitLog(l LogLine) { } } +// Elapsed returns the time since Run started (or zero, before it has), +// without Snapshot's cost of computing percentiles and copying state. +func (e *Engine) Elapsed() time.Duration { + if e.startTime.IsZero() { + return 0 + } + return time.Since(e.startTime) +} + // Snapshot returns a race-free, point-in-time view of the engine's state. // Live percentiles are computed from at most the most recent // livePercentileSampleCap samples, to keep this cheap to call frequently diff --git a/main.go b/main.go index 0e13ebc..94d65ec 100644 --- a/main.go +++ b/main.go @@ -135,7 +135,7 @@ func isInteractiveTerminal() bool { } func run(ctx context.Context, cmd *cli.Command) error { - interactive := isInteractiveTerminal() && !cmd.Bool("no-tui") + interactive := isInteractiveTerminal() && !cmd.Bool("non-interactive") cfg, err := buildConfig(cmd, interactive) if err != nil { @@ -145,7 +145,16 @@ func run(ctx context.Context, cmd *cli.Command) error { if interactive { return runTUI(cfg) } - return runPlain(cfg) + + format, err := ParseOutputFormat(cmd.String("output")) + if err != nil { + return err + } + statusInterval := cmd.Duration("status-interval") + if statusInterval <= 0 { + return fmt.Errorf("--status-interval must be greater than 0") + } + return runPlain(cfg, statusInterval, format) } func main() { @@ -184,8 +193,19 @@ func main() { Usage: "show stdout/stderr from each process", }, &cli.BoolFlag{ - Name: "no-tui", - Usage: "force plain-text output instead of the fullscreen TUI", + Name: "non-interactive", + Usage: "force plain-text output instead of the fullscreen TUI (for CI or agentic use)", + }, + &cli.DurationFlag{ + Name: "status-interval", + Usage: "interval between status lines in non-interactive mode", + Value: 5 * time.Second, + }, + &cli.StringFlag{ + Name: "output", + Aliases: []string{"o"}, + Usage: `output format in non-interactive mode: "plain" or "json" (JSON Lines on stdout)`, + Value: string(OutputFormatPlain), }, &cli.StringFlag{ Name: "log-dir", diff --git a/plain.go b/plain.go index 691b76d..b55b52f 100644 --- a/plain.go +++ b/plain.go @@ -7,21 +7,65 @@ import ( "time" ) +// statusHeartbeatEvery is how many status-interval ticks pass between forced +// status lines, so a consumer watching the log for liveness sees a line even +// when nothing has changed since the last tick. +const statusHeartbeatEvery = 6 + +// OutputFormat selects how runPlain renders its output. +type OutputFormat string + +const ( + OutputFormatPlain OutputFormat = "plain" + OutputFormatJSON OutputFormat = "json" +) + +// ParseOutputFormat validates a --output flag value. +func ParseOutputFormat(s string) (OutputFormat, error) { + switch f := OutputFormat(s); f { + case OutputFormatPlain, OutputFormatJSON: + return f, nil + default: + return "", fmt.Errorf("invalid --output value %q (want %q or %q)", s, OutputFormatPlain, OutputFormatJSON) + } +} + +// plainReporter renders the events runPlain produces. textReporter and +// jsonReporter are the two implementations; everything else in this file is +// oblivious to which one is in use. +type plainReporter interface { + // header prints the config/log-dir header shown once at startup. + header(cfg Config) + // notice prints a one-off human-readable message: a signal-handling + // transition or the final "waiting for processes" line. + notice(msg string) + // systemLog prints a process-error line as it occurs. + systemLog(elapsed time.Duration, procID int64, text string) + // status prints a periodic progress line. + status(snap Snapshot) + // summary prints the final results. + summary(snap Snapshot) +} + +func newPlainReporter(format OutputFormat) plainReporter { + if format == OutputFormatJSON { + return jsonReporter{} + } + return textReporter{} +} + // runPlain drives an Engine and reports progress the way the CLI has always -// behaved: a config header, a live status line overwritten on stderr once a -// second, error lines printed as they occur, and a final summary. Used when +// behaved: a config header, a status line printed to stderr on a timer, +// error lines printed as they occur, and a final summary. Used when // stdout/stderr isn't an interactive terminal. -func runPlain(cfg Config) error { +func runPlain(cfg Config, statusInterval time.Duration, format OutputFormat) error { eng, err := NewEngine(cfg) if err != nil { return err } + reporter := newPlainReporter(format) - fmt.Fprint(os.Stderr, FormatConfig(cfg)) - if cfg.LogDir != "" { - fmt.Fprintf(os.Stderr, "log dir: %s\n", cfg.LogDir) - } - fmt.Fprintln(os.Stderr) + reporter.header(cfg) // Three-level signal handling: // first Ctrl-C → stop launching new processes @@ -35,55 +79,19 @@ func runPlain(cfg Config) error { stopKillDone := eng.WatchInterrupts(sigCh, func() { - fmt.Fprintln(os.Stderr, "\nStopping launch loop — press Ctrl-C again to kill running processes") + reporter.notice("Stopping launch loop — press Ctrl-C again to kill running processes") }, func() { - fmt.Fprintln(os.Stderr, "\nKilling running processes") + reporter.notice("Killing running processes") }, ) - forceQuit := make(chan struct{}) - go func() { - <-stopKillDone - select { - case <-sigCh: - fmt.Fprintln(os.Stderr, "\nForcing exit — running processes may be left behind") - close(forceQuit) - case <-eng.Finished(): - } - }() + forceQuit := watchForceQuit(eng, sigCh, stopKillDone, reporter) - // Status reporter: overwrites the current line every second on stderr. - // Errors printed by the log-line goroutine prefix a newline to avoid - // overlap. statusDone := make(chan struct{}) - go func() { - ticker := time.NewTicker(time.Second) - defer ticker.Stop() - for { - select { - case <-ticker.C: - snap := eng.Snapshot() - fmt.Fprintf(os.Stderr, "\rlaunched=%-6d running=%-6d completed=%-6d failed=%-6d", - snap.Launched, snap.Running, snap.Completed, snap.Failed) - case <-statusDone: - return - } - } - }() + go runStatusTicker(eng, statusInterval, reporter, statusDone) - // In plain mode, OutputMode is never OutputCapture, so LogLines() only - // ever carries "system" lines (process errors) — verbose stdout/stderr - // goes straight to os.Stdout/os.Stderr in Engine.launchOne - // (OutputPassthrough) or is discarded (OutputDiscard). logDone := make(chan struct{}) - go func() { - defer close(logDone) - for line := range eng.LogLines() { - if line.Stream == "system" { - fmt.Fprintf(os.Stderr, "\n[%d] %s\n", line.ProcID, line.Text) - } - } - }() + go streamSystemLog(eng, reporter, logDone) runDone := make(chan struct{}) go func() { @@ -93,7 +101,7 @@ func runPlain(cfg Config) error { <-eng.Stopping() close(statusDone) - fmt.Fprintln(os.Stderr, "\nWaiting for running processes to complete...") + reporter.notice("Waiting for running processes to complete...") select { case <-runDone: @@ -102,8 +110,69 @@ func runPlain(cfg Config) error { } <-logDone - // The summary has always gone to stdout (unlike the config header and - // status line, which go to stderr) so it can be captured separately. - fmt.Print("\n" + FormatSummary(eng.FinalSnapshot())) + reporter.summary(eng.FinalSnapshot()) return nil } + +// watchForceQuit waits for the stop/kill sequence to finish, then watches for +// a third Ctrl-C (or the engine finishing on its own): given one, it reports +// and closes the returned channel so runPlain can give up waiting immediately. +func watchForceQuit(eng *Engine, sigCh <-chan os.Signal, stopKillDone <-chan struct{}, reporter plainReporter) <-chan struct{} { + forceQuit := make(chan struct{}) + go func() { + <-stopKillDone + select { + case <-sigCh: + reporter.notice("Forcing exit — running processes may be left behind") + close(forceQuit) + case <-eng.Finished(): + } + }() + return forceQuit +} + +// runStatusTicker prints one status line per tick until done is closed. To +// keep a long-running test's output from filling up with duplicate lines, a +// tick is only printed when the counters changed since the last one printed, +// except every statusHeartbeatEvery-th tick, which is always printed so a +// log/agent watching for liveness still sees regular output. +func runStatusTicker(eng *Engine, interval time.Duration, reporter plainReporter, done <-chan struct{}) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + var last Snapshot + havePrinted := false + ticks := 0 + for { + select { + case <-ticker.C: + ticks++ + snap := eng.Snapshot() + changed := !havePrinted || + snap.Launched != last.Launched || + snap.Running != last.Running || + snap.Completed != last.Completed || + snap.Failed != last.Failed + if changed || ticks%statusHeartbeatEvery == 0 { + reporter.status(snap) + last = snap + havePrinted = true + } + case <-done: + return + } + } +} + +// streamSystemLog reports each "system" line (a process error) as it occurs, +// closing done once the engine closes its log-line channel. In plain mode, +// OutputMode is never OutputCapture, so LogLines() only ever carries "system" +// lines — verbose stdout/stderr goes straight to os.Stdout/os.Stderr in +// Engine.launchOne (OutputPassthrough) or is discarded (OutputDiscard). +func streamSystemLog(eng *Engine, reporter plainReporter, done chan<- struct{}) { + defer close(done) + for line := range eng.LogLines() { + if line.Stream == "system" { + reporter.systemLog(eng.Elapsed(), line.ProcID, line.Text) + } + } +} diff --git a/plain_reporters.go b/plain_reporters.go new file mode 100644 index 0000000..cc1e353 --- /dev/null +++ b/plain_reporters.go @@ -0,0 +1,165 @@ +package main + +import ( + "encoding/json" + "fmt" + "os" + "sync" + "time" +) + +// textReporter is the original human-readable plainReporter: config header, +// status, and errors go to stderr; the summary goes to stdout (so it can be +// captured separately from the rest). +type textReporter struct{} + +func (textReporter) header(cfg Config) { + fmt.Fprint(os.Stderr, FormatConfig(cfg)) + if cfg.LogDir != "" { + fmt.Fprintf(os.Stderr, "log dir: %s\n", cfg.LogDir) + } + fmt.Fprintln(os.Stderr) +} + +func (textReporter) notice(msg string) { + fmt.Fprintln(os.Stderr, msg) +} + +func (textReporter) systemLog(_ time.Duration, procID int64, text string) { + fmt.Fprintf(os.Stderr, "[%d] %s\n", procID, text) +} + +func (textReporter) status(snap Snapshot) { + fmt.Fprintf(os.Stderr, "[%s] launched=%-6d running=%-6d completed=%-6d failed=%-6d\n", + snap.Elapsed.Round(time.Second), snap.Launched, snap.Running, snap.Completed, snap.Failed) +} + +func (textReporter) summary(snap Snapshot) { + fmt.Print("\n" + FormatSummary(snap)) +} + +// jsonReporter renders runPlain's events as JSON Lines on stdout: one +// self-contained JSON object per line, discriminated by a "type" field. It +// only emits status, log, and summary events — the config header and +// signal-handling notices are text-only concepts with no place in that +// schema, so they're dropped rather than mixed in as a different shape. +type jsonReporter struct{} + +func (jsonReporter) header(Config) {} +func (jsonReporter) notice(string) {} + +func (jsonReporter) systemLog(elapsed time.Duration, procID int64, text string) { + writeJSONLine(jsonLogEvent{ + Type: "log", + ElapsedSeconds: elapsed.Seconds(), + ProcID: procID, + Text: text, + }) +} + +func (jsonReporter) status(snap Snapshot) { + writeJSONLine(jsonStatusEvent{ + Type: "status", + ElapsedSeconds: snap.Elapsed.Seconds(), + Launched: snap.Launched, + Running: snap.Running, + Completed: snap.Completed, + Failed: snap.Failed, + }) +} + +func (jsonReporter) summary(snap Snapshot) { + writeJSONLine(jsonSummaryEvent{ + Type: "summary", + Launched: snap.Launched, + Completed: snap.Completed, + Successes: snap.Completed - snap.Failed, + Failures: snap.Failed, + DurationOK: jsonPercentilesFromSnapshot(snap.PercentilesOK), + DurationFail: jsonPercentilesFromSnapshot(snap.PercentilesFail), + }) +} + +// jsonLogEvent is one "log" line of the JSONL stream: a process-error +// ("system") line, as also streamed to the TUI's log panel and, if logging +// is enabled, written to proc-N.log. +type jsonLogEvent struct { + Type string `json:"type"` + ElapsedSeconds float64 `json:"elapsed_seconds"` + ProcID int64 `json:"proc_id"` + Text string `json:"text"` +} + +// jsonStatusEvent is one "status" line of the JSONL stream. +type jsonStatusEvent struct { + Type string `json:"type"` + ElapsedSeconds float64 `json:"elapsed_seconds"` + Launched int64 `json:"launched"` + Running int64 `json:"running"` + Completed int64 `json:"completed"` + Failed int64 `json:"failed"` +} + +// jsonSummaryEvent is the single "summary" line printed once at the end. +type jsonSummaryEvent struct { + Type string `json:"type"` + Launched int64 `json:"launched"` + Completed int64 `json:"completed"` + Successes int64 `json:"successes"` + Failures int64 `json:"failures"` + DurationOK *jsonPercentiles `json:"duration_ok,omitempty"` + DurationFail *jsonPercentiles `json:"duration_fail,omitempty"` +} + +// jsonPercentiles mirrors Percentiles with durations in milliseconds, which +// is easier for a JSON consumer to work with than encoding/json's default +// time.Duration representation (nanoseconds as a plain number). +type jsonPercentiles struct { + Count int `json:"count"` + MinMs float64 `json:"min_ms"` + AvgMs float64 `json:"avg_ms"` + P50Ms float64 `json:"p50_ms"` + P95Ms float64 `json:"p95_ms"` + P99Ms float64 `json:"p99_ms"` + MaxMs float64 `json:"max_ms"` +} + +// jsonPercentilesFromSnapshot returns nil when there's no data for this +// bucket (e.g. no failures), so the summary event omits the field entirely +// rather than emitting misleading zeroes. +func jsonPercentilesFromSnapshot(p Percentiles) *jsonPercentiles { + if p.Count == 0 { + return nil + } + return &jsonPercentiles{ + Count: p.Count, + MinMs: durationMs(p.Min), + AvgMs: durationMs(p.Avg), + P50Ms: durationMs(p.P50), + P95Ms: durationMs(p.P95), + P99Ms: durationMs(p.P99), + MaxMs: durationMs(p.Max), + } +} + +func durationMs(d time.Duration) float64 { + return float64(d) / float64(time.Millisecond) +} + +// jsonStdoutMu serialises writeJSONLine calls: the status ticker and system-log +// goroutines can both write concurrently, and without this a long line could +// interleave with another mid-write and corrupt both as JSON. +var jsonStdoutMu sync.Mutex + +// writeJSONLine marshals v and writes it, newline-terminated, to stdout. +func writeJSONLine(v any) { + data, err := json.Marshal(v) + if err != nil { + panic(fmt.Sprintf("jsonReporter: marshal %T: %v", v, err)) + } + data = append(data, '\n') + + jsonStdoutMu.Lock() + defer jsonStdoutMu.Unlock() + _, _ = os.Stdout.Write(data) +} diff --git a/tui.go b/tui.go index 3b5ae35..28fb155 100644 --- a/tui.go +++ b/tui.go @@ -54,7 +54,7 @@ func runTUI(cfg Config) error { // itself and quits immediately, before Update ever sees it — bypassing // StopLaunching/KillRunning and leaving already-launched processes // running. Disable it and handle SIGINT ourselves instead, mirroring - // plain.go's two-stage Ctrl-C behavior. + // plain.go's two-stage Ctrl-C behaviour. p := tea.NewProgram(newModel(eng, cfg), tea.WithAltScreen(), tea.WithoutSignalHandler()) sigCh := make(chan os.Signal, 2) @@ -648,7 +648,7 @@ func (m Model) renderActivityPanel() string { maxRows := clampInt(m.bodyHeight-panelBorderPaddingHeight, 0, len(m.snap.Recent)) - // The status column is fixed-width and colored, so it's rendered + // The status column is fixed-width and coloured, so it's rendered // separately from the rest of the row: truncateEllipsis isn't // ANSI-aware, so it must never be applied to styled text, only to the // plain-text prefix ahead of it. Reserving the status column's width