feat(logsink): shaterd's own operational log — download, size cap, real disable

The daemon's own log (engine + control-plane) went only to os.Stderr →
procd → the logread RAM ring: no file, no wall-clock timestamps, no size
cap, and "LogLevel=none" silenced ONLY the engine while the control-plane
kept writing at trace. So "download last day/3d/all", "limit the size" and
"fully turn it off" were all unmet.

New shater/logsink: one long-lived, atomically-reconfigurable Sink that
receives BOTH halves' byte streams, stamps every complete line with a UTC
RFC3339 wall clock (what makes date ranges real), and fans each line to a
size-capped 2-segment rotated file (ToFile) and/or the real os.Stderr
(ToSyslog). Both off = the line is dropped — the only true full silence.
Persistent path sits behind a stats-style disk-free guard (suspend+warn
once, auto-resume); tmpfs path is bounded by the cap itself. ANSI stripped
from the file copy only.

Wiring: control-plane via log.SetStdLogger over the sink; engine via a new
box.Options.DefaultLogWriter threaded into all three box.New sites
(apply/close-then-start/restore) by engine.SetDefaultLogWriter; live
reconfigure on every apply.Reconcile (SIGHUP / control socket / panel
apply) so panel changes take effect without a daemon restart.
controlLogLevel now makes the control-plane respect Globals.LogLevel
(silent vocab → panic-only; unknown → warn, mirroring generate).

Globals: LogToSyslog/LogToFile (default true), LogPersist (default false =
/var/log tmpfs; true = /etc/shater flash), LogMaxKB (default 2048, clamped
[128,8192]; 0 = default, not off — LogToFile is the off switch). UCI
parse/render/aliases + ValidateGlobals clamp-warn.

Endpoint GET /api/log?range=1d|3d|all (session-gated): streams the log line
by line, oldest segment first, filtered by the timestamp prefix; UTC
attachment filename. Honest fallbacks — file off + syslog on → a
"# note: … syslog ring only, ranges approximate" comment then a
`logread -e shater` scrape; both off → "# logging disabled". Unknown range
→ 400.

init.d: shater/shater-cron gate their `logger -t` status lines on
log_syslog so "logread off" is honest at the shell layer too.

