diff --git a/logutil/slogutil/jsonhybrid.go b/logutil/slogutil/jsonhybrid.go index 3454fa3..dd05bbe 100644 --- a/logutil/slogutil/jsonhybrid.go +++ b/logutil/slogutil/jsonhybrid.go @@ -2,11 +2,13 @@ package slogutil import ( "context" + "encoding" + "encoding/json" "fmt" "io" "log/slog" "slices" - "time" + "sync" "github.com/AdguardTeam/golibs/errors" "github.com/AdguardTeam/golibs/syncutil" @@ -14,41 +16,48 @@ import ( // JSONHybridHandler is a hybrid JSON-and-text [slog.Handler] more suitable for // stricter environments. It guarantees that the only properties present in the -// resulting objects are "level", "msg", "time", and "source", depending on the -// options. All other attributes are packed into the "msg" property using the -// same format as [slogutil.TextHandler]. +// resulting objects are "severity" and "message". All other attributes are +// packed into the "message" property using the same format as +// [slog.TextHandler]. // // NOTE: [JSONHybridHandler.WithGroup] is not currently supported and panics. // // Example of output: // -// {"time":"2023-12-01T12:34:56.789Z","level":"INFO","msg":"listening; attrs: prefix=websvc url=http://127.0.0.1:8080"} +// {"severity":"NORMAL","message":"time=2024-10-22T12:09:59.525+03:00 level=INFO msg=listening prefix=websvc server=http://127.0.0.1:8181"} type JSONHybridHandler struct { - json *slog.JSONHandler - attrPool *syncutil.Pool[[]slog.Attr] + level slog.Leveler + encoder *json.Encoder bufTextPool *syncutil.Pool[bufferedTextHandler] - textAttrs []slog.Attr -} -const ( - // initAttrsLenEst is the estimation used to set the initial length of - // attribute slices. - initAttrsLenEst = 2 + // mu protects encoder. + mu *sync.Mutex - // initLineLenEst is the estimation used to set the initial sizes of - // log-line buffers. - initLineLenEst = 256 -) + textAttrs []slog.Attr +} + +// initLineLenEst is the estimation used to set the initial sizes of log-line +// buffers. +const initLineLenEst = 256 // NewJSONHybridHandler creates a new properly initialized *JSONHybridHandler. -// opts are used for the underlying JSON handler. +// opts are used for the underlying text handler. func NewJSONHybridHandler(w io.Writer, opts *slog.HandlerOptions) (h *JSONHybridHandler) { + enc := json.NewEncoder(w) + enc.SetEscapeHTML(false) + + lvl := slog.LevelInfo + if opts != nil && opts.Level != nil { + lvl = opts.Level.Level() + } + return &JSONHybridHandler{ - json: slog.NewJSONHandler(w, opts), - attrPool: syncutil.NewSlicePool[slog.Attr](initAttrsLenEst), + level: lvl, + encoder: enc, bufTextPool: syncutil.NewPool(func() (bufTextHdlr *bufferedTextHandler) { - return newBufferedTextHandler(initLineLenEst) + return newBufferedTextHandler(initLineLenEst, opts) }), + mu: &sync.Mutex{}, textAttrs: nil, } } @@ -57,8 +66,8 @@ func NewJSONHybridHandler(w io.Writer, opts *slog.HandlerOptions) (h *JSONHybrid var _ slog.Handler = (*JSONHybridHandler)(nil) // Enabled implements the [slog.Handler] interface for *JSONHybridHandler. -func (h *JSONHybridHandler) Enabled(ctx context.Context, level slog.Level) (ok bool) { - return h.json.Enabled(ctx, level) +func (h *JSONHybridHandler) Enabled(_ context.Context, level slog.Level) (ok bool) { + return level >= h.level.Level() } // Handle implements the [slog.Handler] interface for *JSONHybridHandler. @@ -68,46 +77,62 @@ func (h *JSONHybridHandler) Handle(ctx context.Context, r slog.Record) (err erro bufTextHdlr.reset() - _, _ = bufTextHdlr.buffer.WriteString(r.Message) + r.AddAttrs(h.textAttrs...) - numAttrs := r.NumAttrs() + len(h.textAttrs) - if numAttrs > 0 { - _, _ = bufTextHdlr.buffer.WriteString("; attrs: ") + err = bufTextHdlr.handler.Handle(ctx, r) + if err != nil { + return fmt.Errorf("handling text for data: %w", err) } - textAttrsPtr := h.attrPool.Get() - defer h.attrPool.Put(textAttrsPtr) + msg := byteString(bufTextHdlr.buffer.Bytes()) + + // Remove newline. + msg = msg[:len(msg)-1] + data := newJSONHybridMessage(r.Level, msg) + + h.mu.Lock() + defer h.mu.Unlock() - *textAttrsPtr = (*textAttrsPtr)[:0] - r.Attrs(func(a slog.Attr) (cont bool) { - *textAttrsPtr = append(*textAttrsPtr, a) + return h.encoder.Encode(data) +} - return true - }) +// byteString optimizes memory allocations in [JSONHybridHandler.Handle]. +type byteString []byte - textRec := slog.NewRecord(time.Time{}, r.Level, "", 0) - textRec.AddAttrs(h.textAttrs...) - textRec.AddAttrs(*textAttrsPtr...) +// type check +var _ encoding.TextMarshaler = byteString{} - err = bufTextHdlr.handler.Handle(ctx, textRec) - if err != nil { - return fmt.Errorf("handling text for msg: %w", err) - } +// MarshalText implements the [encoding.TextMarshaler] interface for byteString. +func (b byteString) MarshalText() (res []byte, err error) { + return b, nil +} - msgForJSON := bufTextHdlr.buffer.String() +// jsonHybridMessage represents the data structure for *JSONHybridHandler. +type jsonHybridMessage = struct { + Severity string `json:"severity"` + Message byteString `json:"message"` +} - // Remove newline. - msgForJSON = msgForJSON[:len(msgForJSON)-1] +// newJSONHybridMessage returns new properly initialized message. +func newJSONHybridMessage(lvl slog.Level, msg byteString) (m *jsonHybridMessage) { + severity := "NORMAL" + if lvl >= slog.LevelError { + severity = "ERROR" + } - return h.json.Handle(ctx, slog.NewRecord(r.Time, r.Level, msgForJSON, r.PC)) + return &jsonHybridMessage{ + Severity: severity, + Message: msg, + } } // WithAttrs implements the [slog.Handler] interface for *JSONHybridHandler. func (h *JSONHybridHandler) WithAttrs(attrs []slog.Attr) (res slog.Handler) { return &JSONHybridHandler{ - json: h.json, - attrPool: h.attrPool, + level: h.level, + encoder: h.encoder, bufTextPool: h.bufTextPool, + mu: h.mu, textAttrs: append(slices.Clip(h.textAttrs), attrs...), } } diff --git a/logutil/slogutil/jsonhybrid_example_test.go b/logutil/slogutil/jsonhybrid_example_test.go index d7a248a..e512122 100644 --- a/logutil/slogutil/jsonhybrid_example_test.go +++ b/logutil/slogutil/jsonhybrid_example_test.go @@ -26,11 +26,16 @@ func ExampleJSONHybridHandler() { l.Info("new info with no attributes") l.Info("new info with attributes", "number", 123) + l.Error("error with no attributes") + l.Error("error with attributes", "number", 123) + // Output: - // {"level":"DEBUG","msg":"debug with no attributes"} - // {"level":"DEBUG","msg":"debug with attributes; attrs: number=123"} - // {"level":"INFO","msg":"info with no attributes"} - // {"level":"INFO","msg":"info with attributes; attrs: number=123"} - // {"level":"INFO","msg":"new info with no attributes; attrs: attr=abc"} - // {"level":"INFO","msg":"new info with attributes; attrs: attr=abc number=123"} + // {"severity":"NORMAL","message":"level=DEBUG msg=\"debug with no attributes\""} + // {"severity":"NORMAL","message":"level=DEBUG msg=\"debug with attributes\" number=123"} + // {"severity":"NORMAL","message":"level=INFO msg=\"info with no attributes\""} + // {"severity":"NORMAL","message":"level=INFO msg=\"info with attributes\" number=123"} + // {"severity":"NORMAL","message":"level=INFO msg=\"new info with no attributes\" attr=abc"} + // {"severity":"NORMAL","message":"level=INFO msg=\"new info with attributes\" number=123 attr=abc"} + // {"severity":"ERROR","message":"level=ERROR msg=\"error with no attributes\" attr=abc"} + // {"severity":"ERROR","message":"level=ERROR msg=\"error with attributes\" number=123 attr=abc"} } diff --git a/logutil/slogutil/jsonhybrid_test.go b/logutil/slogutil/jsonhybrid_test.go index 7d909e4..c9d1e65 100644 --- a/logutil/slogutil/jsonhybrid_test.go +++ b/logutil/slogutil/jsonhybrid_test.go @@ -67,7 +67,7 @@ func TestJSONHybridHandler_Handle(t *testing.T) { expectedString := strings.Replace(textString, `level=INFO msg="test message" `, "", 1) jsonString := hybridOutputStrings[i] - gotString := strings.Replace(jsonString, `{"level":"INFO","msg":"test message; attrs: `, "", 1) + gotString := strings.Replace(jsonString, `{"severity":"NORMAL","message":"level=INFO msg=\"test message\" `, "", 1) gotString = strings.Replace(gotString, `"}`, "", 1) assert.Equal(t, expectedString, gotString) @@ -92,10 +92,9 @@ func BenchmarkJSONHybridHandler_Handle(b *testing.B) { require.NoError(b, errSink) - // Most recent results, on a ThinkPad X13 with a Ryzen Pro 7 CPU: - // goos: linux - // goarch: amd64 - // pkg: github.com/AdguardTeam/golibs/logutil/slogutil - // cpu: AMD Ryzen 7 PRO 4750U with Radeon Graphics - // BenchmarkJSONHybridHandler_Handle-16 1035621 1246 ns/op 48 B/op 1 allocs/op + // goos: darwin + // goarch: arm64 + // pkg: github.com/AdguardTeam/golibs/logutil/slogutil + // cpu: Apple M1 Pro + // BenchmarkJSONHybridHandler_Handle-8 1992794 602.4 ns/op 48 B/op 1 allocs/op } diff --git a/logutil/slogutil/legacy.go b/logutil/slogutil/legacy.go index 796ea89..e07057e 100644 --- a/logutil/slogutil/legacy.go +++ b/logutil/slogutil/legacy.go @@ -13,6 +13,10 @@ import ( "github.com/AdguardTeam/golibs/syncutil" ) +// initAttrsLenEst is the estimation used to set the initial length of +// attribute slices. +const initAttrsLenEst = 2 + // AdGuardLegacyHandler is a text [slog.Handler] that uses package // github.com/AdguardTeam/golibs/log for output. It is a legacy handler that // will be removed in a future version. @@ -40,12 +44,37 @@ func NewAdGuardLegacyHandler(lvl slog.Leveler) (h *AdGuardLegacyHandler) { level: lvl, attrPool: syncutil.NewSlicePool[slog.Attr](initAttrsLenEst), bufTextPool: syncutil.NewPool(func() (bufTextHdlr *bufferedTextHandler) { - return newBufferedTextHandler(initLineLenEst) + return newBufferedTextHandler(initLineLenEst, legacyTextHandlerOpts) }), attrs: nil, } } +// legacyTextHandlerOpts are the options used by buffered text handlers of +// [FormatAdGuardLegacy] handlers. +var legacyTextHandlerOpts = &slog.HandlerOptions{ + ReplaceAttr: legacyRemoveTopLevel, +} + +// legacyRemoveTopLevel is a [slog.HandlerOptions.ReplaceAttr] function that +// removes "level", "msg", "time", and "source" attributes. +func legacyRemoveTopLevel(groups []string, a slog.Attr) (res slog.Attr) { + if len(groups) > 0 { + return a + } + + switch a.Key { + case + slog.LevelKey, + slog.MessageKey, + slog.TimeKey, + slog.SourceKey: + return slog.Attr{} + default: + return a + } +} + // type check var _ slog.Handler = (*AdGuardLegacyHandler)(nil) diff --git a/logutil/slogutil/slogutil.go b/logutil/slogutil/slogutil.go index ee70087..b03d545 100644 --- a/logutil/slogutil/slogutil.go +++ b/logutil/slogutil/slogutil.go @@ -22,7 +22,7 @@ const ( KeyMessage = slog.MessageKey KeySource = slog.SourceKey KeyTime = slog.TimeKey - keyLevel = slog.LevelKey + KeyLevel = slog.LevelKey ) // Config contains the configuration for a logger. @@ -119,8 +119,8 @@ func newReplaceAttr(removeTime bool) func(groups []string, a slog.Attr) (res slo } } -// traceAttrValue is a [LevelTrace] value under the [slog.LevelKey] key. -var traceAttrValue = slog.StringValue("TRACE") +// valueLevelTrace is a [LevelTrace] value under the [slog.LevelKey] key. +var valueLevelTrace = slog.StringValue("TRACE") // ReplaceLevel is a function for [slog.HandlerOptions.ReplaceAttr] that adds // [LevelTrace] custom name for level attribute. @@ -132,7 +132,7 @@ func ReplaceLevel(groups []string, a slog.Attr) (res slog.Attr) { if a.Key == slog.LevelKey { lvl := a.Value.Any().(slog.Level) if lvl == LevelTrace { - a.Value = traceAttrValue + a.Value = valueLevelTrace } } @@ -191,37 +191,12 @@ type bufferedTextHandler struct { // newBufferedTextHandler returns a new bufferedTextHandler with the given // buffer length. -func newBufferedTextHandler(l int) (h *bufferedTextHandler) { +func newBufferedTextHandler(l int, handlerOpts *slog.HandlerOptions) (h *bufferedTextHandler) { buf := bytes.NewBuffer(make([]byte, 0, l)) return &bufferedTextHandler{ buffer: buf, - handler: slog.NewTextHandler(buf, textHandlerOpts), - } -} - -// textHandlerOpts are the options used by buffered text handlers of JSON hybrid -// handlers. -var textHandlerOpts = &slog.HandlerOptions{ - ReplaceAttr: removeTopLevel, -} - -// removeTopLevel is a [slog.HandlerOptions.ReplaceAttr] function that removes -// "level", "msg", "time", and "source" attributes. -func removeTopLevel(groups []string, a slog.Attr) (res slog.Attr) { - if len(groups) > 0 { - return a - } - - switch a.Key { - case - slog.LevelKey, - slog.MessageKey, - slog.TimeKey, - slog.SourceKey: - return slog.Attr{} - default: - return a + handler: slog.NewTextHandler(buf, handlerOpts), } }