6d5f7c4 feat(logging): per-run log files and make tty/logs workflow · neferwl

M .gitignore +1 -0

@@ -1,4 +1,5 @@
1	1		/nefertty
	2	+	/bin/
2	3		*.test
3	4		*.out
4	5		coverage/

@@ -1,4 +1,5 @@
1	/nefertty	1		/nefertty
		2	+	/bin/
2	*.test	3		*.test
3	*.out	4		*.out
4	coverage/	5		coverage/

M Makefile +17 -1

@@ -1,4 +1,20 @@
1		-	.PHONY: build test vet race mocks mocks-check arch check
	1	+	.PHONY: build test vet race mocks mocks-check arch check bin tty logs
	2	+
	3	+	TTY_TIMEOUT ?= 60s
	4	+	RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/nefertty/runs
	5	+
	6	+	# Build a fresh binary with the git revision embedded.
	7	+	bin:
	8	+	CGO_ENABLED=0 go build -o bin/nefertty ./cmd/nefertty
	9	+
	10	+	# Run on the current TTY. Quit: Ctrl+Alt+Backspace, or wait TTY_TIMEOUT.
	11	+	tty: bin
	12	+	./bin/nefertty --backend=drm --debug=all --timeout=$(TTY_TIMEOUT); \
	13	+	echo "exit $$? - log: $(RUNS)/latest.log"
	14	+
	15	+	# Summarise the last run: lifecycle, warnings and errors.
	16	+	logs:
	17	+	@jq -r 'select(.level != "debug") \| "\(.time) \(.level) [\(.component)] \(.message) \(del(.time,.level,.component,.message) \| tostring)"' $(RUNS)/latest.log
2	18		build:
3	19		CGO_ENABLED=0 go build ./...
4	20		test:

@@ -1,4 +1,20 @@
1	-	.PHONY: build test vet race mocks mocks-check arch check	1	+	.PHONY: build test vet race mocks mocks-check arch check bin tty logs
			2	+
			3	+	TTY_TIMEOUT ?= 60s
			4	+	RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/nefertty/runs
			5	+
			6	+	# Build a fresh binary with the git revision embedded.
			7	+	bin:
			8	+	CGO_ENABLED=0 go build -o bin/nefertty ./cmd/nefertty
			9	+
			10	+	# Run on the current TTY. Quit: Ctrl+Alt+Backspace, or wait TTY_TIMEOUT.
			11	+	tty: bin
			12	+	./bin/nefertty --backend=drm --debug=all --timeout=$(TTY_TIMEOUT); \
			13	+	echo "exit $$? - log: $(RUNS)/latest.log"
			14	+
			15	+	# Summarise the last run: lifecycle, warnings and errors.
			16	+	logs:
			17	+	@jq -r 'select(.level != "debug") \| "\(.time) \(.level) [\(.component)] \(.message) \(del(.time,.level,.component,.message) \| tostring)"' $(RUNS)/latest.log
2		build:	18		build:
3		CGO_ENABLED=0 go build ./...	19		CGO_ENABLED=0 go build ./...
4		test:	20		test:

M cmd/nefertty/main.go +24 -9


