From 8d253dcd88fce9da0b680614ba9be9946b9b3931 Mon Sep 17 00:00:00 2001 From: ginuerzh Date: Tue, 13 Oct 2026 02:40:19 +0000 Subject: [PATCH] fix(logger): rotate a file log that names no rotation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A log config can name an output without naming a rotation, and that combination used to receive a plain *os.File — nothing rotates it, ever. One spoke on Android ran debug-level logging into exactly that shape and grew the file to 111MB with no backups, which on a phone is not untidy so much as fatal. Default the rotation instead. The values match what an unconfigured logger has always carried, so naming an output is no longer a way to ask for an unbounded file, and a configured rotation still wins as written. outputWriter is split out of ParseLogger so the decision — the part that chooses whether a file log stops growing — is testable without a logger. Signed-off-by: Step 5 Preview Free --- .../2026-10-07-tun-device-probe/progress.md | 27 ++++++ config/parsing/logger/parse.go | 71 ++++++++-------- config/parsing/logger/parse_test.go | 82 +++++++++++++++++++ 3 files changed, 147 insertions(+), 33 deletions(-) create mode 100644 .superpowers/sdd/2026-10-07-tun-device-probe/progress.md diff --git a/.superpowers/sdd/2026-10-07-tun-device-probe/progress.md b/.superpowers/sdd/2026-10-07-tun-device-probe/progress.md new file mode 100644 index 0000000..6b543b5 --- /dev/null +++ b/.superpowers/sdd/2026-10-07-tun-device-probe/progress.md @@ -0,0 +1,27 @@ +# SDD ledger — plan: x/docs/superpowers/plans/2026-10-07-tun-device-probe.md + +Ruling: sdd-workspace script absent in this skill install (only task-start/task-done exist) — workspace created manually at x/.superpowers/sdd/2026-10-07-tun-device-probe/. Cost if wrong: none, git-ignored scratch. + +Pre-flight shared-interface rows: +- T1→T2: md.probe/probeReport + runDeviceProbe signature. Plan pins report func(sentDelta, ackedDelta uint64); runDeviceProbe assumes non-nil (nil guard lives in probeDevice). No conflict. +- T1+T2→T3: h.md.probe/probeReport, runDeviceProbe, handleClient iterCtx/conn/ips. handleClient shape to verify in code recon before wiring. +- T3→T4: only files + green suite; no interface. + +Task 1: complete (no commit per plan Global Constraints; tests: go test -count=1 ./handler/tun/ ./observer/stats/ → both ok, tun 14.356s). +Ruling: metadata constructor alias is xmd (github.com/go-gost/x/metadata), not mdx as plan Step 1 guessed — plan told me to grep first, did. Cost if wrong: nil. +Task 2: complete (no commit per plan Global Constraints; tests: go test -count=1 ./handler/tun/ → ok 14.987s). +Ruling: probeInterval/probeRecvTimeout are vars not consts (plan pinned values 30s/5s kept; tests override). Pinned signature runDeviceProbe(ctx,dev,ip,report,log) unchanged. Cost if wrong: nil. +Ruling: wrote runDeviceProbe impl before its loop test, caught it, deleted impl, re-did RED (undefined) → GREEN. Cost if wrong: unproven test. +Ruling: loop tests use atomic counters + polling (net.Pipe Read returns before writer Write/report; plain vars would race). Plan sketch used plain vars. Cost if wrong: flaky test. +Task 3: complete (no commit per plan Global Constraints; tests: go test -count=1 ./handler/tun/ ./observer/stats/ → both ok). +Note: gofmt -l flags observer/stats/wrapper/io_test.go — pre-existing, untouched (not in git status). My files clean; go vet clean. +Ruling: probeDevice takes no log param (uses h.options.Logger, same as keepalive); conn at the wire site IS the tun device (transportClient(ctx, tun=conn, ...) proves it). Cost if wrong: probe writes into the tunnel stream. +Task 4: green to the release gate (build ./... + both suites PASS). STOPPING before tag+push: publish side effect, maintainer-manual per plan + repo no-push norm. Awaiting human: commit + tag v0.23.0. +Final: fresh review via subagent. C1 (UDP length 16→must be 24, acked could never fire on real device) — confirmed real, re-graded Critical stands. +Final: fixed C1 — TestBuildProbePacket UDP-length assertion RED→GREEN, suite handler/tun ok. +Final: fixed I1 (Reset forgot probe counters) — TestStatsProbeReset RED→GREEN, suite observer/stats ok. +Final: minor (deferred): M1 redial overlap — old probe writes ≤5s alongside new after iterCtx cancel; datagram-atomic, self-healing. +Final: minor (deferred): M2 log assumed non-nil in probe paths. +Final: minor (deferred): M3 gate goroutine spawn on probeReport != nil to avoid one throwaway goroutine per redial on gost path. +Final: reviewer declined go toolchain — overruled, tests ran under /root/.local/go/bin (see memory dev-container-toolchain); kernel trim-vs-drop of len-16 packet no longer matters post-fix; water-driver atomicity stands on datagram semantics + keepalive precedent. +Pre-release workspace check (GOWORK=/root/opencode/probework/go.work, x+wisper+gost): go build ./... all three OK; wisper ./tunnel/... PASS (14.6s/15.3s); x handler/tun + observer/stats PASS. diff --git a/config/parsing/logger/parse.go b/config/parsing/logger/parse.go index 540e461..3771a06 100644 --- a/config/parsing/logger/parse.go +++ b/config/parsing/logger/parse.go @@ -1,10 +1,8 @@ package logger import ( - "fmt" "io" "os" - "path/filepath" "github.com/go-gost/core/logger" "github.com/go-gost/x/config" @@ -26,8 +24,34 @@ func ParseLogger(cfg *config.LoggerConfig) logger.Logger { xlogger.LevelOption(logger.LogLevel(cfg.Log.Level)), } + opts = append(opts, xlogger.OutputOption(outputWriter(cfg.Log))) + + return xlogger.NewLogger(opts...) +} + +// defaultLogRotation is what a file log gets when its config leaves the +// rotation out. It matches what an unconfigured logger has always carried, so +// a log: section that names an output but no rotation is not a way to ask for +// an unbounded file. +// +// The reason this is a default rather than a warning: an unrotated debug log +// is not untidy, it stops the device. A spoke's log section with no rotation: +// key grew to 111MB with no backups, on a phone. +func defaultLogRotation() *config.LogRotationConfig { + return &config.LogRotationConfig{ + MaxSize: 10, + MaxAge: 7, + MaxBackups: 10, + LocalTime: true, + } +} + +// outputWriter resolves the LogConfig's output to the writer that receives the +// lines. Split out of ParseLogger so the rotation decision — the part that +// decides whether a file log stops growing — is reachable without a logger. +func outputWriter(cfg *config.LogConfig) io.Writer { var out io.Writer = os.Stderr - switch cfg.Log.Output { + switch cfg.Output { case "none", "null": out = io.Discard case "stdout": @@ -35,38 +59,19 @@ func ParseLogger(cfg *config.LoggerConfig) logger.Logger { case "stderr", "": out = os.Stderr default: - if cfg.Log.Rotation != nil { - out = &lumberjack.Logger{ - Filename: cfg.Log.Output, - MaxSize: cfg.Log.Rotation.MaxSize, - MaxAge: cfg.Log.Rotation.MaxAge, - MaxBackups: cfg.Log.Rotation.MaxBackups, - LocalTime: cfg.Log.Rotation.LocalTime, - Compress: cfg.Log.Rotation.Compress, - } - } else { - // Nothing rotates this file, and it is the only place that sees both - // the path and the missing rotation — the default (an unconfigured - // logger) always carries one. - fmt.Fprintf(os.Stderr, "logger: %s has no rotation configured: it will grow without bound\n", cfg.Log.Output) - os.MkdirAll(filepath.Dir(cfg.Log.Output), 0755) - f, err := os.OpenFile(cfg.Log.Output, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666) - if err != nil { - // Reported on stderr, not through logger.Default(): that logger - // is what this call is on its way to installing and is nil until - // it is — calling a method on it panics, which aborted the whole - // process on a log path that could not be opened (an app whose - // working directory is not writable, say). A log file that - // cannot be opened leaves the default output in place instead. - fmt.Fprintf(os.Stderr, "logger: open %s: %v (logging to stderr)\n", cfg.Log.Output, err) - } else { - out = f - } + if cfg.Rotation == nil { + cfg.Rotation = defaultLogRotation() + } + out = &lumberjack.Logger{ + Filename: cfg.Output, + MaxSize: cfg.Rotation.MaxSize, + MaxAge: cfg.Rotation.MaxAge, + MaxBackups: cfg.Rotation.MaxBackups, + LocalTime: cfg.Rotation.LocalTime, + Compress: cfg.Rotation.Compress, } } - opts = append(opts, xlogger.OutputOption(out)) - - return xlogger.NewLogger(opts...) + return out } // List resolves one or more logger names from the registry. It returns only diff --git a/config/parsing/logger/parse_test.go b/config/parsing/logger/parse_test.go index 90e3f0a..f383b89 100644 --- a/config/parsing/logger/parse_test.go +++ b/config/parsing/logger/parse_test.go @@ -5,11 +5,13 @@ import ( "io" "os" "os/exec" + "path/filepath" "testing" "github.com/go-gost/core/logger" "github.com/go-gost/x/config" xlogger "github.com/go-gost/x/logger" + "gopkg.in/natefinch/lumberjack.v2" ) // probeEnv marks the child process TestParseLogger_UnopenableOutput spawns: @@ -180,3 +182,83 @@ func TestParseLogger_UnopenableOutput(t *testing.T) { t.Fatalf("a log file that cannot be opened must not be fatal:\n%s", out) } } + +// TestParseLoggerUnrotatedFileRotates is the defect that filled a phone's +// storage. A log: section without a rotation: key used to get a plain +// *os.File — nothing rotates it — and one debug-level spoke grew it to 111MB +// with no backups, which on a phone is not untidy so much as fatal. +// +// The default rotation is what the unconfigured logger already carries, so +// naming one should not be a way to opt out of it. +func TestParseLoggerUnrotatedFileRotates(t *testing.T) { + file := filepath.Join(t.TempDir(), "wisper.log") + cfg := &config.LoggerConfig{ + Log: &config.LogConfig{ + Output: file, + Level: "debug", + Format: "json", + // Rotation deliberately absent: the shape wisper.yaml on Android has. + }, + } + + w := outputWriter(cfg.Log) + if w == nil { + t.Fatal("outputWriter = nil") + } + if _, ok := w.(*lumberjack.Logger); !ok { + t.Fatalf("outputWriter = %T, want a *lumberjack.Logger so the file rotates", w) + } + + lg := w.(*lumberjack.Logger) + if lg.Filename != file { + t.Errorf("Filename = %q, want %q", lg.Filename, file) + } + if lg.MaxSize <= 0 || lg.MaxBackups <= 0 { + t.Errorf("rotation is off: MaxSize=%d MaxBackups=%d, want both positive", lg.MaxSize, lg.MaxBackups) + } +} + +// TestParseLoggerExplicitRotationWins: a configured rotation is respected as +// written, so the default is only a floor for what was left out. +func TestParseLoggerExplicitRotationWins(t *testing.T) { + file := filepath.Join(t.TempDir(), "wisper.log") + cfg := &config.LoggerConfig{ + Log: &config.LogConfig{ + Output: file, + Rotation: &config.LogRotationConfig{ + MaxSize: 33, + MaxBackups: 5, + }, + }, + } + + lg, ok := outputWriter(cfg.Log).(*lumberjack.Logger) + if !ok { + t.Fatalf("outputWriter = %T, want *lumberjack.Logger", outputWriter(cfg.Log)) + } + if lg.MaxSize != 33 || lg.MaxBackups != 5 { + t.Errorf("MaxSize=%d MaxBackups=%d, want 33 and 5 as configured", lg.MaxSize, lg.MaxBackups) + } +} + +// TestParseLoggerNotAFileStillGoesToTheSink: stderr/stdout/none are unaffected, +// so defaulting the rotation cannot leak a file into a stream. +func TestParseLoggerNotAFileStillGoesToTheSink(t *testing.T) { + for _, out := range []string{"stderr", "stdout", "none", ""} { + w := outputWriter(&config.LogConfig{Output: out}) + switch out { + case "none": + if w != io.Discard { + t.Errorf("none: writer = %T, want io.Discard", w) + } + case "stdout": + if w != os.Stdout { + t.Errorf("stdout: writer = %T, want os.Stdout", w) + } + default: + if w != os.Stderr { + t.Errorf("%q: writer = %T, want os.Stderr", out, w) + } + } + } +}