diff --git a/deploy/helm/solidping/README.md b/deploy/helm/solidping/README.md index cdc417ec6..b1825ad7e 100644 --- a/deploy/helm/solidping/README.md +++ b/deploy/helm/solidping/README.md @@ -17,4 +17,7 @@ PostgreSQL create a Secret with the connection string under `url` and set The JWT signing key is generated on first install and kept across upgrades. Set `auth.existingSecret` (key `jwt-secret`) to manage it yourself. +Logs are JSON, one object per line (`SP_LOG_FORMAT=json`). Set +`extraEnv.SP_LOG_FORMAT` to change it. + First login is `admin@solidping.io` / `solidpass`. Change it immediately. diff --git a/deploy/helm/solidping/templates/deployment.yaml b/deploy/helm/solidping/templates/deployment.yaml index 7af8056b2..c3971d9a8 100644 --- a/deploy/helm/solidping/templates/deployment.yaml +++ b/deploy/helm/solidping/templates/deployment.yaml @@ -43,6 +43,11 @@ spec: name: {{ required "database.existingSecret is required with database.type=postgres" .Values.database.existingSecret }} key: url {{- end }} + {{- /* One JSON object per line for the cluster's log collector. extraEnv.SP_LOG_FORMAT replaces it. */}} + {{- if not (hasKey .Values.extraEnv "SP_LOG_FORMAT") }} + - name: SP_LOG_FORMAT + value: json + {{- end }} {{- range $k, $v := .Values.extraEnv }} - name: {{ $k }} value: {{ $v | quote }} diff --git a/deploy/helm/solidping/values.yaml b/deploy/helm/solidping/values.yaml index 1984ebd13..31371dc01 100644 --- a/deploy/helm/solidping/values.yaml +++ b/deploy/helm/solidping/values.yaml @@ -26,6 +26,7 @@ persistence: existingClaim: "" # Extra SP_* environment variables, e.g. { SP_SERVER_COMPRESSION: "true" }. +# The chart sets SP_LOG_FORMAT=json; an SP_LOG_FORMAT entry here replaces it. extraEnv: {} # ICMP (ping) checks need a raw socket. diff --git a/server/AGENTS.md b/server/AGENTS.md index 4192a66e4..17fde447d 100644 --- a/server/AGENTS.md +++ b/server/AGENTS.md @@ -29,7 +29,8 @@ This file provides backend-specific guidance for the SolidPing monitoring system The measurement core (median/p95/spread and the "not significant" rule) is pure, unit-tested code in `internal/membench`; `internal/meminfo` holds the `/proc` + cgroup parsers behind `/api/mgmt/memory`. -- **Set log level**: `LOG_LEVEL=debug ./solidping serve` (valid values: debug, info, warn, error) +- **Set log level**: `SP_LOG_LEVEL=debug ./solidping serve` (valid values: debug, info, warn, error). `LOG_LEVEL` is still accepted as a fallback when `SP_LOG_LEVEL` is unset (`config.LogLevelFromEnv`). +- **Log format**: `SP_LOG_FORMAT` = `auto` (default), `text`, `json` or `pretty`. `auto` is resolved once at logger setup in `internal/logsetup`: json on Kubernetes, pretty on a terminal or in a container, text otherwise. Colors follow `NO_COLOR` / `FORCE_COLOR`, then whether the writer itself is a TTY or a container. ## Architecture Overview diff --git a/server/cmd_mcp_test.go b/server/cmd_mcp_test.go index 2870feaa2..d019a6f48 100644 --- a/server/cmd_mcp_test.go +++ b/server/cmd_mcp_test.go @@ -55,7 +55,7 @@ func runMCPStdioHelper(raw string) int { return 2 } - setupLogger(config.ParseLogLevel(os.Getenv("LOG_LEVEL")), config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) + setupLogger(config.LogLevelFromEnv(os.Getenv), config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) return run(context.Background(), buildRootCommand(), append([]string{"solidping"}, args...)) } diff --git a/server/go.mod b/server/go.mod index 8757b4e3a..23d811924 100644 --- a/server/go.mod +++ b/server/go.mod @@ -273,6 +273,7 @@ require ( github.com/lib/pq v1.12.3 github.com/likexian/whois v1.15.7 github.com/likexian/whois-parser v1.24.21 + github.com/lmittmann/tint v1.2.1 github.com/mattn/go-sqlite3 v1.14.52 github.com/microsoft/go-mssqldb v1.11.2 github.com/miekg/dns v1.1.73 diff --git a/server/go.sum b/server/go.sum index dde399aa6..6218e7c88 100644 --- a/server/go.sum +++ b/server/go.sum @@ -421,6 +421,8 @@ github.com/likexian/whois v1.15.7 h1:sajjDhi2bVD71AHJhjV7jLYxN92H4AWhTwxM8hmj7c0 github.com/likexian/whois v1.15.7/go.mod h1:kdPQtYb+7SQVftBEbCblDadUkycN7Mg1k1/Li/rwvmc= github.com/likexian/whois-parser v1.24.21 h1:MxsrGRxDOiZIVp7q7N/yAIbKuN4QAkGjCpOtTDA5OsM= github.com/likexian/whois-parser v1.24.21/go.mod h1:o3DUruO65Pb8WXCJCTlSVkTbwuYVrBCeoMTw2q0mxY4= +github.com/lmittmann/tint v1.2.1 h1:zOadah+f+nSm3jZM044jOsqh0+vSfgG/d9Ota9a/TLE= +github.com/lmittmann/tint v1.2.1/go.mod h1:HIS3gSy7qNwGCj+5oRjAutErFBl4BzdQP6cJZ0NfMwE= github.com/lufia/plan9stats v0.0.0-20260330125221-c963978e514e h1:Q6MvJtQK/iRcRtzAscm/zF23XxJlbECiGPyRicsX+Ak= github.com/lufia/plan9stats v0.0.0-20260330125221-c963978e514e/go.mod h1:autxFIvghDt3jPTLoqZ9OZ7s9qTGNAWmYCjVFWPX/zg= github.com/lunixbochs/struc v0.0.0-20241101090106-8d528fa2c543 h1:GxMuVb9tJajC1QpbQwYNY1ZAo1EIE8I+UclBjOfjz/M= diff --git a/server/internal/config/config.go b/server/internal/config/config.go index 32ebed83b..3b0cc18b7 100644 --- a/server/internal/config/config.go +++ b/server/internal/config/config.go @@ -586,7 +586,7 @@ type Config struct { AI AIConfig `koanf:"ai"` RunMode string `koanf:"runmode"` // "test" for test mode, empty for normal mode UserAgent string `koanf:"useragent"` // Identity string for protocol checks (SP_USERAGENT) - LogLevel slog.Level `koanf:"-"` // Logging level (parsed from LOG_LEVEL env var) + LogLevel slog.Level `koanf:"-"` // Logging level (SP_LOG_LEVEL, LOG_LEVEL as fallback) LogFormat LogFormat `koanf:"-"` // Logging output format (parsed from SP_LOG_FORMAT env var) } @@ -2298,8 +2298,7 @@ func Load() (*Config, error) { applyDBSlowQueryEnv(&cfg.Database) applyMigrationGuardModeEnv(&cfg.Database) - // Parse LOG_LEVEL environment variable - cfg.LogLevel = ParseLogLevel(os.Getenv("SP_LOG_LEVEL")) + cfg.LogLevel = LogLevelFromEnv(os.Getenv) cfg.LogFormat = ParseLogFormat(os.Getenv("SP_LOG_FORMAT")) // App / GitHub: SP_APP_GITHUB_ISSUES_TOKEN takes precedence over the @@ -3863,27 +3862,42 @@ func ParseLogLevel(level string) slog.Level { } } +// LogLevelFromEnv reads the log level from the environment: SP_LOG_LEVEL wins, +// LOG_LEVEL is the fallback. main (before the configuration loads) and Load +// both go through it, so LOG_LEVEL set alone is no longer reset to info once +// the configuration is loaded. +func LogLevelFromEnv(getenv func(key string) string) slog.Level { + if level := strings.TrimSpace(getenv("SP_LOG_LEVEL")); level != "" { + return ParseLogLevel(level) + } + + return ParseLogLevel(getenv("LOG_LEVEL")) +} + // LogFormat selects how log records are rendered on stdout. type LogFormat string const ( - // LogFormatText is Go's key=value logfmt-style handler. The default: it - // stays readable with no tooling, which is what a self-hosted operator - // tailing a container gets without opting in to anything. + // LogFormatAuto is the default: the concrete format is picked from the + // environment when the logger is built (json on Kubernetes, pretty on a + // terminal or in a container, text otherwise). See internal/logsetup. + LogFormatAuto LogFormat = "auto" + // LogFormatText is Go's key=value logfmt-style handler. It stays readable + // with no tooling. LogFormatText LogFormat = "text" // LogFormatJSON emits one JSON object per record. Pick this when a log // collector parses stdout — attributes become queryable fields instead of // being buried in a formatted message. LogFormatJSON LogFormat = "json" - // LogFormatPretty is the colorized, human-first handler. For interactive - // development; it is not machine-parseable. + // LogFormatPretty is the colorized, human-first handler. For terminals and + // `docker logs`; it is not machine-parseable. LogFormatPretty LogFormat = "pretty" ) // ParseLogFormat parses a log format string into a LogFormat. -// Valid values: text, json, pretty (case-insensitive). -// Returns LogFormatText if the value is empty or unrecognized — an unreadable -// typo must not cost the operator their logs. +// Valid values: auto, text, json, pretty (case-insensitive). +// Returns LogFormatAuto if the value is empty or unrecognized — a typo must +// not cost the operator their logs. func ParseLogFormat(format string) LogFormat { switch strings.ToLower(strings.TrimSpace(format)) { case "json": @@ -3893,6 +3907,6 @@ func ParseLogFormat(format string) LogFormat { case "text", "logfmt": return LogFormatText default: - return LogFormatText + return LogFormatAuto } } diff --git a/server/internal/config/config_test.go b/server/internal/config/config_test.go index b68743319..4cc845d4d 100644 --- a/server/internal/config/config_test.go +++ b/server/internal/config/config_test.go @@ -333,14 +333,19 @@ func TestParseLogFormat(t *testing.T) { expected: LogFormatPretty, }, { - name: "empty string defaults to text", + name: "auto", + input: "Auto", + expected: LogFormatAuto, + }, + { + name: "empty string defaults to auto", input: "", - expected: LogFormatText, + expected: LogFormatAuto, }, { - name: "invalid value defaults to text", + name: "invalid value defaults to auto", input: "yaml", - expected: LogFormatText, + expected: LogFormatAuto, }, { name: "whitespace trimmed", @@ -353,10 +358,57 @@ func TestParseLogFormat(t *testing.T) { t.Run(testCase.name, func(t *testing.T) { t.Parallel() - result := ParseLogFormat(testCase.input) - if result != testCase.expected { - t.Errorf("ParseLogFormat(%q) = %v, want %v", testCase.input, result, testCase.expected) - } + require.Equal(t, testCase.expected, ParseLogFormat(testCase.input)) + }) + } +} + +func TestLogLevelFromEnv(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + env map[string]string + expected slog.Level + }{ + { + name: "nothing set defaults to info", + env: map[string]string{}, + expected: slog.LevelInfo, + }, + { + name: "SP_LOG_LEVEL alone", + env: map[string]string{"SP_LOG_LEVEL": "debug"}, + expected: slog.LevelDebug, + }, + { + name: "LOG_LEVEL alone is the fallback", + env: map[string]string{"LOG_LEVEL": "warn"}, + expected: slog.LevelWarn, + }, + { + name: "SP_LOG_LEVEL wins over LOG_LEVEL", + env: map[string]string{"SP_LOG_LEVEL": "error", "LOG_LEVEL": "debug"}, + expected: slog.LevelError, + }, + { + name: "blank SP_LOG_LEVEL falls back to LOG_LEVEL", + env: map[string]string{"SP_LOG_LEVEL": " ", "LOG_LEVEL": "warn"}, + expected: slog.LevelWarn, + }, + { + name: "invalid SP_LOG_LEVEL is info, not LOG_LEVEL", + env: map[string]string{"SP_LOG_LEVEL": "loud", "LOG_LEVEL": "warn"}, + expected: slog.LevelInfo, + }, + } + + for _, testCase := range tests { + t.Run(testCase.name, func(t *testing.T) { + t.Parallel() + + getenv := func(key string) string { return testCase.env[key] } + require.Equal(t, testCase.expected, LogLevelFromEnv(getenv)) }) } } diff --git a/server/internal/logsetup/ansi_other.go b/server/internal/logsetup/ansi_other.go new file mode 100644 index 000000000..16d9a5791 --- /dev/null +++ b/server/internal/logsetup/ansi_other.go @@ -0,0 +1,8 @@ +//go:build !windows + +package logsetup + +import "io" + +// enableANSI is a no-op outside Windows: terminals render ANSI natively. +func enableANSI(io.Writer) {} diff --git a/server/internal/logsetup/ansi_windows.go b/server/internal/logsetup/ansi_windows.go new file mode 100644 index 000000000..519dfdf1a --- /dev/null +++ b/server/internal/logsetup/ansi_windows.go @@ -0,0 +1,27 @@ +//go:build windows + +package logsetup + +import ( + "io" + + "golang.org/x/sys/windows" +) + +// enableANSI turns on virtual terminal processing on a Windows console, so it +// renders the ANSI color sequences instead of printing them. +func enableANSI(out io.Writer) { + file, ok := out.(fdWriter) + if !ok { + return + } + + handle := windows.Handle(file.Fd()) + + var mode uint32 + if err := windows.GetConsoleMode(handle, &mode); err != nil { + return + } + + _ = windows.SetConsoleMode(handle, mode|windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING) +} diff --git a/server/internal/logsetup/logsetup.go b/server/internal/logsetup/logsetup.go new file mode 100644 index 000000000..9737a6124 --- /dev/null +++ b/server/internal/logsetup/logsetup.go @@ -0,0 +1,177 @@ +// Package logsetup builds the process slog handler. It resolves the "auto" log +// format against the environment (Kubernetes, terminal, container) and decides +// whether the pretty format writes ANSI colors. +package logsetup + +import ( + "io" + "log/slog" + "os" + + "github.com/lmittmann/tint" + "golang.org/x/term" + + "github.com/fclairamb/solidping/server/internal/config" +) + +const ( + // prettyTimeFormat is the short local timestamp of the pretty format. The + // date is left out: a terminal session or `docker logs` rarely spans days, + // and the other formats keep the full RFC 3339 time. + prettyTimeFormat = "15:04:05.000" + + // colorBrightRed is the ANSI 8-bit color of error attribute values. + colorBrightRed = 9 +) + +// containerMarkers are the files a container runtime leaves at the root of the +// container filesystem: Docker writes /.dockerenv, Podman /run/.containerenv. +// +//nolint:gochecknoglobals // read-only lookup table +var containerMarkers = []string{"/.dockerenv", "/run/.containerenv"} + +// Environment is what format and color resolution look at. Every input is +// injectable, so the decision table is testable without a real terminal, +// container or Kubernetes pod. +type Environment struct { + // Getenv reads an environment variable, "" when unset. + Getenv func(key string) string + // IsTerminal reports whether the log writer itself is a terminal. + IsTerminal bool + // FileExists reports whether a file exists at path. + FileExists func(path string) bool +} + +// SystemEnvironment probes the real process for a logger writing to out. +func SystemEnvironment(out io.Writer) Environment { + return Environment{ + Getenv: os.Getenv, + IsTerminal: isTerminal(out), + FileExists: fileExists, + } +} + +func (e Environment) inKubernetes() bool { + return e.Getenv("KUBERNETES_SERVICE_HOST") != "" +} + +func (e Environment) inContainer() bool { + for _, marker := range containerMarkers { + if e.FileExists(marker) { + return true + } + } + + return false +} + +// ResolveFormat turns config.LogFormatAuto into a concrete format. An explicit +// format is returned unchanged. +// +// - Kubernetes (KUBERNETES_SERVICE_HOST set): json, a collector reads stdout. +// - The writer is a terminal: pretty. +// - In a container (/.dockerenv, /run/.containerenv): pretty, for +// `docker logs` and Docker Desktop. +// - Otherwise: text. +func ResolveFormat(format config.LogFormat, env Environment) config.LogFormat { + if format != config.LogFormatAuto { + return format + } + + switch { + case env.inKubernetes(): + return config.LogFormatJSON + case env.IsTerminal: + return config.LogFormatPretty + case env.inContainer(): + return config.LogFormatPretty + default: + return config.LogFormatText + } +} + +// UseColor reports whether the pretty format writes ANSI colors. NO_COLOR +// disables them and FORCE_COLOR forces them. Otherwise they are on when the +// writer is a terminal or the process runs in a container (Docker Desktop and +// `docker logs` render ANSI). +func UseColor(env Environment) bool { + switch { + case env.Getenv("NO_COLOR") != "": + return false + case env.Getenv("FORCE_COLOR") != "": + return true + default: + return env.IsTerminal || env.inContainer() + } +} + +// NewHandler builds the handler for format, writing to out at level. The auto +// format and the colors are resolved here, once, against the real environment +// and against out itself (not os.Stdout: the client and mcp commands log to +// stderr). +func NewHandler(out io.Writer, level slog.Level, format config.LogFormat) slog.Handler { + return newHandler(out, level, format, SystemEnvironment(out)) +} + +func newHandler(out io.Writer, level slog.Level, format config.LogFormat, env Environment) slog.Handler { + opts := &slog.HandlerOptions{Level: level} + + switch ResolveFormat(format, env) { + case config.LogFormatJSON: + return slog.NewJSONHandler(out, opts) + case config.LogFormatPretty: + return newPrettyHandler(out, level, UseColor(env)) + case config.LogFormatText, config.LogFormatAuto: + return slog.NewTextHandler(out, opts) + default: + return slog.NewTextHandler(out, opts) + } +} + +// newPrettyHandler is the human-first format: short timestamp, short colored +// level, the message, then the attributes in record order (the logger's own +// WithAttrs ones first, group names as a "group." prefix). +func newPrettyHandler(out io.Writer, level slog.Level, color bool) slog.Handler { + opts := &tint.Options{ + Level: level, + TimeFormat: prettyTimeFormat, + NoColor: !color, + } + + if color { + enableANSI(out) + + opts.ReplaceAttr = redErrors + } + + return tint.NewTextHandler(out, opts) +} + +// redErrors writes the value of an "error" or "err" attribute in red. +func redErrors(_ []string, attr slog.Attr) slog.Attr { + if attr.Key == "error" || attr.Key == "err" { + return tint.Attr(colorBrightRed, attr) + } + + return attr +} + +// fdWriter is a writer backed by a file descriptor, such as *os.File. +type fdWriter interface { + Fd() uintptr +} + +func isTerminal(out io.Writer) bool { + file, ok := out.(fdWriter) + if !ok { + return false + } + + return term.IsTerminal(int(file.Fd())) +} + +func fileExists(path string) bool { + _, err := os.Stat(path) + + return err == nil +} diff --git a/server/internal/logsetup/logsetup_test.go b/server/internal/logsetup/logsetup_test.go new file mode 100644 index 000000000..a50d6317b --- /dev/null +++ b/server/internal/logsetup/logsetup_test.go @@ -0,0 +1,240 @@ +package logsetup + +import ( + "bytes" + "encoding/json" + "errors" + "log/slog" + "regexp" + "testing" + + "github.com/stretchr/testify/require" + + "github.com/fclairamb/solidping/server/internal/config" +) + +var errDiskFull = errors.New("disk full") + +// testEnv builds an Environment from a fixed set of variables and files. +func testEnv(vars map[string]string, tty bool, files ...string) Environment { + return Environment{ + Getenv: func(key string) string { return vars[key] }, + IsTerminal: tty, + FileExists: func(path string) bool { + for _, file := range files { + if file == path { + return true + } + } + + return false + }, + } +} + +func TestResolveFormat(t *testing.T) { + t.Parallel() + + k8s := map[string]string{"KUBERNETES_SERVICE_HOST": "10.0.0.1"} + + tests := []struct { + name string + format config.LogFormat + env Environment + expected config.LogFormat + }{ + { + name: "auto on kubernetes is json", + format: config.LogFormatAuto, + env: testEnv(k8s, false), + expected: config.LogFormatJSON, + }, + { + name: "auto on kubernetes beats a terminal", + format: config.LogFormatAuto, + env: testEnv(k8s, true, "/.dockerenv"), + expected: config.LogFormatJSON, + }, + { + name: "auto on a terminal is pretty", + format: config.LogFormatAuto, + env: testEnv(nil, true), + expected: config.LogFormatPretty, + }, + { + name: "auto in docker is pretty", + format: config.LogFormatAuto, + env: testEnv(nil, false, "/.dockerenv"), + expected: config.LogFormatPretty, + }, + { + name: "auto in podman is pretty", + format: config.LogFormatAuto, + env: testEnv(nil, false, "/run/.containerenv"), + expected: config.LogFormatPretty, + }, + { + name: "auto piped outside a container is text", + format: config.LogFormatAuto, + env: testEnv(nil, false), + expected: config.LogFormatText, + }, + { + name: "explicit text wins on a terminal", + format: config.LogFormatText, + env: testEnv(nil, true), + expected: config.LogFormatText, + }, + { + name: "explicit pretty wins on kubernetes", + format: config.LogFormatPretty, + env: testEnv(k8s, false), + expected: config.LogFormatPretty, + }, + { + name: "explicit json wins in docker", + format: config.LogFormatJSON, + env: testEnv(nil, true, "/.dockerenv"), + expected: config.LogFormatJSON, + }, + } + + for _, testCase := range tests { + t.Run(testCase.name, func(t *testing.T) { + t.Parallel() + + require.Equal(t, testCase.expected, ResolveFormat(testCase.format, testCase.env)) + }) + } +} + +func TestUseColor(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + env Environment + expected bool + }{ + {name: "terminal", env: testEnv(nil, true), expected: true}, + {name: "container", env: testEnv(nil, false, "/.dockerenv"), expected: true}, + {name: "piped", env: testEnv(nil, false), expected: false}, + {name: "NO_COLOR on a terminal", env: testEnv(map[string]string{"NO_COLOR": "1"}, true), expected: false}, + {name: "FORCE_COLOR when piped", env: testEnv(map[string]string{"FORCE_COLOR": "1"}, false), expected: true}, + { + name: "NO_COLOR beats FORCE_COLOR", + env: testEnv(map[string]string{"NO_COLOR": "1", "FORCE_COLOR": "1"}, true), + expected: false, + }, + } + + for _, testCase := range tests { + t.Run(testCase.name, func(t *testing.T) { + t.Parallel() + + require.Equal(t, testCase.expected, UseColor(testCase.env)) + }) + } +} + +func TestNewHandlerFormats(t *testing.T) { + t.Parallel() + + t.Run("auto on kubernetes writes json", func(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + env := testEnv(map[string]string{"KUBERNETES_SERVICE_HOST": "10.0.0.1"}, false) + slog.New(newHandler(&buf, slog.LevelInfo, config.LogFormatAuto, env)).Info("hello", "key", "value") + + var record map[string]any + r.NoError(json.Unmarshal(buf.Bytes(), &record)) + r.Equal("hello", record["msg"]) + r.Equal("value", record["key"]) + }) + + t.Run("auto piped writes text", func(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + slog.New(newHandler(&buf, slog.LevelInfo, config.LogFormatAuto, testEnv(nil, false))).Info("hello") + + r.Contains(buf.String(), "level=INFO msg=hello") + }) + + t.Run("level is honored", func(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + logger := slog.New(newHandler(&buf, slog.LevelWarn, config.LogFormatPretty, testEnv(nil, false))) + logger.Info("dropped") + logger.Warn("kept") + + r.NotContains(buf.String(), "dropped") + r.Contains(buf.String(), "kept") + }) +} + +// prettyLine matches one uncolored pretty line: short timestamp, short level, +// message, attributes. +var prettyLine = regexp.MustCompile(`^\d{2}:\d{2}:\d{2}\.\d{3} INF starting server a=1 http.b=2 http.c=3 d=4 z=last\n$`) + +func TestPrettyAttributeOrder(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + logger := slog.New(newPrettyHandler(&buf, slog.LevelInfo, false)) + logger.With("a", 1).WithGroup("http").With("b", 2).Info("starting server", "c", 3, slog.Group("", "d", 4)) + + r.Regexp(`^\d{2}:\d{2}:\d{2}\.\d{3} INF starting server a=1 http.b=2 http.c=3 http.d=4\n$`, buf.String()) + + // Same keys every time, same order every time: the old handler went + // through a JSON map and shuffled them per line. + for range 20 { + buf.Reset() + logger := slog.New(newPrettyHandler(&buf, slog.LevelInfo, false)) + logger.With("a", 1).Info("starting server", slog.Group("http", "b", 2, "c", 3), "d", 4, "z", "last") + r.Regexp(prettyLine, buf.String()) + } +} + +func TestPrettyColors(t *testing.T) { + t.Parallel() + + t.Run("errors are red", func(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + logger := slog.New(newPrettyHandler(&buf, slog.LevelInfo, true)) + logger.Error("boom", "error", errDiskFull, "err", "short", "other", "plain") + + out := buf.String() + r.Contains(out, "\x1b[91m", "the level and error values use bright red") + r.Regexp(`\x1b\[2;91merror=\x1b\[22m"?disk full"?\x1b\[0m`, out) + r.Regexp(`\x1b\[2;91merr=\x1b\[22mshort\x1b\[0m`, out) + r.Regexp(`\x1b\[2mother=\x1b\[0mplain`, out, "other attributes keep the default color") + }) + + t.Run("no color writes no escape sequence", func(t *testing.T) { + t.Parallel() + r := require.New(t) + + var buf bytes.Buffer + + logger := slog.New(newPrettyHandler(&buf, slog.LevelInfo, false)) + logger.Error("boom", "error", errDiskFull) + + r.NotContains(buf.String(), "\x1b") + r.Contains(buf.String(), `ERR boom error="disk full"`) + }) +} diff --git a/server/internal/utils/slog/pretty/pretty.go b/server/internal/utils/slog/pretty/pretty.go deleted file mode 100644 index 41530ec2b..000000000 --- a/server/internal/utils/slog/pretty/pretty.go +++ /dev/null @@ -1,181 +0,0 @@ -// Package pretty provides slog handlers that prints the log. -package pretty - -import ( - "bytes" - "context" - "encoding/json" - "fmt" - "io" - "log/slog" - "strings" - "sync" -) - -const ( - reset = "\033[0m" - - black = 30 - red = 31 - green = 32 - yellow = 33 - blue = 34 - magenta = 35 - cyan = 36 - lightGray = 37 - darkGray = 90 - lightRed = 91 - lightGreen = 92 - lightYellow = 93 - lightBlue = 94 - lightMagenta = 95 - lightCyan = 96 - white = 97 -) - -// Handler is a slog handler that pretty prints the log. -// From: https://dusted.codes/creating-a-pretty-console-logger-using-gos-slog-package -type Handler struct { - h slog.Handler - b *bytes.Buffer - w io.Writer - m *sync.Mutex - withColor bool -} - -// NewPretty creates a new pretty handler. -func NewPretty(writer io.Writer, opts *slog.HandlerOptions) *Handler { - if opts == nil { - opts = &slog.HandlerOptions{} - } - b := &bytes.Buffer{} - withColor := terminalSupportsColor() - return &Handler{ - b: b, - w: writer, - h: slog.NewJSONHandler(b, &slog.HandlerOptions{ - Level: opts.Level, - AddSource: opts.AddSource, - ReplaceAttr: suppressDefaults(opts.ReplaceAttr), - }), - m: &sync.Mutex{}, - withColor: withColor, - } -} - -// Enabled reports whether the handler handles records at the given level. -func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool { - return h.h.Enabled(ctx, level) -} - -// WithAttrs returns a new Handler whose attributes consists of. -func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { - return &Handler{ - h: h.h.WithAttrs(attrs), - w: h.w, - b: h.b, - m: h.m, - withColor: h.withColor, - } -} - -// WithGroup returns a new Handler with the given group appended to. -func (h *Handler) WithGroup(name string) slog.Handler { - return &Handler{ - h: h.h.WithGroup(name), - w: h.w, - b: h.b, - m: h.m, - withColor: h.withColor, - } -} - -// Handle handles the Record. -func (h *Handler) Handle(ctx context.Context, record slog.Record) error { //nolint:gocritic - // Format level with brackets - level := fmt.Sprintf("[%-5s]", record.Level.String()) - - var levelColor int - switch record.Level { - case slog.LevelDebug: - levelColor = lightGray - case slog.LevelInfo: - levelColor = green - case slog.LevelWarn: - levelColor = yellow - case slog.LevelError: - levelColor = red - } - level = h.colorize(levelColor, level) - - attrs, err := h.computeAttrs(ctx, record) - if err != nil { - return err - } - - // Format attributes as key=value pairs - var attrStrSb strings.Builder - for k, v := range attrs { - if str, ok := v.(string); ok { - fmt.Fprintf(&attrStrSb, " %s=%s", h.colorize(cyan, k), h.colorize(magenta, str)) - } else { - fmt.Fprintf(&attrStrSb, " %s=%v", h.colorize(cyan, k), v) - } - } - attrStr := attrStrSb.String() - - // Print without the timestamp and with proper spacing - if _, err := fmt.Fprintf(h.w, "%s %-50s%s\n", - level, - record.Message, - attrStr, - ); err != nil { - return fmt.Errorf("error when writing to writer: %w", err) - } - - return nil -} - -func (h *Handler) computeAttrs( - ctx context.Context, - record slog.Record, //nolint:gocritic -) (map[string]any, error) { - h.m.Lock() - defer func() { - h.b.Reset() - h.m.Unlock() - }() - if err := h.h.Handle(ctx, record); err != nil { - return nil, fmt.Errorf("error when calling inner handler's Handle: %w", err) - } - - var attrs map[string]any - err := json.Unmarshal(h.b.Bytes(), &attrs) - if err != nil { - return nil, fmt.Errorf("error when unmarshaling inner handler's Handle result: %w", err) - } - return attrs, nil -} - -func (h *Handler) colorize(colorCode int, v string) string { - if !h.withColor { - return v - } - return fmt.Sprintf("\033[%dm%v%s", colorCode, v, reset) -} - -func suppressDefaults( - next func([]string, slog.Attr) slog.Attr, -) func([]string, slog.Attr) slog.Attr { - return func(groups []string, attr slog.Attr) slog.Attr { - if attr.Key == slog.TimeKey || - attr.Key == slog.LevelKey || - attr.Key == slog.MessageKey { - return slog.Attr{} - } - if next == nil { - return attr - } - return next(groups, attr) - } -} diff --git a/server/internal/utils/slog/pretty/terminal_unix.go b/server/internal/utils/slog/pretty/terminal_unix.go deleted file mode 100644 index 9746ab089..000000000 --- a/server/internal/utils/slog/pretty/terminal_unix.go +++ /dev/null @@ -1,19 +0,0 @@ -//go:build !windows - -package pretty - -import ( - "os" - - "golang.org/x/term" -) - -func terminalSupportsColor() bool { - if os.Getenv("NO_COLOR") != "" { - return false - } - if os.Getenv("FORCE_COLOR") != "" { - return true - } - return term.IsTerminal(int(os.Stdout.Fd())) -} diff --git a/server/internal/utils/slog/pretty/terminal_windows.go b/server/internal/utils/slog/pretty/terminal_windows.go deleted file mode 100644 index f691099da..000000000 --- a/server/internal/utils/slog/pretty/terminal_windows.go +++ /dev/null @@ -1,24 +0,0 @@ -//go:build windows - -package pretty - -import ( - "os" - - "golang.org/x/sys/windows" -) - -func terminalSupportsColor() bool { - handle := windows.Handle(os.Stdout.Fd()) - var mode uint32 - - err := windows.GetConsoleMode(handle, &mode) - if err != nil { - return false - } - - // Enable ENABLE_VIRTUAL_TERMINAL_PROCESSING - mode |= windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING - err = windows.SetConsoleMode(handle, mode) - return err == nil -} diff --git a/server/main.go b/server/main.go index cb3ecccd0..40a81de78 100644 --- a/server/main.go +++ b/server/main.go @@ -25,11 +25,11 @@ import ( "github.com/fclairamb/solidping/server/internal/db/sqlite" "github.com/fclairamb/solidping/server/internal/envcheck" "github.com/fclairamb/solidping/server/internal/healthcheck" + "github.com/fclairamb/solidping/server/internal/logsetup" "github.com/fclairamb/solidping/server/internal/memlimit" "github.com/fclairamb/solidping/server/internal/otelsetup" "github.com/fclairamb/solidping/server/internal/procwatch" slogutil "github.com/fclairamb/solidping/server/internal/utils/slog" - "github.com/fclairamb/solidping/server/internal/utils/slog/pretty" "github.com/fclairamb/solidping/server/internal/version" spCli "github.com/fclairamb/solidping/server/pkg/cli" ) @@ -40,10 +40,10 @@ const ( ) func main() { - // Set up logger early (before config load to ensure it's always configured) - // Read LOG_LEVEL env var directly to configure logger before config load - logLevel := config.ParseLogLevel(os.Getenv("LOG_LEVEL")) - setupLogger(logLevel, config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) + // Set up the logger before the configuration loads, from the same + // environment variables config.Load reads, so startup logs already honor + // them. + setupLogger(config.LogLevelFromEnv(os.Getenv), config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) os.Exit(run(context.Background(), buildRootCommand(), os.Args)) } @@ -67,8 +67,8 @@ func run(ctx context.Context, cmd *cli.Command, args []string) int { // own "Application failed" included) must never land in it. The other server // commands keep logging to stdout. func logToStderr(ctx context.Context, _ *cli.Command) (context.Context, error) { - handler := newLogHandlerTo(os.Stderr, - config.ParseLogLevel(os.Getenv("LOG_LEVEL")), config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) + handler := logsetup.NewHandler(os.Stderr, + config.LogLevelFromEnv(os.Getenv), config.ParseLogFormat(os.Getenv("SP_LOG_FORMAT"))) slog.SetDefault(slog.New(handler)) return ctx, nil @@ -144,33 +144,12 @@ func buildRootCommand() *cli.Command { } } -// newLogHandler builds the stdout handler for the requested format. It is the -// single place that maps a config.LogFormat onto a slog.Handler, so the plain -// path and the OTel fanout path below can never drift apart. -func newLogHandler(level slog.Level, format config.LogFormat) slog.Handler { - return newLogHandlerTo(os.Stdout, level, format) -} - -// newLogHandlerTo is newLogHandler writing to out instead of stdout. -func newLogHandlerTo(out io.Writer, level slog.Level, format config.LogFormat) slog.Handler { - opts := &slog.HandlerOptions{Level: level} - - switch format { - case config.LogFormatJSON: - return slog.NewJSONHandler(out, opts) - case config.LogFormatPretty: - return pretty.NewPretty(out, opts) - case config.LogFormatText: - return slog.NewTextHandler(out, opts) - default: - return slog.NewTextHandler(out, opts) - } -} - -// setupLogger configures the default slog logger with the given level and format. +// setupLogger points the default slog logger at stdout with the given level +// and format. logsetup.NewHandler is the single place that maps a +// config.LogFormat onto a slog.Handler, so this path, the stderr one and the +// OTel fanout path below can never drift apart. func setupLogger(level slog.Level, format config.LogFormat) { - logger := slog.New(newLogHandler(level, format)) - slog.SetDefault(logger) + slog.SetDefault(slog.New(logsetup.NewHandler(os.Stdout, level, format))) } func serve(ctx context.Context, _ *cli.Command) error { @@ -231,7 +210,7 @@ func loadServeConfig(ctx context.Context, logOut io.Writer) (*config.Config, fun } // Re-configure logger with the log level from config - slog.SetDefault(slog.New(newLogHandlerTo(logOut, cfg.LogLevel, cfg.LogFormat))) + slog.SetDefault(slog.New(logsetup.NewHandler(logOut, cfg.LogLevel, cfg.LogFormat))) // Warn about unrecognized SP_* environment variables before validating: a // typo'd var is often *why* validation fails, so the hint must print before @@ -282,7 +261,7 @@ func loadServeConfig(ctx context.Context, logOut io.Writer) (*config.Config, fun // If OTel logs are enabled, add otelslog bridge via fanout if logProvider != nil { - outHandler := newLogHandlerTo(logOut, cfg.LogLevel, cfg.LogFormat) + outHandler := logsetup.NewHandler(logOut, cfg.LogLevel, cfg.LogFormat) otelHandler := otelslog.NewHandler( "solidping", otelslog.WithLoggerProvider(logProvider), diff --git a/server/main_test.go b/server/main_test.go index fa4337602..46e070068 100644 --- a/server/main_test.go +++ b/server/main_test.go @@ -215,7 +215,7 @@ func TestClientMCPFailureKeepsStdoutClean(t *testing.T) { // runClientMCPHelper is the child side: it mirrors main() (stdout logger, // then run) and exits with run's code. func runClientMCPHelper(mode string) { - setupLogger(config.ParseLogLevel(os.Getenv("LOG_LEVEL")), config.LogFormatText) + setupLogger(config.LogLevelFromEnv(os.Getenv), config.LogFormatText) root := buildRootCommand() diff --git a/web/docs/docs/configuration/index.md b/web/docs/docs/configuration/index.md index eccc3b24a..fe4038efb 100644 --- a/web/docs/docs/configuration/index.md +++ b/web/docs/docs/configuration/index.md @@ -187,10 +187,20 @@ used, so edits made through the API are preserved across restarts. | Variable | Default | Description | |----------|---------|-------------| | `SP_LOG_LEVEL` | `info` | Log level: `debug`, `info`, `warn`, `error` | -| `SP_LOG_FORMAT` | `text` | Output format: `text` (key=value logfmt), `json` (one object per record, for log collectors), `pretty` (colourized, for interactive use) | -| `LOG_LEVEL` | `info` | Same, but read before the configuration system loads — use it to debug startup itself | -| `NO_COLOR` | - | Set to any value to disable coloured terminal output ([no-color.org](https://no-color.org/)) | -| `FORCE_COLOR` | - | Set to any value to force coloured output when the terminal is not detected as a TTY | +| `LOG_LEVEL` | - | Fallback for `SP_LOG_LEVEL`, used when `SP_LOG_LEVEL` is not set | +| `SP_LOG_FORMAT` | `auto` | Output format: `auto`, `text` (key=value logfmt), `json` (one object per record, for log collectors), `pretty` (colourized, for people) | +| `NO_COLOR` | - | Set to any value to disable coloured output ([no-color.org](https://no-color.org/)) | +| `FORCE_COLOR` | - | Set to any value to force coloured output when neither a terminal nor a container is detected | + +`auto` picks the format when the server starts: + +- `json` on Kubernetes (`KUBERNETES_SERVICE_HOST` is set). The Helm chart also sets `SP_LOG_FORMAT=json` explicitly. +- `pretty` when the output is a terminal, or inside a Docker or Podman container (`/.dockerenv` or `/run/.containerenv` exists), so `docker logs` is readable. +- `text` otherwise. + +If you ship Docker logs to a log collector, set `SP_LOG_FORMAT=json`. + +`pretty` is coloured on a terminal and in a container. A typo in `SP_LOG_FORMAT` falls back to `auto`. ### Authentication @@ -359,7 +369,7 @@ SP_GOOGLE_CLIENT_SECRET=your-google-client-secret # Logging SP_LOG_LEVEL=info -SP_LOG_FORMAT=text +SP_LOG_FORMAT=auto ``` ### Configuration File (config.yml) diff --git a/web/docs/docs/installation/docker-compose.md b/web/docs/docs/installation/docker-compose.md index 90bab0aec..569141d6f 100644 --- a/web/docs/docs/installation/docker-compose.md +++ b/web/docs/docs/installation/docker-compose.md @@ -38,7 +38,7 @@ services: environment: SP_DB_TYPE: postgres SP_DB_URL: postgresql://postgres:postgres@postgres:5432/postgres?sslmode=disable - LOG_LEVEL: debug + SP_LOG_LEVEL: debug volumes: - solidping-data:/data depends_on: @@ -97,7 +97,7 @@ services: SP_EMAIL_USERNAME: ${SMTP_USERNAME} SP_EMAIL_PASSWORD: ${SMTP_PASSWORD} SP_EMAIL_FROM: ${SMTP_FROM} - LOG_LEVEL: info + SP_LOG_LEVEL: info volumes: - solidping-data:/data depends_on: @@ -125,7 +125,7 @@ SMTP_FROM=noreply@example.com # Start in background docker-compose up -d -# View logs +# View logs (coloured "pretty" format by default in a container) docker-compose logs -f solidping # Stop @@ -135,6 +135,8 @@ docker-compose down docker-compose down -v ``` +If you ship the container logs to a log collector, set `SP_LOG_FORMAT: json`. See [Logging](/configuration#logging). + ## With Reverse Proxy (Traefik) Example with Traefik for automatic HTTPS: diff --git a/web/docs/docs/installation/linux.md b/web/docs/docs/installation/linux.md index 0ebc631c6..47c212dba 100644 --- a/web/docs/docs/installation/linux.md +++ b/web/docs/docs/installation/linux.md @@ -184,7 +184,7 @@ SP_EMAIL_PASSWORD=smtp-password SP_EMAIL_FROM=noreply@example.com # Logging -LOG_LEVEL=info +SP_LOG_LEVEL=info ``` Update the systemd service to use the environment file: diff --git a/wiki/runbooks/api-testing-with-curl.md b/wiki/runbooks/api-testing-with-curl.md index e58e441d9..292a524e5 100644 --- a/wiki/runbooks/api-testing-with-curl.md +++ b/wiki/runbooks/api-testing-with-curl.md @@ -100,4 +100,4 @@ not a special case for the seeded admin. Test mode (`test@test.com`) is not flag ## Troubleshooting - If token expires, re-run the login command to get a fresh token - Check server is running: `curl -s http://localhost:4000/api/mgmt/health` -- Enable debug logging: `LOG_LEVEL=debug ./solidping serve` +- Enable debug logging: `SP_LOG_LEVEL=debug ./solidping serve`