blog: Send syslog messages at severity matching their level

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

blog/severity.go

@@ -0,0 +1,120 @@
+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. It tracks the configured minimum level
+// itself, so the wrapped handlers do no level filtering of their own.
+type severityHandler struct {
+	level slog.Level
+	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 {
+		// configToSlogLevel never returns a level below LevelDebug, so these
+		// chains accept every record that severityHandler.Enabled accepts.
+		// Each chain gets its own HandlerOptions because newAuditHandler
+		// modifies opts.ReplaceAttr in place.
+		opts := &slog.HandlerOptions{Level: slog.LevelDebug}
+		return newAuditHandler(newChecksumWriter(&severityWriter{fn: fn}), opts)
+	}
+	return &severityHandler{
+		level: configToSlogLevel(confLevel),
+		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.
+func (h *severityHandler) Enabled(_ context.Context, l slog.Level) bool {
+	return l >= h.level
+}
+
+// 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{
+		level: h.level,
+		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{
+		level: h.level,
+		err:   h.err.WithGroup(name),
+		warn:  h.warn.WithGroup(name),
+		info:  h.info.WithGroup(name),
+		debug: h.debug.WithGroup(name),
+	}
+}

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 "<checksum> [AUDIT] <record>" / "<checksum> <record>",
+	// 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])
+		}
+	}
+}