From 36254473a34310a8f74b87dd7f9bae00289c6288 Mon Sep 17 00:00:00 2001 From: Jakob Borg Date: Fri, 5 Sep 2025 08:52:49 +0000 Subject: [PATCH] chore(slogutil): add configurable logging format (fixes #10352) (#10354) This adds several options for configuring the log format of timestamps and severity levels, making it more suitable for integration with log systems like systemd. --log-format-timestamp="2006-01-02 15:04:05" Format for timestamp, set to empty to disable timestamps ($STLOGFORMATTIMESTAMP) --[no-]log-format-level-string Whether to include level string in log line ($STLOGFORMATLEVELSTRING) --[no-]log-format-level-syslog Whether to include level as syslog prefix in log line ($STLOGFORMATLEVELSYSLOG) So, to get a timestamp suitable for systemd (syslog prefix, no level string, no timestamp) we can pass `--log-format-timestamp="" --no-log-format-level-string --log-format-level-syslog` or, equivalently, set `STLOGFORMATTIMESTAMP="" STLOGFORMATLEVELSTRING=false STLOGFORMATLEVELSYSLOG=true`. Signed-off-by: Jakob Borg --- cmd/syncthing/main.go | 24 ++++++++--- etc/linux-systemd/system/syncthing@.service | 3 ++ etc/linux-systemd/user/syncthing.service | 5 ++- internal/slogutil/formatting.go | 46 +++++++++++++-------- internal/slogutil/formatting_test.go | 7 +++- internal/slogutil/leveler.go | 19 +++++++++ internal/slogutil/line.go | 37 +++++++++++++---- internal/slogutil/sloginit.go | 39 +++++++---------- 8 files changed, 122 insertions(+), 58 deletions(-) diff --git a/cmd/syncthing/main.go b/cmd/syncthing/main.go index c609e2058..c9006c5cb 100644 --- a/cmd/syncthing/main.go +++ b/cmd/syncthing/main.go @@ -164,6 +164,9 @@ type serveCmd struct { LogLevel slog.Level `help:"Log level for all packages (DEBUG,INFO,WARN,ERROR)" env:"STLOGLEVEL" default:"INFO"` LogMaxFiles int `name:"log-max-old-files" help:"Number of old files to keep (zero to keep only current)" default:"${logMaxFiles}" placeholder:"N" env:"STLOGMAXOLDFILES"` LogMaxSize int `help:"Maximum size of any file (zero to disable log rotation)" default:"${logMaxSize}" placeholder:"BYTES" env:"STLOGMAXSIZE"` + LogFormatTimestamp string `name:"log-format-timestamp" help:"Format for timestamp, set to empty to disable timestamps" env:"STLOGFORMATTIMESTAMP" default:"${timestampFormat}"` + LogFormatLevelString bool `name:"log-format-level-string" help:"Whether to include level string in log line" env:"STLOGFORMATLEVELSTRING" default:"${levelString}" negatable:""` + LogFormatLevelSyslog bool `name:"log-format-level-syslog" help:"Whether to include level as syslog prefix in log line" env:"STLOGFORMATLEVELSYSLOG" default:"${levelSyslog}" negatable:""` NoBrowser bool `help:"Do not start browser" env:"STNOBROWSER"` NoPortProbing bool `help:"Don't try to find free ports for GUI and listen addresses on first startup" env:"STNOPORTPROBING"` NoRestart bool `help:"Do not restart Syncthing when exiting due to API/GUI command, upgrade, or crash" env:"STNORESTART"` @@ -186,10 +189,13 @@ type serveCmd struct { } func defaultVars() kong.Vars { - vars := kong.Vars{} - - vars["logMaxSize"] = strconv.Itoa(10 << 20) // 10 MiB - vars["logMaxFiles"] = "3" // plus the current one + vars := kong.Vars{ + "logMaxSize": strconv.Itoa(10 << 20), // 10 MiB + "logMaxFiles": "3", // plus the current one + "levelString": strconv.FormatBool(slogutil.DefaultLineFormat.LevelString), + "levelSyslog": strconv.FormatBool(slogutil.DefaultLineFormat.LevelSyslog), + "timestampFormat": slogutil.DefaultLineFormat.TimestampFormat, + } // On non-Windows, we explicitly default to "-" which means stdout. On // Windows, the "default" options.logFile will later be replaced with the @@ -262,8 +268,14 @@ func (c *serveCmd) Run() error { osutil.HideConsole() } - // The default log level for all packages + // Customize the logging early + slogutil.SetLineFormat(slogutil.LineFormat{ + TimestampFormat: c.LogFormatTimestamp, + LevelString: c.LogFormatLevelString, + LevelSyslog: c.LogFormatLevelSyslog, + }) slogutil.SetDefaultLevel(c.LogLevel) + slogutil.SetLevelOverrides(os.Getenv("STTRACE")) // Treat an explicitly empty log file name as no log file if c.LogFile == "" { @@ -1039,7 +1051,7 @@ func (m migratingAPI) Serve(ctx context.Context) error { w.Header().Set("Content-Type", "text/plain") w.Write([]byte("*** Database migration in progress ***\n\n")) for _, line := range slogutil.GlobalRecorder.Since(time.Time{}) { - line.WriteTo(w) + _, _ = line.WriteTo(w, slogutil.DefaultLineFormat) } }), } diff --git a/etc/linux-systemd/system/syncthing@.service b/etc/linux-systemd/system/syncthing@.service index 4e5f42cd8..21dfdfe8d 100644 --- a/etc/linux-systemd/system/syncthing@.service +++ b/etc/linux-systemd/system/syncthing@.service @@ -7,6 +7,9 @@ StartLimitBurst=4 [Service] User=%i +Environment="STLOGFORMATTIMESTAMP=" +Environment="STLOGFORMATLEVELSTRING=false" +Environment="STLOGFORMATLEVELSYSLOG=true" ExecStart=/usr/bin/syncthing serve --no-browser --no-restart Restart=on-failure RestartSec=1 diff --git a/etc/linux-systemd/user/syncthing.service b/etc/linux-systemd/user/syncthing.service index 18078d05f..ca5b7344d 100644 --- a/etc/linux-systemd/user/syncthing.service +++ b/etc/linux-systemd/user/syncthing.service @@ -5,7 +5,10 @@ StartLimitIntervalSec=60 StartLimitBurst=4 [Service] -ExecStart=/usr/bin/syncthing serve --no-browser --no-restart --logflags=0 +Environment="STLOGFORMATTIMESTAMP=" +Environment="STLOGFORMATLEVELSTRING=false" +Environment="STLOGFORMATLEVELSYSLOG=true" +ExecStart=/usr/bin/syncthing serve --no-browser --no-restart Restart=on-failure RestartSec=1 SuccessExitStatus=3 4 diff --git a/internal/slogutil/formatting.go b/internal/slogutil/formatting.go index 351bd1d80..6c88d57c3 100644 --- a/internal/slogutil/formatting.go +++ b/internal/slogutil/formatting.go @@ -18,14 +18,30 @@ import ( "time" ) -type formattingHandler struct { - attrs []slog.Attr - groups []string +type LineFormat struct { + TimestampFormat string + LevelString bool + LevelSyslog bool +} + +type formattingOptions struct { + LineFormat + out io.Writer recs []*lineRecorder timeOverride time.Time } +type formattingHandler struct { + attrs []slog.Attr + groups []string + opts *formattingOptions +} + +func SetLineFormat(f LineFormat) { + globalFormatter.LineFormat = f +} + var _ slog.Handler = (*formattingHandler)(nil) func (h *formattingHandler) Enabled(context.Context, slog.Level) bool { @@ -83,19 +99,19 @@ func (h *formattingHandler) Handle(_ context.Context, rec slog.Record) error { } line := Line{ - When: cmp.Or(h.timeOverride, rec.Time), + When: cmp.Or(h.opts.timeOverride, rec.Time), Message: sb.String(), Level: rec.Level, } // If there is a recorder, record the line. - for _, rec := range h.recs { + for _, rec := range h.opts.recs { rec.record(line) } // If there's an output, print the line. - if h.out != nil { - _, _ = line.WriteTo(h.out) + if h.opts.out != nil { + _, _ = line.WriteTo(h.opts.out, h.opts.LineFormat) } return nil } @@ -143,11 +159,9 @@ func (h *formattingHandler) WithAttrs(attrs []slog.Attr) slog.Handler { } } return &formattingHandler{ - attrs: append(h.attrs, attrs...), - groups: h.groups, - recs: h.recs, - out: h.out, - timeOverride: h.timeOverride, + attrs: append(h.attrs, attrs...), + groups: h.groups, + opts: h.opts, } } @@ -156,11 +170,9 @@ func (h *formattingHandler) WithGroup(name string) slog.Handler { return h } return &formattingHandler{ - attrs: h.attrs, - groups: append([]string{name}, h.groups...), - recs: h.recs, - out: h.out, - timeOverride: h.timeOverride, + attrs: h.attrs, + groups: append([]string{name}, h.groups...), + opts: h.opts, } } diff --git a/internal/slogutil/formatting_test.go b/internal/slogutil/formatting_test.go index b5790ee9f..c0525f894 100644 --- a/internal/slogutil/formatting_test.go +++ b/internal/slogutil/formatting_test.go @@ -17,8 +17,11 @@ import ( func TestFormattingHandler(t *testing.T) { buf := new(bytes.Buffer) h := &formattingHandler{ - out: buf, - timeOverride: time.Unix(1234567890, 0).In(time.UTC), + opts: &formattingOptions{ + LineFormat: DefaultLineFormat, + out: buf, + timeOverride: time.Unix(1234567890, 0).In(time.UTC), + }, } l := slog.New(h).With("a", "a") diff --git a/internal/slogutil/leveler.go b/internal/slogutil/leveler.go index 5ca1eecd5..314480bb6 100644 --- a/internal/slogutil/leveler.go +++ b/internal/slogutil/leveler.go @@ -9,6 +9,7 @@ package slogutil import ( "log/slog" "maps" + "strings" "sync" ) @@ -39,6 +40,24 @@ func SetDefaultLevel(level slog.Level) { globalLevels.SetDefault(level) } +func SetLevelOverrides(sttrace string) { + pkgs := strings.Split(sttrace, ",") + for _, pkg := range pkgs { + pkg = strings.TrimSpace(pkg) + if pkg == "" { + continue + } + level := slog.LevelDebug + if cutPkg, levelStr, ok := strings.Cut(pkg, ":"); ok { + pkg = cutPkg + if err := level.UnmarshalText([]byte(levelStr)); err != nil { + slog.Warn("Bad log level requested in STTRACE", slog.String("pkg", pkg), slog.String("level", levelStr), Error(err)) + } + } + globalLevels.Set(pkg, level) + } +} + type levelTracker struct { mut sync.RWMutex defLevel slog.Level diff --git a/internal/slogutil/line.go b/internal/slogutil/line.go index 2776a5d95..db135abab 100644 --- a/internal/slogutil/line.go +++ b/internal/slogutil/line.go @@ -7,6 +7,7 @@ package slogutil import ( + "bytes" "encoding/json" "fmt" "io" @@ -22,13 +23,22 @@ type Line struct { Level slog.Level `json:"level"` } -func (l *Line) WriteTo(w io.Writer) (int64, error) { - n, err := fmt.Fprintf(w, "%s %s %s\n", l.timeStr(), l.levelStr(), l.Message) - return int64(n), err -} - -func (l *Line) timeStr() string { - return l.When.Format("2006-01-02 15:04:05") +func (l *Line) WriteTo(w io.Writer, f LineFormat) (int64, error) { + buf := new(bytes.Buffer) + if f.LevelSyslog { + _, _ = fmt.Fprintf(buf, "<%d>", l.syslogPriority()) + } + if f.TimestampFormat != "" { + buf.WriteString(l.When.Format(f.TimestampFormat)) + buf.WriteRune(' ') + } + if f.LevelString { + buf.WriteString(l.levelStr()) + buf.WriteRune(' ') + } + buf.WriteString(l.Message) + buf.WriteRune('\n') + return buf.WriteTo(w) } func (l *Line) levelStr() string { @@ -51,6 +61,19 @@ func (l *Line) levelStr() string { } } +func (l *Line) syslogPriority() int { + switch { + case l.Level < slog.LevelInfo: + return 7 + case l.Level < slog.LevelWarn: + return 6 + case l.Level < slog.LevelError: + return 4 + default: + return 3 + } +} + func (l *Line) MarshalJSON() ([]byte, error) { // Custom marshal to get short level strings instead of default JSON serialisation return json.Marshal(map[string]any{ diff --git a/internal/slogutil/sloginit.go b/internal/slogutil/sloginit.go index bfd2a5711..1065fb257 100644 --- a/internal/slogutil/sloginit.go +++ b/internal/slogutil/sloginit.go @@ -10,20 +10,26 @@ import ( "io" "log/slog" "os" - "strings" + "time" ) var ( - GlobalRecorder = &lineRecorder{level: -1000} - ErrorRecorder = &lineRecorder{level: slog.LevelError} - globalLevels = &levelTracker{ + GlobalRecorder = &lineRecorder{level: -1000} + ErrorRecorder = &lineRecorder{level: slog.LevelError} + DefaultLineFormat = LineFormat{ + TimestampFormat: time.DateTime, + LevelString: true, + } + globalLevels = &levelTracker{ levels: make(map[string]slog.Level), descrs: make(map[string]string), } - slogDef = slog.New(&formattingHandler{ - recs: []*lineRecorder{GlobalRecorder, ErrorRecorder}, - out: logWriter(), - }) + globalFormatter = &formattingOptions{ + LineFormat: DefaultLineFormat, + recs: []*lineRecorder{GlobalRecorder, ErrorRecorder}, + out: logWriter(), + } + slogDef = slog.New(&formattingHandler{opts: globalFormatter}) ) func logWriter() io.Writer { @@ -38,21 +44,4 @@ func logWriter() io.Writer { func init() { slog.SetDefault(slogDef) - - // Handle legacy STTRACE var - pkgs := strings.Split(os.Getenv("STTRACE"), ",") - for _, pkg := range pkgs { - pkg = strings.TrimSpace(pkg) - if pkg == "" { - continue - } - level := slog.LevelDebug - if cutPkg, levelStr, ok := strings.Cut(pkg, ":"); ok { - pkg = cutPkg - if err := level.UnmarshalText([]byte(levelStr)); err != nil { - slog.Warn("Bad log level requested in STTRACE", slog.String("pkg", pkg), slog.String("level", levelStr), Error(err)) - } - } - globalLevels.Set(pkg, level) - } }