@@ -10,6 +10,7 @@ import (
10	10		"runtime/debug"
11	11		"strings"
12	12		"syscall"
	13	+	"time"
13	14
14	15		"github.com/bnema/nefertty/internal/adapters/config"
15	16		"github.com/bnema/nefertty/internal/app"

@@ -161,15 +162,29 @@ func run() error {
161	162		}
162	163		defer closeLog()
163	164		log := logging.For(ctx, "app")
	165	+	defer func() {
	166	+	if p := recover(); p != nil {
	167	+	log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit")
	168	+	_ = closeLog()
	169	+	panic(p)
	170	+	}
	171	+	}()
	172	+	start := time.Now()
	173	+	log.Info().Strs("args", os.Args[1:]).Str("backend", *backend).Str("tty", os.Getenv("XDG_VTNR")).Str("session_type", os.Getenv("XDG_SESSION_TYPE")).Msg("run")
164	174		configLog := logging.For(ctx, "config")
165	175		configLog.Info().Str("path", path).Msg("loaded config")
166		-	if err := app.Run(ctx, app.Options{Backend: backend, Config: cfg, ConfigPath: path, Timeout: timeout, NoTerminal: noTerminal, ScreenshotDir: screenshot, Script: script}); err != nil {
167		-	// SIGINT and SIGTERM cancel the context and are clean exits.
168		-	if ctx.Err() != nil && errors.Is(err, context.Canceled) {
169		-	return nil
170		-	}
171		-	log.Error().Err(err).Msg("application failed")
172		-	return err
173		-	}
174		-	return nil
	176	+	err = app.Run(ctx, app.Options{Backend: backend, Config: cfg, ConfigPath: path, Timeout: timeout, NoTerminal: noTerminal, ScreenshotDir: screenshot, Script: script})
	177	+	// SIGINT and SIGTERM cancel the context and are clean exits.
	178	+	if err != nil && ctx.Err() != nil && errors.Is(err, context.Canceled) {
	179	+	err = nil
	180	+	}
	181	+	reason := "clean"
	182	+	switch {
	183	+	case err != nil:
	184	+	reason = "error"
	185	+	case ctx.Err() != nil:
	186	+	reason = "signal"
	187	+	}
	188	+	log.Info().Str("reason", reason).AnErr("error", err).Dur("uptime", time.Since(start)).Msg("exit")
	189	+	return err
175	190		}

 	"runtime/debug"
 	"strings"
 	"syscall"
+	"time"
 	"github.com/bnema/nefertty/internal/adapters/config"
 	"github.com/bnema/nefertty/internal/app"
 	}
 	defer closeLog()
 	log := logging.For(ctx, "app")
+	defer func() {
+		if p := recover(); p != nil {
+			log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit")
+			_ = closeLog()
+			panic(p)
+		}
+	}()
+	start := time.Now()
+	log.Info().Strs("args", os.Args[1:]).Str("backend", *backend).Str("tty", os.Getenv("XDG_VTNR")).Str("session_type", os.Getenv("XDG_SESSION_TYPE")).Msg("run")
 	configLog := logging.For(ctx, "config")
 	configLog.Info().Str("path", path).Msg("loaded config")
-	if err := app.Run(ctx, app.Options{Backend: *backend, Config: cfg, ConfigPath: path, Timeout: *timeout, NoTerminal: *noTerminal, ScreenshotDir: *screenshot, Script: script}); err != nil {
+	err = app.Run(ctx, app.Options{Backend: *backend, Config: cfg, ConfigPath: path, Timeout: *timeout, NoTerminal: *noTerminal, ScreenshotDir: *screenshot, Script: script})
-		// SIGINT and SIGTERM cancel the context and are clean exits.
+	// SIGINT and SIGTERM cancel the context and are clean exits.
-		if ctx.Err() != nil && errors.Is(err, context.Canceled) {
+	if err != nil && ctx.Err() != nil && errors.Is(err, context.Canceled) {
-			return nil
+		err = nil
-		}
+	}
-		log.Error().Err(err).Msg("application failed")
+	reason := "clean"
-		return err
+	switch {
-	}
+	case err != nil:
-	return nil
+		reason = "error"
+	case ctx.Err() != nil:
+		reason = "signal"
+	}
+	log.Info().Str("reason", reason).AnErr("error", err).Dur("uptime", time.Since(start)).Msg("exit")
+	return err
 }

M internal/logging/logging.go +25 -6


