diff --git a/go.mod b/go.mod index cf5a3f5..6c438e5 100644 --- a/go.mod +++ b/go.mod @@ -71,6 +71,7 @@ require ( github.com/samber/slog-common v0.22.0 // indirect github.com/spf13/afero v1.15.0 // indirect github.com/spf13/pflag v1.0.10 // indirect + github.com/systemd/slog-journal v0.1.2 // indirect github.com/valyala/bytebufferpool v1.0.0 // indirect github.com/valyala/fasttemplate v1.2.2 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect diff --git a/go.sum b/go.sum index 7df9fb1..ce9a692 100644 --- a/go.sum +++ b/go.sum @@ -121,6 +121,8 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= +github.com/systemd/slog-journal v0.1.2 h1:oU30ghDjjSsQGBGQLzunPeURHe7fyh0Z99Ap5QeiMFY= +github.com/systemd/slog-journal v0.1.2/go.mod h1:3ekGgwBlzs82itNN6iG6c3R1iEhkbrvBCpQHxine2L8= github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw= github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyCJ6HpOuEn7z0Csc= github.com/valyala/fasttemplate v1.2.2 h1:lxLXG0uE3Qnshl9QyaK6XJxMXlQZELvChBOCmQD0Loo= diff --git a/logger/journald.go b/logger/journald.go new file mode 100644 index 0000000..3a228f8 --- /dev/null +++ b/logger/journald.go @@ -0,0 +1,62 @@ +package logger + +import ( + "log/slog" + + slogjournal "github.com/systemd/slog-journal" +) + +// newJournalHandler returns a slog.Handler that delivers records to the +// systemd journal using the native protocol. It returns nil when stderr +// is not connected to journald, in which case the caller falls back to +// the stderr text handler. +func newJournalHandler(opts *slog.HandlerOptions) slog.Handler { + if !stderrIsJournal() { + return nil + } + h, err := slogjournal.NewHandler(&slogjournal.Options{ + Level: opts.Level, + ReplaceAttr: journalReplaceAttr, + ReplaceGroup: sanitizeJournalKey, + }) + if err != nil { + return nil + } + return h +} + +// journalReplaceAttr sanitizes slog attribute keys so they satisfy the +// journal's ^[A-Z_][A-Z0-9_]*$ constraint. Without this, otherwise +// valid attributes from third-party handlers (e.g. the trace_id/span_id +// injected by slogtraceid) are silently dropped by the journal. +func journalReplaceAttr(groups []string, a slog.Attr) slog.Attr { + a.Key = sanitizeJournalKey(a.Key) + return a +} + +// sanitizeJournalKey maps an arbitrary string to a journal-legal key: +// upper-cases ASCII letters, replaces everything outside [A-Z0-9_] with +// '_', and prefixes '_' if the first byte is a digit. +func sanitizeJournalKey(k string) string { + if k == "" { + return k + } + b := make([]byte, 0, len(k)+1) + for i := 0; i < len(k); i++ { + c := k[i] + switch { + case c >= 'A' && c <= 'Z', c == '_': + b = append(b, c) + case c >= 'a' && c <= 'z': + b = append(b, c-'a'+'A') + case c >= '0' && c <= '9': + if i == 0 { + b = append(b, '_') + } + b = append(b, c) + default: + b = append(b, '_') + } + } + return string(b) +} diff --git a/logger/journald_linux.go b/logger/journald_linux.go new file mode 100644 index 0000000..46243ba --- /dev/null +++ b/logger/journald_linux.go @@ -0,0 +1,41 @@ +//go:build linux + +package logger + +import ( + "os" + "strconv" + "strings" + "syscall" +) + +// stderrIsJournal reports whether os.Stderr is currently connected to +// the systemd journal. systemd.exec(5) sets JOURNAL_STREAM to +// ":" of the journal stream at service start. Detection +// must fstat(2) the actual stderr and compare — a child process may +// redirect stderr while inheriting the env var, so presence of the +// variable alone is not sufficient. +func stderrIsJournal() bool { + dev, ino, ok := parseJournalStream(os.Getenv("JOURNAL_STREAM")) + if !ok { + return false + } + var st syscall.Stat_t + if err := syscall.Fstat(int(os.Stderr.Fd()), &st); err != nil { + return false + } + return uint64(st.Dev) == dev && uint64(st.Ino) == ino +} + +func parseJournalStream(v string) (dev, ino uint64, ok bool) { + sep := strings.IndexByte(v, ':') + if sep <= 0 || sep == len(v)-1 { + return 0, 0, false + } + d, err1 := strconv.ParseUint(v[:sep], 10, 64) + n, err2 := strconv.ParseUint(v[sep+1:], 10, 64) + if err1 != nil || err2 != nil { + return 0, 0, false + } + return d, n, true +} diff --git a/logger/journald_linux_test.go b/logger/journald_linux_test.go new file mode 100644 index 0000000..ea27eee --- /dev/null +++ b/logger/journald_linux_test.go @@ -0,0 +1,76 @@ +//go:build linux + +package logger + +import ( + "fmt" + "os" + "syscall" + "testing" +) + +func TestParseJournalStream(t *testing.T) { + tests := []struct { + name string + input string + wantDev uint64 + wantIno uint64 + wantOK bool + }{ + {"empty", "", 0, 0, false}, + {"no separator", "12345", 0, 0, false}, + {"leading colon", ":12345", 0, 0, false}, + {"trailing colon", "8:", 0, 0, false}, + {"non-numeric dev", "x:12345", 0, 0, false}, + {"non-numeric ino", "8:x", 0, 0, false}, + {"valid small", "8:12345", 8, 12345, true}, + {"valid large", "18446744073709551615:1", 18446744073709551615, 1, true}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + dev, ino, ok := parseJournalStream(tt.input) + if ok != tt.wantOK { + t.Fatalf("ok=%v want %v (input=%q)", ok, tt.wantOK, tt.input) + } + if ok && (dev != tt.wantDev || ino != tt.wantIno) { + t.Fatalf("dev=%d ino=%d want dev=%d ino=%d", dev, ino, tt.wantDev, tt.wantIno) + } + }) + } +} + +func TestStderrIsJournal_Unset(t *testing.T) { + t.Setenv("JOURNAL_STREAM", "") + if stderrIsJournal() { + t.Fatal("stderrIsJournal returned true with JOURNAL_STREAM unset") + } +} + +func TestStderrIsJournal_Bogus(t *testing.T) { + t.Setenv("JOURNAL_STREAM", "not-a-valid-value") + if stderrIsJournal() { + t.Fatal("stderrIsJournal returned true with bogus JOURNAL_STREAM") + } +} + +func TestStderrIsJournal_Mismatch(t *testing.T) { + // Pick impossibly high dev:inode that won't match real stderr. + t.Setenv("JOURNAL_STREAM", "999999999:999999999") + if stderrIsJournal() { + t.Fatal("stderrIsJournal returned true for mismatching dev:ino") + } +} + +func TestStderrIsJournal_Match(t *testing.T) { + // Point JOURNAL_STREAM at the real stderr's dev:inode and confirm + // detection works. This exercises the fstat+compare path without + // needing an actual journal socket. + var st syscall.Stat_t + if err := syscall.Fstat(int(os.Stderr.Fd()), &st); err != nil { + t.Fatalf("fstat stderr: %v", err) + } + t.Setenv("JOURNAL_STREAM", fmt.Sprintf("%d:%d", uint64(st.Dev), uint64(st.Ino))) + if !stderrIsJournal() { + t.Fatal("stderrIsJournal returned false when JOURNAL_STREAM matches stderr dev:ino") + } +} diff --git a/logger/journald_other.go b/logger/journald_other.go new file mode 100644 index 0000000..d758289 --- /dev/null +++ b/logger/journald_other.go @@ -0,0 +1,8 @@ +//go:build !linux + +package logger + +// stderrIsJournal always returns false on non-Linux platforms. The +// systemd journal is Linux-only; developer workstations and other +// targets fall back to the stderr text handler. +func stderrIsJournal() bool { return false } diff --git a/logger/journald_test.go b/logger/journald_test.go new file mode 100644 index 0000000..ace3b11 --- /dev/null +++ b/logger/journald_test.go @@ -0,0 +1,28 @@ +package logger + +import "testing" + +func TestSanitizeJournalKey(t *testing.T) { + tests := []struct { + in, want string + }{ + {"", ""}, + {"MESSAGE", "MESSAGE"}, + {"trace_id", "TRACE_ID"}, + {"span.id", "SPAN_ID"}, + {"http-method", "HTTP_METHOD"}, + {"a", "A"}, + {"123abc", "_123ABC"}, + {"weird!@#key", "WEIRD___KEY"}, + {"_leading", "_LEADING"}, + {"MiXeD_Case", "MIXED_CASE"}, + } + for _, tt := range tests { + t.Run(tt.in, func(t *testing.T) { + got := sanitizeJournalKey(tt.in) + if got != tt.want { + t.Errorf("sanitizeJournalKey(%q) = %q, want %q", tt.in, got, tt.want) + } + }) + } +} diff --git a/logger/logger.go b/logger/logger.go index d801270..c5946a9 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -128,6 +128,15 @@ func setupStdErrHandler() slog.Handler { } } + // DEBUG_INVOCATION is set by systemd on a restart attempt of a unit + // configured with RestartMode=debug when the previous start failed. + // Treat it as a request to raise stderr verbosity to Debug so the + // next failing cycle yields maximum diagnostics. OTLPLevel is left + // alone — that stays under server/admin control. + if os.Getenv("DEBUG_INVOCATION") != "" { + Level.Set(slog.LevelDebug) + } + logOptions := &slog.HandlerOptions{Level: Level} if len(os.Getenv("INVOCATION_ID")) > 0 { @@ -137,8 +146,15 @@ func setupStdErrHandler() slog.Handler { logOptions.ReplaceAttr = logRemoveTime } + var base slog.Handler + if h := newJournalHandler(logOptions); h != nil { + base = h + } else { + base = slog.NewTextHandler(os.Stderr, logOptions) + } + logHandler := slogtraceid.OtelHandler{ - Next: slog.NewTextHandler(os.Stderr, logOptions), + Next: base, } return logHandler