From: Anderson A. Giacomolli Date: Tue, 10 Nov 2026 01:26:01 +0000 (-0300) Subject: Format short daemon events with slog X-Git-Url: http://git.giacomolli.uk/onechat/commitdiff_plain/4c199e7d93b6a4529ed5956807911b5f6c5489a7?ds=inline Format short daemon events with slog A shared handler writes the event and ordered attributes, with the error cause last. Journal lines carry a syslog priority and terminal lines carry the time and level, so each output keeps short, readable events. --- diff --git a/daemon_log.go b/daemon_log.go new file mode 100644 index 0000000..15426bc --- /dev/null +++ b/daemon_log.go @@ -0,0 +1,143 @@ +package main + +import ( + "context" + "fmt" + "io" + "log/slog" + "strings" + "sync" +) + +// DaemonLogHandler writes short event lines with ordered attributes. Copies +// share the writer lock. The err attribute follows all other attributes as a +// cause. Journal lines carry a syslog priority instead of a time and level. +type DaemonLogHandler struct { + out io.Writer + prefix string + journal bool + mutex *sync.Mutex + attrs []slog.Attr + group string +} + +func (h *DaemonLogHandler) Enabled(_ context.Context, _ slog.Level) bool { + return true +} + +func (h *DaemonLogHandler) Handle(_ context.Context, record slog.Record) error { + var line strings.Builder + + if h.journal { + priority := 7 + switch { + case record.Level >= slog.LevelError: + priority = 3 + case record.Level >= slog.LevelWarn: + priority = 4 + case record.Level >= slog.LevelInfo: + priority = 6 + } + + fmt.Fprintf(&line, "<%d>", priority) + } else { + line.WriteString(record.Time.Format("2006/01/02 15:04:05")) + line.WriteByte(' ') + line.WriteString(record.Level.String()) + line.WriteByte(' ') + } + + line.WriteString(h.prefix) + line.WriteString(record.Message) + + var cause string + + for _, attr := range h.attrs { + daemonLogAttr(&line, "", attr, &cause) + } + + record.Attrs(func(attr slog.Attr) bool { + daemonLogAttr(&line, h.group, attr, &cause) + + return true + }) + + if cause != "" { + line.WriteString(": ") + line.WriteString(cause) + } + + line.WriteByte('\n') + h.mutex.Lock() + defer h.mutex.Unlock() + + _, err := io.WriteString(h.out, line.String()) + if err != nil { + return fmt.Errorf("write daemon log: %w", err) + } + + return nil +} + +func (h *DaemonLogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + clone := *h + clone.attrs = append([]slog.Attr(nil), h.attrs...) + for _, attr := range attrs { + if h.group != "" { + attr = slog.Group(strings.TrimSuffix(h.group, "."), attr) + } + + clone.attrs = append(clone.attrs, attr) + } + + return &clone +} + +func (h *DaemonLogHandler) WithGroup(name string) slog.Handler { + clone := *h + if name != "" { + clone.group += name + "." + } + + return &clone +} + +// daemonLogAttr resolves and writes one attribute, or keeps its cause for the +// end of the line. Groups flatten into dotted keys and empty attributes produce +// no text. +func daemonLogAttr(line *strings.Builder, group string, attr slog.Attr, cause *string) { + attr.Value = attr.Value.Resolve() + if attr.Equal(slog.Attr{}) { + return + } + + if attr.Value.Kind() == slog.KindGroup { + if attr.Key != "" { + group += attr.Key + "." + } + + for _, child := range attr.Value.Group() { + daemonLogAttr(line, group, child, cause) + } + + return + } + + if attr.Key == "err" { + if attr.Value.Any() != nil { + *cause = fmt.Sprint(attr.Value.Any()) + } + + return + } + + line.WriteByte(' ') + line.WriteString(group + attr.Key) + line.WriteByte('=') + + if attr.Value.Kind() == slog.KindDuration { + line.WriteString(durationText(attr.Value.Duration())) + } else { + fmt.Fprint(line, attr.Value.Any()) + } +} diff --git a/daemon_log_test.go b/daemon_log_test.go new file mode 100644 index 0000000..31a3278 --- /dev/null +++ b/daemon_log_test.go @@ -0,0 +1,136 @@ +package main + +import ( + "context" + "errors" + "io" + "log/slog" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestDaemonLogFormatsLevelsAndPrefixes(t *testing.T) { + testCases := []struct { + name string + level slog.Level + prefix string + priority string + }{ + { + name: "error names the failed part", + level: slog.LevelError, + prefix: "onechat: ", + priority: "3", + }, + { + name: "warning names the retried part", + level: slog.LevelWarn, + prefix: "telegram: ", + priority: "4", + }, + { + name: "info names the connected part", + level: slog.LevelInfo, + prefix: "whatsapp: ", + priority: "6", + }, + { + name: "debug has its own priority", + level: slog.LevelDebug, + prefix: "onechat: ", + priority: "7", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + for _, journal := range []bool{false, true} { + var out strings.Builder + + handler := &DaemonLogHandler{ + out: &out, + prefix: tc.prefix, + journal: journal, + mutex: &sync.Mutex{}, + } + + record := slog.NewRecord(time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC), tc.level, "ready", 0) + require.True(t, handler.Enabled(t.Context(), tc.level)) + require.NoError(t, handler.Handle(t.Context(), record)) + + expected := "2026/01/02 03:04:05 " + tc.level.String() + " " + tc.prefix + "ready\n" + if journal { + expected = "<" + tc.priority + ">" + tc.prefix + "ready\n" + } + + require.Equal(t, expected, out.String()) + } + }) + } +} + +func TestDaemonLogKeepsAttributesInOrderAndCauseLast(t *testing.T) { + var out strings.Builder + + handler := &DaemonLogHandler{ + out: &out, + prefix: "telegram: ", + journal: true, + mutex: &sync.Mutex{}, + } + + logger := slog.New(handler).With("first", "two words", slog.Attr{}) + logger.Warn("receive failed", "err", errors.New("502 Bad Gateway"), "retry", 2040*time.Millisecond, "count", 3, "short", 1500*time.Microsecond) + require.Equal(t, "<4>telegram: receive failed first=two words retry=2s count=3 short=2ms: 502 Bad Gateway\n", out.String()) +} + +func TestDaemonLogOmitsEmptyAttributesAndNilCause(t *testing.T) { + var out strings.Builder + + handler := &DaemonLogHandler{ + out: &out, + prefix: "onechat: ", + journal: true, + mutex: &sync.Mutex{}, + } + + slog.New(handler).Info("ready", slog.Attr{}, slog.Group("empty"), "err", nil) + require.Equal(t, "<6>onechat: ready\n", out.String()) +} + +func TestDaemonLogGroupsDoNotChangeOtherLoggers(t *testing.T) { + var out strings.Builder + + handler := &DaemonLogHandler{ + out: &out, + journal: true, + mutex: &sync.Mutex{}, + } + + logger := slog.New(handler) + grouped := logger.With("before", 1).WithGroup("outer").With("saved", 2).WithGroup("inner") + grouped.Info("done", slog.Group("", "count", 3)) + logger.Info("ready") + require.Equal(t, "<6>done before=1 outer.saved=2 outer.inner.count=3\n<6>ready\n", out.String()) +} + +func TestDaemonLogReturnsWriteFailure(t *testing.T) { + handler := &DaemonLogHandler{ + out: DaemonLogBrokenWriter{}, + mutex: &sync.Mutex{}, + } + + err := handler.Handle(context.Background(), slog.NewRecord(time.Now(), slog.LevelInfo, "ready", 0)) + require.ErrorIs(t, err, io.ErrClosedPipe) + require.ErrorContains(t, err, "write daemon log") +} + +type DaemonLogBrokenWriter struct{} + +func (w DaemonLogBrokenWriter) Write(_ []byte) (int, error) { + return 0, io.ErrClosedPipe +}