fix(logger): rotate a file log that names no rotation

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 <noreply@stepfun.com>
This commit is contained in:
ginuerzh
2026-10-13 02:40:19 +00:00
parent 49c998ee45
commit 8d253dcd88
3 changed files with 147 additions and 33 deletions
@@ -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.
+37 -32
View File
@@ -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 {
if cfg.Rotation == nil {
cfg.Rotation = defaultLogRotation()
}
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
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
+82
View File
@@ -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)
}
}
}
}