Tests: logsink rotation-cap/timestamp/toggle-gating/engine→sink,
model round-trip + validate, endpoint session-gate/range/fallbacks.
VM-verified on QEMU (x86_64, OpenWrt 24.10): download+ranges, size-cap
rotation, file-off/full-off, persistent path, live reconfigure — all green.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
2026-07-23 01:18:45 +03:00
co-authored by Claude Fable 5
parent 278e50aa61
commit f573af9a5f
19 changed files with 1510 additions and 10 deletions
+15
View File
@@ -64,6 +64,16 @@ type Options struct {
option.Options
Context context.Context
PlatformLogWriter log.PlatformWriter
// lx:begin shaterd_logsink
// DefaultLogWriter, when non-nil, is where the box log goes while
// options.Log.Output is unset — replacing log.New's nil->os.Stderr default.
// The shater daemon passes its long-lived logsink here (via
// engine.SetDefaultLogWriter) so every Apply-swapped box writes into the
// same reconfigurable sink instead of raw stderr. It takes precedence over
// the platform-interface io.Discard fallback below: an embedder that
// supplies a writer wants the log, explicitly.
DefaultLogWriter io.Writer
// lx:end
}
func Context(
@@ -181,6 +191,11 @@ func New(options Options) (*Box, error) {
if platformInterface != nil {
defaultLogWriter = io.Discard
}
// lx:begin shaterd_logsink — an explicitly-supplied default writer wins.
if options.DefaultLogWriter != nil {
defaultLogWriter = options.DefaultLogWriter
}
// lx:end
logFactory, err := log.New(log.Options{
Context: ctx,
Options: common.PtrValueOrDefault(options.Log),
+10 -1
View File
@@ -57,6 +57,15 @@ shater_enabled() {
[ "$en" = "1" ]
}
# Syslog line that honors globals.log_syslog — the SAME toggle that silences the
# daemon's own stderr->logread stream. With log_syslog=0 the operator asked for
# a silent syslog, and shell status lines emitted AROUND the binary must not
# leak past the binary's silence. Absent option (or unreadable UCI) = ON, which
# matches the daemon's default.
_slog() {
[ "$(uci -q get shater.globals.log_syslog)" = "0" ] || logger -t shater "$@"
}
# --- procd lifecycle -------------------------------------------------------
start_service() {
@@ -73,7 +82,7 @@ start_service() {
# shaterd upgrade must degrade to "plugin off", not to a box that thinks
# interception is live with nothing behind it.
if [ ! -x "$PROG" ]; then
logger -t shater -p daemon.err \
_slog -p daemon.err \
"shaterd binary missing/not executable at $PROG — refusing to start (LAN stays on plain routing)"
return 0
fi
@@ -58,6 +58,14 @@ shater_enabled() {
[ "$en" = "1" ]
}
# Syslog line that honors globals.log_syslog (same helper as /etc/init.d/shater,
# with this service's tag): with log_syslog=0 the operator asked for a silent
# syslog and the watchdog/updater status lines respect that too. Absent option
# (or unreadable UCI) = ON.
_slog() {
[ "$(uci -q get shater.globals.log_syslog)" = "0" ] || logger -t shater-cron "$@"
}
# The main service raised its live-flag (start) and has not stopped since.
shater_active() {
[ -f "$ACTIVE_FLAG" ]
@@ -142,7 +150,7 @@ shater_run_due() {
shater_stamp "$stamp"
changed=1
else
logger -t shater-cron -p daemon.warn \
_slog -p daemon.warn \
"sub update '$name' failed; retrying in ${RETRY_SECS}s"
shater_stamp_retry "$stamp" "$secs"
fi
@@ -165,7 +173,7 @@ shater_run_due() {
shater_stamp "$stamp"
changed=1
else
logger -t shater-cron -p daemon.warn \
_slog -p daemon.warn \
"ruleset update '$name' failed; retrying in ${RETRY_SECS}s"
shater_stamp_retry "$stamp" "$secs"
fi
@@ -207,7 +215,7 @@ shater_run_due_blocklists() {
if [ "$fired" = "ok" ]; then
shater_stamp "$stamp"
else
logger -t shater-cron -p daemon.warn \
_slog -p daemon.warn \
"blocklist update '$name' failed; retrying in ${RETRY_SECS}s"
shater_stamp_retry "$stamp" "$secs"
fi
@@ -233,13 +241,13 @@ shater_watchdog() {
if [ "$ks" = "closed" ]; then
# Fail-closed is a POLICY: dead engine + standing rules == traffic
# blocked, which is what the admin asked for. Keep it, but say so.
logger -t shater-cron -p daemon.crit \
_slog -p daemon.crit \
"shaterd dead for $(( dead * TICK ))s with interception live; kill_switch=closed keeps LAN blocked — fix the daemon or /etc/init.d/shater stop"
else
# Fail-open: durably stop the stack (clears the live-flag; the daemon
# — or its next respawn — tears interception down) so the LAN returns
# to plain routing.
logger -t shater-cron -p daemon.crit \
_slog -p daemon.crit \
"shaterd dead for $(( dead * TICK ))s with interception live; kill_switch=open — stopping shater (fail-open, LAN back to plain routing)"
"$SHATER_INIT" stop
dead=0
+18
View File
@@ -113,6 +113,16 @@ type Applier struct {
// leaves it nil and the real Apply runs; tests substitute a recorder so the
// arm/disarm decision can be asserted without standing up a real engine.
rollbackApply func(*model.Model) (bool, error)
// logReconfigure, when set, receives the freshly-read Globals at the top of
// every Reconcile — the one funnel every live config change passes through
// (SIGHUP, control-socket apply, panel POST /api/apply) — so the daemon's
// log sink picks up changed toggles/cap/path without a restart. It fires
// BEFORE the apply/teardown and regardless of whether they later succeed:
// an operator flips the log knobs precisely when an apply is failing, and a
// hook gated on success would withhold the very setting needed to debug it.
// Set once at daemon startup, before the Applier is shared — unsynchronized.
logReconfigure func(model.Globals)
}
// New returns an Applier bound to the daemon's single engine. logger may be nil
@@ -124,6 +134,11 @@ func New(eng *engine.Engine, logger log.ContextLogger) *Applier {
return &Applier{eng: eng, log: logger}
}
// SetLogReconfigure installs the daemon's log-sink reconfiguration hook (see
// the logReconfigure field). Must be called before the Applier is shared with
// other goroutines — the field is not synchronized.
func (a *Applier) SetLogReconfigure(fn func(model.Globals)) { a.logReconfigure = fn }
// LastGood returns the last successfully-applied model, or nil.
func (a *Applier) LastGood() *model.Model {
a.mu.Lock()
@@ -662,6 +677,9 @@ func (a *Applier) Reconcile() (changed bool, err error) {
if err != nil {
return false, err
}
if a.logReconfigure != nil {
a.logReconfigure(m.Globals)
}
if !m.Globals.Enabled {
return false, a.Teardown()
}
+68
View File
@@ -23,6 +23,7 @@ package main
import (
"bufio"
"context"
"encoding/json"
"errors"
"fmt"
@@ -42,6 +43,7 @@ import (
"github.com/sagernet/sing-box/shater/apply"
"github.com/sagernet/sing-box/shater/devices"
"github.com/sagernet/sing-box/shater/engine"
"github.com/sagernet/sing-box/shater/logsink"
"github.com/sagernet/sing-box/shater/model"
"github.com/sagernet/sing-box/shater/netplane"
"github.com/sagernet/sing-box/shater/panel"
@@ -140,8 +142,36 @@ func notImpl(verb string) int {
// --- run: THE daemon --------------------------------------------------------
func cmdRun() int {
// The shared operational-log sink (shater/logsink): EVERY line of the daemon
// AND of the embedded engine flows through it. It stamps each line with a
// UTC wall-clock timestamp and fans it to the file (rotated, size-capped)
// and/or the REAL os.Stderr (procd -> logread) per the Globals toggles —
// both off is a fully silent process. Until UCI is read below it runs on
// the DefaultGlobals config (syslog on, file on, tmpfs, 2048 KiB), so the
// very first startup lines are captured too.
sink := logsink.New(os.Stderr, logsink.ConfigFromGlobals(model.DefaultGlobals()))
defer func() { _ = sink.Close() }()
// Rebuild the process-wide std logger ON TOP of the sink and install it, so
// every existing log.StdLogger() consumer (engine deprecation notes, apply,
// panel, alerts, stats) writes through the sink instead of raw os.Stderr.
// The level starts at trace (nothing read yet) and is corrected from
// Globals.LogLevel as soon as UCI is read — the control plane now RESPECTS
// the configured level instead of the old unconditional trace.
logFactory := log.NewDefaultFactory(context.Background(),
log.Formatter{BaseTime: time.Now()}, sink, "", nil, false)
log.SetStdLogger(logFactory.Logger())
logger := log.StdLogger()
// reconfigureLog points the sink + the control-plane verbosity at freshly
// read globals. Wired into the Applier below so EVERY Reconcile (SIGHUP,
// control socket, panel apply) re-applies the log settings live — a panel
// change takes effect without a daemon restart.
reconfigureLog := func(g model.Globals) {
sink.Reconfigure(logsink.ConfigFromGlobals(g))
logFactory.SetLevel(controlLogLevel(g.LogLevel))
}
// Refuse to start a second daemon (race-safe single-owner guard). procd's
// term_timeout ensures the previous instance exits before reload restarts us.
if pid, ok := daemonAlive(); ok && pid != os.Getpid() {
@@ -163,13 +193,25 @@ func cmdRun() int {
}
eng := engine.New(logger)
// Point every box the engine will ever build at the shared sink: the
// engine's internal log (option.LogOptions with no Output) then lands in
// the same file/syslog fan-out as the control-plane lines, and the toggles
// govern both halves at once. Must be set before the first Apply.
eng.SetDefaultLogWriter(sink)
applier := apply.New(eng, logger)
applier.SetLogReconfigure(reconfigureLog)
// Read the desired state ONCE at startup: it drives the initial apply, the panel
// listen address (globals.panel_port), and the stats-retention knobs. On a read
// error we stay up with zero-value globals (panel falls back to the env gate below,
// and the aggregator's Config{} uses its built-in defaults).
m, readErr := model.ReadUCI()
if readErr == nil {
// Apply the operator's log settings as early as possible; later changes
// arrive through the Applier's Reconcile hook. On a read error the sink
// keeps its safe defaults (log everything, tmpfs-capped).
reconfigureLog(m.Globals)
}
// Phase-5 statistics aggregator: subscribes to the engine's DNS-query + connection
// event streams and polls the nft counters, feeding /api/stats(/log). Its
@@ -341,6 +383,32 @@ func cmdRun() int {
// apperr is a tiny adapter so the (changed, err) tuple can be logged inline.
func apperr(changed bool, err error) (bool, error) { return changed, err }
// controlLogLevel maps Globals.LogLevel onto the CONTROL-PLANE factory level —
// the same vocabulary the engine consumes (generate.logOptions/logLevel), with
// the same fail-safe fallback:
//
// - engine levels (trace..panic, both warn spellings) parse to themselves;
// - the silent vocabulary (model.SilentLogLevels) quiets the factory to
// panic-only — the QUIETEST a level can express. It is deliberately NOT
// claimed to be full silence: full process silence is the sink's
// LogToSyslog/LogToFile toggles, which drop every line regardless of level
// (and the engine half really is NOP'd via LogOptions.Disabled);
// - anything else (typo, "") falls back to warn, mirroring generate.logLevel —
// an unknown value must not change the daemon's voice more than it changes
// the engine's.
func controlLogLevel(s string) log.Level {
v := strings.ToLower(strings.TrimSpace(s))
for _, silent := range model.SilentLogLevels {
if v == silent {
return log.LevelPanic
}
}
if lvl, err := log.ParseLevel(v); err == nil {
return lvl
}
return log.LevelWarn
}
// fireApplyFail raises ONE incident for an apply/reconcile error observed while
// the plane is enabled. The incident satisfies both the `killswitch` and
// `apply_fail` subscriptions.
+26 -4
View File
@@ -23,6 +23,7 @@ import (
"encoding/hex"
"errors"
"fmt"
"io"
"net/netip"
"strings"
"sync"
@@ -60,6 +61,13 @@ type Engine struct {
current option.Options // options the running Box was built from
hash string // stable hash of current (hex sha256 of canonical JSON)
// defaultLogWriter, when non-nil, is handed to EVERY box.New this engine
// performs (box.Options.DefaultLogWriter): the daemon points it at its
// long-lived logsink once, and each Apply-swapped box then logs into that
// same sink — file/syslog toggles, rotation and the size cap all live in
// the sink, stable across swaps. Guarded by mu (every box.New holds it).
defaultLogWriter io.Writer
lastGood option.Options // last known-good options (the config running BEFORE current)
hasLastGood bool // false until a second successful Apply gives us a predecessor
@@ -188,8 +196,9 @@ func (e *Engine) applyLocked(opts option.Options) (bool, error) {
// (2) build + validate. box.New constructs and validates every adapter.
nb, err := box.New(box.Options{
Context: e.ctx,
Options: opts,
Context: e.ctx,
Options: opts,
DefaultLogWriter: e.defaultLogWriter,
})
if err != nil {
// Validation failed: keep the running instance, do not swap.
@@ -274,7 +283,7 @@ func (e *Engine) closeOldThenStart(discard *box.Box, opts option.Options, newHas
e.instance = nil
// (c) Build a FRESH box for opts (the discarded one cannot be reused).
nb2, err := box.New(box.Options{Context: e.ctx, Options: opts})
nb2, err := box.New(box.Options{Context: e.ctx, Options: opts, DefaultLogWriter: e.defaultLogWriter})
if err == nil {
err = nb2.Start()
if err != nil {
@@ -294,7 +303,7 @@ func (e *Engine) closeOldThenStart(discard *box.Box, opts option.Options, newHas
// (e) The fresh box could not come up and the old one is already closed —
// interception is currently down. Try to RESTORE the previous config so we
// do not leave the tunnel dead.
rb, rerr := box.New(box.Options{Context: e.ctx, Options: prevOpts})
rb, rerr := box.New(box.Options{Context: e.ctx, Options: prevOpts, DefaultLogWriter: e.defaultLogWriter})
if rerr == nil {
rerr = rb.Start()
if rerr != nil {
@@ -371,6 +380,19 @@ func cacheFileLockPath(o option.Options) string {
return o.Experimental.CacheFile.Path
}
// SetDefaultLogWriter installs the writer every SUBSEQUENT box built by this
// engine uses as its default log output (box.Options.DefaultLogWriter → the
// nil->os.Stderr slot in log.New). The daemon calls it ONCE, before the first
// Apply, with its long-lived logsink; nil keeps log.New's own os.Stderr
// default. The already-running box (if any) is not retargeted — its log writer
// was fixed at box.New time — which is fine for the one real caller (set
// before anything runs).
func (e *Engine) SetDefaultLogWriter(w io.Writer) {
e.mu.Lock()
defer e.mu.Unlock()
e.defaultLogWriter = w
}
// Rollback re-applies the last known-good configuration — i.e. the config that
// was running immediately before the current one. It returns an error if no
// such predecessor exists (fewer than two successful Applies so far). On
+11
View File
@@ -0,0 +1,11 @@
//go:build !linux && !darwin
package logsink
// freeBytes on platforms without Statfs (the Windows dev host) honestly reports
// "cannot be determined": the guard then fails open for logging, and the size
// cap alone bounds the file. The daemon only ships on Linux, where the real
// probe in diskfree_unix.go applies.
func freeBytes(string) (uint64, bool) {
return 0, false
}
+26
View File
@@ -0,0 +1,26 @@
//go:build linux || darwin
package logsink
import (
"path/filepath"
"syscall"
)
// freeBytes reports the space actually available on the filesystem holding
// path, and whether it could be determined at all. Same shape and reasoning as
// stats/diskfree_unix.go — the persistent log path lives on a rootfs with only
// tens of MB free, so the sink must be able to yield under disk pressure
// instead of contributing to it.
func freeBytes(path string) (uint64, bool) {
var st syscall.Statfs_t
if err := syscall.Statfs(path, &st); err != nil {
// The directory may not exist yet; fall back to its parent.
if err := syscall.Statfs(filepath.Dir(path), &st); err != nil {
return 0, false
}
}
// Bavail is blocks available to an unprivileged process (Bfree includes the
// root-reserved pool, which we must not count on).
return uint64(st.Bavail) * uint64(st.Bsize), true
}
+420
View File
@@ -0,0 +1,420 @@
// Package logsink is the shared OPERATIONAL log sink of the shaterd daemon.
//
// One long-lived *Sink receives the raw log byte stream of BOTH halves of the
// process — the control-plane logger (cmd/shaterd builds its log factory over
// the sink and installs it via log.SetStdLogger) and the embedded sing-box
// engine (the engine passes the same sink into every box it builds, via
// box.Options.DefaultLogWriter) — so every Apply-swapped box and every daemon
// goroutine writes into the SAME place, and the operator's toggles apply to the
// whole process at once.
//
// What the sink does with each COMPLETE line (Write may deliver fragments; the
// sink buffers until '\n'):
//
// - prefixes it with a wall-clock timestamp in UTC RFC3339. The producers'
// formatters only carry seconds-since-start ("INFO[0012]"), which cannot
// answer "give me the last day" — the prefix is what makes the download
// ranges real. UTC only: the binary ships without tzdata, so any local-zone
// rendering would be a fiction.
// - fans it out according to Config: to the REAL os.Stderr (procd relays fd2
// to syslog/logread) when ToSyslog, and to a size-capped, 2-segment rotated
// file when ToFile. Both off => the line is dropped — that IS the "fully
// silent" the toggles promise, there is no hidden third copy.
//
// The file is capped at ~MaxKB total across two segments: when the active
// segment would exceed MaxKB/2 it is renamed to "<path>.1" (replacing the
// previous .1) and a fresh active segment is started. The persistent path
// additionally sits behind a disk-free guard (same reasoning as
// stats/diskfree_unix.go: the rootfs of a shater router has ~33 MB free and
// filling it takes down far more than logging) — when space runs low the sink
// stops writing the file and says so ONCE, instead of crashing the daemon or
// filling the disk. The tmpfs path needs no guard: the cap itself is its budget.
//
// Reconfigure swaps toggles/cap/path atomically at runtime, so a panel apply
// changes logging behaviour without a daemon restart. All methods are safe for
// concurrent use.
package logsink
import (
"bytes"
"fmt"
"io"
"os"
"path/filepath"
"sync"
"time"
"github.com/sagernet/sing-box/shater/model"
)
const (
// PersistPath / TmpfsPath are the two file locations Globals.LogPersist
// selects between: /etc/shater survives a reboot (and wears flash),
// /var/log is tmpfs (free writes, lost on reboot).
PersistPath = "/etc/shater/shaterd.log"
TmpfsPath = "/var/log/shaterd.log"
// maxPartialLine caps the un-terminated tail buffered while waiting for a
// '\n'. A producer that never sends one (should not happen — both log
// formatters terminate every message) would otherwise grow the buffer
// without bound; instead the tail is flushed as a line of its own.
maxPartialLine = 8 * 1024
// diskProbeEvery is how often the persistent-path disk-free guard re-probes
// the filesystem. Statfs per line would be silly; a minute of staleness on
// a "disk is filling up" verdict is fine.
diskProbeEvery = time.Minute
// diskFloorBytes is the margin the persistent path must keep free BEYOND
// the log's own cap: the guard requires cap+floor available, so even a log
// that grows to its full cap leaves the rootfs this much headroom.
diskFloorBytes = 4 << 20
)
// FilePath returns the log-file location for the given persistence choice.
// The panel's /api/log handler uses it to find the same file the sink writes.
func FilePath(persist bool) string {
if persist {
return PersistPath
}
return TmpfsPath
}
// Config is the sink's runtime configuration — the log-related Globals knobs,
// resolved (see ConfigFromGlobals).
type Config struct {
ToSyslog bool // fan lines to the stderr writer (procd -> logread)
ToFile bool // fan lines to the rotated file
Persist bool // file at PersistPath (flash) instead of TmpfsPath
MaxKB int // total file budget in KiB across both segments
// Path overrides the Persist-derived file location. It exists for tests and
// embedders; production leaves it "" (ConfigFromGlobals never sets it).
Path string
}
// normalized clamps MaxKB into the model's documented bounds. <=0 becomes the
// default — 0 is NOT "file off" (ToFile is); model.ValidateGlobals warns about
// out-of-range values so the clamp never disagrees silently with the operator.
func (c Config) normalized() Config {
if c.MaxKB <= 0 {
c.MaxKB = model.LogMaxKBDefault
}
if c.MaxKB < model.LogMaxKBMin {
c.MaxKB = model.LogMaxKBMin
}
if c.MaxKB > model.LogMaxKBMax {
c.MaxKB = model.LogMaxKBMax
}
return c
}
// path resolves the effective file location.
func (c Config) path() string {
if c.Path != "" {
return c.Path
}
return FilePath(c.Persist)
}
// ConfigFromGlobals maps the model's log knobs onto a sink Config (clamped).
// It lives here — next to the consumer — so the daemon and the applier hook
// cannot drift apart on the mapping.
func ConfigFromGlobals(g model.Globals) Config {
return Config{
ToSyslog: g.LogToSyslog,
ToFile: g.LogToFile,
Persist: g.LogPersist,
MaxKB: g.LogMaxKB,
}.normalized()
}
// Sink is the shared line sink. Create with New; write producers' raw log bytes
// via Write (io.Writer); flip settings with Reconfigure; Close on shutdown.
type Sink struct {
mu sync.Mutex
cfg Config
// stderr is the syslog half's destination — the REAL os.Stderr in the
// daemon (procd relays it to logread). Injected so tests can observe it.
stderr io.Writer
buf []byte // un-terminated tail awaiting its '\n'
file *os.File // active segment; nil until first file write (lazy open)
fileSize int64 // bytes in the active segment
fileErr bool // a standing open/write failure was already warned about
suspended bool // persistent-path disk guard tripped
lastProbe time.Time // last disk-free probe
// test seams
now func() time.Time
free func(string) (uint64, bool)
}
// New returns a Sink fanning to stderr (the daemon passes os.Stderr) under cfg.
// The file is opened lazily on the first line that needs it.
func New(stderr io.Writer, cfg Config) *Sink {
return &Sink{
cfg: cfg.normalized(),
stderr: stderr,
now: time.Now,
free: freeBytes,
}
}
// Write implements io.Writer for the log producers. It never returns an error
// and always reports the full length: a logging destination that fails must
// degrade (warn once, drop), never propagate failure back into the code that
// was merely trying to log.
func (s *Sink) Write(p []byte) (int, error) {
s.mu.Lock()
defer s.mu.Unlock()
s.buf = append(s.buf, p...)
for {
i := bytes.IndexByte(s.buf, '\n')
if i < 0 {
if len(s.buf) > maxPartialLine {
s.emitLocked(s.buf)
s.buf = s.buf[:0]
}
break
}
s.emitLocked(s.buf[:i])
s.buf = append(s.buf[:0], s.buf[i+1:]...)
}
return len(p), nil
}
// Reconfigure atomically installs a new configuration. A changed file location
// (Persist flip / Path override) closes the old file and starts fresh at the
// new one; a re-enabled or re-pointed file also gets a fresh disk-guard verdict
// instead of inheriting a stale "suspended".
func (s *Sink) Reconfigure(cfg Config) {
cfg = cfg.normalized()
s.mu.Lock()
defer s.mu.Unlock()
if cfg == s.cfg {
return
}
if cfg.path() != s.cfg.path() || !cfg.ToFile {
s.closeFileLocked()
}
s.suspended = false
s.lastProbe = time.Time{}
s.fileErr = false
s.cfg = cfg
}
// Close flushes a pending partial line and closes the file segment. The sink
// must not be written to afterwards.
func (s *Sink) Close() error {
s.mu.Lock()
defer s.mu.Unlock()
if len(s.buf) > 0 {
s.emitLocked(s.buf)
s.buf = nil
}
if s.file != nil {
err := s.file.Close()
s.file = nil
s.fileSize = 0
return err
}
return nil
}
// --- internals (caller holds s.mu) -------------------------------------------
// emitLocked stamps one complete line with the UTC wall clock and fans it out.
func (s *Sink) emitLocked(line []byte) {
if !s.cfg.ToSyslog && !s.cfg.ToFile {
return // fully off: the line is dropped, nowhere else to go
}
line = bytes.TrimSuffix(line, []byte{'\r'})
ts := s.now().UTC().Format(time.RFC3339)
if s.cfg.ToSyslog && s.stderr != nil {
out := make([]byte, 0, len(ts)+1+len(line)+1)
out = append(out, ts...)
out = append(out, ' ')
out = append(out, line...)
out = append(out, '\n')
_, _ = s.stderr.Write(out)
}
if s.cfg.ToFile {
// The file gets the line with ANSI colour codes stripped: the producers
// colour for a terminal, and a downloaded .log full of escape bytes is
// broken UX. The syslog copy is passed through untouched (unchanged
// behaviour vs the pre-sink daemon).
clean := stripANSI(line)
out := make([]byte, 0, len(ts)+1+len(clean)+1)
out = append(out, ts...)
out = append(out, ' ')
out = append(out, clean...)
out = append(out, '\n')
s.fileWriteLocked(out)
}
}
// fileWriteLocked appends one stamped line to the active segment, rotating
// when the segment budget (MaxKB/2) would be exceeded.
func (s *Sink) fileWriteLocked(out []byte) {
if s.cfg.Persist && !s.diskOKLocked() {
return
}
if s.file == nil && !s.openLocked() {
return
}
segCap := int64(s.cfg.MaxKB) * 1024 / 2
if s.fileSize > 0 && s.fileSize+int64(len(out)) > segCap {
s.rotateLocked()
if s.file == nil {
return
}
}
n, err := s.file.Write(out)
s.fileSize += int64(n)
if err != nil {
if !s.fileErr {
s.fileErr = true
s.warnLocked("write " + s.cfg.path() + ": " + err.Error() + " — file logging degraded")
}
return
}
s.fileErr = false
}
// openLocked opens (creating if needed) the active segment for append and
// learns its current size so the rotation budget survives a daemon restart.
func (s *Sink) openLocked() bool {
path := s.cfg.path()
if err := os.MkdirAll(filepath.Dir(path), 0o755); err != nil {
s.warnOpenFailLocked(err)
return false
}
f, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
if err != nil {
s.warnOpenFailLocked(err)
return false
}
var size int64
if st, err := f.Stat(); err == nil {
size = st.Size()
}
s.file = f
s.fileSize = size
s.fileErr = false
return true
}
func (s *Sink) warnOpenFailLocked(err error) {
if s.fileErr {
return
}
s.fileErr = true
s.warnLocked("open " + s.cfg.path() + ": " + err.Error() + " — file logging unavailable")
}
// rotateLocked replaces "<path>.1" with the full active segment and starts a
// fresh one. If the rename is impossible the active segment is truncated in
// place — losing the older half is strictly better than growing past the cap.
func (s *Sink) rotateLocked() {
path := s.cfg.path()
s.closeFileLocked()
// os.Rename replaces an existing target on POSIX but not on Windows (dev
// host / tests), so drop the old .1 explicitly first.
_ = os.Remove(path + ".1")
if err := os.Rename(path, path+".1"); err != nil {
if f, terr := os.OpenFile(path, os.O_TRUNC|os.O_CREATE|os.O_WRONLY, 0o644); terr == nil {
s.file = f
s.fileSize = 0
s.warnLocked("rotate " + path + ": " + err.Error() + " — truncated the active segment instead")
return
}
s.warnLocked("rotate " + path + ": " + err.Error() + " — file logging unavailable")
return
}
s.openLocked()
}
func (s *Sink) closeFileLocked() {
if s.file != nil {
_ = s.file.Close()
s.file = nil
}
s.fileSize = 0
}
// diskOKLocked is the persistent-path guard: require the full log cap PLUS a
// fixed floor to be free before writing flash, re-probing at most once a
// minute. An undeterminable free count fails OPEN for logging (the file is the
// thing being asked for; refusing it on a stat error helps nobody) — the cap
// still bounds what can be written. Mirrors the reasoning of
// stats/diskfree_unix.go: on a ~33 MB-free rootfs, filling the disk takes down
// far more than logging, so under pressure the log yields, warns once, and the
// daemon lives.
func (s *Sink) diskOKLocked() bool {
nowT := s.now()
if !s.lastProbe.IsZero() && nowT.Sub(s.lastProbe) < diskProbeEvery {
return !s.suspended
}
s.lastProbe = nowT
freeB, ok := s.free(filepath.Dir(s.cfg.path()))
if !ok {
s.suspended = false
return true
}
need := uint64(s.cfg.MaxKB)*1024 + diskFloorBytes
if freeB < need {
if !s.suspended {
s.suspended = true
s.closeFileLocked()
s.warnLocked(fmt.Sprintf("only %d KiB free at %s (need %d KiB) — suspending persistent file logging",
freeB/1024, filepath.Dir(s.cfg.path()), need/1024))
}
return false
}
if s.suspended {
s.suspended = false
s.warnLocked("disk space recovered — resuming persistent file logging")
}
return true
}
// warnLocked reports a sink-internal problem on the syslog half only (the file
// half is, in every caller, the thing that is failing). With ToSyslog off there
// is nowhere left the operator allowed us to speak — the warning is dropped,
// which is exactly what "fully silent" means.
func (s *Sink) warnLocked(msg string) {
if !s.cfg.ToSyslog || s.stderr == nil {
return
}
ts := s.now().UTC().Format(time.RFC3339)
_, _ = s.stderr.Write([]byte(ts + " WARN logsink: " + msg + "\n"))
}
// stripANSI removes CSI escape sequences (ESC '[' … final byte 0x40–0x7E) —
// the colour codes both log formatters emit — from a line bound for the file.
func stripANSI(b []byte) []byte {
if !bytes.ContainsRune(b, 0x1b) {
return b
}
out := make([]byte, 0, len(b))
for i := 0; i < len(b); {
if b[i] == 0x1b && i+1 < len(b) && b[i+1] == '[' {
j := i + 2
for j < len(b) && (b[j] < 0x40 || b[j] > 0x7e) {
j++
}
if j < len(b) {
j++ // consume the final byte
}
i = j
continue
}
out = append(out, b[i])
i++
}
return out
}
+346
View File
@@ -0,0 +1,346 @@
package logsink
import (
"bytes"
"fmt"
"os"
"path/filepath"
"strings"
"testing"
"time"
"github.com/sagernet/sing-box/log"
"github.com/sagernet/sing-box/option"
)
// fileCfg returns a Config writing to a temp file, with the given toggles.
func fileCfg(t *testing.T, toSyslog, toFile bool, maxKB int) Config {
t.Helper()
return Config{
ToSyslog: toSyslog,
ToFile: toFile,
MaxKB: maxKB,
Path: filepath.Join(t.TempDir(), "shaterd.log"),
}
}
func readFile(t *testing.T, path string) string {
t.Helper()
b, err := os.ReadFile(path)
if err != nil {
t.Fatalf("read %s: %v", path, err)
}
return string(b)
}
// TestLinesPrefixedUTCRFC3339: every COMPLETE line — however the producer
// fragments its writes — comes out prefixed with a parseable UTC RFC3339
// timestamp, in both the file and the syslog stream.
func TestLinesPrefixedUTCRFC3339(t *testing.T) {
var stderr bytes.Buffer
cfg := fileCfg(t, true, true, 0)
s := New(&stderr, cfg)
// Writes deliberately NOT on line boundaries.
for _, chunk := range []string{"hel", "lo one\nwo", "rld two\n"} {
if _, err := s.Write([]byte(chunk)); err != nil {
t.Fatalf("Write: %v", err)
}
}
if err := s.Close(); err != nil {
t.Fatalf("Close: %v", err)
}
for _, src := range []struct{ name, body string }{
{"file", readFile(t, cfg.Path)},
{"stderr", stderr.String()},
} {
lines := strings.Split(strings.TrimSuffix(src.body, "\n"), "\n")
if len(lines) != 2 {
t.Fatalf("%s: got %d lines, want 2: %q", src.name, len(lines), src.body)
}
wantTail := []string{"hello one", "world two"}
for i, line := range lines {
ts, ok := LineTime([]byte(line))
if !ok {
t.Fatalf("%s line %d has no parseable RFC3339 prefix: %q", src.name, i, line)
}
if _, off := ts.Zone(); off != 0 {
t.Errorf("%s line %d timestamp is not UTC (offset %d): %q", src.name, i, off, line)
}
if got := line[strings.IndexByte(line, ' ')+1:]; got != wantTail[i] {
t.Errorf("%s line %d payload = %q, want %q", src.name, i, got, wantTail[i])
}
}
}
}
// TestTogglesBothOffIsFullyOff: with both outputs off NOTHING is written
// anywhere — no file created, no bytes on stderr. That is the "fully silent"
// contract of the two toggles.
func TestTogglesBothOffIsFullyOff(t *testing.T) {
var stderr bytes.Buffer
cfg := fileCfg(t, false, false, 0)
s := New(&stderr, cfg)
_, _ = s.Write([]byte("must vanish\nentirely\n"))
_ = s.Close()
if stderr.Len() != 0 {
t.Fatalf("stderr received %q with ToSyslog=false", stderr.String())
}
if _, err := os.Stat(cfg.Path); !os.IsNotExist(err) {
t.Fatalf("file %s exists (err=%v) with ToFile=false", cfg.Path, err)
}
}
// TestToggleFileOnly / TestToggleSyslogOnly: each output can be kept alone.
func TestToggleFileOnly(t *testing.T) {
var stderr bytes.Buffer
cfg := fileCfg(t, false, true, 0)
s := New(&stderr, cfg)
_, _ = s.Write([]byte("file-only line\n"))
_ = s.Close()
if stderr.Len() != 0 {
t.Fatalf("stderr received %q with ToSyslog=false", stderr.String())
}
if got := readFile(t, cfg.Path); !strings.Contains(got, "file-only line") {
t.Fatalf("file missing the line: %q", got)
}
}
func TestToggleSyslogOnly(t *testing.T) {
var stderr bytes.Buffer
cfg := fileCfg(t, true, false, 0)
s := New(&stderr, cfg)
_, _ = s.Write([]byte("syslog-only line\n"))
_ = s.Close()
if !strings.Contains(stderr.String(), "syslog-only line") {
t.Fatalf("stderr missing the line: %q", stderr.String())
}
if _, err := os.Stat(cfg.Path); !os.IsNotExist(err) {
t.Fatalf("file %s exists (err=%v) with ToFile=false", cfg.Path, err)
}
}
// TestRotationHoldsTotalCap: writing far more than the cap leaves BOTH segments
// together at (approximately) the cap — the active one plus one rotated .1 —
// with a tolerance of one line (rotation is checked before a write, so a
// segment may exceed its half by at most the line that triggered it).
func TestRotationHoldsTotalCap(t *testing.T) {
cfg := fileCfg(t, false, true, MinKBForTest)
s := New(nil, cfg)
line := strings.Repeat("x", 1000) + "\n" // ~1 KiB payload per line
total := 0
for i := 0; i < 300; i++ { // ~300 KiB >> 128 KiB cap
n, _ := s.Write([]byte(fmt.Sprintf("%04d %s", i, line)))
total += n
}
_ = s.Close()
capBytes := int64(MinKBForTest) * 1024
var sum int64
for _, p := range []string{cfg.Path, cfg.Path + ".1"} {
st, err := os.Stat(p)
if err != nil {
t.Fatalf("stat %s: %v (rotation should have produced both segments)", p, err)
}
sum += st.Size()
if st.Size() > capBytes/2+2048 {
t.Errorf("segment %s is %d bytes, want <= %d (+one-line slack)", p, st.Size(), capBytes/2)
}
}
if sum > capBytes+2048 {
t.Fatalf("segments total %d bytes, want <= cap %d (+one-line slack); wrote %d", sum, capBytes, total)
}
// Sanity: we really did write well past the cap, so the numbers above prove
// rotation, not a small input.
if int64(total) < 2*capBytes {
t.Fatalf("test wrote only %d bytes; not enough to exercise the cap %d", total, capBytes)
}
// The NEWEST lines must be in the active segment (nothing lost at the tail).
if got := readFile(t, cfg.Path); !strings.Contains(got, "0299 ") {
t.Fatalf("active segment lost the newest line")
}
}
// MinKBForTest aliases the model's minimum so the test reads clearly.
const MinKBForTest = 128
// TestEngineFactoryLinesReachFile is the proof for the engine hookup: a line
// emitted through the ENGINE'S OWN log constructor (log.New with
// DefaultWriter=sink — exactly what box.New does with
// box.Options.DefaultLogWriter) ends up in the sink's file, timestamped, with
// the formatter's ANSI colours stripped.
func TestEngineFactoryLinesReachFile(t *testing.T) {
cfg := fileCfg(t, false, true, 0)
s := New(nil, cfg)
f, err := log.New(log.Options{Options: option.LogOptions{}, DefaultWriter: s})
if err != nil {
t.Fatalf("log.New over sink: %v", err)
}
f.Logger().Warn("engine-line-marker")
_ = s.Close()
got := readFile(t, cfg.Path)
if !strings.Contains(got, "engine-line-marker") {
t.Fatalf("engine log line did not reach the sink file: %q", got)
}
if strings.ContainsRune(got, 0x1b) {
t.Fatalf("file contains ANSI escapes: %q", got)
}
line := strings.SplitN(strings.TrimSuffix(got, "\n"), "\n", 2)[0]
if _, ok := LineTime([]byte(line)); !ok {
t.Fatalf("engine line lacks the RFC3339 prefix: %q", line)
}
}
// TestReconfigureSwitchesPathAndToggles: a live Reconfigure moves the file to a
// new path (closing the old one) and a later both-off Reconfigure silences the
// sink entirely.
func TestReconfigureSwitchesPathAndToggles(t *testing.T) {
dir := t.TempDir()
cfgA := Config{ToFile: true, Path: filepath.Join(dir, "a.log")}
cfgB := Config{ToFile: true, Path: filepath.Join(dir, "b.log")}
s := New(nil, cfgA)
_, _ = s.Write([]byte("goes to a\n"))
s.Reconfigure(cfgB)
_, _ = s.Write([]byte("goes to b\n"))
s.Reconfigure(Config{}) // both toggles off
_, _ = s.Write([]byte("goes nowhere\n"))
_ = s.Close()
if got := readFile(t, cfgA.Path); !strings.Contains(got, "goes to a") || strings.Contains(got, "goes to b") {
t.Fatalf("a.log content wrong: %q", got)
}
if got := readFile(t, cfgB.Path); !strings.Contains(got, "goes to b") || strings.Contains(got, "goes nowhere") {
t.Fatalf("b.log content wrong: %q", got)
}
}
// TestDiskGuardSuspendsAndResumes: on the PERSISTENT path, low free space stops
// file writes with exactly one warning on the syslog half; recovered space
// (after the probe interval) resumes them.
func TestDiskGuardSuspendsAndResumes(t *testing.T) {
var stderr bytes.Buffer
cfg := Config{
ToSyslog: true, ToFile: true, Persist: true,
Path: filepath.Join(t.TempDir(), "persist.log"),
}
s := New(&stderr, cfg)
now := time.Now()
s.now = func() time.Time { return now }
lowDisk := true
s.free = func(string) (uint64, bool) {
if lowDisk {
return 1 << 20, true // 1 MiB free: below cap+floor
}
return 1 << 30, true // 1 GiB free
}
_, _ = s.Write([]byte("while low 1\nwhile low 2\n"))
if _, err := os.Stat(cfg.Path); !os.IsNotExist(err) {
t.Fatalf("file written despite low disk (err=%v)", err)
}
if n := strings.Count(stderr.String(), "suspending persistent file logging"); n != 1 {
t.Fatalf("want exactly 1 suspension warning, got %d in %q", n, stderr.String())
}
// The lines still reached the syslog half — only the FILE is suspended.
if !strings.Contains(stderr.String(), "while low 1") {
t.Fatalf("syslog half lost lines during file suspension: %q", stderr.String())
}
// Space recovers; the next probe (after the interval) resumes the file.
lowDisk = false
now = now.Add(2 * diskProbeEvery)
_, _ = s.Write([]byte("after recovery\n"))
_ = s.Close()
if got := readFile(t, cfg.Path); !strings.Contains(got, "after recovery") {
t.Fatalf("file writes did not resume after disk recovery: %q", got)
}
}
// TestCopyRangeFiltersByPrefix: the reader keeps lines at/after the cutoff,
// lets timestamp-less continuation lines ride with their predecessor, and a
// zero cutoff returns everything including unparseable lines.
func TestCopyRangeFiltersByPrefix(t *testing.T) {
now := time.Now().UTC()
stamp := func(d time.Duration) string { return now.Add(-d).Format(time.RFC3339) }
dir := t.TempDir()
older := filepath.Join(dir, "shaterd.log.1")
active := filepath.Join(dir, "shaterd.log")
if err := os.WriteFile(older, []byte(
"no timestamp at file head\n"+
stamp(100*time.Hour)+" ancient line\n"+
stamp(48*time.Hour)+" two days old\n"+
" continuation of two-days-old\n"), 0o644); err != nil {
t.Fatal(err)
}
if err := os.WriteFile(active, []byte(
stamp(1*time.Hour)+" fresh line\n"+
" continuation of fresh\n"), 0o644); err != nil {
t.Fatal(err)
}
segs := Segments(active)
if len(segs) != 2 || segs[0] != older || segs[1] != active {
t.Fatalf("Segments = %v, want [%s %s] (oldest first)", segs, older, active)
}
run := func(cutoff time.Time) string {
var buf bytes.Buffer
if err := CopyRange(&buf, segs, cutoff); err != nil {
t.Fatalf("CopyRange: %v", err)
}
return buf.String()
}
day := run(now.Add(-24 * time.Hour))
for _, want := range []string{"fresh line", "continuation of fresh"} {
if !strings.Contains(day, want) {
t.Errorf("1d range missing %q:\n%s", want, day)
}
}
for _, banned := range []string{"ancient", "two days old", "continuation of two-days-old", "file head"} {
if strings.Contains(day, banned) {
t.Errorf("1d range leaked %q:\n%s", banned, day)
}
}
threeDays := run(now.Add(-72 * time.Hour))
for _, want := range []string{"two days old", "continuation of two-days-old", "fresh line"} {
if !strings.Contains(threeDays, want) {
t.Errorf("3d range missing %q:\n%s", want, threeDays)
}
}
if strings.Contains(threeDays, "ancient") {
t.Errorf("3d range leaked the ancient line:\n%s", threeDays)
}
all := run(time.Time{})
for _, want := range []string{"file head", "ancient", "two days old", "fresh line", "continuation of fresh"} {
if !strings.Contains(all, want) {
t.Errorf("all range missing %q:\n%s", want, all)
}
}
}
// TestConfigNormalization pins the clamp: <=0 becomes the default (0 is NOT
// "file off"), and out-of-range values land on the documented bounds — the
// same numbers model.ValidateGlobals warns about.
func TestConfigNormalization(t *testing.T) {
cases := []struct{ in, want int }{
{0, 2048}, {-5, 2048}, {1, 128}, {127, 128}, {128, 128},
{2048, 2048}, {8192, 8192}, {100000, 8192},
}
for _, c := range cases {
if got := (Config{MaxKB: c.in}).normalized().MaxKB; got != c.want {
t.Errorf("normalized MaxKB(%d) = %d, want %d", c.in, got, c.want)
}
}
}
+94
View File
@@ -0,0 +1,94 @@
package logsink
// The READ side of the sink's on-disk format, consumed by the panel's
// GET /api/log download endpoint. It lives in this package — next to the code
// that writes the format — so the writer and the reader cannot drift apart on
// what a line looks like ("<UTC RFC3339> <original line>").
import (
"bufio"
"bytes"
"io"
"os"
"time"
)
// Segments returns the on-disk segments of the log at path, OLDEST FIRST
// ("<path>.1" then "<path>"), skipping ones that do not exist. Concatenating
// them in this order yields the log in chronological order.
func Segments(path string) []string {
var out []string
for _, p := range []string{path + ".1", path} {
if _, err := os.Stat(p); err == nil {
out = append(out, p)
}
}
return out
}
// LineTime parses the wall-clock timestamp the sink prefixed onto a line.
// ok=false means the line carries no parseable prefix (a continuation line —
// should not occur in sink-written files, but the reader must not choke on one).
func LineTime(line []byte) (time.Time, bool) {
i := bytes.IndexByte(line, ' ')
if i <= 0 {
return time.Time{}, false
}
ts, err := time.Parse(time.RFC3339, string(line[:i]))
if err != nil {
return time.Time{}, false
}
return ts, true
}
// CopyRange streams the log lines of paths (read in the given order — pass
// Segments() output, oldest first) to w, LINE BY LINE, never holding more than
// one line in memory.
//
// A zero cutoff means "everything" — every line is copied, parseable timestamp
// or not. A non-zero cutoff keeps only lines whose prefixed timestamp is at or
// after it; a line WITHOUT a parseable timestamp inherits the verdict of the
// last timestamped line seen (it is a continuation of it), and is excluded
// while no timestamp has been seen yet — the head of the oldest segment is by
// construction the oldest content.
//
// A segment that cannot be opened is skipped (it may have been rotated away
// between Segments() and here — best-effort is the honest contract for reading
// a live log). A write error (client went away) aborts and is returned.
func CopyRange(w io.Writer, paths []string, cutoff time.Time) error {
bw := bufio.NewWriter(w)
all := cutoff.IsZero()
included := false // verdict inherited by continuation lines
for _, p := range paths {
if err := copyRangeFile(bw, p, cutoff, all, &included); err != nil {
return err
}
}
return bw.Flush()
}
func copyRangeFile(w *bufio.Writer, path string, cutoff time.Time, all bool, included *bool) error {
f, err := os.Open(path)
if err != nil {
return nil // rotated away mid-read: skip, keep streaming the rest
}
defer f.Close()
sc := bufio.NewScanner(f)
sc.Buffer(make([]byte, 64*1024), 1024*1024)
for sc.Scan() {
line := sc.Bytes()
if ts, ok := LineTime(line); ok {
*included = !ts.Before(cutoff)
}
if !all && !*included {
continue
}
if _, err := w.Write(line); err != nil {
return err
}
if err := w.WriteByte('\n'); err != nil {
return err
}
}
return sc.Err()
}
+102
View File
@@ -0,0 +1,102 @@
package model
// Tests for the operational-log Globals knobs (shater/logsink):
// log_syslog / log_file / log_persist / log_max_kb — defaults, aliases,
// round-trip (including explicit false and explicit 0), and the ValidateGlobals
// clamp warning.
import (
"strings"
"testing"
)
// TestLogKnobsDefaults: a config written before the knobs existed (no options
// at all) must come back as syslog ON, file ON, tmpfs, 2048 KiB — i.e. keep
// logging exactly as the pre-sink daemon did, plus the bounded tmpfs file.
func TestLogKnobsDefaults(t *testing.T) {
m, err := ParseUCIExport("package shater\n\nconfig globals 'globals'\n\toption enabled '1'\n")
if err != nil {
t.Fatal(err)
}
g := m.Globals
if !g.LogToSyslog || !g.LogToFile || g.LogPersist || g.LogMaxKB != LogMaxKBDefault {
t.Fatalf("absent log knobs: syslog=%v file=%v persist=%v max_kb=%d, want true/true/false/%d",
g.LogToSyslog, g.LogToFile, g.LogPersist, g.LogMaxKB, LogMaxKBDefault)
}
}
// TestLogKnobsRoundTrip: every combination that matters — explicit FALSE
// booleans (the "fully silent" config) and an explicit log_max_kb=0 — must
// survive WriteUCI->ReadUCI (render+parse are their pure halves). This is why
// render.go emits the bools always and the int via intOptAlways.
func TestLogKnobsRoundTrip(t *testing.T) {
cases := []Globals{
{LogToSyslog: false, LogToFile: false, LogPersist: false, LogMaxKB: 0},
{LogToSyslog: true, LogToFile: false, LogPersist: false, LogMaxKB: 512},
{LogToSyslog: false, LogToFile: true, LogPersist: true, LogMaxKB: 8192},
{LogToSyslog: true, LogToFile: true, LogPersist: true, LogMaxKB: 128},
}
for i, g := range cases {
m := &Model{Globals: g}
got, err := ParseUCIExport(RenderUCIExport(m))
if err != nil {
t.Fatalf("case %d parse: %v", i, err)
}
gg := got.Globals
if gg.LogToSyslog != g.LogToSyslog || gg.LogToFile != g.LogToFile ||
gg.LogPersist != g.LogPersist || gg.LogMaxKB != g.LogMaxKB {
t.Fatalf("case %d round-trip: got syslog=%v file=%v persist=%v max_kb=%d, want %v/%v/%v/%d",
i, gg.LogToSyslog, gg.LogToFile, gg.LogPersist, gg.LogMaxKB,
g.LogToSyslog, g.LogToFile, g.LogPersist, g.LogMaxKB)
}
}
}
// TestLogKnobsAliases: the no-underscore spellings parse too, and the canonical
// key wins when both are present (same contract as loglevel/log_level).
func TestLogKnobsAliases(t *testing.T) {
m, err := ParseUCIExport("package shater\n\nconfig globals 'globals'\n" +
"\toption logsyslog '0'\n" +
"\toption logfile '0'\n" +
"\toption logpersist '1'\n" +
"\toption logmaxkb '512'\n")
if err != nil {
t.Fatal(err)
}
g := m.Globals
if g.LogToSyslog || g.LogToFile || !g.LogPersist || g.LogMaxKB != 512 {
t.Fatalf("aliases: syslog=%v file=%v persist=%v max_kb=%d, want false/false/true/512",
g.LogToSyslog, g.LogToFile, g.LogPersist, g.LogMaxKB)
}
m2, err := ParseUCIExport("package shater\n\nconfig globals 'globals'\n" +
"\toption log_syslog '1'\n" +
"\toption logsyslog '0'\n" +
"\toption log_max_kb '1024'\n" +
"\toption logmaxkb '256'\n")
if err != nil {
t.Fatal(err)
}
if !m2.Globals.LogToSyslog {
t.Fatalf("canonical log_syslog must win over the alias")
}
if m2.Globals.LogMaxKB != 1024 {
t.Fatalf("canonical log_max_kb must win: got %d, want 1024", m2.Globals.LogMaxKB)
}
}
// TestValidateGlobalsLogMaxKB: out-of-range positive values warn (they are
// applied clamped by the sink); 0 and in-range values do not.
func TestValidateGlobalsLogMaxKB(t *testing.T) {
for _, ok := range []int{0, LogMaxKBMin, 2048, LogMaxKBMax} {
if ws := ValidateGlobals(Globals{LogMaxKB: ok}); len(ws) != 0 {
t.Errorf("log_max_kb=%d should not warn: %v", ok, ws)
}
}
for _, bad := range []int{1, LogMaxKBMin - 1, LogMaxKBMax + 1, 1 << 20} {
ws := ValidateGlobals(Globals{LogMaxKB: bad})
if len(ws) != 1 || !strings.Contains(ws[0].Message, "log_max_kb") {
t.Errorf("log_max_kb=%d should warn once about the clamp, got %v", bad, ws)
}
}
}
+48
View File
@@ -112,8 +112,40 @@ type Globals struct {
// The fallback is not politeness: log.New rejects an unknown level outright,
// which fails box.New and leaves the engine down — with the kill-switch closed,
// that is the whole LAN offline over a typo.
//
// Since the logsink rework this level ALSO sets the control-plane daemon's
// verbosity (cmd/shaterd builds its factory over the shared sink and applies
// this level via SetLevel) — previously the daemon logged at trace
// unconditionally, so "warning" silenced the engine while the daemon kept
// talking. A silent level quiets the control plane to panic-only; FULL
// process silence is what LogToSyslog/LogToFile both-off delivers.
LogLevel string
// The shaterd OPERATIONAL log — the daemon's own lines plus the embedded
// engine's, fanned through the shared shater/logsink sink. Two INDEPENDENT
// output toggles: both off = the process is fully silent (lines are dropped
// at the sink; nothing reaches the file OR logread), or keep either one.
//
// LogToSyslog uci log_syslog (alias logsyslog), default true — lines go to
// the real stderr, which procd relays to syslog/logread.
// LogToFile uci log_file (alias logfile), default true — lines go to a
// size-capped, 2-segment rotated file that GET /api/log serves
// (per-day ranges need the file: logread has no wall-clock
// retention worth promising).
// LogPersist uci log_persist (alias logpersist), default false — file at
// /etc/shater/shaterd.log (survives reboot, wears flash, sits
// behind a disk-free guard) instead of tmpfs
// /var/log/shaterd.log (free writes, lost on reboot).
// LogMaxKB uci log_max_kb (alias logmaxkb), default 2048 — TOTAL file
// budget in KiB across both segments. Clamped by the sink to
// [LogMaxKBMin, LogMaxKBMax] (ValidateGlobals warns when the
// configured value is outside them). <=0 is applied as the
// default — 0 is NOT "file off"; LogToFile is the off switch.
LogToSyslog bool
LogToFile bool
LogPersist bool
LogMaxKB int
// KillSwitch is live and load-bearing in three places: the nft forward chain is
// fail-closed unless it is "open" (netplane.killSwitchClosed), route generation
// omits the final direct fallback (generate/route.go), and apply reports it.
@@ -244,6 +276,15 @@ type Globals struct {
StatsDiskLimitMB int
}
// LogMaxKB bounds. They live in model (not in shater/logsink, which imports
// model) so ValidateGlobals and the sink's clamp read the SAME numbers and can
// never disagree about what an out-of-range value becomes.
const (
LogMaxKBDefault = 2048
LogMaxKBMin = 128
LogMaxKBMax = 8192
)
// DefaultGlobals returns the Globals seeded before a `config globals` section is
// applied. These are the canonical defaults of the model contract:
// FwmarkBase/TableBase = 0x2000, KillSwitch = "closed" (fail-closed), IPv6 on.
@@ -253,10 +294,17 @@ type Globals struct {
// an absent UCI option must fall back to a bounded default, while an EXPLICIT "0" in UCI
// (parsed over this seed) is honored as unlimited. render.go always emits these three so
// an explicit 0 survives the WriteUCI->ReadUCI round-trip.
//
// The operational-log knobs are seeded to syslog ON + file ON + tmpfs + 2048 KiB: a
// config written before they existed keeps today's behaviour (lines reach logread) and
// additionally gains the bounded tmpfs file the /api/log download reads.
func DefaultGlobals() Globals {
return Globals{
Enabled: true,
LogLevel: "warning",
LogToSyslog: true,
LogToFile: true,
LogMaxKB: LogMaxKBDefault,
KillSwitch: "closed",
Untunnelable: "block",
IPv6: true,
+8
View File
@@ -45,6 +45,14 @@ func RenderUCIExport(m *Model) string {
g := m.Globals
w.boolOpt("enabled", g.Enabled)
w.strOpt("loglevel", g.LogLevel)
// Operational-log knobs: the bools are always emitted (boolOpt) like every
// other bool; log_max_kb uses intOptAlways because an explicit 0 must
// round-trip as 0 (the sink then applies the default — 0 is documented as
// "not off" — but the operator's written value may not silently mutate).
w.boolOpt("log_syslog", g.LogToSyslog)
w.boolOpt("log_file", g.LogToFile)
w.boolOpt("log_persist", g.LogPersist)
w.intOptAlways("log_max_kb", g.LogMaxKB)
w.strOpt("kill_switch", g.KillSwitch)
w.boolOpt("ipv6", g.IPv6)
w.hexOpt("fwmark_base", g.FwmarkBase)
+12
View File
@@ -274,6 +274,18 @@ func applyGlobals(g *Globals, s uciSection) {
// silently leaves the level at its default (e.g. `log_level=debug` producing no
// DEBUG output because the real key stayed `warn`/`info`).
g.LogLevel = s.optOr("loglevel", s.optOr("log_level", g.LogLevel))
// Operational-log knobs (shater/logsink). Canonical key first, no-underscore
// alias second (same nesting as loglevel above: an explicit canonical value
// wins over the alias). Defaults (g.*) come from the DefaultGlobals seed —
// syslog on, file on, tmpfs, 2048 KiB — so a config written before these
// options existed keeps logging exactly as before. render.go always emits
// all four (bools as '1'/'0', the int via intOptAlways), so an explicit
// value — including log_max_kb=0 and explicit-false toggles — survives the
// WriteUCI->ReadUCI round-trip.
g.LogToSyslog = s.optBool("log_syslog", s.optBool("logsyslog", g.LogToSyslog))
g.LogToFile = s.optBool("log_file", s.optBool("logfile", g.LogToFile))
g.LogPersist = s.optBool("log_persist", s.optBool("logpersist", g.LogPersist))
g.LogMaxKB = parseInt(s.opt("log_max_kb"), parseInt(s.opt("logmaxkb"), g.LogMaxKB))
g.KillSwitch = s.optOr("kill_switch", g.KillSwitch)
// No dns_mode: the option was deleted, not deprecated. An old config still
// carrying it parses fine (unknown options are ignored) and re-rendering drops
+19
View File
@@ -261,6 +261,25 @@ func ValidateGlobals(g Globals) []Warning {
g.LogLevel, strings.Join(EngineLogLevels, "/"), strings.Join(SilentLogLevels, "/")))
}
// The log-file budget is clamped by the sink (shater/logsink reads these
// same constants), so an out-of-range value is ACCEPTED but not applied as
// written — exactly the class of defect this validator exists for. 0 and
// negatives are applied as the default and do NOT warn: 0 is the Go zero
// value floating through JSON/partial structs everywhere, and "file off" is
// LogToFile's job, documented on the field.
if g.LogMaxKB > 0 && (g.LogMaxKB < LogMaxKBMin || g.LogMaxKB > LogMaxKBMax) {
clamped := g.LogMaxKB
if clamped < LogMaxKBMin {
clamped = LogMaxKBMin
}
if clamped > LogMaxKBMax {
clamped = LogMaxKBMax
}
add(fmt.Sprintf("log_max_kb %d is outside [%d, %d] and is applied as %d; "+
"to turn the log file off use log_file '0', not a size.",
g.LogMaxKB, LogMaxKBMin, LogMaxKBMax, clamped))
}
// The sweep schedule resolves through the SAME function apply uses, so the
// warning the operator reads and the behaviour they get cannot disagree.
if _, _, warn := g.SweepSchedule(); warn != "" {
+94
View File
@@ -7,6 +7,7 @@ import (
"fmt"
"io"
"net/http"
"os/exec"
"sort"
"strconv"
"strings"
@@ -18,6 +19,7 @@ import (
"github.com/sagernet/sing-box/shater/devices"
"github.com/sagernet/sing-box/shater/engine"
"github.com/sagernet/sing-box/shater/generate"
"github.com/sagernet/sing-box/shater/logsink"
"github.com/sagernet/sing-box/shater/model"
"github.com/sagernet/sing-box/shater/netplane"
"github.com/sagernet/sing-box/shater/parse"
@@ -231,6 +233,98 @@ func parseLogQuery(r *http.Request) stats.LogQuery {
return lq
}
// --- shaterd operational-log download ----------------------------------------
// Test seams for handleLog (same pattern as writeConfig above): production
// binds the real UCI read, the sink's path derivation and a `logread` exec;
// tests substitute temp files and canned globals.
var (
logConfigRead = model.ReadUCI
logSinkPath = logsink.FilePath
logNow = time.Now
// logSyslogScrape streams the syslog ring, filtered to shater lines, into w —
// the best-effort fallback when file logging is off but syslog is on. logread
// has no wall-clock retention worth promising, hence "ranges approximate" in
// the note the handler prepends.
logSyslogScrape = func(w io.Writer) error {
cmd := exec.Command("logread", "-e", "shater")
cmd.Stdout = w
return cmd.Run()
}
)
// handleLog → GET /api/log?range=1d|3d|all: download shaterd's OPERATIONAL log
// (the daemon's own lines + the embedded engine's, as written by shater/logsink)
// as a text/plain attachment. CONTRACT (the panel is built against this):
//
// - GET only; session-gated like every /api/* route.
// - range=1d|3d|all (absent = all; anything else = 400 JSON {"error":...}).
// 1d/3d filter by each line's UTC-RFC3339 prefix against now-24h/now-72h
// (UTC); timestamp-less lines ride with the last timestamped line.
// - 200 with Content-Type: text/plain; charset=utf-8 and
// Content-Disposition: attachment; filename="shaterd-<range>-<YYYYMMDD>.log"
// (date in UTC). The body is STREAMED line by line — never buffered whole —
// from the sink's segments, oldest first (<path>.1 then <path>).
// - honesty fallbacks: file logging off but syslog on => a best-effort
// `logread -e shater` scrape prefixed with an explanatory comment line;
// BOTH off => the single line "# logging disabled". Both are 200 — an
// honest empty answer, not an error.
func (s *Server) handleLog(w http.ResponseWriter, r *http.Request) {
if r.Method != http.MethodGet {
writeError(w, http.StatusMethodNotAllowed, "method not allowed")
return
}
now := logNow().UTC()
rng := r.URL.Query().Get("range")
var cutoff time.Time // zero = everything
switch rng {
case "", "all":
rng = "all"
case "1d":
cutoff = now.Add(-24 * time.Hour)
case "3d":
cutoff = now.Add(-72 * time.Hour)
default:
writeError(w, http.StatusBadRequest, "unknown range "+strconv.Quote(rng)+" (want 1d, 3d or all)")
return
}
// The toggles are read at REQUEST time so the download reflects what is
// being logged right now. A failed read falls back to the defaults (file
// on, tmpfs) and simply streams whatever exists — the log endpoint is a
// debugging tool, and it must keep working exactly when things are broken.
g := model.DefaultGlobals()
if m, err := logConfigRead(); err == nil {
g = m.Globals
}
w.Header().Set("Content-Type", "text/plain; charset=utf-8")
w.Header().Set("Cache-Control", "no-store")
w.Header().Set("Content-Disposition",
`attachment; filename="shaterd-`+rng+`-`+now.Format("20060102")+`.log"`)
switch {
case !g.LogToFile && !g.LogToSyslog:
_, _ = io.WriteString(w, "# logging disabled\n")
case !g.LogToFile:
_, _ = io.WriteString(w, "# note: file logging disabled; showing syslog ring only, ranges approximate\n")
if err := logSyslogScrape(w); err != nil {
_, _ = fmt.Fprintf(w, "# logread unavailable: %v\n", err)
}
default:
segs := logsink.Segments(logSinkPath(g.LogPersist))
if len(segs) == 0 {
_, _ = io.WriteString(w, "# no log file yet\n")
return
}
if err := logsink.CopyRange(w, segs, cutoff); err != nil {
// Headers are long gone; nothing to do but note it server-side
// (usually the client hung up mid-download).
s.log.Debug("log download aborted: ", err)
}
}
}
// handleStatsLog → GET /api/stats/log?limit=&before=&after=: the live DNS query log,
// ALWAYS newest first, each row carrying a monotonic `seq` cursor. With no cursor it
// returns the newest `limit` rows; before=<seq> returns the next OLDER page (seq<before);
+179
View File
@@ -0,0 +1,179 @@
package panel
// Tests for GET /api/log — the shaterd operational-log download. The handler's
// external inputs (UCI globals, the sink file location, `logread`, the clock)
// are all package-var seams; each test swaps them and restores via t.Cleanup.
import (
"io"
"net/http"
"net/http/httptest"
"os"
"path/filepath"
"strings"
"testing"
"time"
"github.com/sagernet/sing-box/shater/model"
)
// withLogSeams points the handler at a temp log file and canned globals.
func withLogSeams(t *testing.T, g model.Globals, logBody string) (path string) {
t.Helper()
dir := t.TempDir()
path = filepath.Join(dir, "shaterd.log")
if logBody != "" {
if err := os.WriteFile(path, []byte(logBody), 0o644); err != nil {
t.Fatal(err)
}
}
origRead, origPath := logConfigRead, logSinkPath
logConfigRead = func() (*model.Model, error) { return &model.Model{Globals: g}, nil }
logSinkPath = func(bool) string { return path }
t.Cleanup(func() { logConfigRead, logSinkPath = origRead, origPath })
return path
}
func getDaemonLog(t *testing.T, srv *httptest.Server, cookie *http.Cookie, query string) *http.Response {
t.Helper()
req, _ := http.NewRequest(http.MethodGet, srv.URL+"/api/log"+query, nil)
if cookie != nil {
req.AddCookie(cookie)
}
resp, err := http.DefaultClient.Do(req)
if err != nil {
t.Fatalf("GET /api/log%s: %v", query, err)
}
return resp
}
func TestLogRequiresSession(t *testing.T) {
s := newTestServer(t)
srv := httptest.NewServer(s.Handler())
defer srv.Close()
resp := getDaemonLog(t, srv, nil, "?range=all")
defer resp.Body.Close()
if resp.StatusCode != http.StatusUnauthorized {
t.Fatalf("GET /api/log without session: got %d, want 401", resp.StatusCode)
}
}
func TestLogRangeFiltersAndHeaders(t *testing.T) {
now := time.Now().UTC()
stamp := func(d time.Duration) string { return now.Add(-d).Format(time.RFC3339) }
g := model.DefaultGlobals() // file on, tmpfs
withLogSeams(t, g,
stamp(48*time.Hour)+" old line\n"+
stamp(1*time.Hour)+" fresh line\n")
s := newTestServer(t)
srv := httptest.NewServer(s.Handler())
defer srv.Close()
cookie := login(t, srv, s)
// range=1d keeps only the fresh line.
resp := getDaemonLog(t, srv, cookie, "?range=1d")
body, _ := io.ReadAll(resp.Body)
resp.Body.Close()
if resp.StatusCode != http.StatusOK {
t.Fatalf("range=1d: got %d, want 200 (%s)", resp.StatusCode, body)
}
if ct := resp.Header.Get("Content-Type"); !strings.HasPrefix(ct, "text/plain") {
t.Errorf("Content-Type = %q, want text/plain", ct)
}
wantName := `filename="shaterd-1d-` + now.Format("20060102") + `.log"`
if cd := resp.Header.Get("Content-Disposition"); !strings.Contains(cd, "attachment") || !strings.Contains(cd, wantName) {
t.Errorf("Content-Disposition = %q, want attachment with %s", cd, wantName)
}
if !strings.Contains(string(body), "fresh line") || strings.Contains(string(body), "old line") {
t.Fatalf("range=1d body wrong:\n%s", body)
}
// range=all returns everything.
resp = getDaemonLog(t, srv, cookie, "?range=all")
body, _ = io.ReadAll(resp.Body)
resp.Body.Close()
if !strings.Contains(string(body), "old line") || !strings.Contains(string(body), "fresh line") {
t.Fatalf("range=all body wrong:\n%s", body)
}
// absent range behaves as all (documented in the handler contract).
resp = getDaemonLog(t, srv, cookie, "")
body, _ = io.ReadAll(resp.Body)
resp.Body.Close()
if !strings.Contains(string(body), "old line") {
t.Fatalf("absent range should mean all:\n%s", body)
}
}
func TestLogUnknownRangeIs400(t *testing.T) {
withLogSeams(t, model.DefaultGlobals(), "")
s := newTestServer(t)
srv := httptest.NewServer(s.Handler())
defer srv.Close()
cookie := login(t, srv, s)
resp := getDaemonLog(t, srv, cookie, "?range=7w")
body, _ := io.ReadAll(resp.Body)
resp.Body.Close()
if resp.StatusCode != http.StatusBadRequest {
t.Fatalf("range=7w: got %d, want 400 (%s)", resp.StatusCode, body)
}
if !strings.Contains(string(body), "error") {
t.Fatalf("400 body is not the writeError JSON shape: %s", body)
}
}
func TestLogFileOffFallsBackToSyslogScrape(t *testing.T) {
g := model.DefaultGlobals()
g.LogToFile = false // syslog stays on
withLogSeams(t, g, "")
origScrape := logSyslogScrape
logSyslogScrape = func(w io.Writer) error {
_, err := io.WriteString(w, "ring line from logread\n")
return err
}
t.Cleanup(func() { logSyslogScrape = origScrape })
s := newTestServer(t)
srv := httptest.NewServer(s.Handler())
defer srv.Close()
cookie := login(t, srv, s)
resp := getDaemonLog(t, srv, cookie, "?range=1d")
body, _ := io.ReadAll(resp.Body)
resp.Body.Close()
if resp.StatusCode != http.StatusOK {
t.Fatalf("got %d, want 200", resp.StatusCode)
}
lines := strings.SplitN(string(body), "\n", 2)
if lines[0] != "# note: file logging disabled; showing syslog ring only, ranges approximate" {
t.Fatalf("first line must be the honesty note, got %q", lines[0])
}
if !strings.Contains(string(body), "ring line from logread") {
t.Fatalf("scrape output missing:\n%s", body)
}
}
func TestLogBothOffSaysSo(t *testing.T) {
g := model.DefaultGlobals()
g.LogToFile = false
g.LogToSyslog = false
withLogSeams(t, g, "")
s := newTestServer(t)
srv := httptest.NewServer(s.Handler())
defer srv.Close()
cookie := login(t, srv, s)
resp := getDaemonLog(t, srv, cookie, "?range=all")
body, _ := io.ReadAll(resp.Body)
resp.Body.Close()
if resp.StatusCode != http.StatusOK {
t.Fatalf("got %d, want 200", resp.StatusCode)
}
if string(body) != "# logging disabled\n" {
t.Fatalf("body = %q, want the single '# logging disabled' line", body)
}
}
+1
View File
@@ -171,6 +171,7 @@ func (s *Server) buildRouter() http.Handler {
mux.Handle("/api/apply", s.requireSession(http.HandlerFunc(s.handleApply)))
mux.Handle("/api/confirm", s.requireSession(http.HandlerFunc(s.handleConfirm)))
mux.Handle("/api/rollback", s.requireSession(http.HandlerFunc(s.handleRollback)))
mux.Handle("/api/log", s.requireSession(http.HandlerFunc(s.handleLog)))
mux.Handle("/api/stats", s.requireSession(http.HandlerFunc(s.handleStats)))
mux.Handle("/api/stats/log", s.requireSession(http.HandlerFunc(s.handleStatsLog)))
mux.Handle("/api/stats/conns", s.requireSession(http.HandlerFunc(s.handleStatsConns)))