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 <jakob@kastelo.net>

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)
 			}
 		}),
 	}

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

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

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,
 	}
 }
 

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")

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

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{

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)
-	}
 }