Compare commits

...

2 Commits

Author SHA1 Message Date
Chris F Ravenscroft 8838ae9fbc Merge branch 'master' into fix/logger-json-escaping 2026-09-13 17:04:40 -07:00
Chris F Ravenscroft 36416e6b02 fix: route library log output through the logger
customWriter is the sink for log output from libraries that emit
unstructured text. With structured logging enabled it bypassed the
logger and hand-rolled JSON straight to os.Stderr, which had two
consequences.

It escaped only double quotes, so backslashes and control characters
were emitted raw. A Windows path produced "path C:\Users\x", where \U
is not a valid JSON escape, and a message containing a newline split
one record across two lines. Anything parsing these logs saw malformed
records.

It also wrote to stderr regardless of where the logger pointed, so
library messages could not follow the logger to another sink.

zerolog already emits the same fields with correct escaping, so the
branch is removed and everything goes through e.logr. Output is
byte-identical for plain text and quoted strings.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014L5EoqGWsuZWr8fCVM6izP
2026-09-13 16:55:02 -07:00
3 changed files with 65 additions and 17 deletions
+3 -8
View File
@@ -56,14 +56,13 @@ func InitLogging(reqdebug bool, reqsyslog bool, reqstructlog bool) zerolog.Logge
logr = zerolog.New(mainWriter).Level(level).With().Timestamp().Logger()
}
log.SetOutput(customWriter{logr: logr, structlog: reqstructlog})
log.SetOutput(customWriter{logr: logr})
return logr
}
type customWriter struct {
logr zerolog.Logger
structlog bool
logr zerolog.Logger
}
func (e customWriter) Write(p []byte) (int, error) {
@@ -75,10 +74,6 @@ func (e customWriter) Write(p []byte) (int, error) {
if msg == "" {
msg = strings.TrimSpace(string(p))
}
if e.structlog {
fmt.Fprintf(os.Stderr, "{\"level\":\"info\",\"time\":\"%s\",\"message\":\"%s\"}\n", time.Now().Format(time.RFC1123Z), strings.Replace(strings.TrimSpace(msg), `"`, `\"`, -1))
} else {
e.logr.Info().Msg(msg)
}
e.logr.Info().Msg(msg)
return len(p), nil
}
+59
View File
@@ -0,0 +1,59 @@
package logging
import (
"bytes"
"encoding/json"
"strings"
"testing"
"github.com/rs/zerolog"
)
// customWriter adapts log output from libraries that emit unstructured text.
// Everything it receives must go through the logger, so that it lands wherever
// the logger points - notably syslog only, when syslog is enabled.
func TestCustomWriterEmitsValidJSONThroughTheLogger(t *testing.T) {
for _, tc := range []struct {
name string
in string
want string
}{
{"plain", "something happened", "something happened"},
{"quotes", `bind for "cn=foo"`, `bind for "cn=foo"`},
{"backslashes", `path C:\Users\x`, `path C:\Users\x`},
{"control characters", "tab\there\nand a newline", "tab\there\nand a newline"},
{
"library timestamp prefix is stripped",
"2026/09/13 16:50:54 connection closed",
"connection closed",
},
} {
t.Run(tc.name, func(t *testing.T) {
var buf bytes.Buffer
w := customWriter{logr: zerolog.New(&buf).With().Timestamp().Logger()}
if _, err := w.Write([]byte(tc.in)); err != nil {
t.Fatalf("Write: %v", err)
}
// One record, one line: an unescaped newline would split this.
if got := strings.Count(strings.TrimRight(buf.String(), "\n"), "\n"); got != 0 {
t.Fatalf("expected a single log line, got %d extra newlines in %q", got, buf.String())
}
var record struct {
Level string `json:"level"`
Message string `json:"message"`
}
if err := json.Unmarshal(buf.Bytes(), &record); err != nil {
t.Fatalf("emitted invalid JSON (%v): %s", err, buf.String())
}
if record.Message != tc.want {
t.Errorf("message = %q, want %q", record.Message, tc.want)
}
if record.Level != "info" {
t.Errorf("level = %q, want %q", record.Level, "info")
}
})
}
}
+3 -9
View File
@@ -4,7 +4,6 @@
package logging
import (
"fmt"
"io"
"log"
"os"
@@ -42,14 +41,13 @@ func InitLogging(reqdebug bool, reqsyslog bool, reqstructlog bool) zerolog.Logge
logr := zerolog.New(mainWriter).Level(level).With().Timestamp().Logger()
log.SetOutput(customWriter{logr: logr, structlog: reqstructlog})
log.SetOutput(customWriter{logr: logr})
return logr
}
type customWriter struct {
logr zerolog.Logger
structlog bool
logr zerolog.Logger
}
func (e customWriter) Write(p []byte) (int, error) {
@@ -61,10 +59,6 @@ func (e customWriter) Write(p []byte) (int, error) {
if msg == "" {
msg = strings.TrimSpace(string(p))
}
if e.structlog {
fmt.Fprintf(os.Stderr, "{\"level\":\"info\",\"time\":\"%s\",\"message\":\"%s\"}\n", time.Now().Format(time.RFC1123Z), strings.Replace(strings.TrimSpace(msg), `"`, `\"`, -1))
} else {
e.logr.Info().Msg(msg)
}
e.logr.Info().Msg(msg)
return len(p), nil
}