Skip to content

Commit

Permalink
Pull request: ADG-9189-logfmt-jsonl
Browse files Browse the repository at this point in the history 
Squashed commit of the following:

commit fe3135c
Author: Dimitry Kolyshev <[email protected]>
Date:   Thu Oct 24 10:49:17 2024 +0300

    slogutil: imp code

commit 89f12e4
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Oct 23 14:56:01 2024 +0300

    slogutil: imp code

commit 75f05de
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Oct 23 11:58:22 2024 +0300

    slogutil: imp code

commit e30fd00
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Oct 22 15:34:51 2024 +0300

    slogutil: imp code

commit c6caad7
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Oct 22 12:34:54 2024 +0300

    slogutil: imp code

commit 9d54b20
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Oct 22 12:16:00 2024 +0300

    slogutil: jsonhybrid

commit abce6ff
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Oct 22 11:49:58 2024 +0300

    slogutil: jsonhybrid

commit 1eb6fbc
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Oct 22 10:41:56 2024 +0300

    slogutil: jsonhybrid

commit d9aaf55
Merge: 463cf48 e5711ca
Author: Dimitry Kolyshev <[email protected]>
Date:   Mon Oct 21 09:46:16 2024 +0300

    Merge remote-tracking branch 'origin/master'

commit 463cf48
Author: Eugene Burkov <[email protected]>
Date:   Fri Oct 18 18:50:39 2024 +0300

    slogutil: fix keys

commit da3d5e0
Author: Dimitry Kolyshev <[email protected]>
Date:   Fri Oct 18 12:38:31 2024 +0300

    slogutil: imp code

commit b50b124
Author: Dimitry Kolyshev <[email protected]>
Date:   Fri Oct 18 10:55:27 2024 +0300

    slogutil: jsonl logformat
  • Loading branch information
@Mizzick
Mizzick committed Oct 24, 2024
1 parent e5711ca commit e119bb9
Show file tree
Hide file tree
Showing 5 changed files with 125 additions and 92 deletions.
119 changes: 72 additions & 47 deletions logutil/slogutil/jsonhybrid.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,53 +2,62 @@ package slogutil

import (
"context"
"encoding"
"encoding/json"
"fmt"
"io"
"log/slog"
"slices"
"time"
"sync"

"github.com/AdguardTeam/golibs/errors"
"github.com/AdguardTeam/golibs/syncutil"
)

// 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,
}
}
Expand All @@ -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.
Expand All @@ -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...),
}
}
Expand Down
17 changes: 11 additions & 6 deletions logutil/slogutil/jsonhybrid_example_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"}
}
13 changes: 6 additions & 7 deletions logutil/slogutil/jsonhybrid_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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
}
31 changes: 30 additions & 1 deletion logutil/slogutil/legacy.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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)

Expand Down
37 changes: 6 additions & 31 deletions logutil/slogutil/slogutil.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand All @@ -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
}
}

Expand Down Expand Up @@ -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),
}
}

Expand Down

0 comments on commit e119bb9

Please sign in to comment.