@@ -6,7 +6,9 @@ import (
6	6		"fmt"
7	7		"os"
8	8		"path/filepath"
	9	+	"sort"
9	10		"strings"
	11	+	"time"
10	12
11	13		"github.com/bnema/zerowrap"
12	14		"github.com/rs/zerolog"

@@ -40,7 +42,11 @@ func ParseDebug(value string) (map[string]bool, error) {
40	42		return selected, nil
41	43		}
42	44
43		-	// Open rotates the previous run's log, opens a fresh JSON log and attaches the logger to ctx.
	45	+	// keepRuns is how many per-run log files Open retains.
	46	+	const keepRuns = 20
	47	+
	48	+	// Open creates runs/<timestamp>.log, points runs/latest.log at it, prunes old runs
	49	+	// and attaches the logger to ctx.
44	50		// The caller must invoke close after all logging is complete.
45	51		func Open(ctx context.Context, level, debug string) (context.Context, func() error, error) {
46	52		selected, err := ParseDebug(debug)

@@ -55,18 +61,22 @@ func Open(ctx context.Context, level, debug string) (context.Context, func() err
55	61		}
56	62		state = filepath.Join(home, ".local", "state")
57	63		}
58		-	dir := filepath.Join(state, "nefertty")
	64	+	dir := filepath.Join(state, "nefertty", "runs")
59	65		if err := os.MkdirAll(dir, 0o700); err != nil {
60	66		return nil, nil, err
61	67		}
62		-	path := filepath.Join(dir, "nefertty.log")
63		-	if err := os.Rename(path, path+".1"); err != nil && !os.IsNotExist(err) {
	68	+	name := time.Now().Format("20060102-150405.000") + ".log"
	69	+	file, err := os.OpenFile(filepath.Join(dir, name), os.O_CREATE\|os.O_EXCL\|os.O_WRONLY, 0o600)
	70	+	if err != nil {
64	71		return nil, nil, err
65	72		}
66		-	file, err := os.OpenFile(path, os.O_CREATE\|os.O_TRUNC\|os.O_WRONLY, 0o600)
67		-	if err != nil {
	73	+	latest := filepath.Join(dir, "latest.log")
	74	+	_ = os.Remove(latest)
	75	+	if err := os.Symlink(name, latest); err != nil {
	76	+	_ = file.Close()
68	77		return nil, nil, err
69	78		}
	79	+	pruneRuns(dir)
70	80		var output = zerowrap.Config{Level: level, Format: "json", Output: file}
71	81		if term.IsTerminal(int(os.Stderr.Fd())) {
72	82		output.Output = &consoleAndFile{file: file}

@@ -77,6 +87,15 @@ func Open(ctx context.Context, level, debug string) (context.Context, func() err
77	87		return ctx, file.Close, nil
78	88		}
79	89
	90	+	func pruneRuns(dir string) {
	91	+	runs, _ := filepath.Glob(filepath.Join(dir, "2*.log"))
	92	+	sort.Strings(runs)
	93	+	for len(runs) > keepRuns {
	94	+	_ = os.Remove(runs[0])
	95	+	runs = runs[1:]
	96	+	}
	97	+	}
	98	+
80	99		type consoleAndFile struct{ file *os.File }
81	100
82	101		func (w *consoleAndFile) Write(p []byte) (int, error) {

 	"fmt"
 	"os"
 	"path/filepath"
+	"sort"
 	"strings"
+	"time"
 	"github.com/bnema/zerowrap"
 	"github.com/rs/zerolog"
 	return selected, nil
 }
-// Open rotates the previous run's log, opens a fresh JSON log and attaches the logger to ctx.
+// keepRuns is how many per-run log files Open retains.
+const keepRuns = 20
+// Open creates runs/<timestamp>.log, points runs/latest.log at it, prunes old runs
+// and attaches the logger to ctx.
 // The caller must invoke close after all logging is complete.
 func Open(ctx context.Context, level, debug string) (context.Context, func() error, error) {
 	selected, err := ParseDebug(debug)
 		}
 		state = filepath.Join(home, ".local", "state")
 	}
-	dir := filepath.Join(state, "nefertty")
+	dir := filepath.Join(state, "nefertty", "runs")
 	if err := os.MkdirAll(dir, 0o700); err != nil {
 		return nil, nil, err
 	}
-	path := filepath.Join(dir, "nefertty.log")
+	name := time.Now().Format("20060102-150405.000") + ".log"
-	if err := os.Rename(path, path+".1"); err != nil && !os.IsNotExist(err) {
+	file, err := os.OpenFile(filepath.Join(dir, name), os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600)
+	if err != nil {
 		return nil, nil, err
 	}
-	file, err := os.OpenFile(path, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0o600)
+	latest := filepath.Join(dir, "latest.log")
-	if err != nil {
+	_ = os.Remove(latest)
+	if err := os.Symlink(name, latest); err != nil {
+		_ = file.Close()
 		return nil, nil, err
 	}
+	pruneRuns(dir)
 	var output = zerowrap.Config{Level: level, Format: "json", Output: file}
 	if term.IsTerminal(int(os.Stderr.Fd())) {
 		output.Output = &consoleAndFile{file: file}
 	return ctx, file.Close, nil
 }
+func pruneRuns(dir string) {
+	runs, _ := filepath.Glob(filepath.Join(dir, "2*.log"))
+	sort.Strings(runs)
+	for len(runs) > keepRuns {
+		_ = os.Remove(runs[0])
+		runs = runs[1:]
+	}
+}
 type consoleAndFile struct{ file *os.File }
 func (w *consoleAndFile) Write(p []byte) (int, error) {

M internal/logging/logging_test.go +8 -4


@@ -7,6 +7,7 @@ import (
7	7		"os"
8	8		"path/filepath"
9	9		"testing"
	10	+	"time"
10	11		)
11	12
12	13		func TestParseDebug(t *testing.T) {

@@ -32,8 +33,10 @@ func TestParseDebug(t *testing.T) {
32	33
33	34		func TestComponentLevelsAndRotation(t *testing.T) {
34	35		t.Setenv("XDG_STATE_HOME", t.TempDir())
35		-	path := filepath.Join(os.Getenv("XDG_STATE_HOME"), "nefertty", "nefertty.log")
36		-	for run := 0; run < 2; run++ {
	36	+	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "nefertty", "runs")
	37	+	path := filepath.Join(dir, "latest.log")
	38	+	for run := 0; run < keepRuns+2; run++ {
	39	+	time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
37	40		ctx, closeLog, err := Open(context.Background(), "info", "core")
38	41		if err != nil {
39	42		t.Fatal(err)

@@ -64,8 +67,9 @@ func TestComponentLevelsAndRotation(t *testing.T) {
64	67		}
65	68		}
66	69		}
67		-	if _, err := os.Stat(path + ".1"); err != nil {
68		-	t.Fatal(err)
	70	+	runs, _ := filepath.Glob(filepath.Join(dir, "2*.log"))
	71	+	if len(runs) != keepRuns {
	72	+	t.Fatalf("kept %d runs, want %d", len(runs), keepRuns)
69	73		}
70	74		}
71	75

 	"os"
 	"path/filepath"
 	"testing"
+	"time"
 )
 func TestParseDebug(t *testing.T) {
 func TestComponentLevelsAndRotation(t *testing.T) {
 	t.Setenv("XDG_STATE_HOME", t.TempDir())
-	path := filepath.Join(os.Getenv("XDG_STATE_HOME"), "nefertty", "nefertty.log")
+	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "nefertty", "runs")
-	for run := 0; run < 2; run++ {
+	path := filepath.Join(dir, "latest.log")
+	for run := 0; run < keepRuns+2; run++ {
+		time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
 		ctx, closeLog, err := Open(context.Background(), "info", "core")
 		if err != nil {
 			t.Fatal(err)
 			}
 		}
 	}
-	if _, err := os.Stat(path + ".1"); err != nil {
+	runs, _ := filepath.Glob(filepath.Join(dir, "2*.log"))
-		t.Fatal(err)
+	if len(runs) != keepRuns {
+		t.Fatalf("kept %d runs, want %d", len(runs), keepRuns)
 	}
 }