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