From 0e470ae3fcbd1ed83d489bf02cbc3b89a7739d2e Mon Sep 17 00:00:00 2001 From: Samantha Date: Thu, 2 Jul 2026 13:51:50 -0400 Subject: [PATCH] blog: send syslog messages at severity matching their level The slog migration (#8606) dialed syslog once at LOG_INFO and pushed every record through plain io.Writer.Write, which stamps the dial-time priority on every message. As a result all lines, including errors and audit errors, arrived at syslog with severity 6, breaking any rsyslog routing or alerting keyed on syslog severity, contrary to the migration's stated goal of leaving log routing unchanged. Route each record through the severity-specific syslog method (Err, Warning, Info, Debug) matching its slog level, restoring pre-migration behavior. Note for deployment: anything adapted to the flattened all-INFO behavior since #8606 will see severities change back. --- blog/logger.go | 4 +- blog/severity.go | 116 ++++++++++++++++++++++++++++++++++++++++ blog/severity_test.go | 120 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 237 insertions(+), 3 deletions(-) create mode 100644 blog/severity.go create mode 100644 blog/severity_test.go diff --git a/blog/logger.go b/blog/logger.go index de262925178..71196016b66 100644 --- a/blog/logger.go +++ b/blog/logger.go @@ -63,9 +63,7 @@ func New(conf Config) (*logger, error) { return nil, fmt.Errorf("failed to connect to syslog: %w", err) } - writer := newChecksumWriter(syslogger) - opts := &slog.HandlerOptions{Level: configToSlogLevel(conf.SyslogLevel)} - syslogHandler = &contextHandler{inner: newAuditHandler(writer, opts)} + syslogHandler = &contextHandler{inner: newSeverityHandler(syslogger, conf.SyslogLevel)} } var l *slog.Logger diff --git a/blog/severity.go b/blog/severity.go new file mode 100644 index 00000000000..73535b83503 --- /dev/null +++ b/blog/severity.go @@ -0,0 +1,116 @@ +package blog + +// This file provides a slog.Handler which routes each record to the syslog +// severity matching the record's slog level. The stdlib syslog.Writer applies +// its dial-time priority to every plain Write call, so if we treated it as a +// simple io.Writer then every line, including errors and audit errors, would +// arrive at syslog with severity INFO, breaking any downstream routing or +// alerting keyed on syslog severity (e.g. rsyslog "*.err" selectors). Instead +// we build one full handler chain per severity, each bottoming out in the +// severity-specific method (Err, Warning, Info, Debug) on the shared +// syslog.Writer, and dispatch each record to the chain matching its level. + +import ( + "context" + "io" + "log/slog" + "log/syslog" +) + +// syslogWriter is the subset of *syslog.Writer used by severityHandler. It +// exists so that tests can substitute a fake. +type syslogWriter interface { + Err(string) error + Warning(string) error + Info(string) error + Debug(string) error +} + +var _ syslogWriter = (*syslog.Writer)(nil) + +// severityWriter adapts one severity-specific method of a syslog.Writer to the +// io.Writer interface expected by the checksum and audit writers. +type severityWriter struct { + fn func(string) error +} + +var _ io.Writer = (*severityWriter)(nil) + +// Write implements the io.Writer interface. It forwards its input to the +// wrapped severity-specific syslog method, which serializes concurrent calls +// with the syslog.Writer's internal mutex. +func (w *severityWriter) Write(in []byte) (int, error) { + return len(in), w.fn(string(in)) +} + +// severityHandler is a slog.Handler which dispatches each record to one of +// four wrapped handlers based on the record's level, so that each line reaches +// syslog with the matching severity. All four wrapped handlers are constructed +// with the same HandlerOptions-derived level, so Enabled is uniform across +// them. +type severityHandler struct { + err slog.Handler + warn slog.Handler + info slog.Handler + debug slog.Handler +} + +var _ slog.Handler = (*severityHandler)(nil) + +// newSeverityHandler builds a severityHandler over the given syslog writer. +// The confLevel argument is the syslog-style (0-7) level from our Config. +func newSeverityHandler(w syslogWriter, confLevel int) *severityHandler { + build := func(fn func(string) error) slog.Handler { + // Each chain gets its own HandlerOptions because newAuditHandler + // modifies opts.ReplaceAttr in place. + opts := &slog.HandlerOptions{Level: configToSlogLevel(confLevel)} + return newAuditHandler(newChecksumWriter(&severityWriter{fn: fn}), opts) + } + return &severityHandler{ + err: build(w.Err), + warn: build(w.Warning), + info: build(w.Info), + debug: build(w.Debug), + } +} + +// Enabled reports whether records at the given level would be handled. All +// wrapped handlers share the same level, so consulting one suffices. +func (h *severityHandler) Enabled(ctx context.Context, l slog.Level) bool { + return h.info.Enabled(ctx, l) +} + +// Handle dispatches the record to the wrapped handler whose syslog severity +// matches the record's level. +func (h *severityHandler) Handle(ctx context.Context, r slog.Record) error { + switch { + case r.Level >= slog.LevelError: + return h.err.Handle(ctx, r) + case r.Level >= slog.LevelWarn: + return h.warn.Handle(ctx, r) + case r.Level >= slog.LevelInfo: + return h.info.Handle(ctx, r) + default: + return h.debug.Handle(ctx, r) + } +} + +// WithAttrs calls WithAttrs on all wrapped handlers. +func (h *severityHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &severityHandler{ + err: h.err.WithAttrs(attrs), + warn: h.warn.WithAttrs(attrs), + info: h.info.WithAttrs(attrs), + debug: h.debug.WithAttrs(attrs), + } +} + +// WithGroup calls WithGroup on all wrapped handlers. +func (h *severityHandler) WithGroup(name string) slog.Handler { + return &severityHandler{ + err: h.err.WithGroup(name), + warn: h.warn.WithGroup(name), + info: h.info.WithGroup(name), + debug: h.debug.WithGroup(name), + } +} diff --git a/blog/severity_test.go b/blog/severity_test.go new file mode 100644 index 00000000000..361b2f35973 --- /dev/null +++ b/blog/severity_test.go @@ -0,0 +1,120 @@ +package blog + +import ( + "context" + "errors" + "log/slog" + "strings" + "sync" + "testing" +) + +// fakeSyslog records which severity-specific method each line arrived on. +type fakeSyslog struct { + mu sync.Mutex + lines map[string][]string +} + +func newFakeSyslog() *fakeSyslog { + return &fakeSyslog{lines: make(map[string][]string)} +} + +func (f *fakeSyslog) record(severity, m string) error { + f.mu.Lock() + defer f.mu.Unlock() + f.lines[severity] = append(f.lines[severity], m) + return nil +} + +func (f *fakeSyslog) Err(m string) error { return f.record("err", m) } +func (f *fakeSyslog) Warning(m string) error { return f.record("warning", m) } +func (f *fakeSyslog) Info(m string) error { return f.record("info", m) } +func (f *fakeSyslog) Debug(m string) error { return f.record("debug", m) } + +var _ syslogWriter = (*fakeSyslog)(nil) + +func TestSeverityHandlerRouting(t *testing.T) { + t.Parallel() + + // Each log level must reach syslog via the matching severity-specific + // method, so that the syslog-layer severity (used by rsyslog routing and + // alerting) matches the level inside the message. + fake := newFakeSyslog() + l := &logger{inner: slog.New(&contextHandler{inner: newSeverityHandler(fake, 7)})} + ctx := context.Background() + + l.Error(ctx, "an error", errors.New("boom")) + l.AuditError(ctx, "an audit error", errors.New("bang")) + l.Warn(ctx, "a warning") + l.Info(ctx, "some info") + l.AuditInfo(ctx, "some audit info") + l.Debug(ctx, "some detail") + + fake.mu.Lock() + defer fake.mu.Unlock() + + for severity, wantMsgs := range map[string][]string{ + "err": {"an error", "an audit error"}, + "warning": {"a warning"}, + "info": {"some info", "some audit info"}, + "debug": {"some detail"}, + } { + got := fake.lines[severity] + if len(got) != len(wantMsgs) { + t.Fatalf("severity %q received %d lines, want %d: %v", severity, len(got), len(wantMsgs), got) + } + for i, want := range wantMsgs { + if !strings.Contains(got[i], want) { + t.Errorf("severity %q line %d = %q, does not contain %q", severity, i, got[i], want) + } + } + } + + // Audit lines must retain their [AUDIT] tag and all lines their checksum, + // regardless of which severity chain they took. + if !strings.Contains(fake.lines["err"][1], "[AUDIT]") { + t.Errorf("audit error line %q should contain [AUDIT]", fake.lines["err"][1]) + } + if !strings.Contains(fake.lines["info"][1], "[AUDIT]") { + t.Errorf("audit info line %q should contain [AUDIT]", fake.lines["info"][1]) + } + // Lines are formatted " [AUDIT] " / " ", + // with the checksum covering everything after it except the trailing + // newline. + for severity, lines := range fake.lines { + for _, line := range lines { + checksum, body, ok := strings.Cut(strings.TrimSuffix(line, "\n"), " ") + if !ok || checksum != LogLineChecksum(body) { + t.Errorf("severity %q line %q lacks a valid checksum prefix", severity, line) + } + } + } +} + +func TestSeverityHandlerLevelFiltering(t *testing.T) { + t.Parallel() + + // A severityHandler built at level 3 (errors only) must not emit anything + // for lower-severity records. + fake := newFakeSyslog() + l := &logger{inner: slog.New(&contextHandler{inner: newSeverityHandler(fake, 3)})} + ctx := context.Background() + + l.Error(ctx, "an error", errors.New("boom")) + l.Warn(ctx, "a warning") + l.Info(ctx, "some info") + l.Debug(ctx, "some detail") + + fake.mu.Lock() + defer fake.mu.Unlock() + + if len(fake.lines["err"]) != 1 { + t.Errorf("severity err received %d lines, want 1: %v", len(fake.lines["err"]), fake.lines["err"]) + } + for _, severity := range []string{"warning", "info", "debug"} { + if len(fake.lines[severity]) != 0 { + t.Errorf("severity %q received %d lines, want 0 at config level 3: %v", + severity, len(fake.lines[severity]), fake.lines[severity]) + } + } +}