diff --git a/cli.go b/cli.go new file mode 100644 index 0000000..f1f7c0e --- /dev/null +++ b/cli.go @@ -0,0 +1,313 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +package main + +import ( + "bufio" + "context" + "database/sql" + "errors" + "fmt" + "io" + "log/slog" + "math" + "strconv" + "strings" + "text/tabwriter" + "time" +) + +// tokenListHeader holds the header cells of `token list` +var tokenListHeader = []string{"TOKEN", "DESCRIPTION", "ACTIVE", "CREATED_AT", "DELETED_AT"} + +// auditListHeader holds the header cells of `audit` +var auditListHeader = []string{"TIME", "TOKEN", "ORIGIN", "OPERATION"} + +// tokenListAll is the only argument accepted by `token list` (case-sensitive) +const tokenListAll = "all" + +// auditAll is the only word accepted by `audit` (case-sensitive): print every row +const auditAll = "all" + +// defaultAuditLimit is the number of rows printed by `audit` without arguments +const defaultAuditLimit = 10 + +// auditUnits maps the window unit letters (lowercase only) to their duration +var auditUnits = map[byte]time.Duration{ + 's': time.Second, + 'm': time.Minute, + 'h': time.Hour, + 'd': 24 * time.Hour, + 'w': 7 * 24 * time.Hour, +} + +// auditSelection is a parsed audit argument: exactly one of all, limit > 0 and window > 0 holds +type auditSelection struct { + all bool // print every row + limit int // latest rows to print + window time.Duration // print the rows with time >= now - window +} + +// tokenCommand is a parsed token subcommand ready to run against a store +type tokenCommand func(ctx context.Context, store *TokenStore) error + +// parseTokenCommand validates the arguments following "token" without touching the database +func (a *app) parseTokenCommand(args []string) (string, tokenCommand, error) { + if len(args) == 0 { + return "", nil, usageErrorf("missing token subcommand") + } + switch args[0] { + case "list": + if len(args) > 2 { + return "", nil, usageErrorf("token list takes at most one argument") + } + if len(args) == 2 && args[1] != tokenListAll { + return "", nil, usageErrorf("unknown token list argument") + } + activeOnly := len(args) == 1 + return "token list", func(ctx context.Context, store *TokenStore) error { + return a.tokenList(ctx, store, activeOnly) + }, nil + case "new": + if len(args) > 2 { + return "", nil, usageErrorf("token new takes at most one argument") + } + description := "" + if len(args) == 2 { + description = args[1] + } + return "token new", func(ctx context.Context, store *TokenStore) error { + return a.tokenNew(ctx, store, description) + }, nil + case "delete": + if len(args) != 2 { + return "", nil, usageErrorf("token delete requires exactly one argument") + } + value := args[1] + return "token delete", func(ctx context.Context, store *TokenStore) error { + return a.tokenDelete(ctx, store, value) + }, nil + default: + return "", nil, usageErrorf("unknown token subcommand") + } +} + +// runTokenCommand parses and executes a token subcommand +func (a *app) runTokenCommand(ctx context.Context, cfg Config, log *slog.Logger, args []string) (err error) { + defer traceFunc(ctx, log, "app.runTokenCommand")() + + // Parse first: usage errors never touch the database + name, cmd, err := a.parseTokenCommand(args) + if err != nil { + return err + } + log.DebugContext(ctx, "cli dispatch", "command", name) + + return a.withDatabase(ctx, cfg, log, name, func(db *sql.DB) error { + return cmd(ctx, NewTokenStore(db, log, a.now, a.generateToken)) + }) +} + +// withDatabase opens the database, runs the named CLI command against it and closes it +func (a *app) withDatabase(ctx context.Context, cfg Config, log *slog.Logger, name string, cmd func(db *sql.DB) error) (err error) { + // Open the database + db, err := OpenDatabase(ctx, cfg.DBPath, log) + if err != nil { + return err + } + defer closeDatabase(ctx, db, log, &err) + + // Execute + err = cmd(db) + log.DebugContext(ctx, "cli command finished", "command", name, "ok", err == nil) + return err +} + +// writeTable prints the header and the rows as a column-aligned table +// Every column but the last is padded with spaces to its widest cell (in runes) plus 2; lines carry no trailing whitespace +func writeTable(out io.Writer, header []string, rows [][]string) error { + w := bufio.NewWriter(out) + tw := tabwriter.NewWriter(w, 0, 0, 2, ' ', 0) + fmt.Fprintln(tw, strings.Join(header, "\t")) + for _, row := range rows { + fmt.Fprintln(tw, strings.Join(row, "\t")) + } + + // Write errors are reported once, keeping the first one + err := tw.Flush() + if ferr := w.Flush(); err == nil { + err = ferr + } + if err != nil { + return fmt.Errorf("write output: %w", err) + } + return nil +} + +// formatTokenRow renders the cells of one `token list` line +// The description is Go-quoted so every row is exactly one line whatever its content +func formatTokenRow(tok Token) []string { + deletedAt := "-" + if tok.DeletedAt != nil { + deletedAt = formatTime(*tok.DeletedAt) + } + return []string{tok.Token, strconv.Quote(tok.Description), strconv.FormatBool(tok.Active), formatTime(tok.CreatedAt), deletedAt} +} + +// tokenList prints the header and the active tokens, or every token when activeOnly is false +func (a *app) tokenList(ctx context.Context, store *TokenStore, activeOnly bool) error { + defer traceFunc(ctx, store.log, "app.tokenList")() + + tokens, err := store.ListTokens(ctx, activeOnly) + if err != nil { + return err + } + rows := make([][]string, 0, len(tokens)) + for _, tok := range tokens { + rows = append(rows, formatTokenRow(tok)) + } + return writeTable(a.stdout, tokenListHeader, rows) +} + +// tokenNew creates a token and prints it +func (a *app) tokenNew(ctx context.Context, store *TokenStore, description string) error { + defer traceFunc(ctx, store.log, "app.tokenNew")() + + tok, err := store.CreateToken(ctx, description) + if err != nil { + return err + } + store.log.DebugContext(ctx, "token created", "token_id", tokenID(tok.Token)) + if _, err := fmt.Fprintln(a.stdout, tok.Token); err != nil { + return fmt.Errorf("write output: %w", err) + } + return nil +} + +// tokenDelete deactivates a token; nothing is printed on success +func (a *app) tokenDelete(ctx context.Context, store *TokenStore, value string) error { + defer traceFunc(ctx, store.log, "app.tokenDelete")() + + if err := store.DeactivateToken(ctx, value); err != nil { + return err + } + store.log.DebugContext(ctx, "token deactivated", "token_id", tokenID(value)) + return nil +} + +// parseAuditArgs validates the arguments following "audit" without touching the database +// Accepted: nothing (latest 10 rows), all (every row), (latest n rows), (rows of the last n units) +// all is exact and case-sensitive; n is ASCII decimal digits only (leading zeros allowed) and at least 1; the argument is never echoed +func parseAuditArgs(args []string) (auditSelection, error) { + switch len(args) { + case 0: + return auditSelection{limit: defaultAuditLimit}, nil + case 1: + default: + return auditSelection{}, usageErrorf("audit takes at most one argument") + } + if args[0] == auditAll { + return auditSelection{all: true}, nil + } + + // Split an optional trailing unit letter + digits, unit := args[0], time.Duration(0) + if n := len(digits); n > 0 { + if u, ok := auditUnits[digits[n-1]]; ok { + digits, unit = digits[:n-1], u + } + } + + // The count must be a positive decimal integer that fits an int + n, err := parsePositiveDecimal(digits) + if err != nil { + return auditSelection{}, usageErrorf("invalid audit argument") + } + if unit == 0 { + return auditSelection{limit: n}, nil + } + + // The window must fit a time.Duration + if int64(n) > math.MaxInt64/int64(unit) { + return auditSelection{}, usageErrorf("invalid audit argument") + } + return auditSelection{window: time.Duration(n) * unit}, nil +} + +// parsePositiveDecimal accepts only ASCII decimal digits (no sign, no whitespace) with a value >= 1 that fits an int +func parsePositiveDecimal(s string) (int, error) { + if s == "" { + return 0, errors.New("empty number") + } + for i := 0; i < len(s); i++ { + if s[i] < '0' || s[i] > '9' { + return 0, errors.New("not a decimal integer") + } + } + n, err := strconv.Atoi(s) + if err != nil { + return 0, err + } + if n < 1 { + return 0, errors.New("number must be at least 1") + } + return n, nil +} + +// runAuditCommand parses and executes the audit command +func (a *app) runAuditCommand(ctx context.Context, cfg Config, log *slog.Logger, args []string) error { + defer traceFunc(ctx, log, "app.runAuditCommand")() + + // Parse first: usage errors never touch the database + sel, err := parseAuditArgs(args) + if err != nil { + return err + } + switch { + case sel.all: + log.DebugContext(ctx, "cli dispatch", "command", "audit", "all", true) + case sel.window > 0: + log.DebugContext(ctx, "cli dispatch", "command", "audit", "window", sel.window) + default: + log.DebugContext(ctx, "cli dispatch", "command", "audit", "limit", sel.limit) + } + + return a.withDatabase(ctx, cfg, log, "audit", func(db *sql.DB) error { + return a.auditList(ctx, NewAuditStore(db, log, a.now), sel) + }) +} + +// formatOperationRow renders the cells of one `audit` line +// Time and token are printed exactly as stored; origin and operation are written by the server and contain no tabs or newlines +func formatOperationRow(op Operation) []string { + return []string{op.TimeText, op.Token, op.Origin, op.Operation} +} + +// auditList prints the header and the selected audit rows, oldest first +func (a *app) auditList(ctx context.Context, store *AuditStore, sel auditSelection) error { + defer traceFunc(ctx, store.log, "app.auditList")() + + // Resolve the selection against the clock; the zero query selects every row + var q OperationQuery + switch { + case sel.all: + case sel.window > 0: + since := a.now().Add(-sel.window) + q.Since = &since + store.log.DebugContext(ctx, "audit window resolved", "since", formatTime(since)) + default: + q.Limit = sel.limit + } + + ops, err := store.ListOperations(ctx, q) + if err != nil { + return err + } + store.log.DebugContext(ctx, "audit rows listed", "rows", len(ops)) + rows := make([][]string, 0, len(ops)) + for _, op := range ops { + rows = append(rows, formatOperationRow(op)) + } + return writeTable(a.stdout, auditListHeader, rows) +} diff --git a/cli_test.go b/cli_test.go new file mode 100644 index 0000000..fe86d11 --- /dev/null +++ b/cli_test.go @@ -0,0 +1,1234 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +package main + +import ( + "context" + "database/sql" + "errors" + "fmt" + "math" + "os" + "path/filepath" + "regexp" + "slices" + "strconv" + "strings" + "testing" + "time" + "unicode/utf8" +) + +// cliResult captures one CLI invocation +type cliResult struct { + code int + stdout string + stderr string +} + +// cliEnv describes the environment of a CLI invocation +type cliEnv struct { + env map[string]string + gen func() (string, error) + now func() time.Time + ctx context.Context + out interface{ Write([]byte) (int, error) } + setup func(a *app) +} + +func runApp(t *testing.T, e cliEnv, args ...string) cliResult { + t.Helper() + stdout, stderr := &syncBuffer{}, &syncBuffer{} + a := newApp(envMap(e.env), stdout, stderr) + if e.out != nil { + a.stdout = e.out + } + if e.gen != nil { + a.generateToken = e.gen + } + if e.now != nil { + a.now = e.now + } + if e.setup != nil { + e.setup(a) + } + ctx := e.ctx + if ctx == nil { + ctx = context.Background() + } + code := a.run(ctx, args) + return cliResult{code: code, stdout: stdout.String(), stderr: stderr.String()} +} + +// cli runs a command against the database at path with a deterministic clock +func cli(t *testing.T, path string, gen func() (string, error), clock *fakeClock, args ...string) cliResult { + t.Helper() + e := cliEnv{env: map[string]string{"DB_PATH": path}, gen: gen} + if clock != nil { + e.now = clock.Now + } + return runApp(t, e, args...) +} + +func expect(t *testing.T, got cliResult, code int, stdout, stderr string) { + t.Helper() + if got.code != code || got.stdout != stdout || got.stderr != stderr { + t.Fatalf("got code=%d stdout=%q stderr=%q\nwant code=%d stdout=%q stderr=%q", + got.code, got.stdout, got.stderr, code, stdout, stderr) + } +} + +// emptyTokenList is the whole `token list` output without rows: the header cells padded by their own widths +const emptyTokenList = "TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n" + +// emptyAuditList is the whole `audit` output without rows +const emptyAuditList = "TIME TOKEN ORIGIN OPERATION\n" + +// padTable renders lines the way `token list` and `audit` print them, independently of text/tabwriter: +// every column but the last is padded with spaces to its widest cell in runes plus 2, the last cell is never padded +func padTable(lines ...[]string) string { + widths := make([]int, len(lines[0])-1) + for _, line := range lines { + for i, cell := range line[:len(line)-1] { + widths[i] = max(widths[i], utf8.RuneCountInString(cell)+2) + } + } + var b strings.Builder + for _, line := range lines { + for i, cell := range line[:len(line)-1] { + b.WriteString(cell + strings.Repeat(" ", widths[i]-utf8.RuneCountInString(cell))) + } + b.WriteString(line[len(line)-1] + "\n") + } + return b.String() +} + +func TestCLITokenListEmpty(t *testing.T) { + t.Parallel() + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}} { + path := testDBPath(t) + expect(t, cli(t, path, nil, nil, args...), 0, emptyTokenList, "") + if _, err := os.Stat(path); err != nil { + t.Fatalf("%q: database not created: %v", args, err) + } + } +} + +func TestCLITokenListOne(t *testing.T) { + t.Parallel() + path := testDBPath(t) + clock := newFakeClock(t0, time.Millisecond) + expect(t, cli(t, path, seqGenerator("tok-1"), clock, "token", "new", "first token"), 0, "tok-1\n", "") + want := "" + + "TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n" + + "tok-1 \"first token\" true 2026-10-05T12:00:00.123456789Z -\n" + expect(t, cli(t, path, nil, nil, "token", "list"), 0, want, "") + expect(t, cli(t, path, nil, nil, "token", "list", "all"), 0, want, "") + + // Once deactivated it is only listed with "all" + expect(t, cli(t, path, nil, clock, "token", "delete", "tok-1"), 0, "", "") + expect(t, cli(t, path, nil, nil, "token", "list"), 0, emptyTokenList, "") + want = "" + + "TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n" + + "tok-1 \"first token\" false 2026-10-05T12:00:00.123456789Z 2026-10-05T12:00:00.124456789Z\n" + expect(t, cli(t, path, nil, nil, "token", "list", "all"), 0, want, "") +} + +func TestCLITokenListMany(t *testing.T) { + t.Parallel() + path := testDBPath(t) + clock := newFakeClock(time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC), 500*time.Millisecond) + gen := seqGenerator("c", "b", "a", "d") + expect(t, cli(t, path, gen, clock, "token", "new"), 0, "c\n", "") // 00.000 + expect(t, cli(t, path, gen, clock, "token", "new", "tab\there"), 0, "b\n", "") // 00.5 + expect(t, cli(t, path, gen, clock, "token", "new", "multi\nline \"q\" é"), 0, "a\n", "") // 01.0 + expect(t, cli(t, path, nil, clock, "token", "delete", "b"), 0, "", "") // 01.5 + expect(t, cli(t, path, gen, clock, "token", "new", "ünïcödé — 日本語 🚀 «quoted»"), 0, "d\n", "") // 02.0 + + // Widths count runes: the quoted multi-byte description is 26 runes but 43 bytes, and the CJK runes count as 1 (not double-width) + wantAll := "" + + "TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n" + + "c \"\" true 2026-01-01T00:00:00Z -\n" + + "b \"tab\\there\" false 2026-01-01T00:00:00.5Z 2026-01-01T00:00:01.5Z\n" + + "a \"multi\\nline \\\"q\\\" é\" true 2026-01-01T00:00:01Z -\n" + + "d \"ünïcödé — 日本語 🚀 «quoted»\" true 2026-01-01T00:00:02Z -\n" + expect(t, cli(t, path, nil, nil, "token", "list", "all"), 0, wantAll, "") + + // Without "all" the inactive row is hidden and the widths are computed over the printed lines only + wantActive := "" + + "TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n" + + "c \"\" true 2026-01-01T00:00:00Z -\n" + + "a \"multi\\nline \\\"q\\\" é\" true 2026-01-01T00:00:01Z -\n" + + "d \"ünïcödé — 日本語 🚀 «quoted»\" true 2026-01-01T00:00:02Z -\n" + expect(t, cli(t, path, nil, nil, "token", "list"), 0, wantActive, "") + + // The independent renderer agrees with the literal tables + cells := func(tok, desc, active, created, deleted string) []string { + return []string{tok, strconv.Quote(desc), active, created, deleted} + } + c := cells("c", "", "true", "2026-01-01T00:00:00Z", "-") + b := cells("b", "tab\there", "false", "2026-01-01T00:00:00.5Z", "2026-01-01T00:00:01.5Z") + a := cells("a", "multi\nline \"q\" é", "true", "2026-01-01T00:00:01Z", "-") + d := cells("d", "ünïcödé — 日本語 🚀 «quoted»", "true", "2026-01-01T00:00:02Z", "-") + if padTable(tokenListHeader, c, b, a, d) != wantAll || padTable(tokenListHeader, c, a, d) != wantActive { + t.Fatal("padTable disagrees with the literal tables") + } +} + +func TestCLITokenListManyGenerated(t *testing.T) { + t.Parallel() + path := testDBPath(t) + clock := newFakeClock(t0, 1500*time.Microsecond) + descriptions := []string{"", "x", "日本語", "with quoted spaces", "line\nbreak", "tab\t", "\x00\xff", "🚀🚀🚀🚀🚀🚀🚀🚀🚀🚀🚀🚀", "'single' \"double\""} + var all, active [][]string + for i := 0; i < 30; i++ { + desc := descriptions[i%len(descriptions)] + res := cli(t, path, nil, clock, "token", "new", desc) + tok := strings.TrimSuffix(res.stdout, "\n") + if res.code != 0 || !tokenAlphabet.MatchString(tok) { + t.Fatalf("%+v", res) + } + created := formatTime(t0.Add(time.Duration(i) * 1500 * time.Microsecond)) + row := []string{tok, strconv.Quote(desc), "true", created, "-"} + if i%4 == 1 { + expect(t, cli(t, path, nil, nil, "token", "delete", tok), 0, "", "") + } + all = append(all, row) + } + for i, row := range all { + if i%4 == 1 { + continue + } + active = append(active, row) + } + + // Deleted rows: read their deleted_at from the full listing (real clock) and check the rest exactly + full := cli(t, path, nil, nil, "token", "list", "all") + lines := strings.Split(strings.TrimSuffix(full.stdout, "\n"), "\n") + if full.code != 0 || full.stderr != "" || len(lines) != 31 { + t.Fatalf("%+v", full) + } + for i := range all { + if i%4 == 1 { + fields := strings.Fields(lines[i+1]) + all[i][2], all[i][4] = "false", fields[len(fields)-1] + } + } + expect(t, cli(t, path, nil, nil, "token", "list", "all"), 0, padTable(append([][]string{tokenListHeader}, all...)...), "") + want := padTable(append([][]string{tokenListHeader}, active...)...) + expect(t, cli(t, path, nil, nil, "token", "list"), 0, want, "") + + // Every token is 43 runes: the TOKEN column is always 45 wide; no line has trailing whitespace + for _, line := range strings.Split(strings.TrimSuffix(want, "\n"), "\n")[1:] { + if line[43:45] != " " || line[45] == ' ' || strings.TrimRight(line, " ") != line { + t.Fatalf("line %q", line) + } + } +} + +func TestCLITokenNew(t *testing.T) { + t.Parallel() + path := testDBPath(t) + descriptions := []string{ + "", "simple", "with quoted spaces", "'single' \"double\" `back` $HOME $(id) ; | & < > *", + "line\nbreak", "日本語 🚀", "-dash-leading", "--", "x'); DROP TABLE tokens; --", + } + for _, desc := range descriptions { + res := cli(t, path, nil, nil, "token", "new", desc) + if res.code != 0 || res.stderr != "" || !strings.HasSuffix(res.stdout, "\n") { + t.Fatalf("%q: %+v", desc, res) + } + tok := strings.TrimSuffix(res.stdout, "\n") + if !tokenAlphabet.MatchString(tok) { + t.Fatalf("printed token %q", tok) + } + db, err := sql.Open("sqlite", "file:"+path) + if err != nil { + t.Fatal(err) + } + var stored string + var active int + err = db.QueryRow(`SELECT description, active FROM tokens WHERE token = ?`, tok).Scan(&stored, &active) + db.Close() + if err != nil || stored != desc || active != 1 { + t.Fatalf("%q: stored %q active=%d err=%v", desc, stored, active, err) + } + } + // Without a description argument at all + res := cli(t, path, seqGenerator("nodesc"), nil, "token", "new") + expect(t, res, 0, "nodesc\n", "") + if !regexp.MustCompile(`(?m)^nodesc +"" +true +\S+ +-$`).MatchString(cli(t, path, nil, nil, "token", "list").stdout) { + t.Fatal("empty description not listed") + } +} + +func TestCLITokenDelete(t *testing.T) { + t.Parallel() + path := testDBPath(t) + expect(t, cli(t, path, seqGenerator("victim"), nil, "token", "new"), 0, "victim\n", "") + expect(t, cli(t, path, nil, nil, "token", "delete", "victim"), 0, "", "") + expect(t, cli(t, path, nil, nil, "token", "delete", "victim"), 1, "", "dpsapi: token already inactive\n") + expect(t, cli(t, path, nil, nil, "token", "delete", "unknown-secret"), 1, "", "dpsapi: token not found\n") + expect(t, cli(t, path, nil, nil, "token", "delete", ""), 1, "", "dpsapi: token not found\n") + expect(t, cli(t, path, nil, nil, "token", "delete", "VICTIM"), 1, "", "dpsapi: token not found\n") + expect(t, cli(t, path, nil, nil, "token", "list"), 0, emptyTokenList, "") + list := cli(t, path, nil, nil, "token", "list", "all").stdout + if !regexp.MustCompile(`\Avictim +"" +false +\S+ +\S+\n\z`).MatchString(strings.SplitN(list, "\n", 2)[1]) || + strings.Contains(list, " -\n") { + t.Fatalf("list after delete:\n%s", list) + } +} + +func TestCLIDeleteDoesNotEchoToken(t *testing.T) { + t.Parallel() + path := testDBPath(t) + const secret = "DoNotEchoMe_0123456789abcdefghijklmnopqrstu" + e := cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "TRACE"}} + res := runApp(t, e, "token", "delete", secret) + if res.code != 1 || strings.Contains(res.stderr, secret) || strings.Contains(res.stdout, secret) { + t.Fatalf("token echoed: %+v", res) + } + if !strings.HasSuffix(res.stderr, "dpsapi: token not found\n") { + t.Fatalf("stderr = %q", res.stderr) + } +} + +func TestCLIUsageErrors(t *testing.T) { + t.Parallel() + cases := []struct { + args []string + msg string + }{ + {[]string{"foo"}, "unknown command"}, + {[]string{"tokens"}, "unknown command"}, + {[]string{"-h"}, "unknown command"}, + {[]string{"--help"}, "unknown command"}, + {[]string{"Help"}, "unknown command"}, + {[]string{"HELP"}, "unknown command"}, + {[]string{"help "}, "unknown command"}, + {[]string{"-help"}, "unknown command"}, + {[]string{"help", "x"}, "help takes no arguments"}, + {[]string{"help", ""}, "help takes no arguments"}, + {[]string{"help", "help"}, "help takes no arguments"}, + {[]string{"help", "token", "list"}, "help takes no arguments"}, + {[]string{"token", "help"}, "unknown token subcommand"}, + {[]string{""}, "unknown command"}, + {[]string{"TOKEN", "list"}, "unknown command"}, + {[]string{"token"}, "missing token subcommand"}, + {[]string{"token", "lst"}, "unknown token subcommand"}, + {[]string{"token", "LIST"}, "unknown token subcommand"}, + {[]string{"token", ""}, "unknown token subcommand"}, + {[]string{"token", "list", "extra"}, "unknown token list argument"}, + {[]string{"token", "list", ""}, "unknown token list argument"}, + {[]string{"token", "list", "ALL"}, "unknown token list argument"}, + {[]string{"token", "list", "All"}, "unknown token list argument"}, + {[]string{"token", "list", "--all"}, "unknown token list argument"}, + {[]string{"token", "list", "-a"}, "unknown token list argument"}, + {[]string{"token", "list", " all"}, "unknown token list argument"}, + {[]string{"token", "list", "all "}, "unknown token list argument"}, + {[]string{"token", "list", "active"}, "unknown token list argument"}, + {[]string{"token", "list", "help"}, "unknown token list argument"}, + {[]string{"token", "list", "all", "all"}, "token list takes at most one argument"}, + {[]string{"token", "list", "x", "y"}, "token list takes at most one argument"}, + {[]string{"token", "list", "", ""}, "token list takes at most one argument"}, + {[]string{"token", "list", "all", "x", "y"}, "token list takes at most one argument"}, + {[]string{"token", "new", "a", "b"}, "token new takes at most one argument"}, + {[]string{"token", "new", "a", ""}, "token new takes at most one argument"}, + {[]string{"token", "delete"}, "token delete requires exactly one argument"}, + {[]string{"token", "delete", "a", "b"}, "token delete requires exactly one argument"}, + } + for _, c := range cases { + path := testDBPath(t) + res := cli(t, path, nil, nil, c.args...) + expect(t, res, 2, "", "dpsapi: usage error: "+c.msg+"\n"+usageText) + // Usage errors never touch the database + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("%q: database created on usage error", c.args) + } + } +} + +func TestCLIConfigErrors(t *testing.T) { + t.Parallel() + cases := []struct { + env map[string]string + msg string + }{ + {map[string]string{}, "DB_PATH is required"}, + {map[string]string{"DB_PATH": ""}, "DB_PATH must not be empty"}, + {map[string]string{"DB_PATH": "x", "HTTP_PORT": "0"}, `invalid HTTP_PORT "0": must be an integer between 1 and 65535`}, + {map[string]string{"DB_PATH": "x", "HTTP_ADDR": "localhost"}, `invalid HTTP_ADDR "localhost": must be an IPv4 or IPv6 address`}, + {map[string]string{"DB_PATH": "x", "LOG_LEVEL": "verbose"}, `invalid LOG_LEVEL "verbose": must be one of ERROR, WARN, INFO, DEBUG, TRACE`}, + {map[string]string{"DB_PATH": "x", "LOG_LEVEL": "a\nb"}, `invalid LOG_LEVEL "a\nb": must be one of ERROR, WARN, INFO, DEBUG, TRACE`}, + } + for _, c := range cases { + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}, {"token", "list", "x"}, {}, {"bogus"}, {"help"}, {"help", "x"}} { + res := runApp(t, cliEnv{env: c.env}, args...) + // Configuration is validated first, so config errors win over usage errors + expect(t, res, 2, "", "dpsapi: configuration error: "+c.msg+"\n") + } + } +} + +func TestCLIPersistenceError(t *testing.T) { + t.Parallel() + dir := t.TempDir() + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}, {"token", "new"}, {"token", "delete", "x"}} { + res := cli(t, dir, nil, nil, args...) + if res.code != 1 || res.stdout != "" || !strings.HasPrefix(res.stderr, "dpsapi: initialize database schema: ") || + strings.Count(res.stderr, "\n") != 1 { + t.Fatalf("%q: %+v", args, res) + } + } + // List failing after the database opened (bad stored row) + path := testDBPath(t) + expect(t, cli(t, path, nil, nil, "token", "list"), 0, emptyTokenList, "") + db, _ := sql.Open("sqlite", "file:"+path) + mustExec(t, db, `INSERT INTO tokens VALUES ('t', '', 1, 'garbage', NULL)`) + db.Close() + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}} { + res := cli(t, path, nil, nil, args...) + if res.code != 1 || res.stdout != "" || !strings.HasPrefix(res.stderr, "dpsapi: read token row: parse stored timestamp") { + t.Fatalf("%q: %+v", args, res) + } + } +} + +func TestCLIGeneratorFailure(t *testing.T) { + t.Parallel() + path := testDBPath(t) + res := cli(t, path, func() (string, error) { return "", errors.New("entropy\nexhausted") }, nil, "token", "new") + // Multi-line error text is folded onto one line + expect(t, res, 1, "", "dpsapi: generate token: entropy exhausted\n") +} + +type failingWriter struct{} + +func (failingWriter) Write([]byte) (int, error) { return 0, errors.New("broken pipe") } + +func TestCLIStdoutWriteFailure(t *testing.T) { + t.Parallel() + path := testDBPath(t) + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}, {"token", "new"}} { + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path}, out: failingWriter{}}, args...) + expect(t, res, 1, "", "dpsapi: write output: broken pipe\n") + } + + // A table larger than the output buffer fails while the table is flushed: still reported once + for i := 0; i < 200; i++ { + expect(t, cli(t, path, seqGenerator(fmt.Sprintf("big-%03d-%s", i, strings.Repeat("x", 35))), nil, "token", "new", "description"), + 0, fmt.Sprintf("big-%03d-%s\n", i, strings.Repeat("x", 35)), "") + } + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path}, out: failingWriter{}}, "token", "list") + expect(t, res, 1, "", "dpsapi: write output: broken pipe\n") +} + +func TestCLILoggingLevels(t *testing.T) { + t.Parallel() + path := testDBPath(t) + + // INFO (default) and above: a successful command writes nothing to stderr + for _, level := range []string{"ERROR", "WARN", "INFO"} { + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": level}}, "token", "new", "x") + if res.code != 0 || res.stderr != "" { + t.Fatalf("%s: %+v", level, res) + } + } + + // DEBUG: lifecycle records, no TRACE + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "DEBUG"}, gen: seqGenerator("dbg-secret-value")}, "token", "new", "x") + for _, want := range []string{ + `level=DEBUG msg="configuration resolved" db_path=` + path + ` http_addr=0.0.0.0 http_port=80 log_level=DEBUG`, + `level=DEBUG msg=dispatch mode=cli`, + `level=DEBUG msg="cli dispatch" command="token new"`, + `level=DEBUG msg="database schema initialized"`, + `level=DEBUG msg="database opened"`, + `level=DEBUG msg="token created" token_id=` + tokenID("dbg-secret-value"), + `level=DEBUG msg="cli command finished" command="token new" ok=true`, + `level=DEBUG msg="database closed"`, + } { + if !strings.Contains(res.stderr, want) { + t.Errorf("DEBUG: missing %q in:\n%s", want, res.stderr) + } + } + if strings.Contains(res.stderr, "level=TRACE") || strings.Contains(res.stderr, "dbg-secret-value") { + t.Fatalf("DEBUG output leaked trace or secret:\n%s", res.stderr) + } + + // TRACE: function entry/exit and row records, token redacted + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "trace"}, gen: seqGenerator("trace-secret-value")}, "token", "new", "described") + if res.stdout != "trace-secret-value\n" { + t.Fatalf("stdout = %q", res.stdout) + } + for _, want := range []string{ + `level=TRACE msg="function entry" func=app.execute`, + `level=TRACE msg="function entry" func=app.runTokenCommand`, + `level=TRACE msg="function entry" func=app.tokenNew`, + `level=TRACE msg="function entry" func=TokenStore.CreateToken`, + `level=TRACE msg="row inserted" table=tokens token_id=` + tokenID("trace-secret-value") + ` description=described`, + `level=TRACE msg="function exit" func=app.execute`, + } { + if !strings.Contains(res.stderr, want) { + t.Errorf("TRACE: missing %q", want) + } + } + if strings.Contains(res.stderr, "trace-secret-value") { + t.Fatalf("secret in trace output:\n%s", res.stderr) + } + + // TRACE for list and delete + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "TRACE"}}, "token", "delete", "trace-secret-value") + if res.code != 0 || !strings.Contains(res.stderr, `msg="row updated" table=tokens token_id=`+tokenID("trace-secret-value")) || + !strings.Contains(res.stderr, `level=DEBUG msg="token deactivated"`) || strings.Contains(res.stderr, "trace-secret-value") { + t.Fatalf("delete trace: %+v", res) + } + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "TRACE"}}, "token", "list", "all") + if res.code != 0 || !strings.Contains(res.stderr, `func=app.tokenList`) || strings.Contains(res.stderr, "trace-secret-value") || + !strings.Contains(res.stderr, `msg="row read" table=tokens token_id=`+tokenID("trace-secret-value")) { + t.Fatalf("list trace: %+v", res) + } + if !strings.Contains(res.stdout, "trace-secret-value") { + t.Fatal("token list all must print full tokens on stdout") + } + + // DEBUG for list: both forms dispatch as "token list"; the deactivated token is not even read without "all" + for _, args := range [][]string{{"token", "list"}, {"token", "list", "all"}} { + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "TRACE"}}, args...) + if res.code != 0 || !strings.Contains(res.stderr, `level=DEBUG msg="cli dispatch" command="token list"`+"\n") || + !strings.Contains(res.stderr, `level=DEBUG msg="cli command finished" command="token list" ok=true`) || + strings.Contains(res.stderr, "trace-secret-value") { + t.Fatalf("%q: %+v", args, res) + } + read := strings.Contains(res.stderr, `msg="row read" table=tokens token_id=`+tokenID("trace-secret-value")) + if listed := strings.Contains(res.stdout, "trace-secret-value"); read != (len(args) == 3) || listed != read { + t.Fatalf("%q: inactive token read=%v listed=%v", args, read, listed) + } + } +} + +func TestRunEntryPoint(t *testing.T) { + t.Parallel() + path := filepath.Join(t.TempDir(), "entry.db") + stdout, stderr := &syncBuffer{}, &syncBuffer{} + code := run([]string{"token", "list"}, envMap(map[string]string{"DB_PATH": path}), stdout, stderr) + if code != 0 || stdout.String() != emptyTokenList || stderr.String() != "" { + t.Fatalf("code=%d stdout=%q stderr=%q", code, stdout.String(), stderr.String()) + } + code = run([]string{"nope"}, envMap(map[string]string{"DB_PATH": path}), stdout, stderr) + if code != 2 { + t.Fatalf("code=%d", code) + } +} + +func TestFormatTokenRow(t *testing.T) { + t.Parallel() + deleted := time.Date(2026, 2, 3, 4, 5, 6, 7, time.UTC) + got := formatTokenRow(Token{Token: "t", Description: "a\tb\x00\xff", Active: false, CreatedAt: t0, DeletedAt: &deleted}) + want := []string{"t", `"a\tb\x00\xff"`, "false", "2026-10-05T12:00:00.123456789Z", "2026-02-03T04:05:06.000000007Z"} + if !slices.Equal(got, want) { + t.Fatalf("got %q\nwant %q", got, want) + } + got = formatTokenRow(Token{Token: "u", Description: "日本語 é", Active: true, CreatedAt: t0}) + want = []string{"u", `"日本語 é"`, "true", "2026-10-05T12:00:00.123456789Z", "-"} + if !slices.Equal(got, want) { + t.Fatalf("got %q\nwant %q", got, want) + } +} + +// seedAudit creates the database at path with the tokens "tok" (active) and "old" (inactive) +// and the given operations rows (token, time), inserted in order with origin 10.0.0. +func seedAudit(t *testing.T, path string, rows ...[2]string) *sql.DB { + t.Helper() + db := openTestDBAt(t, path) + mustExec(t, db, `INSERT INTO tokens VALUES ('tok', '', 1, '2026-01-01T00:00:00Z', NULL)`) + mustExec(t, db, `INSERT INTO tokens VALUES ('old', '', 0, '2026-01-01T00:00:00Z', '2026-01-02T00:00:00Z')`) + insertOperations(t, db, rows...) + return db +} + +// auditOut renders the expected `audit` output for the given 1-based indexes into rows +func auditOut(rows [][2]string, idx ...int) string { + lines := [][]string{auditListHeader} + for _, i := range idx { + lines = append(lines, []string{rows[i-1][1], rows[i-1][0], fmt.Sprintf("10.0.0.%d", i), "GET containers"}) + } + return padTable(lines...) +} + +// auditCLI runs `audit args...` against path with a fixed clock +func auditCLI(t *testing.T, path string, now time.Time, args ...string) cliResult { + t.Helper() + e := cliEnv{env: map[string]string{"DB_PATH": path}, now: func() time.Time { return now }} + return runApp(t, e, append([]string{"audit"}, args...)...) +} + +// indexes parses a comma-separated list of 1-based row indexes +func indexes(s string) []int { + var out []int + for _, f := range strings.Split(s, ",") { + n, _ := strconv.Atoi(f) + out = append(out, n) + } + return out +} + +func TestCLIAuditEmpty(t *testing.T) { + t.Parallel() + for _, args := range [][]string{{}, {"1"}, {"5"}, {"1s"}, {"1h"}, {"1w"}, {"all"}} { + // Fresh database: created, schema initialized, header only + path := testDBPath(t) + expect(t, auditCLI(t, path, t0, args...), 0, emptyAuditList, "") + if _, err := os.Stat(path); err != nil { + t.Fatalf("%q: database not created: %v", args, err) + } + // Existing database with tokens but no audit rows + path = testDBPath(t) + seedAudit(t, path) + expect(t, auditCLI(t, path, t0, args...), 0, emptyAuditList, "") + } +} + +func TestCLIAuditCount(t *testing.T) { + t.Parallel() + path := testDBPath(t) + var rows [][2]string + for i := 0; i < 15; i++ { + tok := "tok" + if i%2 == 1 { + tok = "old" + } + rows = append(rows, [2]string{tok, formatTime(t0.Add(time.Duration(i) * time.Second))}) + } + seedAudit(t, path, rows...) + all := indexes("1,2,3,4,5,6,7,8,9,10,11,12,13,14,15") + cases := []struct { + args []string + want []int + }{ + {nil, all[5:]}, // default: the latest 10 + {[]string{"10"}, all[5:]}, + {[]string{"010"}, all[5:]}, // leading zeros + {[]string{"0000000000000000000000000000010"}, all[5:]}, + {[]string{"1"}, all[14:]}, + {[]string{"01"}, all[14:]}, + {[]string{"2"}, all[13:]}, + {[]string{"14"}, all[1:]}, + {[]string{"15"}, all}, + {[]string{"16"}, all}, // more than available: everything + {[]string{"1000"}, all}, + {[]string{"9223372036854775807"}, all}, // math.MaxInt + {[]string{"all"}, all}, // every row, not the latest 10 + } + for _, c := range cases { + expect(t, auditCLI(t, path, t0, c.args...), 0, auditOut(rows, c.want...), "") + } +} + +func TestCLIAuditOrdering(t *testing.T) { + t.Parallel() + path := testDBPath(t) + seedAudit(t, path, orderingRows...) + now := time.Date(2026, 1, 1, 0, 0, 1, 0, time.UTC) + cases := []struct { + args []string + want string + }{ + {[]string{"100"}, orderingSorted}, + {nil, "1,12,3,14,11,4,5,7,10,9"}, + {[]string{"3"}, "7,10,9"}, + // Ties (same instant, different spelling) keep insertion order; the cut falls between tied rows + {[]string{"4"}, "5,7,10,9"}, + {[]string{"1s"}, "2,13,8,1,12,3,14,11,4,5,7,10,9"}, + {[]string{"60s"}, orderingSorted}, + {[]string{"all"}, orderingSorted}, + } + for _, c := range cases { + expect(t, auditCLI(t, path, now, c.args...), 0, auditOut(orderingRows, indexes(c.want)...), "") + } +} + +func TestCLIAuditAll(t *testing.T) { + t.Parallel() + // The clock plays no part: rows far in the past and in the future are all printed + clocks := []time.Time{t0, time.Date(1970, 1, 1, 0, 0, 0, 0, time.UTC), time.Date(3000, 1, 1, 0, 0, 0, 0, time.UTC)} + + // No rows: header only + path := testDBPath(t) + seedAudit(t, path) + for _, now := range clocks { + expect(t, auditCLI(t, path, now, "all"), 0, emptyAuditList, "") + } + + // One row + path = testDBPath(t) + one := [][2]string{{"old", "2026-01-01T00:00:00Z"}} + seedAudit(t, path, one...) + for _, now := range clocks { + expect(t, auditCLI(t, path, now, "all"), 0, auditOut(one, 1), "") + } + + // More than 10 rows inserted newest first, spanning decades: every row, oldest first + path = testDBPath(t) + var rows [][2]string + var want []int + for i := 0; i < 25; i++ { + rows = append(rows, [2]string{"tok", formatTime(t0.Add(-time.Duration(i) * 400 * 24 * time.Hour))}) + want = append([]int{i + 1}, want...) + } + seedAudit(t, path, rows...) + for _, now := range clocks { + expect(t, auditCLI(t, path, now, "all"), 0, auditOut(rows, want...), "") + } + + // Mixed fraction lengths, zones and ties: (time, rowid) order, more than 10 rows + path = testDBPath(t) + seedAudit(t, path, orderingRows...) + for _, now := range clocks { + expect(t, auditCLI(t, path, now, "all"), 0, auditOut(orderingRows, indexes(orderingSorted)...), "") + } +} + +func TestCLIAuditWindowUnits(t *testing.T) { + t.Parallel() + // The clock is not UTC: the window is an instant comparison, independent of zones + now := time.Date(2026, 10, 6, 14, 0, 0, 0, time.FixedZone("CEST", 2*3600)) + cases := []struct { + arg string + dur time.Duration + }{ + {"1s", time.Second}, + {"45s", 45 * time.Second}, + {"1m", time.Minute}, + {"90m", 90 * time.Minute}, + {"1h", time.Hour}, + {"01h", time.Hour}, + {"36h", 36 * time.Hour}, + {"1d", 24 * time.Hour}, + {"10d", 240 * time.Hour}, + {"1w", 7 * 24 * time.Hour}, + {"0002w", 14 * 24 * time.Hour}, + } + for _, c := range cases { + since := now.Add(-c.dur) + rows := [][2]string{ + {"tok", formatTime(since.Add(-time.Nanosecond))}, // just outside + {"old", formatTime(since)}, // boundary: included + {"tok", formatTime(since.Add(time.Nanosecond))}, + {"tok", formatTime(now)}, + {"tok", formatTime(now.Add(time.Hour))}, // later than now: still >= since + {"tok", formatTime(since.Add(-c.dur))}, // far outside + } + path := testDBPath(t) + seedAudit(t, path, rows...) + expect(t, auditCLI(t, path, now, c.arg), 0, auditOut(rows, 2, 3, 4, 5), "") + } +} + +func TestCLIAuditLargestValues(t *testing.T) { + t.Parallel() + path := testDBPath(t) + rows := [][2]string{{"tok", "1700-01-01T00:00:00Z"}, {"tok", "1740-01-01T00:00:00Z"}, {"tok", "2026-01-01T00:00:00Z"}} + seedAudit(t, path, rows...) + // The largest window per unit that fits a time.Duration (about 292 years) + for _, arg := range []string{"9223372036s", "153722867m", "2562047h", "106751d", "15250w"} { + expect(t, auditCLI(t, path, t0, arg), 0, auditOut(rows, 2, 3), "") + } +} + +func TestCLIAuditUsageErrors(t *testing.T) { + t.Parallel() + const many = "audit takes at most one argument" + const invalid = "invalid audit argument" + cases := []struct { + args []string + msg string + }{ + {[]string{"AUDIT"}, "unknown command"}, + {[]string{"Audit"}, "unknown command"}, + {[]string{"audits"}, "unknown command"}, + {[]string{"audit", "1", "2"}, many}, + {[]string{"audit", "10", "1h"}, many}, + {[]string{"audit", "", ""}, many}, + {[]string{"audit", "1", ""}, many}, + {[]string{"audit", "all", "x"}, many}, + {[]string{"audit", "all", "all"}, many}, + {[]string{"audit", "all", ""}, many}, + {[]string{"audit", "1", "all"}, many}, + } + for _, arg := range []string{ + // zero + "0", "00", "0s", "0m", "0h", "0d", "0w", "000w", + // signs and whitespace + "-1", "+1", "-1h", "+1h", "--1", " 1", "1 ", "\t1", "1\n", "1h ", "1 h", " ", "1\x00", + // empty, unit only, unknown/uppercase/multi-letter units + "", "s", "h", "d", "1H", "1D", "1W", "1S", "1M", "1y", "1ms", "1us", "1ns", "1hh", "1h1", "h1", "1x", + // other number syntaxes + "1.5", "1.5h", "1e3", "1_000", "0x10", "0b1", "1,000", "١", "１", "one", "-h", "--help", "help", "audit", + // overflow: count beyond int, window beyond time.Duration + "9223372036854775808", "99999999999999999999999999", "9223372036854775808s", + "9223372037s", "153722868m", "2562048h", "106752d", "15251w", "9223372036854775807w", + // SQL/shell payloads + "1; DROP TABLE operations", "1' OR '1'='1", "$(id)", + // all is exact and lowercase only + "ALL", "All", "aLL", "all1", "1all", "allh", " all", "all ", "\tall", "all\n", "alls", "al", "a", "--all", "-all", "-a", + "all\x00", "\"all\"", "ａｌｌ", "every", + } { + cases = append(cases, struct { + args []string + msg string + }{[]string{"audit", arg}, invalid}) + } + for _, c := range cases { + path := testDBPath(t) + res := cli(t, path, nil, nil, c.args...) + // The exact stderr proves the argument is never echoed + expect(t, res, 2, "", "dpsapi: usage error: "+c.msg+"\n"+usageText) + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("%q: database created on usage error", c.args) + } + } +} + +func TestParseAuditArgs(t *testing.T) { + t.Parallel() + cases := []struct { + args []string + want auditSelection + }{ + {nil, auditSelection{limit: 10}}, + {[]string{}, auditSelection{limit: 10}}, + {[]string{"7"}, auditSelection{limit: 7}}, + {[]string{"007"}, auditSelection{limit: 7}}, + {[]string{"9223372036854775807"}, auditSelection{limit: math.MaxInt}}, + {[]string{"3s"}, auditSelection{window: 3 * time.Second}}, + {[]string{"3m"}, auditSelection{window: 3 * time.Minute}}, + {[]string{"3h"}, auditSelection{window: 3 * time.Hour}}, + {[]string{"3d"}, auditSelection{window: 72 * time.Hour}}, + {[]string{"3w"}, auditSelection{window: 504 * time.Hour}}, + {[]string{"9223372036s"}, auditSelection{window: 9223372036 * time.Second}}, + {[]string{"all"}, auditSelection{all: true}}, + } + for _, c := range cases { + got, err := parseAuditArgs(c.args) + if err != nil || got != c.want { + t.Errorf("parseAuditArgs(%q) = %+v, %v; want %+v", c.args, got, err, c.want) + } + } + for _, arg := range []string{"0", "ALL", "all1"} { + if _, err := parseAuditArgs([]string{arg}); !errors.Is(err, errUsage) { + t.Fatalf("%q: expected usage error, got %v", arg, err) + } + } +} + +func TestCLIAuditConfigErrorsFirst(t *testing.T) { + t.Parallel() + for _, args := range [][]string{{"audit"}, {"audit", "1h"}, {"audit", "0"}, {"audit", "1", "2"}, {"audit", "all"}, {"audit", "ALL"}} { + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": "x", "LOG_LEVEL": "loud"}}, args...) + expect(t, res, 2, "", "dpsapi: configuration error: invalid LOG_LEVEL \"loud\": must be one of ERROR, WARN, INFO, DEBUG, TRACE\n") + } +} + +func TestCLIAuditPersistenceErrors(t *testing.T) { + t.Parallel() + dir := t.TempDir() + for _, args := range [][]string{{"audit"}, {"audit", "5"}, {"audit", "1h"}, {"audit", "all"}} { + res := cli(t, dir, nil, nil, args...) + if res.code != 1 || res.stdout != "" || !strings.HasPrefix(res.stderr, "dpsapi: initialize database schema: ") || + strings.Count(res.stderr, "\n") != 1 { + t.Fatalf("%q: %+v", args, res) + } + } + // A stored time that does not parse fails the command instead of misordering; nothing reaches stdout + path := testDBPath(t) + seedAudit(t, path, [2]string{"tok", "2026-01-01T00:00:00Z"}, [2]string{"tok", "yesterday"}) + for _, args := range [][]string{{}, {"1"}, {"1w"}, {"all"}} { + res := auditCLI(t, path, t0, args...) + if res.code != 1 || res.stdout != "" || !strings.HasPrefix(res.stderr, "dpsapi: read operation row: parse stored timestamp") || + strings.Count(res.stderr, "\n") != 1 || strings.Contains(res.stderr, "usage") { + t.Fatalf("%q: %+v", args, res) + } + } +} + +func TestCLIAuditStdoutWriteFailure(t *testing.T) { + t.Parallel() + path := testDBPath(t) + seedAudit(t, path, [2]string{"tok", "2026-01-01T00:00:00Z"}) + for _, args := range [][]string{{"audit"}, {"audit", "1"}, {"audit", "1w"}, {"audit", "all"}} { + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path}, out: failingWriter{}}, args...) + expect(t, res, 1, "", "dpsapi: write output: broken pipe\n") + } +} + +// tableDump renders every row of tokens and operations (with rowids) for before/after comparisons +func tableDump(t *testing.T, db *sql.DB) string { + t.Helper() + var b strings.Builder + for _, q := range []string{ + `SELECT rowid, token, description, active, created_at, IFNULL(deleted_at, 'NULL') FROM tokens ORDER BY rowid`, + `SELECT rowid, token, origin, operation, time FROM operations ORDER BY rowid`, + } { + rows, err := db.Query(q) + if err != nil { + t.Fatal(err) + } + cols, _ := rows.Columns() + for rows.Next() { + vals := make([]any, len(cols)) + ptrs := make([]any, len(cols)) + for i := range vals { + ptrs[i] = &vals[i] + } + if err := rows.Scan(ptrs...); err != nil { + t.Fatal(err) + } + fmt.Fprintln(&b, vals...) + } + rows.Close() + } + return b.String() +} + +func TestCLIAuditReadOnly(t *testing.T) { + t.Parallel() + path := testDBPath(t) + db := seedAudit(t, path, orderingRows...) + // Any write to either table would abort the command + for _, table := range []string{"tokens", "operations"} { + for _, op := range []string{"INSERT", "UPDATE", "DELETE"} { + mustExec(t, db, fmt.Sprintf(`CREATE TRIGGER ro_%s_%s BEFORE %s ON %s BEGIN SELECT RAISE(ABORT, 'read-only'); END`, + op, table, op, table)) + } + } + before := tableDump(t, db) + for _, args := range [][]string{{}, {"1"}, {"100"}, {"1s"}, {"1w"}, {"all"}, {"0"}, {"x"}, {"ALL"}} { + res := auditCLI(t, path, t0, args...) + if res.code == 1 { + t.Fatalf("%q: %+v", args, res) + } + } + if after := tableDump(t, db); after != before { + t.Fatalf("tables changed:\n%s\nvs\n%s", before, after) + } + // On a fresh database only the schema is created: both tables stay empty + path = testDBPath(t) + expect(t, auditCLI(t, path, t0), 0, emptyAuditList, "") + fresh := openTestDBAt(t, path) + if countRows(t, fresh, "tokens") != 0 || countRows(t, fresh, "operations") != 0 { + t.Fatal("audit wrote rows") + } +} + +func TestCLIAuditLogging(t *testing.T) { + t.Parallel() + const secret = "AuditCliSecret_0123456789abcdefghijklmnopqr" + path := testDBPath(t) + db := seedAudit(t, path) + mustExec(t, db, `INSERT INTO tokens VALUES (?, '', 1, '2026-01-01T00:00:00Z', NULL)`, secret) + mustExec(t, db, `INSERT INTO operations VALUES (?, '192.0.2.9', 'GET containers', '2026-10-05T11:59:00Z')`, secret) + mustExec(t, db, `INSERT INTO operations VALUES ('tok', '192.0.2.8', 'GET containers', '2026-10-05T10:00:00Z')`) + wantOut := "" + + "TIME TOKEN ORIGIN OPERATION\n" + + "2026-10-05T11:59:00Z " + secret + " 192.0.2.9 GET containers\n" + env := func(level string) cliEnv { + return cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": level}, now: func() time.Time { return t0 }} + } + + // INFO and above: a successful audit writes nothing to stderr; the full token is on stdout only + for _, level := range []string{"ERROR", "WARN", "INFO"} { + expect(t, runApp(t, env(level), "audit", "1"), 0, wantOut, "") + } + + // DEBUG: dispatch, selection, result count, no TRACE, no secret + res := runApp(t, env("DEBUG"), "audit", "1h") + if res.code != 0 || res.stdout != wantOut { + t.Fatalf("%+v", res) + } + for _, want := range []string{ + `level=DEBUG msg=dispatch mode=cli`, + `level=DEBUG msg="cli dispatch" command=audit window=1h0m0s`, + `level=DEBUG msg="database opened"`, + `level=DEBUG msg="audit window resolved" since=2026-10-05T11:00:00.123456789Z`, + `level=DEBUG msg="audit rows listed" rows=1`, + `level=DEBUG msg="cli command finished" command=audit ok=true`, + `level=DEBUG msg="database closed"`, + } { + if !strings.Contains(res.stderr, want) { + t.Errorf("DEBUG: missing %q in:\n%s", want, res.stderr) + } + } + if strings.Contains(res.stderr, "level=TRACE") || strings.Contains(res.stderr, secret) { + t.Fatalf("DEBUG output leaked trace or secret:\n%s", res.stderr) + } + res = runApp(t, env("DEBUG"), "audit") + if !strings.Contains(res.stderr, `level=DEBUG msg="cli dispatch" command=audit limit=10`) || + !strings.Contains(res.stderr, `level=DEBUG msg="audit rows listed" rows=2`) || strings.Contains(res.stderr, "window") { + t.Fatalf("DEBUG default:\n%s", res.stderr) + } + res = runApp(t, env("DEBUG"), "audit", "all") + wantAll := "" + + "TIME TOKEN ORIGIN OPERATION\n" + + "2026-10-05T10:00:00Z tok 192.0.2.8 GET containers\n" + + "2026-10-05T11:59:00Z " + secret + " 192.0.2.9 GET containers\n" + if res.code != 0 || res.stdout != wantAll || + !strings.Contains(res.stderr, `level=DEBUG msg="cli dispatch" command=audit all=true`+"\n") || + !strings.Contains(res.stderr, `level=DEBUG msg="audit rows listed" rows=2`) || + !strings.Contains(res.stderr, `level=DEBUG msg="cli command finished" command=audit ok=true`) || + strings.Contains(res.stderr, "limit=") || strings.Contains(res.stderr, "window") || + strings.Contains(res.stderr, "level=TRACE") || strings.Contains(res.stderr, secret) || strings.Contains(res.stderr, secret[:12]) { + t.Fatalf("DEBUG all: %+v", res) + } + + // TRACE: function path and every row read, token redacted to token_id + res = runApp(t, env("TRACE"), "audit", "1") + if res.code != 0 || res.stdout != wantOut { + t.Fatalf("%+v", res) + } + for _, want := range []string{ + `level=TRACE msg="function entry" func=app.execute`, + `level=TRACE msg="function entry" func=app.runAuditCommand`, + `level=TRACE msg="function entry" func=app.auditList`, + `level=TRACE msg="function entry" func=AuditStore.ListOperations`, + `level=TRACE msg="row read" table=operations rowid=1 token_id=` + tokenID(secret) + ` origin=192.0.2.9 operation="GET containers" time=2026-10-05T11:59:00Z`, + `level=TRACE msg="row read" table=operations rowid=2 token_id=` + tokenID("tok") + ` origin=192.0.2.8`, + `level=TRACE msg="function exit" func=AuditStore.ListOperations`, + `level=TRACE msg="function exit" func=app.runAuditCommand`, + `level=DEBUG msg="cli dispatch" command=audit limit=1`, + } { + if !strings.Contains(res.stderr, want) { + t.Errorf("TRACE: missing %q in:\n%s", want, res.stderr) + } + } + if strings.Contains(res.stderr, secret) || strings.Contains(res.stderr, secret[:12]) { + t.Fatalf("secret in trace output:\n%s", res.stderr) + } + + // Failures: the error is the last stderr line, still without the secret, stdout empty + mustExec(t, db, `INSERT INTO operations VALUES (?, '192.0.2.9', 'GET containers', 'bogus')`, secret) + for _, args := range [][]string{{"audit"}, {"audit", "all"}} { + res = runApp(t, env("TRACE"), args...) + if res.code != 1 || res.stdout != "" || strings.Contains(res.stderr, secret) || + !strings.Contains(res.stderr, `level=DEBUG msg="cli command finished" command=audit ok=false`) || + !strings.HasSuffix(res.stderr, "dpsapi: read operation row: parse stored timestamp: parsing time \"bogus\" as \"2006-01-02T15:04:05.999999999Z07:00\": cannot parse \"bogus\" as \"2006\"\n") { + t.Fatalf("%q: %+v", args, res) + } + } +} + +func TestCLIAuditAfterServerRequests(t *testing.T) { + t.Parallel() + path := testDBPath(t) + tok := strings.TrimSpace(cli(t, path, nil, nil, "token", "new", "auditor").stdout) + h := startServer(t, map[string]string{"DB_PATH": path}, nil) + for i := 0; i < 3; i++ { + if resp, _ := h.get("/api/v1/containers", bearer(tok)); resp.StatusCode != 200 { + t.Fatalf("status %d", resp.StatusCode) + } + } + h.get("/api/v1/containers", nil) // 401: not audited + h.get("/api/v1/containers", bearer(tok+"x")) // 401: not audited + + // The CLI reads the live database while the server is running, with the real clock + for _, args := range [][]string{{"audit"}, {"audit", "3"}, {"audit", "1h"}, {"audit", "all"}, {"audit", "2"}} { + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path}}, args...) + lines := strings.Split(strings.TrimSuffix(res.stdout, "\n"), "\n") + want := 4 + if args[len(args)-1] == "2" { + want = 3 + } + if res.code != 0 || res.stderr != "" || len(lines) != want || !slices.Equal(strings.Fields(lines[0]), auditListHeader) { + t.Fatalf("%q: %+v", args, res) + } + // The columns are aligned: the token starts where the TOKEN header starts, at the TIME width + at := strings.Index(lines[0], "TOKEN") + var prev time.Time + for _, line := range lines[1:] { + f := strings.Fields(line) + if len(f) != 5 || f[1] != tok || f[2] != "127.0.0.1" || f[3]+" "+f[4] != "GET containers" || + line[at:at+len(tok)] != tok || line[at-2:at] != " " || !strings.HasSuffix(line, " 127.0.0.1 GET containers") { + t.Fatalf("%q: line %q", args, line) + } + at, err := time.Parse(time.RFC3339Nano, f[0]) + if err != nil || at.Before(prev) || !strings.HasSuffix(f[0], "Z") { + t.Fatalf("%q: time %q (prev %v): %v", args, f[0], prev, err) + } + prev = at + } + } + h.cancel() + if code := h.wait(); code != 0 { + t.Fatalf("server exit %d", code) + } +} + +func TestFormatOperationRow(t *testing.T) { + t.Parallel() + op := Operation{RowID: 7, Token: "tok-full-value", Origin: "::1", Operation: operationGetContainers, + Time: time.Date(2026, 1, 1, 0, 0, 0, 500000000, time.UTC), TimeText: "2026-01-01T01:00:00.5+01:00"} + if got, want := formatOperationRow(op), []string{"2026-01-01T01:00:00.5+01:00", "tok-full-value", "::1", "GET containers"}; !slices.Equal(got, want) { + t.Fatalf("got %q\nwant %q", got, want) + } +} + +func TestCLIAuditPadded(t *testing.T) { + t.Parallel() + const long = "AbCdEfGhIjKlMnOpQrStUvWxYz0123456789-_AbCdE" + path := testDBPath(t) + db := seedAudit(t, path) + mustExec(t, db, `INSERT INTO tokens VALUES (?, '', 1, '2026-01-01T00:00:00Z', NULL)`, long) + for _, r := range [][3]string{ + {"tok", "10.0.0.1", "2026-10-05T11:00:00Z"}, + {"old", "2001:db8::1234:5678", "2026-10-05T12:00:00.123456789Z"}, + {long, "::1", "2026-10-05T13:00:00.5+01:00"}, + } { + mustExec(t, db, `INSERT INTO operations VALUES (?, ?, 'GET containers', ?)`, r[0], r[1], r[2]) + } + now := time.Date(2026, 10, 5, 12, 30, 0, 0, time.UTC) + + // No rows: the header cells padded by their own widths + expect(t, auditCLI(t, path, now, "1s"), 0, emptyAuditList, "") + + // One row: the times are printed as stored; OPERATION is the last column and contains a space + one := "" + + "TIME TOKEN ORIGIN OPERATION\n" + + "2026-10-05T13:00:00.5+01:00 " + long + " ::1 GET containers\n" + expect(t, auditCLI(t, path, now, "1"), 0, one, "") + + // Many rows: every column but the last is as wide as its widest cell plus 2 + many := "" + + "TIME TOKEN ORIGIN OPERATION\n" + + "2026-10-05T11:00:00Z tok 10.0.0.1 GET containers\n" + + "2026-10-05T12:00:00.123456789Z old 2001:db8::1234:5678 GET containers\n" + + "2026-10-05T13:00:00.5+01:00 " + long + " ::1 GET containers\n" + expect(t, auditCLI(t, path, now), 0, many, "") + expect(t, auditCLI(t, path, now, "3"), 0, many, "") + expect(t, auditCLI(t, path, now, "all"), 0, many, "") + + // Window selection: the widths follow the printed rows only + window := "" + + "TIME TOKEN ORIGIN OPERATION\n" + + "2026-10-05T12:00:00.123456789Z old 2001:db8::1234:5678 GET containers\n" + + "2026-10-05T13:00:00.5+01:00 " + long + " ::1 GET containers\n" + expect(t, auditCLI(t, path, now, "1h"), 0, window, "") + expect(t, auditCLI(t, path, now, "2"), 0, window, "") +} + +func TestWriteTable(t *testing.T) { + t.Parallel() + cases := []struct { + header []string + rows [][]string + want string + }{ + {[]string{"A"}, nil, "A\n"}, + {[]string{"A", "B"}, nil, "A B\n"}, + {[]string{"A", "B"}, [][]string{{"", ""}}, "A B\n \n"}, + {[]string{"LONG", "B", "C"}, [][]string{{"x", "yyyy", "last cell with spaces"}}, "LONG B C\nx yyyy last cell with spaces\n"}, + // Runes, not bytes and not display width + {[]string{"K", "V"}, [][]string{{"日本語", "1"}, {"é", "2"}, {"🚀🚀", "3"}}, "K V\n日本語 1\né 2\n🚀🚀 3\n"}, + } + for _, c := range cases { + var b strings.Builder + if err := writeTable(&b, c.header, c.rows); err != nil || b.String() != c.want { + t.Errorf("%q %q: got %q, %v; want %q", c.header, c.rows, b.String(), err, c.want) + } + if padTable(append([][]string{c.header}, c.rows...)...) != c.want { + t.Errorf("%q %q: padTable disagrees", c.header, c.rows) + } + } + if err := writeTable(failingWriter{}, auditListHeader, nil); err == nil || err.Error() != "write output: broken pipe" { + t.Fatalf("got %v", err) + } +} + +func TestUsageText(t *testing.T) { + t.Parallel() + const want = "usage:\n" + + " dpsapi start the HTTP server\n" + + " dpsapi help print this usage text\n" + + " dpsapi token list [all] list the active tokens, or every token with \"all\"\n" + + " dpsapi token new [description] create a token and print it\n" + + " dpsapi token delete deactivate a token\n" + + " dpsapi audit print the latest 10 audit rows\n" + + " dpsapi audit print the latest n audit rows\n" + + " dpsapi audit print the audit rows of the last n units (s, m, h, d, w)\n" + + " dpsapi audit all print every audit row\n" + if usageText != want { + t.Fatalf("usageText = %q", usageText) + } +} + +func TestCLIHelp(t *testing.T) { + t.Parallel() + const secret = "HelpSecret_0123456789abcdefghijklmnopqrstuv" + + // Default and quiet levels: usage text on stdout only, the database is never created + for _, level := range []string{"", "ERROR", "WARN", "INFO"} { + path := testDBPath(t) + env := map[string]string{"DB_PATH": path} + if level != "" { + env["LOG_LEVEL"] = level + } + res := runApp(t, cliEnv{env: env}, "help") + expect(t, res, 0, usageText, "") + if !strings.HasSuffix(res.stdout, "\n dpsapi audit all print every audit row\n") { + t.Fatalf("%q: help lacks audit all: %q", level, res.stdout) + } + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("%q: database created by help", level) + } + } + + // An existing database is not opened either: its rows never reach the output or the logs + path := testDBPath(t) + db := openTestDBAt(t, path) + mustExec(t, db, `INSERT INTO tokens VALUES (?, '', 1, '2026-01-01T00:00:00Z', NULL)`, secret) + expect(t, cli(t, path, nil, nil, "help"), 0, usageText, "") + + // DEBUG: dispatch records only + res := runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "DEBUG"}}, "help") + if res.code != 0 || res.stdout != usageText { + t.Fatalf("%+v", res) + } + dispatch := strings.Index(res.stderr, `level=DEBUG msg=dispatch mode=cli`+"\n") + command := strings.Index(res.stderr, `level=DEBUG msg="cli dispatch" command=help`+"\n") + if dispatch < 0 || command < dispatch || strings.Contains(res.stderr, "database") || strings.Contains(res.stderr, "level=TRACE") || + strings.Contains(res.stderr, secret) || strings.Contains(res.stderr, "token_id") || strings.Count(res.stderr, "\n") != 3 { + t.Fatalf("DEBUG:\n%s", res.stderr) + } + + // TRACE: function path, still no database and no token + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "TRACE"}}, "help") + for _, want := range []string{ + `level=TRACE msg="function entry" func=app.runHelpCommand`, + `level=TRACE msg="function exit" func=app.runHelpCommand`, + `level=DEBUG msg="cli dispatch" command=help`, + } { + if !strings.Contains(res.stderr, want) { + t.Errorf("TRACE: missing %q in:\n%s", want, res.stderr) + } + } + if res.code != 0 || res.stdout != usageText || strings.Contains(res.stderr, "database") || strings.Contains(res.stderr, secret) { + t.Fatalf("TRACE: %+v", res) + } + + // A usage error never logs the help dispatch + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path, "LOG_LEVEL": "DEBUG"}}, "help", secret) + if res.code != 2 || res.stdout != "" || strings.Contains(res.stderr, "command=help") || strings.Contains(res.stderr, secret) || + !strings.HasSuffix(res.stderr, "dpsapi: usage error: help takes no arguments\n"+usageText) { + t.Fatalf("help with argument: %+v", res) + } + + // Write failures are reported like every other command + res = runApp(t, cliEnv{env: map[string]string{"DB_PATH": path}, out: failingWriter{}}, "help") + expect(t, res, 1, "", "dpsapi: write output: broken pipe\n") + + // The process entry point + stdout, stderr := &syncBuffer{}, &syncBuffer{} + if code := run([]string{"help"}, envMap(map[string]string{"DB_PATH": path}), stdout, stderr); code != 0 || + stdout.String() != usageText || stderr.String() != "" { + t.Fatalf("run help: code=%d stdout=%q stderr=%q", code, stdout.String(), stderr.String()) + } +} diff --git a/e2e/tests/host/cli-audit.spec.ts b/e2e/tests/host/cli-audit.spec.ts new file mode 100644 index 0000000..199669f --- /dev/null +++ b/e2e/tests/host/cli-audit.spec.ts @@ -0,0 +1,733 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core item 17: `audit`, `audit all`, `audit ` and `audit ` through the + * compiled binary — header, exact rows and chronological order against the `operations` rows read + * directly from SQLite, the default of 10, every row with `all` (also more than 10, and ties on + * equal stored times in insertion order), counts larger than the row count, every unit, a real + * time window and its boundary band, operation while the server runs (also under concurrent load + * and across restarts), the read-only guarantee (byte-identical database), every usage-error class + * (including the near misses of `all`), configuration-error precedence, log levels, an + * unparseable stored time, and a population of 4000 rows produced by real authenticated requests. + * + * Rows only ever come from real authenticated GETs against FakeDocker. Only two scenarios write + * to the database themselves (server stopped, test-owned connection): the unparseable-time test + * and the equal-timestamps ordering test of `audit all`, which can only get identical stored + * times that way. + */ +import fs from 'node:fs'; +import { DatabaseSync } from 'node:sqlite'; +import { + test, + expect, + AUDIT_COLUMNS, + EMPTY_AUDIT, + LOG_LEVELS, + USAGE_TEXT, + assertDbInvariants, + buildRawRequest, + expectCliFailure, + expectCliSuccess, + expectContainersResponse, + fileDigest, + formatAuditOutput, + levelRank, + mapLimit, + msToNanos, + parseAuditOutput, + parseLogs, + parseTokenList, + padTable, + pollUntil, + printsTokens, + readOperations, + rfc3339ToNanos, + RFC3339NANO_UTC_RE, + tokenId, + visibleLevels, + type AuditRow, + type CliRunner, + type HttpClient, + type LogLevel, + type ServerHandle, +} from '../../harness'; +import { + AUDIT_ALL_EXTRA_ARGS, + AUDIT_ALL_NEAR_MISSES, + AUDIT_MAX_WINDOW, + AUDIT_UNITS, + auditArgsOutcome, + chronological, + expectAuditWindow, + expectedAuditStdout, + expectNoTokenFragments, + stateDigest, +} from '../../harness/personas'; + +const SECOND = AUDIT_UNITS.s; +const nowNs = (skewMs = 0) => msToNanos(Date.now() + skewMs); + +/** One authenticated GET per token in `plan`, sequentially (Playwright request); all must be 200. */ +async function sequential(http: HttpClient, server: ServerHandle, plan: string[]): Promise { + for (const t of plan) expectContainersResponse(await http.get(server.url(), { token: t })); +} + +/** + * Real authenticated GETs pipelined over keep-alive connections (`perConn` requests each, + * `concurrency` connections at a time) — a fast way to produce thousands of audit rows. + */ +async function pipelined(http: HttpClient, server: ServerHandle, plan: string[], { perConn = 50, concurrency = 8 } = {}): Promise { + const chunks: string[][] = []; + for (let i = 0; i < plan.length; i += perConn) chunks.push(plan.slice(i, i + perConn)); + await mapLimit(chunks, concurrency, async (chunk, ci) => { + const data = chunk.map((t, i) => buildRawRequest({ target: '/api/v1/containers', headers: [['Authorization', `Bearer ${t}`]], close: i === chunk.length - 1 })).join(''); + const r = await http.raw({ host: server.connectHost, port: server.port, data, expectResponses: chunk.length, timeoutMs: 30_000 }); + expect(r.responses.map((x) => x.status), `pipelined connection ${ci}: every request answered 200`).toEqual(chunk.map(() => 200)); + }); +} + +/** + * `audit ...args` against `dbPath`: exit 0, empty stderr, strictly parseable stdout that equals + * the oracle's selection over the stored rows byte for byte (windows: no stored row may lie in + * the boundary band, so the expectation is exact). No writer may run concurrently. + */ +async function expectAudit(cli: CliRunner, dbPath: string, args: string[], label = `audit ${JSON.stringify(args)}`): Promise { + const parsed = auditArgsOutcome(args); + if (!parsed.ok) throw new Error(`${label}: not a valid audit argument list`); + const t0 = nowNs(-1); + const r = await cli.run(['audit', ...args], { env: { DB_PATH: dbPath } }); + const t1 = nowNs(1); + expectCliSuccess(r, { stderr: '' }); + const rows = parseAuditOutput(r.stdout); + const ops = readOperations(dbPath); + const sel = parsed.selection; + if ('windowNs' in sel) expect(expectAuditWindow(rows, ops, sel.windowNs, t0, t1, label), `${label}: no stored row near the window boundary`).toBe(0); + else expect(r.stdout, `${label}: stdout equals the stored rows`).toBe(expectedAuditStdout(ops, sel)); + return rows; +} + +test.describe('audit selection forms', () => { + test('fresh database: header only for every form; the database and the empty schema are created, as by the token commands', async ({ cli, ws }) => { + const forms = [[], ['all'], ['1'], ['10'], ['9223372036854775807'], ['1s'], ['1m'], ['1h'], ['1d'], ['1w'], ['15250w']]; + await mapLimit(forms, 5, async (args, i) => { + const db = ws.path(`fresh-${i}.db`); + expect(fs.existsSync(db)).toBe(false); + const r = await cli.run(['audit', ...args], { env: { DB_PATH: db } }); + expectCliSuccess(r, { stdout: EMPTY_AUDIT, stderr: '' }); + expect(fs.existsSync(db), `audit ${args.join(' ')}: database created`).toBe(true); + assertDbInvariants(db, { tokenCount: 0, operationCount: 0 }); + }); + // tokens but no operations yet: still only the header + await cli.tokenNew('no requests yet'); + for (const args of forms) expectCliSuccess(await cli.run(['audit', ...args]), { stdout: EMPTY_AUDIT, stderr: '' }); + assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 0 }); + }); + + test('default 10 and explicit counts with fewer than, exactly and more than 10 rows: exact rows and order from SQLite (server running)', async ({ cli, ws, startServer, http }) => { + const [a, b, c] = [await cli.tokenNew('a'), await cli.tokenNew('b'), await cli.tokenNew('c')]; + const server = await startServer(); + const plan: string[] = []; + const add = async (tokens: string[]) => { + await sequential(http, server, tokens); + plan.push(...tokens); + expect(readOperations(ws.dbPath).map((o) => o.token), 'one row per request, in order').toEqual(plan); + }; + + await test.step('3 rows (fewer than 10)', async () => { + await add([a, b, c]); + expect(await expectAudit(cli, ws.dbPath, [])).toHaveLength(3); + for (const n of ['1', '2', '3', '4', '10']) await expectAudit(cli, ws.dbPath, [n]); + }); + await test.step('exactly 10 rows', async () => { + await add([a, a, b, c, c, a, b]); + const rows = await expectAudit(cli, ws.dbPath, []); + expect(rows.map((r) => r.token)).toEqual(plan); + for (const n of ['9', '10', '11']) await expectAudit(cli, ws.dbPath, [n]); + }); + await test.step('25 rows (more than 10)', async () => { + await add([c, b, a, a, a, c, b, b, c, a, b, c, a, c, b]); + const rows = await expectAudit(cli, ws.dbPath, []); + expect(rows.map((r) => r.token), 'the latest 10, oldest first').toEqual(plan.slice(-10)); + for (const n of ['1', '24', '25', '26', '1000', '010', '0000000000000000000000000000025', '9223372036854775807', '00009223372036854775807']) { + await expectAudit(cli, ws.dbPath, [n]); + } + const all = await expectAudit(cli, ws.dbPath, ['1000']); + expect(all.map((r) => r.token)).toEqual(plan); + expect(all.every((r) => r.origin === '127.0.0.1' && r.operation === 'GET containers')).toBe(true); + }); + expect((await server.stop()).exitCode).toBe(0); + assertDbInvariants(ws.dbPath, { tokenCount: 3, operationCount: 25 }); + }); + + test('every unit s/m/h/d/w, leading zeros and the largest window per unit select every recent row', async ({ cli, ws, startServer, http }) => { + const t = await cli.tokenNew('units'); + const server = await startServer(); + await sequential(http, server, [t, t, t, t, t, t]); + const forms = ['120s', '3600s', '2m', '60m', '1h', '01h', '0001d', '1d', '1w', '00001w']; + for (const u of Object.keys(AUDIT_MAX_WINDOW) as Array) forms.push(`${AUDIT_MAX_WINDOW[u]}${u}`); + for (const f of forms) expect(await expectAudit(cli, ws.dbPath, [f]), f).toHaveLength(6); + expect((await server.stop()).exitCode).toBe(0); + for (const f of ['1h', '15250w']) expect(await expectAudit(cli, ws.dbPath, [f]), `${f} after the server stopped`).toHaveLength(6); + }); + + test('real time window: after a 2 s gap `audit 2s` prints exactly the later rows; every window is a chronological suffix with no row on the wrong side of its boundary band', async ({ cli, ws, startServer, http }) => { + const [early, late] = [await cli.tokenNew('early'), await cli.tokenNew('late')]; + const server = await startServer(); + await sequential(http, server, [early, early, early, early]); + const lastEarly = rfc3339ToNanos(chronological(readOperations(ws.dbPath)).at(-1)!.time); + // poll the clock until the early rows are more than 2 s old (no fixed sleep) + await pollUntil('the early rows to be older than 2 s', () => (nowNs(-30) > lastEarly + 2n * SECOND ? true : undefined), { timeoutMs: 10_000, intervalMs: 10 }); + await sequential(http, server, [late, late, late]); + + const t0 = nowNs(-1); + const r = await cli.run(['audit', '2s']); + const t1 = nowNs(1); + expectCliSuccess(r, { stderr: '' }); + const ops = readOperations(ws.dbPath); + const rows = parseAuditOutput(r.stdout); + expect(expectAuditWindow(rows, ops, 2n * SECOND, t0, t1, 'audit 2s'), 'no stored row inside the boundary band').toBe(0); + expect(r.stdout, 'exactly the rows written after the gap').toBe(formatAuditOutput(ops.slice(4))); + expect(rows.map((x) => x.token)).toEqual([late, late, late]); + + // boundary sanity for a range of windows: each output is a chronological suffix, every row at or + // after now - window is printed and none before; the selections are nested + let previous = -1; + for (const w of ['1s', '2s', '3s', '5s', '30s', '1m', '1h']) { + const s0 = nowNs(-1); + const x = await cli.run(['audit', w]); + const s1 = nowNs(1); + expectCliSuccess(x, { stderr: '' }); + const xs = parseAuditOutput(x.stdout); + const sel = auditArgsOutcome([w]); + if (!sel.ok || !('windowNs' in sel.selection)) throw new Error('window expected'); + expectAuditWindow(xs, ops, sel.selection.windowNs, s0, s1, `audit ${w}`); + expect(xs.length >= previous, `audit ${w} includes the rows of the smaller windows`).toBe(true); + previous = xs.length; + } + expect(previous, 'audit 1h: every row').toBe(7); + expect((await server.stop()).exitCode).toBe(0); + }); +}); + +test.describe('audit all', () => { + test('empty database: `audit all` prints exactly the padded header, exit 0, empty stderr (fresh file and tokens without requests)', async ({ cli, ws }) => { + expect(EMPTY_AUDIT, 'the header-only table').toBe(padTable([AUDIT_COLUMNS])); + expect(EMPTY_AUDIT).toBe('TIME TOKEN ORIGIN OPERATION\n'); + const r = await cli.run(['audit', 'all']); + expectCliSuccess(r, { stdout: EMPTY_AUDIT, stderr: '' }); + assertDbInvariants(ws.dbPath, { tokenCount: 0, operationCount: 0 }); + await cli.tokenNew('never used'); + await cli.tokenDelete(await cli.tokenNew('deleted, never used')); + expect(await cli.audit('all')).toEqual([]); + expectCliSuccess(await cli.run(['audit', 'all']), { stdout: EMPTY_AUDIT, stderr: '' }); + assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 0 }); + }); + + test('every row, oldest first, as the exact padded table with 1, exactly 10, 11 and 25 rows (more than the default 10); tokens printed are registered secrets', async ({ cli, ws, startServer, http, secrets }) => { + expect(printsTokens(['audit', 'all']), 'audit all stdout is scanned for tokens').toBe(true); + const [a, b, c] = [await cli.tokenNew('all a'), await cli.tokenNew('all b'), await cli.tokenNew('all c')]; + const server = await startServer(); + const plan: string[] = []; + for (const batch of [[a], [b, c, a, a, b, c, c, b, a], [c], [a, b, c, a, b, c, a, b, c, a, b, c, a, b]]) { + await sequential(http, server, batch); + plan.push(...batch); + await test.step(`${plan.length} rows`, async () => { + const ops = readOperations(ws.dbPath); + expect(ops.map((o) => o.token), 'one row per request, in order').toEqual(plan); + const r = await cli.run(['audit', 'all']); + expectCliSuccess(r, { stderr: '' }); + // exact stdout: the padded table of every stored row, oldest first + const expected = padTable([[...AUDIT_COLUMNS], ...chronological(ops).map((o) => [o.time, o.token, o.origin, o.operation])]); + expect(r.stdout, 'stdout is the padded table of every stored row').toBe(expected); + expect(r.stdout, 'the oracle agrees').toBe(expectedAuditStdout(ops, { all: true })); + const rows = parseAuditOutput(r.stdout); + expect(rows.map((x) => x.token), 'every row, oldest first').toEqual(plan); + expect(rows.map((x) => x.time), 'TIME exactly as stored').toEqual(ops.map((o) => o.time)); + const times = rows.map((x) => rfc3339ToNanos(x.time)); + expect(times.every((t, k) => k === 0 || times[k - 1] <= t), 'chronological').toBe(true); + // the same bytes as a count that covers every row; the default still stops at 10 + expectCliSuccess(await cli.run(['audit', String(plan.length)]), { stdout: r.stdout, stderr: '' }); + expect((await cli.audit()).map((x) => x.token), 'plain audit: the latest 10').toEqual(plan.slice(-10)); + }); + } + expect(plan).toHaveLength(25); + for (const t of [a, b, c]) expect(secrets.has(t)).toBe(true); + expect((await server.stop()).exitCode).toBe(0); + expect(formatAuditOutput(await cli.audit('all')), 'with the server stopped').toBe(expectedAuditStdout(readOperations(ws.dbPath), { all: true })); + assertDbInvariants(ws.dbPath, { tokenCount: 3, operationCount: 25 }); + }); + + test('equal stored times are printed in insertion order (rowid), after the earlier times — also for rows inserted later with an earlier time', async ({ cli, ws, startServer, http }) => { + const [a, b] = [await cli.tokenNew('ties a'), await cli.tokenNew('ties b')]; + const server = await startServer(); + await sequential(http, server, [a, a, b, b, a, b]); + // no server may use the database while the test writes to it + expect((await server.stop()).exitCode).toBe(0); + const ops = readOperations(ws.dbPath); + expect(ops).toHaveLength(6); + const [r0, r1, r2, r3, r4, r5] = ops; + + // Test-owned write (the only way to get identical stored times): r1, r4, r5 share the latest + // time, r3 the earliest one (tie with r0, inserted later). Every new value is an existing, + // valid stored time after the tokens' created_at, so the database invariants still hold. + const assign: Array<[number, string]> = [ + [r1.rowid, r5.time], + [r3.rowid, r0.time], + [r4.rowid, r5.time], + ]; + const db = new DatabaseSync(ws.dbPath, { timeout: 5000 }); + try { + for (const [rowid, time] of assign) expect(Number(db.prepare('UPDATE operations SET time = ? WHERE rowid = ?').run(time, rowid).changes)).toBe(1); + } finally { + db.close(); + } + assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 6 }); + const tied = readOperations(ws.dbPath); + const byRowid = new Map(tied.map((o) => [o.rowid, o])); + const order = [r0, r3, r2, r1, r4, r5].map((o) => byRowid.get(o.rowid)!); + expect(chronological(tied).map((o) => o.rowid), 'the oracle orders by time, then rowid').toEqual(order.map((o) => o.rowid)); + + const r = await cli.run(['audit', 'all']); + expectCliSuccess(r, { stderr: '' }); + expect(r.stdout, 'time, then insertion order').toBe(formatAuditOutput(order)); + expect(r.stdout).toBe(expectedAuditStdout(tied, { all: true })); + expect(parseAuditOutput(r.stdout).map((x) => x.token)).toEqual([a, b, b, a, a, b]); + // the other forms agree with the same order + expectCliSuccess(await cli.run(['audit', '100']), { stdout: r.stdout, stderr: '' }); + expectCliSuccess(await cli.run(['audit', '3']), { stdout: formatAuditOutput(order.slice(-3)), stderr: '' }); + // stable across invocations + for (let i = 0; i < 3; i++) expectCliSuccess(await cli.run(['audit', 'all']), { stdout: r.stdout, stderr: '' }); + }); + + test('near misses of `all` (case, digits, blanks, options, extra arguments): exact usage error, nothing echoed, no database created, an existing one untouched', async ({ cli, ws }) => { + const cases: Array<[string[], string]> = [ + ...[...new Set(['ALL', 'All', 'all1', '1all', ' all', 'alls', '--all', ...AUDIT_ALL_NEAR_MISSES.map(([v]) => v)])].map((v): [string[], string] => [[v], INVALID]), + ...AUDIT_ALL_EXTRA_ARGS.map((args): [string[], string] => [[...args], TOO_MANY]), + ]; + expect(cases.map(([a]) => JSON.stringify(a)), 'the required near misses are covered').toEqual(expect.arrayContaining(['["ALL"]', '["All"]', '["all1"]', '["1all"]', '[" all"]', '["alls"]', '["--all"]', '["all","x"]'])); + for (const [args, msg] of cases) expect(auditArgsOutcome(args), JSON.stringify(args)).toEqual({ ok: false, message: msg }); + const run = () => + mapLimit(cases, 8, async ([args, msg]) => { + const r = await cli.run(['audit', ...args]); + expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); + expect(r.stderr, `${JSON.stringify(args)}: exact stderr, the argument is never echoed`).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); + }); + await run(); + expect(fs.readdirSync(ws.dir), 'no database created').toEqual([]); + await cli.tokenNew('existing'); + const file = fileDigest(ws.dbPath); + const state = stateDigest(ws.dbPath); + await run(); + expect(fileDigest(ws.dbPath)).toBe(file); + expect(stateDigest(ws.dbPath)).toBe(state); + }); +}); + +test.describe('audit against live and changing state', () => { + test('output equals the operations rows in SQLite (exact time, full token, origin, operation, order) across concurrent writers, token deletion and server restarts', async ({ cli, ws, startServer, http }) => { + const tokens = await Promise.all(['ci', 'ops', 'dash', 'backup'].map((d) => cli.tokenNew(d))); + const server = await startServer(); + // concurrent writers: interleaved times, variable-length fractions (trailing zeros dropped) + await mapLimit(Array.from({ length: 40 }, (_, i) => tokens[i % 4]), 8, async (t, i) => { + expectContainersResponse(i % 5 === 0 ? await http.curl({ url: server.url(), token: t }) : await http.get(server.url(), { token: t })); + }); + const check = async (label: string, expected: number) => { + const all = await expectAudit(cli, ws.dbPath, ['100000'], `${label}: audit 100000`); + expect(all, label).toHaveLength(expected); + expect(await expectAudit(cli, ws.dbPath, ['all'], `${label}: audit all`), `${label}: audit all = audit 100000`).toEqual(all); + await expectAudit(cli, ws.dbPath, [], `${label}: audit`); + await expectAudit(cli, ws.dbPath, ['7'], `${label}: audit 7`); + await expectAudit(cli, ws.dbPath, ['1h'], `${label}: audit 1h`); + // every printed token is a full token known to `token list all` (active or not) + const listed = new Set((await cli.tokenListAll()).map((r) => r.token)); + expect(all.every((r) => listed.has(r.token)), `${label}: tokens correlate with token list all`).toBe(true); + return all; + }; + const first = await check('after 40 concurrent requests', 40); + // lexical and chronological order differ whenever a fraction lost trailing zeros: informative only + const lexicalInversions = first.filter((r, i) => i > 0 && first[i - 1].time > r.time).length; + test.info().annotations.push({ type: 'audit ordering', description: `${lexicalInversions} adjacent row pair(s) whose TIME text sorts differently from the instant` }); + + await test.step('deleted tokens keep their rows, printed with the full token', async () => { + await cli.tokenDelete(tokens[1]); + await cli.tokenDelete(tokens[2]); + const all = await check('after deleting two tokens', 40); + expect(all.filter((r) => r.token === tokens[1])).toHaveLength(10); + expect(all.filter((r) => r.token === tokens[2])).toHaveLength(10); + }); + await test.step('across a restart', async () => { + await server.restart(); + await check('after a restart', 40); + await sequential(http, server, [tokens[0], tokens[3], tokens[0]]); + const all = await check('after requests on the new generation', 43); + expect(all.slice(0, 40)).toEqual(first); + expect(all.slice(40).map((r) => r.token)).toEqual([tokens[0], tokens[3], tokens[0]]); + }); + expect((await server.stop()).exitCode).toBe(0); + await check('with the server stopped', 43); + assertDbInvariants(ws.dbPath, { tokenCount: 4, operationCount: 43 }); + }); + + test('while the server is under concurrent load: every output is a complete table and a consistent snapshot of the history', async ({ cli, ws, startServer, http }) => { + test.setTimeout(90_000); + const tokens = await Promise.all([1, 2, 3, 4].map((i) => cli.tokenNew(`load ${i}`))); + const server = await startServer(); + const PER_TOKEN = 60; + let started = 0; + let completed = 0; + let failed = false; + const writer = async (t: string) => { + try { + for (let i = 0; i < PER_TOKEN; i++) { + started++; + expectContainersResponse(await http.get(server.url(), { token: t })); + completed++; + } + } catch (e) { + failed = true; // stop the reader too: a failed writer must not turn into a hang + throw e; + } + }; + const forms = [['1000000'], [], ['all'], ['1h'], ['01d'], ['5']]; + const snaps: Array<{ args: string[]; stdout: string; before: number; after: number }> = []; + const reader = async () => { + for (let k = 0; !failed && completed < tokens.length * PER_TOKEN; k++) { + const args = forms[k % forms.length]; + const before = completed; + const r = await cli.run(['audit', ...args]); + expectCliSuccess(r, { stderr: '' }); + snaps.push({ args, stdout: r.stdout, before, after: started }); + } + }; + await Promise.all([...tokens.map(writer), reader()]); + expect(snaps.length, 'audit ran repeatedly during the load').toBeGreaterThan(10); + + const final = chronological(readOperations(ws.dbPath)); + expect(final).toHaveLength(tokens.length * PER_TOKEN); + // compared by cells: the padding of a line depends on the widest cells of that invocation + const cells = (r: { time: string; token: string; origin: string; operation: string }) => [r.time, r.token, r.origin, r.operation].join('\t'); + const finalLines = final.map(cells); + const isSubsequence = (lines: string[]) => { + let j = 0; + for (const l of lines) { + while (j < finalLines.length && finalLines[j] !== l) j++; + if (j++ >= finalLines.length) return false; + } + return true; + }; + for (const [i, s] of snaps.entries()) { + const label = `snapshot ${i} (audit ${s.args.join(' ')}, ${s.before} rows committed before it started, ${s.after} requests started before it ended)`; + const rows = parseAuditOutput(s.stdout); // strict: a torn line or header fails here + const times = rows.map((r) => rfc3339ToNanos(r.time)); + expect(times.every((t, k) => k === 0 || times[k - 1] <= t), `${label}: chronological`).toBe(true); + expect(isSubsequence(rows.map(cells)), `${label}: every row is a stored row, in the final relative order`).toBe(true); + expect(s.stdout, `${label}: padded table of its own rows`).toBe(formatAuditOutput(rows)); + const limit = s.args[0] === '5' ? 5 : s.args.length === 0 ? 10 : Infinity; + expect(rows.length, `${label}: lower bound`).toBeGreaterThanOrEqual(Math.min(limit, s.before)); + expect(rows.length, `${label}: upper bound`).toBeLessThanOrEqual(Math.min(limit, s.after)); + } + await expectAudit(cli, ws.dbPath, ['1000000'], 'after the load'); + expect((await server.stop()).exitCode).toBe(0); + assertDbInvariants(ws.dbPath, { tokenCount: 4, operationCount: tokens.length * PER_TOKEN }); + }); + + test('read-only: database file and WAL byte-identical, logical state unchanged and no audit row created, for every form at every log level', async ({ cli, ws, startServer, http }) => { + const t = await cli.tokenNew('read-only'); + const dead = await cli.tokenNew('deleted'); + const server = await startServer(); + await sequential(http, server, [t, dead, t, dead, t]); + await cli.tokenDelete(dead); + const wal = `${ws.dbPath}-wal`; + const before = { db: fileDigest(ws.dbPath), wal: fileDigest(wal), state: stateDigest(ws.dbPath), ops: readOperations(ws.dbPath) }; + expect(before.wal, 'the running server keeps a WAL file').toBeDefined(); + for (const level of LOG_LEVELS) { + for (const args of [[], ['all'], ['3'], ['1000'], ['1h'], ['1w']]) { + const r = await cli.run(['audit', ...args], { env: { LOG_LEVEL: level } }); + expectCliSuccess(r); + const label = `audit ${args.join(' ')} at ${level}`; + expect(fileDigest(ws.dbPath), `${label}: database file bytes`).toBe(before.db); + expect(fileDigest(wal), `${label}: WAL bytes`).toBe(before.wal); + expect(stateDigest(ws.dbPath), `${label}: logical state`).toBe(before.state); + } + } + expect(readOperations(ws.dbPath), 'running audit created no audit row').toEqual(before.ops); + expect(server.logs().requests(), 'audit never talks to the server').toHaveLength(5); + expect((await server.stop()).exitCode).toBe(0); + + // closed database (no server): still nothing written + const closed = { db: fileDigest(ws.dbPath), state: stateDigest(ws.dbPath) }; + for (const args of [[], ['all'], ['2'], ['1d']]) { + expectCliSuccess(await cli.run(['audit', ...args]), { stderr: '' }); + expect(fileDigest(ws.dbPath), `audit ${args.join(' ')} on a closed database: file bytes`).toBe(closed.db); + expect(stateDigest(ws.dbPath)).toBe(closed.state); + } + assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 5 }); + }); +}); + +const INVALID = 'invalid audit argument'; +const TOO_MANY = 'audit takes at most one argument'; +const invalid = (...values: string[]): Array<[string[], string]> => values.map((v) => [[v], INVALID]); + +/** Every class of invalid `audit` argument (README "audit", PLAN §3). */ +const USAGE_ERRORS: Array<[string[], string]> = [ + // more than one argument + [['10', 'h'], TOO_MANY], + [['1', '2'], TOO_MANY], + [['10', 'hours'], TOO_MANY], + [['', ''], TOO_MANY], + [['1h', '--json'], TOO_MANY], + [['1', '2', '3'], TOO_MANY], + // zero in any form + ...invalid('0', '000', '0s', '0m', '00h', '0d', '0000w'), + // signs + ...invalid('-5', '+5', '-0', '-1h', '+1h', '−5'), + // whitespace + ...invalid(' 5', '5 ', '5\n', '\t5', '5 h', '1 0', ' ', '5 ', '　5', '5h\r'), + // empty argument + ...invalid(''), + // uppercase and unknown units + ...invalid('5S', '5M', '5H', '5D', '5W', '5y', '5ms', '5us', '5µs', '5ns', '5sec', '30min', '1hour', '5x', '5ss', '5hh', '5ѕ', '5ｓ'), + // unit without digits + ...invalid('s', 'm', 'h', 'd', 'w', 'hh'), + // other number syntaxes + ...invalid('1.5', '1.5h', '1e3', '0x10', '0b1', '1_000', '1,000', '½', '１０', '٣', 'ten', 'NaN', 'Infinity', '1h30m', 's5', '5d5'), + // count overflowing int64, window overflowing time.Duration + ...invalid('9223372036854775808', '18446744073709551616', '99999999999999999999999999', '9223372037s', '153722868m', '2562048h', '106752d', '15251w', '99999999999999999999w'), + // looks like an option + ...invalid('--help', '-n', '--tail=10'), + // near misses of `all` (exact, lowercase only) and `all` with extra arguments + ...invalid(...new Set(['ALL', 'All', 'all1', '1all', ' all', 'alls', '--all', ...AUDIT_ALL_NEAR_MISSES.map(([v]) => v)])), + ...AUDIT_ALL_EXTRA_ARGS.map((args): [string[], string] => [[...args], TOO_MANY]), +]; + +test.describe('audit usage and configuration errors', () => { + test(`${USAGE_ERRORS.length} invalid argument lists → exit 2, exact error line + usage text, nothing echoed, no database created / existing one untouched`, async ({ cli, ws, startServer, http }) => { + // the oracle agrees with the table (and the table with the README) + for (const [args, msg] of USAGE_ERRORS) expect(auditArgsOutcome(args), JSON.stringify(args)).toEqual({ ok: false, message: msg }); + const run = async (dbPath: string) => + mapLimit(USAGE_ERRORS, 8, async ([args, msg]) => { + const r = await cli.run(['audit', ...args], { env: { DB_PATH: dbPath } }); + expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); + // exact stderr: the argument is never echoed + expect(r.stderr, JSON.stringify(args)).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); + }); + + await test.step('fresh workspace: the database is never created', async () => { + const never = ws.path('never.db'); + await run(never); + expect(fs.readdirSync(ws.dir), 'nothing written to the workspace').toEqual([]); + }); + await test.step('existing database with audit rows: byte-identical afterwards', async () => { + const t = await cli.tokenNew('existing'); + const server = await startServer(); + await sequential(http, server, [t, t, t]); + expect((await server.stop()).exitCode).toBe(0); + const file = fileDigest(ws.dbPath); + const state = stateDigest(ws.dbPath); + await run(ws.dbPath); + expect(fileDigest(ws.dbPath)).toBe(file); + expect(stateDigest(ws.dbPath)).toBe(state); + expect(await expectAudit(cli, ws.dbPath, [])).toHaveLength(3); + }); + }); + + test('the largest accepted count and windows are valid (exit 0)', async ({ cli, ws }) => { + const edges = ['9223372036854775807', '00009223372036854775807', '9223372036s', '153722867m', '2562047h', '106751d', '15250w', '1s', '01h', '010', '1']; + for (const e of edges) expect(auditArgsOutcome([e]).ok, e).toBe(true); + await mapLimit(edges, 4, async (e) => expectCliSuccess(await cli.run(['audit', e]), { stdout: EMPTY_AUDIT, stderr: '' })); + assertDbInvariants(ws.dbPath, { tokenCount: 0, operationCount: 0 }); + }); + + test('configuration errors take precedence over audit usage errors (no usage text, no database)', async ({ cli, ws }) => { + const cases: Array<[Record, string[], string]> = [ + [{ DB_PATH: undefined }, ['0'], 'configuration error: DB_PATH is required'], + [{ DB_PATH: '' }, ['1', 'h'], 'configuration error: DB_PATH must not be empty'], + [{ HTTP_ADDR: 'localhost' }, ['-1'], 'configuration error: invalid HTTP_ADDR "localhost": must be an IPv4 or IPv6 address'], + [{ HTTP_PORT: '0' }, ['1H'], 'configuration error: invalid HTTP_PORT "0": must be an integer between 1 and 65535'], + [{ LOG_LEVEL: 'verbose' }, ['10', 'hours'], 'configuration error: invalid LOG_LEVEL "verbose": must be one of ERROR, WARN, INFO, DEBUG, TRACE'], + // a valid audit invocation is rejected the same way: CLI mode validates every variable + [{ HTTP_PORT: '70000' }, [], 'configuration error: invalid HTTP_PORT "70000": must be an integer between 1 and 65535'], + [{ LOG_LEVEL: '' }, ['1h'], 'configuration error: LOG_LEVEL must not be empty'], + ]; + for (const [env, args, message] of cases) { + const r = await cli.run(['audit', ...args], { env }); + expectCliFailure(r, { exitCode: 2, message, usage: false }); + } + expect(fs.existsSync(ws.dbPath)).toBe(false); + expect(fs.readdirSync(ws.dir)).toEqual([]); + }); +}); + +test('log levels: stdout byte-identical at every level, stderr carries exactly the records the level allows, never a token (only token_id)', async ({ cli, ws, startServer, http, secrets }) => { + const a = await cli.tokenNew('log a'); + const b = await cli.tokenNew('log b'); + const server = await startServer(); + await sequential(http, server, [a, b, a, b, a, a]); + expect((await server.stop()).exitCode).toBe(0); + await cli.tokenDelete(b); + const ops = readOperations(ws.dbPath); + const FUNCS = ['app.execute', 'app.runAuditCommand', 'OpenDatabase', 'InitializeSchema', 'app.auditList', 'AuditStore.ListOperations']; + const forms: Array<{ args: string[]; dispatch: Record; rows: number }> = [ + { args: [], dispatch: { command: 'audit', limit: '10' }, rows: 6 }, + { args: ['3'], dispatch: { command: 'audit', limit: '3' }, rows: 3 }, + { args: ['all'], dispatch: { command: 'audit', all: 'true' }, rows: 6 }, + { args: ['2h'], dispatch: { command: 'audit', window: '2h0m0s' }, rows: 6 }, + { args: ['0090m'], dispatch: { command: 'audit', window: '1h30m0s' }, rows: 6 }, + ]; + for (const f of forms) { + const baseline = await cli.run(['audit', ...f.args]); + expectCliSuccess(baseline, { stderr: '' }); + expect(parseAuditOutput(baseline.stdout)).toHaveLength(f.rows); + expect(baseline.stdout.includes(a) && baseline.stdout.includes(b), 'stdout carries the full tokens').toBe(true); + for (const level of LOG_LEVELS) { + await test.step(`audit ${f.args.join(' ')} at ${level}`, async () => { + const t0 = nowNs(-1); + const r = await cli.run(['audit', ...f.args], { env: { LOG_LEVEL: level } }); + const t1 = nowNs(1); + expectCliSuccess(r); + expect(r.stdout, 'stdout identical at every level').toBe(baseline.stdout); + // no token, nor any 12-character fragment of one, in stderr — although stdout has them + expect(r.stderr.includes(a) || r.stderr.includes(b)).toBe(false); + expectNoTokenFragments(r.stderr, secrets, `stderr at ${level}`); + const logs = parseLogs(r.stderr); + expect(logs.unparsed, 'stderr consists of slog records only').toEqual([]); + const allowed = visibleLevels(level as LogLevel); + expect(logs.records.filter((x) => !allowed.includes(x.level as LogLevel)).map((x) => x.raw)).toEqual([]); + if (levelRank(level) >= levelRank('INFO')) expect(r.stderr, 'successful CLI commands are silent at INFO and above').toBe(''); + + if (levelRank(level) <= levelRank('DEBUG')) { + expect(logs.find({ msg: 'configuration resolved' })!.attrs.log_level).toBe(level); + expect(logs.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' }); + expect(logs.filter({ msg: 'cli dispatch' }).map((x) => x.attrs)).toEqual([f.dispatch]); + expect(logs.filter({ msg: 'audit rows listed' }).map((x) => x.attrs)).toEqual([{ rows: String(f.rows) }]); + expect(logs.filter({ msg: 'cli command finished' }).map((x) => x.attrs)).toEqual([{ command: 'audit', ok: 'true' }]); + for (const m of ['database schema initialized', 'database opened', 'database closed']) expect(logs.count({ level: 'DEBUG', msg: m }), m).toBe(1); + const resolved = logs.filter({ msg: 'audit window resolved' }); + if ('window' in f.dispatch) { + expect(resolved).toHaveLength(1); + const since = resolved[0].attrs.since; + expect(since).toMatch(RFC3339NANO_UTC_RE); + const w = auditArgsOutcome(f.args); + const windowNs = w.ok && 'windowNs' in w.selection ? w.selection.windowNs : 0n; + expect(rfc3339ToNanos(since) >= t0 - windowNs && rfc3339ToNanos(since) <= t1 - windowNs, `since=${since} is now - window`).toBe(true); + } else expect(resolved, 'no window resolved for a count').toEqual([]); + } else expect(logs.count({ level: 'DEBUG' })).toBe(0); + + if (level === 'TRACE') { + for (const fn of FUNCS) { + expect(logs.count({ msg: 'function entry', attrs: { func: fn } }), `entry ${fn}`).toBe(1); + expect(logs.count({ msg: 'function exit', attrs: { func: fn } }), `exit ${fn}`).toBe(1); + } + // one `row read` per stored row (also outside the selection), token redacted to token_id + const reads = logs.filter({ level: 'TRACE', msg: 'row read', attrs: { table: 'operations' } }); + expect(reads.map((x) => x.attrs)).toEqual(ops.map((o) => ({ table: 'operations', rowid: String(o.rowid), token_id: tokenId(o.token), origin: o.origin, operation: o.operation, time: o.time }))); + expect(logs.records.some((x) => 'token' in x.attrs), 'no record has a token attribute').toBe(false); + } else expect(logs.count({ level: 'TRACE' })).toBe(0); + }); + } + } +}); + +test('an unparseable stored time fails every form with exit 1 and nothing on stdout; restoring the row restores the output', async ({ cli, ws, startServer, http, secrets }) => { + const t = await cli.tokenNew('corrupt'); + const server = await startServer(); + await sequential(http, server, [t, t, t]); + // no server may use the database while the test writes to it + expect((await server.stop()).exitCode).toBe(0); + const ops = readOperations(ws.dbPath); + const good = formatAuditOutput(ops); + const victim = ops[1]; + + // Test-owned write: the only scenario that writes to the application database. It replaces one + // row's time and finally restores it; nothing else is touched. + const setTime = (value: string) => { + const db = new DatabaseSync(ws.dbPath, { timeout: 5000 }); + try { + const res = db.prepare('UPDATE operations SET time = ? WHERE rowid = ?').run(value, victim.rowid); + expect(Number(res.changes)).toBe(1); + } finally { + db.close(); + } + }; + const goParse = (v: string) => `read operation row: parse stored timestamp: parsing time ${JSON.stringify(v)} as "2006-01-02T15:04:05.999999999Z07:00": cannot parse ${JSON.stringify(v)} as "2006"`; + const corrupt: Array<[string, string | RegExp]> = [ + ['not-a-time', goParse('not-a-time')], + ['', goParse('')], + ['2026-13-01T00:00:00Z', /^read operation row: parse stored timestamp: parsing time "2026-13-01T00:00:00Z": month out of range$/], + ['2026-10-05 22:00:00Z', /^read operation row: parse stored timestamp: parsing time "2026-10-05 22:00:00Z" as "2006-01-02T15:04:05\.999999999Z07:00": cannot parse /], + ['1759700000', /^read operation row: parse stored timestamp: parsing time "1759700000" as "2006-01-02T15:04:05\.999999999Z07:00": cannot parse /], + ]; + for (const [value, message] of corrupt) { + await test.step(`time = ${JSON.stringify(value)}`, async () => { + setTime(value); + // The harness invariant check flags the deliberately corrupt row — asserted here explicitly + // (the check itself stays enabled everywhere else). + expect(() => assertDbInvariants(ws.dbPath), 'assertDbInvariants flags the corrupt row').toThrow(/database invariants/); + const state = stateDigest(ws.dbPath); + for (const args of [[], ['all'], ['1'], ['1000'], ['1w'], ['15250w']]) { + const r = await cli.run(['audit', ...args]); + expectCliFailure(r, { exitCode: 1, message, usage: false }); + expect(r.stdout, 'no partial output').toBe(''); + } + const trace = await cli.run(['audit'], { env: { LOG_LEVEL: 'TRACE' } }); + expectCliFailure(trace, { exitCode: 1, message, usage: false, exactStderr: false }); + expect(parseLogs(trace.stderr).unparsed.map((u) => u.text), 'only the final error line is not a log record').toHaveLength(1); + secrets.assertNoSecretsIn(trace.stderr, 'TRACE stderr of the failing audit'); + expect(stateDigest(ws.dbPath), 'the failing audit changed nothing').toBe(state); + // the token table is unaffected + expect(parseTokenList((await cli.run(['token', 'list'])).stdout).map((r) => r.token)).toEqual([t]); + }); + } + setTime(victim.time); + expectCliSuccess(await cli.run(['audit']), { stdout: good, stderr: '' }); + assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 3 }); + expect(readOperations(ws.dbPath)).toEqual(ops); +}); + +test('population: 4000 audit rows from real authenticated requests over 40 tokens (pipelined keep-alive connections) — every form equals SQLite', async ({ cli, ws, startServer, http, rng, secrets }) => { + test.setTimeout(120_000); + const tokens = await mapLimit(Array.from({ length: 40 }, (_, i) => `population ${i}`), 16, (d) => cli.tokenNew(d)); + const server = await startServer({ logLevel: 'ERROR' }); + const N = 4000; + const plan = Array.from({ length: N }, () => rng.pick(tokens)); + const t0 = performance.now(); + await pipelined(http, server, plan, { perConn: 50, concurrency: 10 }); + const requestMs = performance.now() - t0; + for (const victim of tokens.slice(0, 8)) await cli.tokenDelete(victim); + const ops = readOperations(ws.dbPath); + expect(ops).toHaveLength(N); + const perToken = new Map(); + for (const t of plan) perToken.set(t, (perToken.get(t) ?? 0) + 1); + for (const [t, n] of perToken) expect(ops.filter((o) => o.token === t).length, `rows of ${tokenId(t)}`).toBe(n); + + const timings: Record = {}; + for (const args of [[], ['all'], ['1'], ['10'], ['3999'], ['4000'], ['4001'], ['100000'], ['0100'], ['1h'], ['1d'], ['1w']]) { + const s = performance.now(); + const rows = await expectAudit(cli, ws.dbPath, args); + timings[args.join(' ') || '(none)'] = Math.round(performance.now() - s); + const sel = auditArgsOutcome(args); + if (sel.ok && 'limit' in sel.selection) expect(rows).toHaveLength(Math.min(N, Number(sel.selection.limit))); + else expect(rows).toHaveLength(N); + } + expect(Math.max(...Object.values(timings)), 'audit over 4000 rows stays fast').toBeLessThan(5000); + + // TRACE: one `row read` per row, identical stdout, no token in 4000+ log lines + const full = await cli.run(['audit', '100000']); + expectCliSuccess(await cli.run(['audit', 'all']), { stdout: full.stdout, stderr: '' }); + const traced = await cli.run(['audit', 'all'], { env: { LOG_LEVEL: 'TRACE' } }); + expectCliSuccess(traced); + expect(traced.stdout).toBe(full.stdout); + const logs = parseLogs(traced.stderr); + expect(logs.count({ msg: 'row read', attrs: { table: 'operations' } })).toBe(N); + secrets.assertNoSecretsIn(traced.stderr, 'TRACE stderr'); + + // the server serves on: the latest row printed is the next request + expectContainersResponse(await http.get(server.url(), { token: tokens[39] })); + const last = await expectAudit(cli, ws.dbPath, ['1']); + expect(last.map((r) => r.token)).toEqual([tokens[39]]); + expect((await server.stop()).exitCode).toBe(0); + assertDbInvariants(ws.dbPath, { tokenCount: 40, operationCount: N + 1 }); + test.info().annotations.push({ type: 'audit population', description: JSON.stringify({ rows: N, requestMs: Math.round(requestMs), auditMs: timings }) }); +}); diff --git a/e2e/tests/host/cli-tokens.spec.ts b/e2e/tests/host/cli-tokens.spec.ts new file mode 100644 index 0000000..2e18134 --- /dev/null +++ b/e2e/tests/host/cli-tokens.spec.ts @@ -0,0 +1,398 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core items 4, 5, 11 (CLI side): token creation with every description family (no-shell + * argv and through a real shell), verbatim storage, deterministic `token list` (active tokens) and + * `token list all` (every token) as padded tables, their usage errors, deletion. + */ +import fs from 'node:fs'; +import { + test, + expect, + assertDbInvariants, + countRows, + expectCliFailure, + expectCliSuccess, + goQuote, + msToNanos, + parseTokenList, + readOperations, + readToken, + readTokens, + rfc3339ToNanos, + RFC3339NANO_UTC_RE, + shellQuote, + EMPTY_TOKEN_LIST, + USAGE_TEXT, + fileDigest, + formatTokenList, + padTable, + runeLength, + type CliRunner, + type TokenListRow, +} from '../../harness'; +import { expectedTokenListStdout, stateDigest } from '../../harness/personas'; + +const hex = (s: string | Buffer) => Buffer.from(s as string).toString('hex').toUpperCase(); + +/** Creates a token, asserting created_at lies within the invocation window. */ +async function createChecked(cli: CliRunner, dbPath: string, description: string | undefined): Promise { + const before = msToNanos(Date.now() - 1); + const token = await cli.tokenNew(description); + const after = msToNanos(Date.now() + 1); + const row = readToken(dbPath, token)!; + expect(row, 'row exists').toBeTruthy(); + expect(row.descriptionHex, 'description stored byte-for-byte').toBe(hex(description ?? '')); + expect(row.active).toBe(1); + expect(row.deleted_at).toBeNull(); + expect(row.created_at).toMatch(RFC3339NANO_UTC_RE); + const created = rfc3339ToNanos(row.created_at); + expect(created >= before && created <= after, `created_at ${row.created_at} within the invocation window`).toBe(true); + return token; +} + +const DESCRIPTIONS: Array<[string, string | undefined]> = [ + ['omitted (no argument)', undefined], + ['explicit empty argument', ''], + ['normal words', 'ci pipeline'], + ['whitespace only', ' \t '], + ['leading/trailing spaces', ' padded value '], + ['newlines, tabs, CR', 'line1\nline2\tcol\r\nend'], + ['ASCII punctuation', `!"#$%&'()*+,-./:;<=>?@[\\]^_\`{|}~`], + ['Unicode letters, emoji, RTL, combining', 'café ☕ 日本語 עברית 🚀 é Ωmega'], + ['non-printable Unicode (NBSP, ZWSP, LS, NEL, tag)', ' nb​z
x\u0085y\u{E0001}'], + ['ASCII control characters and ESC sequences', '\x01\x07\x08\x1b[31mred\x1b[0m\x7f'], + ['SQL injection payload', `'); DROP TABLE tokens; --`], + ['SQL quote games', `x' OR '1'='1`], + ['shell metacharacters', '$(touch /tmp/pwned) `id` ; rm -rf / && echo $HOME | cat > /dev/null &'], + ['looks like an option', '--help'], + ['looks like a subcommand', 'delete'], + ['Go format verbs', '%s %d %v %!x(MISSING) %%'], + ['backslash escapes kept literal', '\\n \\t \\x00 \\u0041'], + ['very long ASCII (100 000 bytes)', 'x'.repeat(100_000)], + ['long multi-byte (30 000 × 日 = 90 000 bytes)', '日'.repeat(30_000)], + ['maximum single argv string (131 071 bytes)', 'a'.repeat(131_071)], +]; + +test.describe('token new: description stored verbatim (argv, no shell)', () => { + for (const [name, description] of DESCRIPTIONS) { + test(name, async ({ cli, ws }) => { + const token = await createChecked(cli, ws.dbPath, description); + const rows = await cli.tokenList(); + expect(rows).toHaveLength(1); + expect(rows[0].token).toBe(token); + expect(rows[0].descriptionQuoted, 'DESCRIPTION column is Go-quoted').toBe(goQuote(description ?? '')); + expect(rows[0].descriptionBytes.equals(Buffer.from(description ?? '')), 'list round-trips the bytes').toBe(true); + expect(rows[0].active).toBe(true); + expect(rows[0].deletedAt).toBeNull(); + assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 0 }); + }); + } + + test('one argument larger than the kernel limit is refused by the OS, not the app', async ({ cli }) => { + // MAX_ARG_STRLEN is 131072 bytes including the terminating NUL: exec fails before dpsapi runs. + await expect(cli.run(['token', 'new', 'a'.repeat(131_072)])).rejects.toThrow(/harness:spawn|E2BIG/); + }); +}); + +test.describe('token new through a real shell (quoting)', () => { + const tricky = [ + 'two words', + `it's "quoted"`, + '$HOME and $(id) and `id`', + 'semi;colon|pipe&>redirect { + for (const d of tricky) { + await test.step(JSON.stringify(d), async () => { + const r = await cli.shell(`"$DPSAPI_BIN" token new ${shellQuote(d)}`); + expectCliSuccess(r, { stderr: '' }); + expect(r.stdout).toMatch(/^[A-Za-z0-9_-]{43}\n$/); + expect(readToken(ws.dbPath, r.stdout.trim())!.descriptionHex).toBe(hex(d)); + }); + } + const rows = await cli.tokenList(); + expect(rows.map((r) => r.description).sort()).toEqual([...tricky].sort()); + assertDbInvariants(ws.dbPath, { tokenCount: tricky.length }); + }); + + test('unquoted multi-word description is a usage error and creates nothing', async ({ cli, ws }) => { + const r = await cli.shell('"$DPSAPI_BIN" token new ci pipeline'); + expectCliFailure(r, { exitCode: 2, message: 'usage error: token new takes at most one argument' }); + expect(fs.existsSync(ws.dbPath), 'usage errors never open/create the database').toBe(false); + }); + + test('double quotes expand variables in the shell (the app stores what it receives)', async ({ cli, ws }) => { + const r = await cli.shell('"$DPSAPI_BIN" token new "home=$HOME_FOR_TEST"', { env: { HOME_FOR_TEST: '/home/someone' } }); + expectCliSuccess(r); + expect(readToken(ws.dbPath, r.stdout.trim())!.description).toBe('home=/home/someone'); + }); + + test('invalid UTF-8 bytes from the shell are stored exactly and listed with \\x escapes', async ({ cli, ws }) => { + const r = await cli.shell(`"$DPSAPI_BIN" token new "$(printf 'bad\\377byte\\300\\200')"`); + expectCliSuccess(r); + const token = r.stdout.trim(); + expect(readToken(ws.dbPath, token)!.descriptionHex).toBe('626164FF62797465C080'); + const rows = await cli.tokenList(); + expect(rows[0].descriptionQuoted).toBe('"bad\\xffbyte\\xc0\\x80"'); + expect(rows[0].descriptionBytes.toString('hex').toUpperCase()).toBe('626164FF62797465C080'); + assertDbInvariants(ws.dbPath); + }); +}); + +test.describe('token list', () => { + test('fresh database: padded header only (list and list all), database and schema created', async ({ cli, ws }) => { + expect(EMPTY_TOKEN_LIST).toBe('TOKEN DESCRIPTION ACTIVE CREATED_AT DELETED_AT\n'); + for (const args of [['token', 'list'], ['token', 'list', 'all']]) { + const db = ws.path(`fresh-${args.length}.db`); + expect(fs.existsSync(db)).toBe(false); + const r = await cli.run(args, { env: { DB_PATH: db } }); + expectCliSuccess(r, { stdout: EMPTY_TOKEN_LIST, stderr: '' }); + expect(fs.existsSync(db), `${args.join(' ')}: database created`).toBe(true); + assertDbInvariants(db, { tokenCount: 0, operationCount: 0 }); + } + }); + + test('only inactive tokens: token list prints the header only, token list all prints them', async ({ cli, ws }) => { + const a = await cli.tokenNew('gone a'); + const b = await cli.tokenNew('gone b'); + await cli.tokenDelete(a); + await cli.tokenDelete(b); + expectCliSuccess(await cli.run(['token', 'list']), { stdout: EMPTY_TOKEN_LIST, stderr: '' }); + const all = await cli.tokenListAll(); + expect(all.map((r) => [r.token, r.active, r.deletedAt !== null])).toEqual([ + [a, false, true], + [b, false, true], + ]); + expect((await cli.run(['token', 'list', 'all'])).stdout).toBe(expectedTokenListStdout(ws.dbPath, 'all')); + }); + + test('deterministic, ordered by created_at then token, exact values for active and inactive rows', async ({ cli, ws }) => { + test.slow(); + const tokens: string[] = []; + // sequential and concurrent creations (concurrent ones may share timestamps closely) + for (let i = 0; i < 6; i++) tokens.push(await cli.tokenNew(`seq ${i}`)); + tokens.push(...(await Promise.all(Array.from({ length: 12 }, (_, i) => cli.tokenNew(`par ${i}`))))); + const deleted = [tokens[1], tokens[7], tokens[12]]; + for (const t of deleted) await cli.tokenDelete(t); + + const a = await cli.run(['token', 'list', 'all']); + const b = await cli.run(['token', 'list', 'all']); + expectCliSuccess(a, { stderr: '' }); + expect(b.stdout, 'two consecutive listings are byte-identical').toBe(a.stdout); + expect(a.stdout, 'token list all equals the stored rows (padded table)').toBe(expectedTokenListStdout(ws.dbPath, 'all')); + const rows = parseTokenList(a.stdout); + expect(rows).toHaveLength(tokens.length); + expect(new Set(rows.map((r) => r.token))).toEqual(new Set(tokens)); + + // plain `token list`: exactly the active rows, same order, its own (narrower or equal) widths + const active = await cli.run(['token', 'list']); + expectCliSuccess(active, { stderr: '' }); + expect(active.stdout, 'token list equals the stored active rows').toBe(expectedTokenListStdout(ws.dbPath, 'active')); + expect(parseTokenList(active.stdout).map((r) => r.token)).toEqual(rows.filter((r) => r.active).map((r) => r.token)); + + // ordering: created_at (as time, not string), then token (bytewise) + const key = (r: TokenListRow) => [rfc3339ToNanos(r.createdAt), r.token] as const; + for (let i = 1; i < rows.length; i++) { + const [ta, ka] = key(rows[i - 1]); + const [tb, kb] = key(rows[i]); + expect(ta < tb || (ta === tb && ka < kb), `row ${i} ordered after row ${i - 1}`).toBe(true); + } + + // every row equals the database + const db = new Map(readTokens(ws.dbPath).map((t) => [t.token, t])); + for (const r of rows) { + const d = db.get(r.token)!; + expect(r.createdAt).toBe(d.created_at); + expect(r.deletedAt).toBe(d.deleted_at); + expect(r.active).toBe(d.active === 1); + expect(r.descriptionQuoted).toBe(goQuote(d.description)); + expect(r.active).toBe(!deleted.includes(r.token)); + if (!r.active) { + expect(r.deletedAt).toMatch(RFC3339NANO_UTC_RE); + expect(rfc3339ToNanos(r.deletedAt!) >= rfc3339ToNanos(r.createdAt)).toBe(true); + expect(r.line).toMatch(new RegExp(` false ${r.createdAt.replace(/\./g, '\\.')} {2,}${r.deletedAt!.replace(/\./g, '\\.')}$`)); + } else { + expect(r.line).toMatch(new RegExp(` true ${r.createdAt.replace(/\./g, '\\.')} {2,}-$`)); + } + } + assertDbInvariants(ws.dbPath, { tokenCount: 18, operationCount: 0 }); + }); +}); + +test.describe('token list [all]: active by default, every token with "all", padded table', () => { + test('default hides inactive tokens; all shows them with ACTIVE false and DELETED_AT set; both byte-exact padded tables', async ({ cli, ws }) => { + const keep = await cli.tokenNew('keep'); + // the longest description belongs to a token that gets deleted: widths differ between the two listings + const long = await cli.tokenNew('a much longer description that only token list all prints'); + const other = await cli.tokenNew('other'); + await cli.tokenDelete(long); + const active = await cli.run(['token', 'list']); + const all = await cli.run(['token', 'list', 'all']); + expectCliSuccess(active, { stderr: '' }); + expectCliSuccess(all, { stderr: '' }); + const db = new Map(readTokens(ws.dbPath).map((t) => [t.token, t])); + const entry = (t: string) => { + const d = db.get(t)!; + return { token: t, description: d.description, active: d.active === 1, createdAt: d.created_at, deletedAt: d.deleted_at }; + }; + expect(active.stdout, 'token list: active rows only').toBe(formatTokenList([keep, other].map(entry))); + expect(all.stdout, 'token list all: every row').toBe(formatTokenList([keep, long, other].map(entry))); + // explicit layout of the default listing (widths computed over the printed lines only) + const k = entry(keep); + const o = entry(other); + const cw = 2 + Math.max(10, k.createdAt.length, o.createdAt.length); + expect(active.stdout).toBe( + 'TOKEN' + ' '.repeat(40) + 'DESCRIPTION ACTIVE ' + 'CREATED_AT'.padEnd(cw) + 'DELETED_AT\n' + + `${keep} "keep" true ${k.createdAt.padEnd(cw)}-\n` + + `${other} "other" true ${o.createdAt.padEnd(cw)}-\n`, + ); + const deleted = parseTokenList(all.stdout).find((r) => r.token === long)!; + expect(deleted.active).toBe(false); + expect(deleted.deletedAt).toBe(db.get(long)!.deleted_at); + expect(deleted.deletedAt).toMatch(RFC3339NANO_UTC_RE); + expect(active.stdout.includes(long), 'the inactive token is not printed by token list').toBe(false); + expect(active.stdout.split('\n')[0].length, 'narrower DESCRIPTION column without the long inactive row').toBeLessThan(all.stdout.split('\n')[0].length); + for (const out of [active.stdout, all.stdout]) expect(out.split('\n').filter((l) => / $/.test(l)), 'no trailing whitespace').toEqual([]); + expect(readOperations(ws.dbPath)).toEqual([]); + assertDbInvariants(ws.dbPath, { tokenCount: 3, operationCount: 0 }); + }); + + test('descriptions with runs of spaces, escaped quotes, multi-byte runes and escapes: columns aligned in runes, parser round-trips', async ({ cli, ws }) => { + const descriptions = ['', 'two spaces three', 'say "hi" \\ back', '日本語', '🚀🚀', 'e\u0301 combining', 'tab\there', '\x01\x7f\xff', '"', ' ', 'x'.repeat(70)]; + const tokens: string[] = []; + for (const d of descriptions) tokens.push(await cli.tokenNew(d)); + await cli.tokenDelete(tokens[3]); + for (const scope of ['active', 'all'] as const) { + const r = await cli.run(scope === 'all' ? ['token', 'list', 'all'] : ['token', 'list']); + expectCliSuccess(r, { stderr: '' }); + expect(r.stdout, `${scope}: exact padded table`).toBe(expectedTokenListStdout(ws.dbPath, scope)); + const rows = parseTokenList(r.stdout); + const want = scope === 'all' ? descriptions : descriptions.filter((_, i) => i !== 3); + expect(rows.map((x) => x.description).sort()).toEqual([...want].sort()); + expect(rows.every((x) => x.descriptionQuoted === goQuote(x.descriptionBytes))).toBe(true); + // every cell of a column starts at the same rune offset (display width is irrelevant to the app) + const lines = r.stdout.slice(0, -1).split('\n'); + const offset = (l: string, cell: string) => runeLength(l.slice(0, l.indexOf(cell))); + const hdr = lines[0]; + for (const x of rows) { + expect(offset(x.line, x.descriptionQuoted), 'DESCRIPTION column').toBe(offset(hdr, 'DESCRIPTION')); + expect(runeLength(x.line) - runeLength(x.line.slice(x.line.lastIndexOf(x.deletedAt ?? '-'))), 'DELETED_AT column').toBe(offset(hdr, 'DELETED_AT')); + } + expect(padTable([lines[0].split(/ +/), ...rows.map((x) => [x.token, x.descriptionQuoted, String(x.active), x.createdAt, x.deletedAt ?? '-'])])).toBe(r.stdout); + } + }); + + const UNKNOWN_ARGUMENT = 'unknown token list argument'; + const TOO_MANY = 'token list takes at most one argument'; + const LIST_USAGE: Array<[string[], string]> = [ + [['ALL'], UNKNOWN_ARGUMENT], + [['All'], UNKNOWN_ARGUMENT], + [[''], UNKNOWN_ARGUMENT], + [['--all'], UNKNOWN_ARGUMENT], + [['-a'], UNKNOWN_ARGUMENT], + [[' all'], UNKNOWN_ARGUMENT], + [['all '], UNKNOWN_ARGUMENT], + [['all\n'], UNKNOWN_ARGUMENT], + [['\u0430ll'], UNKNOWN_ARGUMENT], + [['active'], UNKNOWN_ARGUMENT], + [['inactive'], UNKNOWN_ARGUMENT], + [['extra'], UNKNOWN_ARGUMENT], + [['all', 'all'], TOO_MANY], + [['all', ''], TOO_MANY], + [['', 'all'], TOO_MANY], + [['ALL', 'x'], TOO_MANY], + [['a', 'b', 'c'], TOO_MANY], + ]; + + test(`${LIST_USAGE.length} invalid token list arguments → exit 2, exact stderr (nothing echoed), no database created, existing one byte-identical`, async ({ cli, ws }) => { + const run = async (dbPath: string) => { + for (const [args, msg] of LIST_USAGE) { + const r = await cli.run(['token', 'list', ...args], { env: { DB_PATH: dbPath } }); + expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); + expect(r.stderr, JSON.stringify(args)).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); + } + }; + await run(ws.dbPath); + expect(fs.existsSync(ws.dbPath), 'usage errors never open/create the database').toBe(false); + expect(fs.readdirSync(ws.dir)).toEqual([]); + + const t = await cli.tokenNew('existing'); + await cli.tokenDelete(t); + await cli.tokenNew('still active'); + const file = fileDigest(ws.dbPath); + const state = stateDigest(ws.dbPath); + await run(ws.dbPath); + expect(fileDigest(ws.dbPath)).toBe(file); + expect(stateDigest(ws.dbPath)).toBe(state); + }); +}); + +test.describe('token delete', () => { + test('deactivates silently; repeated/unknown/near-match deletions fail without changing state', async ({ cli, ws }) => { + const keep = await cli.tokenNew('keep'); + const victim = await cli.tokenNew('victim'); + const before = msToNanos(Date.now() - 1); + const r = await cli.run(['token', 'delete', victim]); + const after = msToNanos(Date.now() + 1); + expectCliSuccess(r, { stdout: '', stderr: '' }); + + const row = readToken(ws.dbPath, victim)!; + expect(row.active).toBe(0); + expect(row.deleted_at).toMatch(RFC3339NANO_UTC_RE); + const del = rfc3339ToNanos(row.deleted_at!); + expect(del >= before && del <= after, 'deleted_at within the delete invocation').toBe(true); + expect(readToken(ws.dbPath, keep)!.active).toBe(1); + const snapshot = JSON.stringify(readTokens(ws.dbPath)); + + const flip = (s: string) => s.replace(/[a-zA-Z]/, (c) => (c === c.toLowerCase() ? c.toUpperCase() : c.toLowerCase())); + const failures: Array<[string, string, string]> = [ + ['already inactive', victim, 'token already inactive'], + ['unknown', 'A'.repeat(43), 'token not found'], + ['case changed', flip(keep), 'token not found'], + ['leading space', ` ${keep}`, 'token not found'], + ['trailing newline', `${keep}\n`, 'token not found'], + ['prefix', keep.slice(0, 42), 'token not found'], + ['extended', keep + 'x', 'token not found'], + ['empty string', '', 'token not found'], + ['SQL wildcard', '%', 'token not found'], + ['SQL injection', `' OR '1'='1`, 'token not found'], + ]; + for (const [name, arg, message] of failures) { + await test.step(name, async () => { + const f = await cli.run(['token', 'delete', arg]); + expectCliFailure(f, { exitCode: 1, message }); + if (arg.length > 0) expect(f.stderr.includes(arg), 'supplied token never echoed').toBe(false); + expect(JSON.stringify(readTokens(ws.dbPath)), 'no token row changed').toBe(snapshot); + }); + } + const rows = await cli.tokenListAll(); + expect(rows.map((x) => [x.token, x.active])).toEqual([ + [keep, true], + [victim, false], + ]); + expect((await cli.tokenList()).map((x) => x.token), 'token list hides the deleted token').toEqual([keep]); + expect(readOperations(ws.dbPath), 'CLI commands never write audit rows').toEqual([]); + assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 0 }); + }); + + test('a deleted token stays deleted and keeps its original created_at and description', async ({ cli, ws }) => { + const t = await cli.tokenNew('history'); + const created = readToken(ws.dbPath, t)!.created_at; + await cli.tokenDelete(t); + const first = readToken(ws.dbPath, t)!; + expectCliFailure(await cli.run(['token', 'delete', t]), { exitCode: 1, message: 'token already inactive' }); + const second = readToken(ws.dbPath, t)!; + expect(second).toEqual(first); + expect(second.created_at).toBe(created); + expect(second.description).toBe('history'); + expect(countRows(ws.dbPath, 'tokens')).toBe(1); + }); +}); diff --git a/e2e/tests/host/config-usage.spec.ts b/e2e/tests/host/config-usage.spec.ts new file mode 100644 index 0000000..7c74ab5 --- /dev/null +++ b/e2e/tests/host/config-usage.spec.ts @@ -0,0 +1,372 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core item 16: every startup/configuration failure and every CLI usage failure, with + * exact stderr, exit code (2 usage/config, 1 runtime) and proof that the database was not + * created or modified inappropriately. + */ +import fs from 'node:fs'; +import { + test, + expect, + assertDbInvariants, + expectCliFailure, + expectCliSuccess, + fileDigest, + goQuote, + isPortFree, + occupyPort, + parseLogs, + readTokens, + USAGE_ERROR_MESSAGES, + USAGE_TEXT, +} from '../../harness'; +import { cliOutcome, StateModel } from '../../harness/personas'; + +/** Server mode ([]) and a CLI command must both reject a bad configuration identically. */ +const MODES: Array<[string, string[]]> = [ + ['server mode', []], + ['token list', ['token', 'list']], + ['token new', ['token', 'new', 'x']], + ['audit', ['audit', '5m']], +]; + +/** Configuration is validated before dispatch: also `help` and `token list all` (which never open the database). */ +const CONFIG_MODES: Array<[string, string[]]> = [...MODES, ['token list all', ['token', 'list', 'all']], ['audit all', ['audit', 'all']], ['help', ['help']], ['help with an argument', ['help', 'x']]]; + +const addrMsg = (v: string) => `configuration error: invalid HTTP_ADDR ${goQuote(v)}: must be an IPv4 or IPv6 address`; +const portMsg = (v: string) => `configuration error: invalid HTTP_PORT ${goQuote(v)}: must be an integer between 1 and 65535`; +const levelMsg = (v: string) => `configuration error: invalid LOG_LEVEL ${goQuote(v)}: must be one of ERROR, WARN, INFO, DEBUG, TRACE`; + +const CONFIG_CASES: Array<[string, Record, string]> = [ + ['DB_PATH unset', { DB_PATH: undefined }, 'configuration error: DB_PATH is required'], + ['DB_PATH empty', { DB_PATH: '' }, 'configuration error: DB_PATH must not be empty'], + ['HTTP_ADDR empty', { HTTP_ADDR: '' }, 'configuration error: HTTP_ADDR must not be empty'], + ...['localhost', 'example.com', '127.0.0.1:8080', '[::1]', '256.0.0.1', '1.2.3', '010.0.0.1', ' 127.0.0.1', '127.0.0.1 ', 'fe80::1%lo', '0x7f.0.0.1', '127.0.0.1\n', '*'].map( + (v) => [`HTTP_ADDR=${JSON.stringify(v)}`, { HTTP_ADDR: v }, addrMsg(v)] as [string, Record, string], + ), + ['HTTP_PORT empty', { HTTP_PORT: '' }, 'configuration error: HTTP_PORT must not be empty'], + ...['0', '00000', '-1', '65536', '99999999999999999999', 'abc', ' 80', '80 ', '+80', '1e3', '0x50', '８０', '80\n', '8O'].map( + (v) => [`HTTP_PORT=${JSON.stringify(v)}`, { HTTP_PORT: v }, portMsg(v)] as [string, Record, string], + ), + ['LOG_LEVEL empty', { LOG_LEVEL: '' }, 'configuration error: LOG_LEVEL must not be empty'], + ...['VERBOSE', 'INFO ', ' info', 'warning', 'ERR', 'trace\n', 'İNFO', 'ＩＮＦＯ', 'debug2', 'FATAL', '0'].map( + (v) => [`LOG_LEVEL=${JSON.stringify(v)}`, { LOG_LEVEL: v }, levelMsg(v)] as [string, Record, string], + ), + // precedence: DB_PATH, HTTP_ADDR, HTTP_PORT, LOG_LEVEL — first problem wins + ['DB_PATH missing beats everything', { DB_PATH: undefined, HTTP_ADDR: 'x', HTTP_PORT: 'y', LOG_LEVEL: 'z' }, 'configuration error: DB_PATH is required'], + ['HTTP_ADDR beats HTTP_PORT and LOG_LEVEL', { HTTP_ADDR: 'x', HTTP_PORT: 'y', LOG_LEVEL: 'z' }, addrMsg('x')], + ['HTTP_PORT beats LOG_LEVEL', { HTTP_PORT: 'y', LOG_LEVEL: 'z' }, portMsg('y')], +]; + +test.describe('configuration errors → exit 2, exact message, no database', () => { + for (const [name, env, message] of CONFIG_CASES) { + test(name, async ({ cli, ws }) => { + for (const [mode, args] of CONFIG_MODES) { + await test.step(mode, async () => { + const r = await cli.run(args, { env: { HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1', ...env }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 2, message, usage: false }); + expect(fs.existsSync(ws.dbPath), 'database not created on configuration error').toBe(false); + expect(fs.readdirSync(ws.dir), 'nothing written to the workspace').toEqual([]); + }); + } + }); + } + + test('configuration errors take precedence over usage errors (no usage text)', async ({ cli, ws }) => { + const r = await cli.run(['bogus'], { env: { DB_PATH: undefined } }); + expectCliFailure(r, { exitCode: 2, message: 'configuration error: DB_PATH is required', usage: false }); + const r2 = await cli.run(['token', 'new', 'a', 'b'], { env: { LOG_LEVEL: 'nope' } }); + expectCliFailure(r2, { exitCode: 2, message: levelMsg('nope'), usage: false }); + const r3 = await cli.run(['audit', '0'], { env: { HTTP_PORT: '0' } }); + expectCliFailure(r3, { exitCode: 2, message: portMsg('0'), usage: false }); + expect(fs.existsSync(ws.dbPath)).toBe(false); + }); +}); + +const USAGE_CASES: Array<[string[], string]> = [ + [['bogus'], 'unknown command'], + [['-h'], 'unknown command'], + [['--help'], 'unknown command'], + [['Help'], 'unknown command'], + [['HELP'], 'unknown command'], + [['-help'], 'unknown command'], + [['help '], 'unknown command'], + [['help', 'x'], 'help takes no arguments'], + [['help', ''], 'help takes no arguments'], + [['help', 'help'], 'help takes no arguments'], + [['help', 'token', 'list'], 'help takes no arguments'], + [['token', 'help'], 'unknown token subcommand'], + [['audit', 'help'], 'invalid audit argument'], + [['Token', 'list'], 'unknown command'], + [['TOKEN'], 'unknown command'], + [[''], 'unknown command'], + [['tokens', 'list'], 'unknown command'], + [['token'], 'missing token subcommand'], + [['token', 'bogus'], 'unknown token subcommand'], + [['token', 'LIST'], 'unknown token subcommand'], + [['token', 'New'], 'unknown token subcommand'], + [['token', ''], 'unknown token subcommand'], + [['token', 'remove', 'x'], 'unknown token subcommand'], + [['token', 'list', 'extra'], 'unknown token list argument'], + [['token', 'list', ''], 'unknown token list argument'], + [['token', 'list', 'ALL'], 'unknown token list argument'], + [['token', 'list', 'All'], 'unknown token list argument'], + [['token', 'list', '--all'], 'unknown token list argument'], + [['token', 'list', 'all '], 'unknown token list argument'], + [['token', 'list', 'help'], 'unknown token list argument'], + [['token', 'list', 'all', 'all'], 'token list takes at most one argument'], + [['token', 'list', 'all', ''], 'token list takes at most one argument'], + [['token', 'list', 'x', 'y'], 'token list takes at most one argument'], + [['token', 'new', 'a', 'b'], 'token new takes at most one argument'], + [['token', 'new', '', ''], 'token new takes at most one argument'], + [['token', 'delete'], 'token delete requires exactly one argument'], + [['token', 'delete', 'a', 'b'], 'token delete requires exactly one argument'], + // audit is case-sensitive and singular; one representative per invalid-argument class + // (the exhaustive table is in cli-audit.spec.ts) + [['AUDIT'], 'unknown command'], + [['Audit', '10'], 'unknown command'], + [['audits'], 'unknown command'], + [['audit', '1', 'h'], 'audit takes at most one argument'], + [['audit', '0'], 'invalid audit argument'], + [['audit', '0h'], 'invalid audit argument'], + [['audit', '-5'], 'invalid audit argument'], + [['audit', ' 5'], 'invalid audit argument'], + [['audit', ''], 'invalid audit argument'], + [['audit', '5H'], 'invalid audit argument'], + [['audit', '5y'], 'invalid audit argument'], + [['audit', 'h'], 'invalid audit argument'], + [['audit', '1.5'], 'invalid audit argument'], + [['audit', '9223372036854775808'], 'invalid audit argument'], + [['audit', '15251w'], 'invalid audit argument'], + // `audit all`: `all` is exact and lowercase only, and takes no further argument + [['audit', 'ALL'], 'invalid audit argument'], + [['audit', 'All'], 'invalid audit argument'], + [['audit', 'all1'], 'invalid audit argument'], + [['audit', '--all'], 'invalid audit argument'], + [['audit', 'all', 'x'], 'audit takes at most one argument'], + [['audit', 'all', 'all'], 'audit takes at most one argument'], +]; + +test('the usage table covers every usage error message, and the CLI oracle agrees with it', () => { + const model = new StateModel(); + for (const [args, msg] of USAGE_CASES) expect(cliOutcome(args, model), JSON.stringify(args)).toEqual({ kind: 'error', exitCode: 2, message: `usage error: ${msg}`, usage: true }); + expect([...new Set(USAGE_CASES.map(([, m]) => m))].sort()).toEqual([...USAGE_ERROR_MESSAGES].sort()); + expect(cliOutcome(['help'], model)).toEqual({ kind: 'help', exitCode: 0 }); + expect(cliOutcome(['token', 'list'], model)).toEqual({ kind: 'list', exitCode: 0, scope: 'active' }); + expect(cliOutcome(['token', 'list', 'all'], model)).toEqual({ kind: 'list', exitCode: 0, scope: 'all' }); + expect(cliOutcome(['audit', 'all'], model)).toEqual({ kind: 'audit', exitCode: 0, selection: { all: true } }); + expect(cliOutcome(['audit'], model)).toEqual({ kind: 'audit', exitCode: 0, selection: { limit: 10n } }); +}); + +test.describe('help', () => { + test('help prints exactly the usage text on stdout, nothing on stderr, exit 0; no database created, an existing one byte-identical', async ({ cli, ws }) => { + const r = await cli.help(); + expect(r.stdout).toBe(USAGE_TEXT); + expect(fs.existsSync(ws.dbPath), 'help never opens/creates the database').toBe(false); + expect(fs.readdirSync(ws.dir), 'nothing written to the workspace').toEqual([]); + // the same bytes as the usage text printed after a usage error + const bad = await cli.run(['bogus']); + expect(bad.stderr).toBe(`dpsapi: usage error: unknown command\n${r.stdout}`); + + await cli.tokenNew('existing'); + const digest = fileDigest(ws.dbPath); + const rows = JSON.stringify(readTokens(ws.dbPath)); + await cli.help(); + expect(fileDigest(ws.dbPath)).toBe(digest); + expect(JSON.stringify(readTokens(ws.dbPath))).toBe(rows); + // DB_PATH pointing somewhere unusable does not matter: the database is never opened + for (const db of [ws.path('missing-dir', 'x.db'), ws.mkdir('a-directory')]) await cli.help({ env: { DB_PATH: db } }); + expect(fs.existsSync(ws.path('missing-dir'))).toBe(false); + }); + + test('a configuration error still wins over help: exit 2, the configuration error line only, no usage text, nothing on stdout', async ({ cli, ws }) => { + const cases: Array<[Record, string]> = [ + [{ DB_PATH: undefined }, 'configuration error: DB_PATH is required'], + [{ DB_PATH: '' }, 'configuration error: DB_PATH must not be empty'], + [{ HTTP_ADDR: 'localhost' }, addrMsg('localhost')], + [{ HTTP_PORT: '0' }, portMsg('0')], + [{ LOG_LEVEL: 'verbose' }, levelMsg('verbose')], + [{ LOG_LEVEL: '' }, 'configuration error: LOG_LEVEL must not be empty'], + ]; + for (const [env, message] of cases) { + for (const args of [['help'], ['help', 'x']]) { + const r = await cli.run(args, { env }); + expectCliFailure(r, { exitCode: 2, message, usage: false }); + expect(r.stderr, `${JSON.stringify(args)} ${JSON.stringify(env)}: exact stderr`).toBe(`dpsapi: ${message}\n`); + expect(r.stderr.includes('usage:'), 'no usage text').toBe(false); + } + } + expect(fs.readdirSync(ws.dir)).toEqual([]); + }); + + test('log levels: at DEBUG/TRACE stderr carries only log records (dispatch mode=cli, cli dispatch command=help) while stdout is still exactly the usage text; silent at INFO and above', async ({ cli, ws }) => { + for (const level of ['ERROR', 'WARN', 'INFO', 'DEBUG', 'TRACE', 'debug', 'Trace']) { + await test.step(level, async () => { + const r = await cli.run(['help'], { env: { LOG_LEVEL: level } }); + expectCliSuccess(r, { stdout: USAGE_TEXT }); + const verbose = /^(debug|trace)$/i.test(level); + if (!verbose) { + expect(r.stderr).toBe(''); + return; + } + const logs = parseLogs(r.stderr); + expect(logs.unparsed.map((u) => u.text), 'every stderr line is a log record (no usage text, no dpsapi: line)').toEqual([]); + expect(logs.records.length).toBeGreaterThan(0); + expect(logs.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' }); + expect(logs.filter({ msg: 'cli dispatch' }).map((x) => x.attrs)).toEqual([{ command: 'help' }]); + expect(logs.has({ msg: /^database / }), 'no database record').toBe(false); + expect(logs.count({ level: 'TRACE' }) > 0, 'TRACE records only at TRACE').toBe(/^trace$/i.test(level)); + expect(r.stderr.includes('usage:'), 'the usage text is never on stderr').toBe(false); + }); + } + expect(fs.existsSync(ws.dbPath)).toBe(false); + }); +}); + +test.describe('usage errors → exit 2, error line + usage text, database untouched', () => { + for (const [args, msg] of USAGE_CASES) { + test(`${JSON.stringify(args)} → ${msg}`, async ({ cli, ws }) => { + // fresh workspace: the database must not be created + const r = await cli.run(args); + expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); + expect(r.stderr).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); + expect(fs.existsSync(ws.dbPath), 'usage errors never open/create the database').toBe(false); + + // existing database: byte-identical afterwards + await cli.tokenNew('existing'); + const digest = fileDigest(ws.dbPath); + const rows = JSON.stringify(readTokens(ws.dbPath)); + const r2 = await cli.run(args); + expectCliFailure(r2, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); + expect(fileDigest(ws.dbPath)).toBe(digest); + expect(JSON.stringify(readTokens(ws.dbPath))).toBe(rows); + }); + } +}); + +test.describe('runtime failures → exit 1', () => { + test('DB_PATH in a missing directory: not created, exit 1 (server and CLI)', async ({ cli, ws }) => { + const db = ws.path('missing-dir', 'x.db'); + for (const [mode, args] of MODES) { + await test.step(mode, async () => { + const r = await cli.run(args, { env: { DB_PATH: db, HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1' }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: 'initialize database schema: unable to open database file (14)' }); + expect(fs.existsSync(ws.path('missing-dir'))).toBe(false); + }); + } + }); + + test('DB_PATH is a directory → exit 1', async ({ cli, ws }) => { + const dir = ws.mkdir('a-directory'); + for (const [mode, args] of MODES) { + await test.step(mode, async () => { + const r = await cli.run(args, { env: { DB_PATH: dir, HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1' }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: 'initialize database schema: unable to open database file (14)' }); + expect(fs.readdirSync(dir)).toEqual([]); + }); + } + }); + + test('DB_PATH is not a SQLite database → exit 1, file left untouched', async ({ cli, ws, rng }) => { + const garbage = ws.writeFile('garbage.db', rng.bytes(8192)); + const digest = fileDigest(garbage); + for (const [mode, args] of MODES) { + await test.step(mode, async () => { + const r = await cli.run(args, { env: { DB_PATH: garbage, HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1' }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: 'initialize database schema: file is not a database (26)' }); + expect(fileDigest(garbage)).toBe(digest); + }); + } + }); + + test('DB_PATH in a read-only directory → exit 1, nothing created', async ({ cli, ws }) => { + const dir = ws.mkdir('readonly'); + fs.chmodSync(dir, 0o555); + try { + for (const [mode, args] of MODES) { + await test.step(mode, async () => { + const r = await cli.run(args, { env: { DB_PATH: `${dir}/x.db`, HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1' }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: 'initialize database schema: unable to open database file (14)' }); + expect(fs.readdirSync(dir)).toEqual([]); + }); + } + } finally { + fs.chmodSync(dir, 0o755); + } + }); + + test('port already in use → exit 1 with the listen error; database still valid', async ({ cli, ws, e2e }) => { + const port = await e2e.allocatePort(); + const holder = await occupyPort(port, '127.0.0.1'); + try { + const r = await cli.run([], { env: { HTTP_ADDR: '127.0.0.1', HTTP_PORT: String(port) }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: `listen tcp4 127.0.0.1:${port}: bind: address already in use` }); + assertDbInvariants(ws.dbPath, { tokenCount: 0, operationCount: 0 }); + } finally { + await holder.close(); + } + }); + + test('privileged port as an unprivileged user → exit 1 (permission denied)', async ({ cli }) => { + const r = await cli.run([], { env: { HTTP_ADDR: '127.0.0.1', HTTP_PORT: '1' }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: 'listen tcp4 127.0.0.1:1: bind: permission denied' }); + }); + + test('address not assigned to this host → exit 1 (cannot assign requested address)', async ({ cli, e2e }) => { + const port = await e2e.allocatePort(); + const r = await cli.run([], { env: { HTTP_ADDR: '192.0.2.1', HTTP_PORT: String(port) }, timeoutMs: 10_000 }); + expectCliFailure(r, { exitCode: 1, message: `listen tcp4 192.0.2.1:${port}: bind: cannot assign requested address` }); + }); +}); + +test.describe('valid edge-case configuration', () => { + test('HTTP_PORT with leading zeros and the 65535 upper bound are accepted', async ({ startServer, e2e }) => { + const port = await e2e.allocatePort(); + const s = await startServer({ port: `000${port}`, logLevel: 'INFO' }); + expect(s.logs().find({ msg: 'server listening' })!.attrs.addr).toBe(`127.0.0.1:${port}`); + expect((await s.stop()).exitCode).toBe(0); + + expect(await isPortFree(65535), 'port 65535 must be free on this host for this check').toBe(true); + const top = await startServer({ port: 65535 }); + expect(top.logs().find({ msg: 'server listening' })!.attrs.addr).toBe('127.0.0.1:65535'); + expect((await top.stop()).exitCode).toBe(0); + }); + + test('HTTP_ADDR unset defaults to 0.0.0.0 (IPv4 only)', async ({ startServer, http, cli }) => { + const token = await cli.tokenNew(); + const s = await startServer({ addr: null }); + expect(s.logs().find({ msg: 'server listening' })!.attrs.addr).toBe(`0.0.0.0:${s.port}`); + expect((await http.get(s.url(), { token })).status).toBe(200); + // tcp4 listener: not reachable over IPv6 loopback + const v6 = await http.raw({ host: '::1', port: s.port, data: 'GET / HTTP/1.1\r\nHost: x\r\n\r\n' }); + expect(v6.outcome).toBe('refused'); + expect((await s.stop()).exitCode).toBe(0); + }); + + test('all defaults (0.0.0.0:80, INFO) in a private network namespace', async ({ startServer }) => { + const s = await startServer({ addr: null, port: null, logLevel: null, privateNetwork: true }); + const rec = await s.waitForLog({ msg: 'server listening' }); + expect(rec.level).toBe('INFO'); + expect(rec.attrs.addr).toBe('0.0.0.0:80'); + expect(s.env.HTTP_ADDR).toBeUndefined(); + expect(s.env.HTTP_PORT).toBeUndefined(); + expect(s.env.LOG_LEVEL).toBeUndefined(); + const exit = await s.stop('SIGTERM'); + expect(exit.exitCode).toBe(0); + expect(s.logs().count({ level: ['DEBUG', 'TRACE'] }), 'default level is INFO').toBe(0); + }); + + test('an existing database is reused by every mode (repeated schema initialization)', async ({ cli, ws, startServer }) => { + const t = await cli.tokenNew('first'); + for (let i = 0; i < 3; i++) expectCliSuccess(await cli.run(['token', 'list'])); + const s = await startServer(); + expect((await s.stop()).exitCode).toBe(0); + const s2 = await startServer(); + expect((await s2.stop()).exitCode).toBe(0); + const rows = readTokens(ws.dbPath); + expect(rows.map((r) => r.token)).toEqual([t]); + assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 0 }); + }); +}); diff --git a/e2e/tests/host/logging.spec.ts b/e2e/tests/host/logging.spec.ts new file mode 100644 index 0000000..c3e465b --- /dev/null +++ b/e2e/tests/host/logging.spec.ts @@ -0,0 +1,291 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core items 2, 3, 14: start with explicit HTTP_ADDR/HTTP_PORT at every LOG_LEVEL and + * verify which records must and must not be emitted, for server and CLI mode. + */ +import { + test, + expect, + LOG_LEVELS, + LOG_TIME_RE, + USAGE_TEXT, + levelRank, + parseLogs, + tokenId, + visibleLevels, + expectContainersResponse, + expectErrorResponse, + type LogLevel, + type LogSet, +} from '../../harness'; + +/** Go time.Duration.String() */ +const GO_DURATION_RE = /^(\d+(\.\d+)?(h|m|s|ms|µs|ns))+$|^0s$/; + +const SERVER_FUNCS = [ + 'app.execute', + 'app.runServer', + 'OpenDatabase', + 'InitializeSchema', + 'WebServer.Handler', + 'WebServer.Serve', + 'WebServer.logRequests', + 'WebServer.handleContainers', + 'authenticate', + 'TokenStore.GetToken', + 'AuditStore.RecordOperation', + 'DockerClient.ListRunningContainers', + 'WebServer.handleNotFound', + 'WebServer.handleMethodNotAllowed', +]; + +const DEBUG_SERVER_MESSAGES = [ + 'configuration resolved', + 'dispatch', + 'database schema initialized', + 'database opened', + 'docker client created', + 'routes registered', + 'authentication result', + 'audit row inserted', + 'docker request started', + 'docker request finished', + 'shutdown requested, draining http server', + 'http server shut down', + 'database closed', +]; + +function expectOnlyLevels(logs: LogSet, min: LogLevel): void { + const allowed = visibleLevels(min); + const bad = logs.records.filter((r) => !allowed.includes(r.level as LogLevel)); + expect(bad.map((r) => r.raw), `records below ${min}`).toEqual([]); + for (const r of logs.records) { + expect(r.time, `time attribute of ${r.raw}`).toMatch(LOG_TIME_RE); + expect(LOG_LEVELS).toContain(r.level as LogLevel); + } +} + +for (const level of LOG_LEVELS) { + test(`server at LOG_LEVEL=${level}: emitted records match the level exactly`, async ({ cli, startServer, http }) => { + const active = await cli.tokenNew('logging probe'); + const inactive = await cli.tokenNew('to be deleted'); + await cli.tokenDelete(inactive); + const unknown = 'U'.repeat(43); + + const server = await startServer({ logLevel: level, addr: '127.0.0.1' }); + const fake = server.fakeDocker!.many(2); + + // The same request sequence at every level + expectContainersResponse(await http.get(server.url(), { token: active })); + expectErrorResponse(await http.get(server.url()), 401); + expectErrorResponse(await http.get(server.url(), { token: unknown }), 401); + expectErrorResponse(await http.get(server.url(), { token: inactive }), 401); + expectErrorResponse(await http.get(server.url('/nope')), 404); + expectErrorResponse(await http.fetch(server.url(), { method: 'POST' }), 405); + fake.error500(); + expectErrorResponse(await http.get(server.url(), { token: active }), 500); + fake.many(2); + + const exit = await server.stop('SIGTERM'); + expect(exit.exitCode).toBe(0); + expect(exit.stdout, 'server never writes to stdout').toBe(''); + + const logs = server.logs(); + expect(logs.unparsed, 'every stderr line is a slog record').toEqual([]); + expectOnlyLevels(logs, level); + const shows = (l: LogLevel) => levelRank(l) >= levelRank(level); + + // ERROR: request failures only + expect(logs.filter({ level: 'ERROR' }).map((r) => r.msg)).toEqual(['docker request failed']); + const err = logs.find({ level: 'ERROR', msg: 'docker request failed' })!; + expect(err.attrs.error, 'diagnostics stay in the logs').toContain('fake engine failure'); + + // WARN: nothing is expected from a healthy server + expect(logs.count({ level: 'WARN' })).toBe(0); + + // INFO + const listening = logs.filter({ level: 'INFO', msg: 'server listening' }); + const requests = logs.requests(); + if (shows('INFO')) { + expect(listening).toHaveLength(1); + expect(listening[0].attrs.addr).toBe(`127.0.0.1:${server.port}`); + expect(listening[0].attrs.version).toBeTruthy(); + expect(listening[0].attrs.commit).toBeTruthy(); + expect(logs.filter({ level: 'INFO', msg: 'server stopped' })).toHaveLength(1); + expect(requests.map((r) => [r.level, r.attrs.method, r.attrs.path, r.attrs.status, r.attrs.origin])).toEqual([ + ['INFO', 'GET', '/api/v1/containers', '200', '127.0.0.1'], + ['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'], + ['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'], + ['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'], + ['INFO', 'GET', '/nope', '404', '127.0.0.1'], + ['INFO', 'POST', '/api/v1/containers', '405', '127.0.0.1'], + ['INFO', 'GET', '/api/v1/containers', '500', '127.0.0.1'], + ]); + for (const r of requests) { + expect(r.msg).toBe('this request has been made'); + expect(r.attrs.duration).toMatch(GO_DURATION_RE); + expect(Object.keys(r.attrs).sort()).toEqual(['duration', 'method', 'origin', 'path', 'status']); + } + } else { + expect(listening, 'server listening hidden below INFO').toHaveLength(0); + expect(requests, '"this request has been made" hidden below INFO').toHaveLength(0); + expect(logs.count({ msg: 'server stopped' })).toBe(0); + expect(logs.count({ level: 'INFO' })).toBe(0); + } + + // DEBUG + if (shows('DEBUG')) { + for (const m of DEBUG_SERVER_MESSAGES) expect(logs.count({ level: 'DEBUG', msg: m }), `DEBUG "${m}"`).toBeGreaterThan(0); + expect(logs.find({ msg: 'configuration resolved' })!.attrs).toEqual({ + db_path: server.dbPath, + http_addr: '127.0.0.1', + http_port: String(server.port), + log_level: level, + }); + expect(logs.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'server' }); + expect(logs.find({ msg: 'docker client created' })!.attrs).toEqual({ host: 'unix:///var/run/docker.sock' }); + expect(logs.find({ msg: 'routes registered' })!.attrs).toEqual({ route: 'GET /api/v1/containers' }); + expect(logs.filter({ msg: 'authentication result' }).map((r) => r.attrs.result)).toEqual(['ok', 'missing_header', 'unknown_token', 'inactive_token', 'ok']); + for (const r of logs.filter({ msg: 'authentication result', attrs: { result: 'ok' } })) expect(r.attrs.token_id).toBe(tokenId(active)); + expect(logs.filter({ msg: 'audit row inserted' }).map((r) => r.attrs)).toEqual([ + { token_id: tokenId(active), origin: '127.0.0.1', operation: 'GET containers' }, + { token_id: tokenId(active), origin: '127.0.0.1', operation: 'GET containers' }, + ]); + const finished = logs.filter({ msg: 'docker request finished' }); + expect(finished.map((r) => [r.attrs.ok, r.attrs.containers])).toEqual([ + ['true', '2'], + ['false', undefined], + ]); + expect(logs.count({ msg: 'docker request started' })).toBe(2); + } else { + expect(logs.count({ level: 'DEBUG' })).toBe(0); + } + + // TRACE + if (shows('TRACE')) { + for (const fn of SERVER_FUNCS) { + const entries = logs.count({ level: 'TRACE', msg: 'function entry', attrs: { func: fn } }); + const exits = logs.count({ level: 'TRACE', msg: 'function exit', attrs: { func: fn } }); + expect(entries, `function entry ${fn}`).toBeGreaterThan(0); + expect(exits, `function exit ${fn} balanced with entries`).toBe(entries); + } + // row-level records: token rows identified by token_id only, audit rows, containers + const reads = logs.filter({ level: 'TRACE', msg: 'row read', attrs: { table: 'tokens' } }); + expect(reads.map((r) => [r.attrs.token_id, r.attrs.active])).toEqual([ + [tokenId(active), 'true'], + [tokenId(inactive), 'false'], + [tokenId(active), 'true'], + ]); + expect(reads[0].attrs.description).toBe('logging probe'); + expect(reads[0].attrs.deleted_at).toBe(''); + expect(reads[1].attrs.deleted_at).toMatch(/^\d{4}-.*Z$/); + expect(logs.filter({ level: 'TRACE', msg: 'row not found' }).map((r) => r.attrs)).toEqual([{ table: 'tokens', token_id: tokenId(unknown) }]); + const inserted = logs.filter({ level: 'TRACE', msg: 'row inserted', attrs: { table: 'operations' } }); + expect(inserted).toHaveLength(2); + for (const r of inserted) { + expect(r.attrs.token_id).toBe(tokenId(active)); + expect(r.attrs.origin).toBe('127.0.0.1'); + expect(r.attrs.operation).toBe('GET containers'); + expect(r.attrs.time).toMatch(/^\d{4}-.*Z$/); + } + expect(logs.filter({ level: 'TRACE', msg: 'container listed' }).map((r) => [r.attrs.names, r.attrs.state])).toEqual([ + ['[/fake-0]', 'running'], + ['[/fake-1]', 'running'], + ]); + } else { + expect(logs.count({ level: 'TRACE' })).toBe(0); + } + + // Secrets / headers never logged at any level + for (const t of [active, inactive, unknown]) expect(server.stderr.includes(t), 'token value in logs').toBe(false); + expect(server.stderr).not.toContain('Bearer'); + expect(server.stderr.toLowerCase()).not.toContain('authorization'); + }); + + test(`CLI at LOG_LEVEL=${level}: token commands log exactly what the level allows`, async ({ cli }) => { + const env = { LOG_LEVEL: level }; + const created = await cli.run(['token', 'new', 'cli level probe'], { env }); + expect(created.exitCode).toBe(0); + const token = created.stdout.trim(); + const listed = await cli.run(['token', 'list'], { env }); + expect(listed.exitCode).toBe(0); + const deleted = await cli.run(['token', 'delete', token], { env }); + expect(deleted.exitCode).toBe(0); + expect(deleted.stdout).toBe(''); + const listedAll = await cli.run(['token', 'list', 'all'], { env }); + expect(listedAll.exitCode).toBe(0); + const help = await cli.run(['help'], { env }); + expect(help.exitCode).toBe(0); + expect(help.stdout, 'help: stdout is exactly the usage text at every level').toBe(USAGE_TEXT); + + for (const r of [created, listed, deleted, listedAll, help]) { + expect(r.stderr.includes(token), 'token never in CLI logs').toBe(false); + const logs = parseLogs(r.stderr); + expect(logs.unparsed).toEqual([]); + expectOnlyLevels(logs, level); + if (levelRank(level) >= levelRank('INFO')) expect(r.stderr, 'successful CLI commands are silent at INFO and above').toBe(''); + } + const c = parseLogs(created.stderr); + const d = parseLogs(deleted.stderr); + if (levelRank(level) <= levelRank('DEBUG')) { + expect(c.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' }); + expect(c.find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token new' }); + expect(c.find({ msg: 'token created' })!.attrs).toEqual({ token_id: tokenId(token) }); + expect(c.find({ msg: 'cli command finished' })!.attrs).toEqual({ command: 'token new', ok: 'true' }); + expect(c.has({ msg: 'database closed' })).toBe(true); + expect(parseLogs(listed.stderr).find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token list' }); + // as implemented: `token list all` dispatches under the same command name + expect(parseLogs(listedAll.stderr).find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token list' }); + expect(d.find({ msg: 'token deactivated' })!.attrs).toEqual({ token_id: tokenId(token) }); + const h = parseLogs(help.stderr); + expect(h.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' }); + expect(h.filter({ msg: 'cli dispatch' }).map((x) => x.attrs)).toEqual([{ command: 'help' }]); + expect(h.has({ msg: /^database / }), 'help never opens the database').toBe(false); + } else { + expect(help.stderr, 'help is silent above DEBUG').toBe(''); + } + if (level === 'TRACE') { + for (const fn of ['app.execute', 'app.runTokenCommand', 'OpenDatabase', 'InitializeSchema', 'app.tokenNew', 'TokenStore.CreateToken']) { + expect(c.count({ msg: 'function entry', attrs: { func: fn } }), fn).toBe(1); + expect(c.count({ msg: 'function exit', attrs: { func: fn } }), fn).toBe(1); + } + const ins = c.find({ msg: 'row inserted', attrs: { table: 'tokens' } })!; + expect(ins.attrs).toMatchObject({ token_id: tokenId(token), description: 'cli level probe', active: 'true', deleted_at: '' }); + expect(parseLogs(listed.stderr).find({ msg: 'row read' })!.attrs.token_id).toBe(tokenId(token)); + // after the deletion: plain `token list` reads no row (SQL filter), `token list all` reads it + expect(parseLogs(listedAll.stderr).filter({ msg: 'row read' }).map((x) => x.attrs.token_id)).toEqual([tokenId(token)]); + expect(parseLogs(listedAll.stderr).find({ msg: 'row read' })!.attrs).toMatchObject({ active: 'false' }); + const upd = d.find({ msg: 'row updated', attrs: { table: 'tokens' } })!; + expect(upd.attrs).toMatchObject({ token_id: tokenId(token), active_from: 'true', active_to: 'false' }); + } + }); +} + +test('LOG_LEVEL is ASCII case-insensitive and defaults to INFO', async ({ cli, startServer, http }) => { + for (const [value, canonical] of [ + ['trace', 'TRACE'], + ['Debug', 'DEBUG'], + ['iNfO', 'INFO'], + ['warn', 'WARN'], + ['eRRoR', 'ERROR'], + ] as const) { + const r = await cli.run(['token', 'list'], { env: { LOG_LEVEL: value } }); + expect(r.exitCode, value).toBe(0); + const logs = parseLogs(r.stderr); + expectOnlyLevels(logs, canonical); + if (levelRank(canonical) <= levelRank('DEBUG')) expect(logs.find({ msg: 'configuration resolved' })!.attrs.log_level).toBe(canonical); + else expect(r.stderr).toBe(''); + } + + // Unset LOG_LEVEL → INFO + const token = await cli.tokenNew(); + const server = await startServer({ logLevel: null }); + expectContainersResponse(await http.get(server.url(), { token })); + expect((await server.stop()).exitCode).toBe(0); + const logs = server.logs(); + expectOnlyLevels(logs, 'INFO'); + expect(logs.requests()).toHaveLength(1); + expect(logs.has({ msg: 'server listening' })).toBe(true); +}); diff --git a/e2e/tests/host/population.spec.ts b/e2e/tests/host/population.spec.ts new file mode 100644 index 0000000..502b705 --- /dev/null +++ b/e2e/tests/host/population.spec.ts @@ -0,0 +1,92 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core item 13: a large token population (300 tokens, created only through the binary) + * with listing, deletion, authentication and audit checks (SQLite and the `audit` command) against + * that population. + */ +import { + test, + expect, + assertDbInvariants, + expectCliFailure, + expectContainersResponse, + expectErrorResponse, + formatAuditOutput, + mapLimit, + readOperations, + readTokens, + rfc3339ToNanos, +} from '../../harness'; +import { expectedAuditStdout } from '../../harness/personas'; + +const N = 300; + +test('300 tokens: create, list, delete, authenticate and audit', async ({ cli, startServer, http, ws, rng }) => { + test.setTimeout(240_000); + const server = await startServer(); + server.fakeDocker!.many(1); + + // Created through the binary, 12 CLI processes at a time, while the server is running + const descriptions = Array.from({ length: N }, (_, i) => (i % 10 === 0 ? `pop ${i} ünïcødé ✓` : i % 7 === 0 ? '' : `pop ${i}`)); + const tokens = await mapLimit(descriptions, 12, (d) => cli.tokenNew(d)); + expect(new Set(tokens).size, 'all tokens distinct').toBe(N); + + // list + const rows = await cli.tokenList(); + expect(rows).toHaveLength(N); + const byToken = new Map(rows.map((r) => [r.token, r])); + tokens.forEach((t, i) => expect(byToken.get(t)?.description).toBe(descriptions[i])); + for (let i = 1; i < rows.length; i++) { + const a = rfc3339ToNanos(rows[i - 1].createdAt); + const b = rfc3339ToNanos(rows[i].createdAt); + expect(a < b || (a === b && rows[i - 1].token < rows[i].token)).toBe(true); + } + expect(rows.every((r) => r.active && r.deletedAt === null)).toBe(true); + + // delete a random third, 8 at a time + const shuffled = rng.shuffle(tokens); + const deleted = shuffled.slice(0, 100); + const alive = shuffled.slice(100); + await mapLimit(deleted, 8, (t) => cli.tokenDelete(t)); + const after = await cli.tokenListAll(); + expect(after.filter((r) => !r.active).map((r) => r.token).sort()).toEqual([...deleted].sort()); + expect(after.filter((r) => r.active)).toHaveLength(200); + expect(after.filter((r) => !r.active).every((r) => r.deletedAt !== null)).toBe(true); + // plain `token list`: exactly the 200 alive tokens, in the same relative order as `token list all` + const activeOnly = await cli.tokenList(); + expect(activeOnly.map((r) => r.token)).toEqual(after.filter((r) => r.active).map((r) => r.token)); + expect(new Set(activeOnly.map((r) => r.token))).toEqual(new Set(alive)); + + // authenticate: 60 alive (200), 40 deleted (401), 20 unknown (401), concurrently + const probes = rng.shuffle([ + ...alive.slice(0, 60).map((t) => ({ t, ok: true })), + ...deleted.slice(0, 40).map((t) => ({ t, ok: false })), + ...Array.from({ length: 20 }, () => ({ t: rng.string(43, 'abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789-_'), ok: false })), + ]); + await mapLimit(probes, 10, async (p) => { + const r = await http.get(server.url(), { token: p.t }); + if (p.ok) expectContainersResponse(r); + else expectErrorResponse(r, 401); + }); + + // deleting already-deleted tokens fails and changes nothing + const snapshot = JSON.stringify(readTokens(ws.dbPath)); + for (const t of deleted.slice(0, 10)) expectCliFailure(await cli.run(['token', 'delete', t]), { exitCode: 1, message: 'token already inactive' }); + expect(JSON.stringify(readTokens(ws.dbPath))).toBe(snapshot); + + expect((await server.stop()).exitCode).toBe(0); + + // audit: exactly one row per successful probe, each for the right token + const ops = readOperations(ws.dbPath); + expect(ops.map((o) => o.token).sort()).toEqual(alive.slice(0, 60).sort()); + expect(server.logs().requests().filter((r) => r.attrs.status === '200')).toHaveLength(60); + expect(server.logs().requests().filter((r) => r.attrs.status === '401')).toHaveLength(60); + // `audit` over the population: all 60 rows, the default 10, and a window holding every row + expect(formatAuditOutput(await cli.audit('60'))).toBe(expectedAuditStdout(ops, { limit: 60n })); + expect(formatAuditOutput(await cli.audit())).toBe(expectedAuditStdout(ops, { limit: 10n })); + expect((await cli.audit('1h')).map((r) => r.token).sort()).toEqual(alive.slice(0, 60).sort()); + const report = assertDbInvariants(ws.dbPath, { tokenCount: N, operationCount: 60, auditBeforeDeletion: true }); + expect(report).toEqual({ tokens: N, activeTokens: 200, inactiveTokens: 100, operations: 60 }); +}); diff --git a/e2e/tests/host/token-lifecycle.spec.ts b/e2e/tests/host/token-lifecycle.spec.ts new file mode 100644 index 0000000..222b1dc --- /dev/null +++ b/e2e/tests/host/token-lifecycle.spec.ts @@ -0,0 +1,96 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +/** + * PLAN §12 core item 11 (server side): deleting tokens through the binary while the server runs — + * deleted_at populated, active=0, history retained, 401 afterwards, audit rows keep satisfying the + * foreign key; credential rotation; tokens created while the server runs are usable immediately. + */ +import { + test, + expect, + assertDbInvariants, + expectCliFailure, + expectContainersResponse, + expectErrorResponse, + msToNanos, + readOperations, + readToken, + rfc3339ToNanos, + tokenId, +} from '../../harness'; + +test('delete while serving: 401 afterwards, history and audit rows retained', async ({ cli, startServer, http, ws }) => { + const a = await cli.tokenNew('to delete'); + const b = await cli.tokenNew('survivor'); + const server = await startServer({ logLevel: 'DEBUG' }); + expectContainersResponse(await http.get(server.url(), { token: a })); + expectContainersResponse(await http.curl({ url: server.url(), token: a })); + expectContainersResponse(await http.get(server.url(), { token: b })); + const createdA = readToken(ws.dbPath, a)!.created_at; + + const t0 = msToNanos(Date.now() - 1); + await cli.tokenDelete(a); + const t1 = msToNanos(Date.now() + 1); + + expectErrorResponse(await http.get(server.url(), { token: a }), 401); + expectErrorResponse(await http.curl({ url: server.url(), token: a }), 401); + expectContainersResponse(await http.get(server.url(), { token: b })); + + const rowA = readToken(ws.dbPath, a)!; + expect(rowA.active).toBe(0); + expect(rowA.created_at).toBe(createdA); + expect(rowA.description).toBe('to delete'); + const del = rfc3339ToNanos(rowA.deleted_at!); + expect(del >= t0 && del <= t1).toBe(true); + expect(readToken(ws.dbPath, b)!.active).toBe(1); + + const ops = readOperations(ws.dbPath); + expect(ops.map((o) => o.token)).toEqual([a, a, b, b]); + for (const o of ops.filter((x) => x.token === a)) expect(rfc3339ToNanos(o.time) < del).toBe(true); + + const list = await cli.tokenListAll(); + expect(list.map((r) => [r.token, r.active, r.deletedAt])).toEqual([ + [a, false, rowA.deleted_at], + [b, true, null], + ]); + expect((await cli.tokenList()).map((r) => [r.token, r.active, r.deletedAt]), 'token list: the active token only').toEqual([[b, true, null]]); + expectCliFailure(await cli.run(['token', 'delete', a]), { exitCode: 1, message: 'token already inactive' }); + + expect((await server.stop()).exitCode).toBe(0); + const classes = server.logs().filter({ msg: 'authentication result' }).map((r) => [r.attrs.result, r.attrs.token_id]); + expect(classes).toEqual([ + ['ok', tokenId(a)], + ['ok', tokenId(a)], + ['ok', tokenId(b)], + ['inactive_token', undefined], + ['inactive_token', undefined], + ['ok', tokenId(b)], + ]); + assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 4, auditBeforeDeletion: true }); +}); + +test('credential rotation: new token works immediately, old one stops working, nothing restarts', async ({ cli, startServer, http, ws }) => { + const server = await startServer(); + const old = await cli.tokenNew('rotation v1'); + expectContainersResponse(await http.get(server.url(), { token: old })); + for (let v = 2; v <= 4; v++) { + const next = await cli.tokenNew(`rotation v${v}`); // created while the server runs + expectContainersResponse(await http.get(server.url(), { token: next })); + await cli.tokenDelete(v === 2 ? old : (await cli.tokenList()).find((r) => r.description === `rotation v${v - 1}`)!.token); + expectContainersResponse(await http.get(server.url(), { token: next })); + } + expectErrorResponse(await http.get(server.url(), { token: old }), 401); + const rows = await cli.tokenListAll(); + expect(rows.map((r) => [r.description, r.active])).toEqual([ + ['rotation v1', false], + ['rotation v2', false], + ['rotation v3', false], + ['rotation v4', true], + ]); + expect((await cli.tokenList()).map((r) => r.description), 'token list: only the current credential').toEqual(['rotation v4']); + expect(server.pid, 'same process throughout').toBe(server.pid); + expect(server.generation).toBe(1); + expect((await server.stop()).exitCode).toBe(0); + assertDbInvariants(ws.dbPath, { tokenCount: 4, operationCount: 7, auditBeforeDeletion: true }); +}); diff --git a/main.go b/main.go new file mode 100644 index 0000000..788fafd --- /dev/null +++ b/main.go @@ -0,0 +1,210 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +package main + +import ( + "context" + "database/sql" + "errors" + "fmt" + "io" + "log/slog" + "net" + "os" + "os/signal" + "strings" + "syscall" + "time" +) + +// Exit codes +const ( + exitOK = 0 + exitFailure = 1 + exitUsage = 2 +) + +// errUsage marks command-line usage errors (exit code 2, usage text printed) +var errUsage = errors.New("usage error") + +// usageText is printed to stderr after a usage error and to stdout by `help` +const usageText = `usage: + dpsapi start the HTTP server + dpsapi help print this usage text + dpsapi token list [all] list the active tokens, or every token with "all" + dpsapi token new [description] create a token and print it + dpsapi token delete deactivate a token + dpsapi audit print the latest 10 audit rows + dpsapi audit print the latest n audit rows + dpsapi audit print the audit rows of the last n units (s, m, h, d, w) + dpsapi audit all print every audit row +` + +// usageErrorf builds an error wrapping errUsage +func usageErrorf(format string, args ...any) error { + return fmt.Errorf("%w: "+format, append([]any{errUsage}, args...)...) +} + +// dockerConn is a closable container lister +type dockerConn interface { + ContainerLister + Close() error +} + +// app holds the process-level dependencies; every field is replaceable in tests +type app struct { + lookupEnv func(string) (string, bool) + stdout io.Writer + stderr io.Writer + now func() time.Time + generateToken func() (string, error) + newDocker func(log *slog.Logger) (dockerConn, error) + listen func(network, address string) (net.Listener, error) + shutdownTimeout time.Duration +} + +// newApp returns an app wired with the production dependencies +func newApp(lookupEnv func(string) (string, bool), stdout, stderr io.Writer) *app { + return &app{ + lookupEnv: lookupEnv, + stdout: stdout, + stderr: stderr, + now: time.Now, + generateToken: GenerateToken, + newDocker: func(log *slog.Logger) (dockerConn, error) { + return NewDockerClient(dockerHost, log) + }, + listen: net.Listen, + shutdownTimeout: defaultShutdownTimeout, + } +} + +func main() { + os.Exit(run(os.Args[1:], os.LookupEnv, os.Stdout, os.Stderr)) +} + +// run is the process entry point: it wires SIGINT/SIGTERM to cancellation and returns the exit code +func run(args []string, lookupEnv func(string) (string, bool), stdout, stderr io.Writer) int { + // Create a context cancelled by the OS signals + ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) + defer stop() + + return newApp(lookupEnv, stdout, stderr).run(ctx, args) +} + +// run executes the command and maps its outcome to the exit code +// The "dpsapi: ..." error line is therefore always the last line written to stderr +func (a *app) run(ctx context.Context, args []string) int { + return a.exitCode(a.execute(ctx, args)) +} + +// execute loads the configuration, initializes the logger and dispatches on the arguments +func (a *app) execute(ctx context.Context, args []string) (err error) { + // Load and validate the configuration before anything else + cfg, err := LoadConfig(a.lookupEnv) + if err != nil { + return err + } + + // Initialize the logger + log := NewLogger(a.stderr, cfg.LogLevel) + defer traceFunc(ctx, log, "app.execute")() + log.DebugContext(ctx, "configuration resolved", + "db_path", cfg.DBPath, "http_addr", cfg.HTTPAddr, "http_port", cfg.HTTPPort, "log_level", LevelName(cfg.LogLevel)) + + // Dispatch + switch { + case len(args) == 0: + log.DebugContext(ctx, "dispatch", "mode", "server") + err = a.runServer(ctx, cfg, log) + case args[0] == "help": + log.DebugContext(ctx, "dispatch", "mode", "cli") + err = a.runHelpCommand(ctx, log, args[1:]) + case args[0] == "token": + log.DebugContext(ctx, "dispatch", "mode", "cli") + err = a.runTokenCommand(ctx, cfg, log, args[1:]) + case args[0] == "audit": + log.DebugContext(ctx, "dispatch", "mode", "cli") + err = a.runAuditCommand(ctx, cfg, log, args[1:]) + default: + err = usageErrorf("unknown command") + } + return err +} + +// runHelpCommand prints the usage text to stdout; the database is never opened +func (a *app) runHelpCommand(ctx context.Context, log *slog.Logger, args []string) error { + defer traceFunc(ctx, log, "app.runHelpCommand")() + + if len(args) != 0 { + return usageErrorf("help takes no arguments") + } + log.DebugContext(ctx, "cli dispatch", "command", "help") + if _, err := fmt.Fprint(a.stdout, usageText); err != nil { + return fmt.Errorf("write output: %w", err) + } + return nil +} + +// exitCode prints err (if any) to stderr as a single line and maps it to the process exit code +func (a *app) exitCode(err error) int { + if err == nil { + return exitOK + } + msg := strings.NewReplacer("\r", " ", "\n", " ").Replace(err.Error()) + fmt.Fprintf(a.stderr, "dpsapi: %s\n", msg) + switch { + case errors.Is(err, errUsage): + fmt.Fprint(a.stderr, usageText) + return exitUsage + case errors.Is(err, errConfig): + return exitUsage + default: + return exitFailure + } +} + +// closeDatabase closes the pool, keeping the first error +func closeDatabase(ctx context.Context, db *sql.DB, log *slog.Logger, err *error) { + if cerr := db.Close(); cerr != nil && *err == nil { + *err = fmt.Errorf("close database: %w", cerr) + } + log.DebugContext(ctx, "database closed") +} + +// runServer runs the HTTP server until ctx is cancelled +func (a *app) runServer(ctx context.Context, cfg Config, log *slog.Logger) (err error) { + defer traceFunc(ctx, log, "app.runServer")() + + // Open the database + db, err := OpenDatabase(ctx, cfg.DBPath, log) + if err != nil { + return err + } + defer closeDatabase(ctx, db, log, &err) + tokens := NewTokenStore(db, log, a.now, a.generateToken) + audit := NewAuditStore(db, log, a.now) + + // Create the Docker client (lazy: no connection is made yet) + docker, err := a.newDocker(log) + if err != nil { + return err + } + defer docker.Close() + log.DebugContext(ctx, "docker client created", "host", dockerHost) + + // Create the web server and register the routes + ws := NewWebServer(log, tokens, audit, docker) + + // Listen in the foreground + ln, err := a.listen(cfg.ListenNetwork(), cfg.ListenAddress()) + if err != nil { + return err + } + if err := ws.Serve(ctx, ln, a.shutdownTimeout); err != nil { + return err + } + log.InfoContext(ctx, "server stopped") + return nil +} diff --git a/main_test.go b/main_test.go new file mode 100644 index 0000000..f96e2cd --- /dev/null +++ b/main_test.go @@ -0,0 +1,399 @@ +// SPDX-License-Identifier: GPL-2.0-or-later +// Copyright (C) 2026 Bryan Joshua Pedini + +package main + +import ( + "context" + "database/sql" + "errors" + "fmt" + "io" + "log/slog" + "net" + "net/http" + "os" + "strconv" + "strings" + "sync" + "syscall" + "testing" + "time" +) + +// serverHarness runs app.run in server mode with an ephemeral listener and a fake Docker client +type serverHarness struct { + t *testing.T + path string + docker *fakeDocker + stderr *syncBuffer + stdout *syncBuffer + cancel context.CancelFunc + exited chan struct{} + code int + addr string + network string + reqAddr string +} + +func startServer(t *testing.T, env map[string]string, configure func(a *app)) *serverHarness { + t.Helper() + h := &serverHarness{ + t: t, + path: testDBPath(t), + docker: &fakeDocker{}, + stderr: &syncBuffer{}, + stdout: &syncBuffer{}, + exited: make(chan struct{}), + } + if env == nil { + env = map[string]string{} + } + if _, ok := env["DB_PATH"]; !ok { + env["DB_PATH"] = h.path + } + h.path = env["DB_PATH"] + a := newApp(envMap(env), h.stdout, h.stderr) + ready := make(chan string, 1) + a.newDocker = func(*slog.Logger) (dockerConn, error) { return h.docker, nil } + a.listen = func(network, address string) (net.Listener, error) { + h.network, h.reqAddr = network, address + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err == nil { + ready <- ln.Addr().String() + } + return ln, err + } + if configure != nil { + configure(a) + } + ctx, cancel := context.WithCancel(context.Background()) + h.cancel = cancel + go func() { + h.code = a.run(ctx, nil) + close(h.exited) + }() + select { + case h.addr = <-ready: + case <-h.exited: + case <-time.After(10 * time.Second): + t.Fatal("server did not start") + } + t.Cleanup(func() { + cancel() + select { + case <-h.exited: + case <-time.After(10 * time.Second): + } + }) + return h +} + +func (h *serverHarness) wait() int { + h.t.Helper() + select { + case <-h.exited: + return h.code + case <-time.After(20 * time.Second): + h.t.Fatal("server did not exit") + return -1 + } +} + +func (h *serverHarness) get(path string, header http.Header) (*http.Response, string) { + h.t.Helper() + req, _ := http.NewRequest("GET", "http://"+h.addr+path, nil) + if header != nil { + req.Header = header + } + resp, err := http.DefaultClient.Do(req) + if err != nil { + h.t.Fatal(err) + } + defer resp.Body.Close() + body, _ := io.ReadAll(resp.Body) + return resp, string(body) +} + +func TestServerGracefulShutdown(t *testing.T) { + t.Parallel() + path := testDBPath(t) + tok := strings.TrimSpace(cli(t, path, nil, nil, "token", "new", "srv").stdout) + h := startServer(t, map[string]string{"DB_PATH": path, "HTTP_ADDR": "127.0.0.1", "HTTP_PORT": "8080", "LOG_LEVEL": "DEBUG"}, nil) + if h.network != "tcp4" || h.reqAddr != "127.0.0.1:8080" { + t.Fatalf("listen(%q, %q)", h.network, h.reqAddr) + } + h.docker.containers = makeContainers(1) + + resp, body := h.get("/api/v1/containers", bearer(tok)) + if resp.StatusCode != 200 || !strings.HasPrefix(body, `[{"Id":"`) { + t.Fatalf("got %d %s", resp.StatusCode, body) + } + resp, body = h.get("/api/v1/containers", nil) + if resp.StatusCode != 401 || body != `{"error":"unauthorized"}` { + t.Fatalf("got %d %s", resp.StatusCode, body) + } + + h.cancel() + if code := h.wait(); code != 0 { + t.Fatalf("exit code %d, stderr:\n%s", code, h.stderr.String()) + } + if h.stdout.String() != "" { + t.Fatalf("server wrote to stdout: %q", h.stdout.String()) + } + out := h.stderr.String() + for _, want := range []string{ + `level=DEBUG msg="configuration resolved"`, + `level=DEBUG msg=dispatch mode=server`, + `level=DEBUG msg="database opened"`, + `level=DEBUG msg="docker client created" host=unix:///var/run/docker.sock`, + `level=DEBUG msg="routes registered" route="GET /api/v1/containers"`, + `level=INFO msg="server listening" addr=` + h.addr + ` version=latest commit=undefined`, + `level=INFO msg="this request has been made" method=GET path=/api/v1/containers status=200`, + `level=INFO msg="this request has been made" method=GET path=/api/v1/containers status=401`, + `level=DEBUG msg="shutdown requested, draining http server" timeout=15s`, + `level=DEBUG msg="http server shut down"`, + `level=INFO msg="server stopped"`, + `level=DEBUG msg="database closed"`, + } { + if !strings.Contains(out, want) { + t.Errorf("missing %q in:\n%s", want, out) + } + } + if strings.Contains(out, tok) { + t.Fatal("token leaked into server logs") + } + if !h.docker.closed { + t.Fatal("docker client not closed") + } + // The audit row is in the database after shutdown + db := openTestDBAt(t, path) + if n := countRows(t, db, "operations"); n != 1 { + t.Fatalf("operations = %d", n) + } +} + +func openTestDBAt(t *testing.T, path string) *sql.DB { + t.Helper() + db, err := OpenDatabase(context.Background(), path, traceDiscard()) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { db.Close() }) + return db +} + +func TestServerInfoLevelOutput(t *testing.T) { + t.Parallel() + h := startServer(t, nil, nil) + h.get("/nope", nil) + h.cancel() + if code := h.wait(); code != 0 { + t.Fatalf("exit %d", code) + } + lines := strings.Split(strings.TrimSpace(h.stderr.String()), "\n") + if len(lines) != 3 || + !strings.Contains(lines[0], `level=INFO msg="server listening"`) || + !strings.Contains(lines[1], `level=INFO msg="this request has been made" method=GET path=/nope status=404 duration=`) || + !strings.Contains(lines[1], ` origin=127.0.0.1`) || + !strings.Contains(lines[2], `level=INFO msg="server stopped"`) { + t.Fatalf("unexpected INFO output:\n%s", h.stderr.String()) + } +} + +func TestServerErrorLevelIsSilent(t *testing.T) { + t.Parallel() + h := startServer(t, map[string]string{"LOG_LEVEL": "error"}, nil) + h.get("/nope", nil) + h.cancel() + if code := h.wait(); code != 0 || h.stderr.String() != "" { + t.Fatalf("exit %d stderr %q", code, h.stderr.String()) + } +} + +// failingListener returns a permanent error from Accept +type failingListener struct { + net.Listener +} + +func (failingListener) Accept() (net.Conn, error) { return nil, errors.New("accept exploded") } +func (failingListener) Close() error { return nil } +func (failingListener) Addr() net.Addr { return &net.TCPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 1} } + +func TestServerErrorPropagation(t *testing.T) { + t.Parallel() + stderr := &syncBuffer{} + a := newApp(envMap(map[string]string{"DB_PATH": testDBPath(t)}), io.Discard, stderr) + a.newDocker = func(*slog.Logger) (dockerConn, error) { return &fakeDocker{}, nil } + a.listen = func(string, string) (net.Listener, error) { return failingListener{}, nil } + code := a.run(context.Background(), nil) + if code != 1 || !strings.HasSuffix(stderr.String(), "dpsapi: http server: accept exploded\n") { + t.Fatalf("code=%d stderr=%q", code, stderr.String()) + } +} + +func TestServerListenFailurePortInUse(t *testing.T) { + t.Parallel() + busy, err := net.Listen("tcp4", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + defer busy.Close() + port := busy.Addr().(*net.TCPAddr).Port + stderr := &syncBuffer{} + a := newApp(envMap(map[string]string{ + "DB_PATH": testDBPath(t), "HTTP_ADDR": "127.0.0.1", "HTTP_PORT": strconv.Itoa(port), + }), io.Discard, stderr) + a.newDocker = func(*slog.Logger) (dockerConn, error) { return &fakeDocker{}, nil } + code := a.run(context.Background(), nil) + want := fmt.Sprintf("dpsapi: listen tcp4 127.0.0.1:%d: bind: address already in use\n", port) + if code != 1 || stderr.String() != want { + t.Fatalf("code=%d stderr=%q want %q", code, stderr.String(), want) + } +} + +func TestServerShutdownFailure(t *testing.T) { + t.Parallel() + path := testDBPath(t) + tok := strings.TrimSpace(cli(t, path, nil, nil, "token", "new").stdout) + release := make(chan struct{}) + entered := make(chan struct{}) + h := startServer(t, map[string]string{"DB_PATH": path}, func(a *app) { a.shutdownTimeout = 50 * time.Millisecond }) + var once sync.Once + h.docker.onList = func(ctx context.Context) { + once.Do(func() { close(entered) }) + <-release + } + defer close(release) + + // Start a request that stays in flight + go func() { + req, _ := http.NewRequest("GET", "http://"+h.addr+"/api/v1/containers", nil) + req.Header = bearer(tok) + if resp, err := http.DefaultClient.Do(req); err == nil { + resp.Body.Close() + } + }() + select { + case <-entered: + case <-time.After(10 * time.Second): + t.Fatal("request did not reach Docker") + } + + h.cancel() + code := h.wait() + if code != 1 || !strings.HasSuffix(h.stderr.String(), "dpsapi: http server shutdown: context deadline exceeded\n") { + t.Fatalf("code=%d stderr=%q", code, h.stderr.String()) + } +} + +func TestServerStartupDatabaseFailure(t *testing.T) { + t.Parallel() + stderr := &syncBuffer{} + a := newApp(envMap(map[string]string{"DB_PATH": t.TempDir()}), io.Discard, stderr) + listened := false + a.listen = func(string, string) (net.Listener, error) { listened = true; return nil, errors.New("unreachable") } + code := a.run(context.Background(), nil) + if code != 1 || listened || !strings.HasPrefix(stderr.String(), "dpsapi: initialize database schema: ") { + t.Fatalf("code=%d listened=%v stderr=%q", code, listened, stderr.String()) + } +} + +func TestServerDockerClientFailure(t *testing.T) { + t.Parallel() + stderr := &syncBuffer{} + a := newApp(envMap(map[string]string{"DB_PATH": testDBPath(t)}), io.Discard, stderr) + a.newDocker = func(*slog.Logger) (dockerConn, error) { return nil, errors.New("create docker client: bad host") } + code := a.run(context.Background(), nil) + if code != 1 || stderr.String() != "dpsapi: create docker client: bad host\n" { + t.Fatalf("code=%d stderr=%q", code, stderr.String()) + } +} + +func TestServerProductionDockerFactory(t *testing.T) { + t.Parallel() + // The default factory builds a lazy client for the production socket without connecting + a := newApp(envMap(nil), io.Discard, io.Discard) + d, err := a.newDocker(traceDiscard()) + if err != nil { + t.Fatal(err) + } + defer d.Close() + if _, ok := d.(*DockerClient); !ok { + t.Fatalf("factory returned %T", d) + } +} + +// TestRunSIGTERM drives the real entry point and delivers a real SIGTERM to the test process +// It is deliberately not parallel; the signal is sent only once the server is confirmed to be serving, +// so signal.NotifyContext is registered and the signal cannot terminate the test binary +func TestRunSIGTERM(t *testing.T) { + probe, err := net.Listen("tcp4", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + port := probe.Addr().(*net.TCPAddr).Port + probe.Close() + + stderr := &syncBuffer{} + env := envMap(map[string]string{"DB_PATH": testDBPath(t), "HTTP_ADDR": "127.0.0.1", "HTTP_PORT": strconv.Itoa(port)}) + done := make(chan int, 1) + go func() { done <- run(nil, env, io.Discard, stderr) }() + + // Wait until our server answers (a 404 JSON body proves it is ours) + deadline := time.Now().Add(10 * time.Second) + for { + resp, err := http.Get(fmt.Sprintf("http://127.0.0.1:%d/ready-probe", port)) + if err == nil { + body, _ := io.ReadAll(resp.Body) + resp.Body.Close() + if string(body) == bodyNotFound { + break + } + } + select { + case code := <-done: + t.Fatalf("server exited early with %d: %s", code, stderr.String()) + default: + } + if time.Now().After(deadline) { + t.Fatalf("server not ready: %s", stderr.String()) + } + time.Sleep(20 * time.Millisecond) + } + + if err := syscall.Kill(os.Getpid(), syscall.SIGTERM); err != nil { + t.Fatal(err) + } + select { + case code := <-done: + if code != 0 { + t.Fatalf("exit code %d: %s", code, stderr.String()) + } + case <-time.After(20 * time.Second): + t.Fatal("server did not stop on SIGTERM") + } + if !strings.Contains(stderr.String(), `msg="server stopped"`) { + t.Fatalf("stderr:\n%s", stderr.String()) + } +} + +func TestExitCodeMapping(t *testing.T) { + t.Parallel() + for _, c := range []struct { + err error + code int + }{ + {nil, 0}, + {usageErrorf("x"), 2}, + {configErrorf("x"), 2}, + {ErrTokenNotFound, 1}, + {ErrTokenInactive, 1}, + {errors.New("anything"), 1}, + } { + a := newApp(envMap(nil), io.Discard, io.Discard) + if got := a.exitCode(c.err); got != c.code { + t.Errorf("exitCode(%v) = %d, want %d", c.err, got, c.code) + } + } +}