fblog-like handler (#7)

* feat: added fblog handler, benchmarks and tests

Author: Semior001

.golangci.yml

@@ -54,21 +54,22 @@ run:
 issues:
   exclude-rules:
     - text: "should have a package comment, unless it's in another file for this package"
-      linters:
-        - golint
+      linters: [gosec]
     - text: "G505: Blocklisted import crypto/sha1: weak cryptographic primitive"
-      linters:
-        - gosec
+      linters: [gosec]
     - text: "Use of weak cryptographic primitive"
-      linters:
-        - gosec
+      linters: [gosec]
     - path: _test\.go
       text: "Potential Slowloris Attack because ReadHeaderTimeout is not configured in the http.Server"
-      linters:
-        - gosec
+      linters: [gosec]
     - path: _test\.go
       text: "Deferring unsafe method \"Close\" on type \"io.ReadCloser\""
-      linters:
-        - gosec
+      linters: [gosec]
+    - path: fblog
+      text: "Errors unhandled"
+      linters: [gosec]
+    - path: fblog
+      text: "Use of unsafe calls should be audited"
+      linters: [gosec]
 
   exclude-use-default: false

README.md

@@ -6,6 +6,34 @@ Package slogx contains extensions for standard library's slog package.
 go get github.com/cappuccinotm/slogx
 ```
 
+## Handlers
+- `slog.Chain` - chains the multiple "middlewares" - handlers, which can modify the log entry.
+- `fblog.Handler` - a handler that logs the log entry in the [fblog-like](https://github.com/brocode/fblog) format, like:
+  ```
+  2024-02-05 09:11:37  [INFO]: info message
+                          key: 1
+       some_multi_line_string: "line1\nline2\nline3"
+                multiline_any: "line1\nline2\nline3"
+                    group.int: 1
+                 group.string: "string"
+                group.float64: 1.1
+                   group.bool: false
+   ...some_very_very_long_key: 1
+  ```
+
+  Some benchmarks (though this handler wasn't designed for performance, but for comfortable reading of the logs in debug/local mode):
+  ```
+  BenchmarkHandler
+  BenchmarkHandler/fblog.NewHandler
+  BenchmarkHandler/fblog.NewHandler-8         	 1479525	       800.9 ns/op	     624 B/op	       8 allocs/op
+  BenchmarkHandler/slog.NewJSONHandler
+  BenchmarkHandler/slog.NewJSONHandler-8      	 2407322	       500.0 ns/op	      48 B/op	       1 allocs/op
+  BenchmarkHandler/slog.NewTextHandler
+  BenchmarkHandler/slog.NewTextHandler-8      	 2404581	       490.0 ns/op	      48 B/op	       1 allocs/op
+  ```
+  
+  All the benchmarks were run on a MacBook Pro (14-inch, 2021) with Apple M1 processor, the benchmark contains the only log `lg.Info("message", slog.Int("int", 1))`
+
 ## Middlewares
 - `slogm.RequestID()` - adds a request ID to the context and logs it.
   - `slogm.ContextWithRequestID(ctx context.Context, requestID string) context.Context` - adds a request ID to the context.

fblog/entry.go

@@ -0,0 +1,155 @@
+package fblog
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"log/slog"
+	"strings"
+
+	"github.com/cappuccinotm/slogx/fblog/internal/misc"
+)
+
+type entry struct {
+	timeFmt string
+	rep     func([]string, slog.Attr) slog.Attr
+
+	// internal use
+	headerLen int
+	buf       *bytes.Buffer
+	q         *misc.Queue[grouped]
+}
+
+const lvlSize = 7 // length of the level with braces, e.g. "[DEBUG]"
+
+func newEntry(timeFmt string, rep func([]string, slog.Attr) slog.Attr, numAttrs int) *entry {
+	return &entry{
+		buf:     bytes.NewBuffer(nil),
+		q:       misc.NewQueue[grouped](numAttrs),
+		timeFmt: timeFmt,
+		rep:     rep,
+	}
+}
+
+func (e *entry) WriteHeader(logTimeFmt string, maxKeySize int, rec slog.Record) {
+	if logTimeFmt != "" {
+		tmFmts := rec.Time.Format(logTimeFmt)
+		maxKeySize -= lvlSize
+		switch {
+		case maxKeySize == UnlimitedKeySize-lvlSize:
+			e.buf.WriteString(tmFmts) // TODO handle the case with expanding space prefixes for a long
+		case maxKeySize == HeaderKeySize-lvlSize:
+			e.buf.WriteString(tmFmts)
+		case len(tmFmts) > maxKeySize:
+			// trim the timestamp from the left, add "..." at the beginning
+			e.buf.WriteString("...")
+			e.buf.WriteString(tmFmts[len(tmFmts)-maxKeySize+3:])
+		case maxKeySize > len(tmFmts):
+			e.spaces(maxKeySize-len(tmFmts), false)
+			e.buf.WriteString(tmFmts)
+		default:
+			e.buf.WriteString(tmFmts)
+		}
+		e.buf.WriteString(" ")
+	}
+
+	switch rec.Level {
+	case slog.LevelDebug:
+		e.buf.WriteString("[DEBUG]")
+	case slog.LevelInfo:
+		e.buf.WriteString(" [INFO]")
+	case slog.LevelWarn:
+		e.buf.WriteString(" [WARN]")
+	case slog.LevelError:
+		e.buf.WriteString("[ERROR]")
+	default:
+		e.buf.WriteString("[UNKNW]")
+	}
+
+	e.headerLen = e.buf.Len()
+	e.buf.WriteString(": ")
+	e.buf.WriteString(rec.Message)
+	e.buf.WriteString("\n")
+}
+
+type grouped struct {
+	group []string
+	attr  slog.Attr
+}
+
+func (e *entry) WriteAttr(group []string, a slog.Attr) {
+	e.q.PushBack(grouped{group: group, attr: a})
+
+	for e.q.Len() > 0 {
+		g := e.q.PopFront()
+
+		groups, attr := g.group, g.attr
+		attr = e.rep(groups, attr)
+		attr.Value = attr.Value.Resolve() // resolve the value before writing
+
+		if attr.Value.Kind() == slog.KindGroup {
+			for _, a := range attr.Value.Group() {
+				e.q.PushBack(grouped{group: append(groups, attr.Key), attr: a})
+			}
+			continue
+		}
+
+		e.WriteKey(groups, attr)
+		e.buf.WriteString(": ")
+		e.WriteTextValue(attr)
+		e.buf.WriteString("\n")
+	}
+}
+
+func (e *entry) WriteTextValue(attr slog.Attr) {
+	switch attr.Value.Kind() {
+	case slog.KindString:
+		_, _ = fmt.Fprintf(e.buf, "%q", attr.Value.String()) // escape the string
+	case slog.KindTime:
+		e.buf.WriteString(attr.Value.Time().Format(e.timeFmt))
+	case slog.KindDuration:
+		e.buf.WriteString(attr.Value.Duration().String())
+	case slog.KindGroup:
+		panic("impossible case, group should be resolved to this point, please, file an issue")
+	default:
+		_, _ = fmt.Fprintf(e.buf, "%+v", attr.Value.Any())
+	}
+}
+
+func (e *entry) WriteKey(groups []string, attr slog.Attr) {
+	key := &strings.Builder{}
+	for _, g := range groups {
+		key.WriteString(g)
+		key.WriteString(".")
+	}
+	key.WriteString(attr.Key)
+	s := key.String()
+
+	e.buf.Grow(e.headerLen) // preallocate the space for the key
+	if e.headerLen-key.Len() < 0 {
+		// trim the key from the left, add "..." at the beginning
+		e.buf.WriteString("...")
+		s = s[key.Len()-e.headerLen+3:]
+	}
+
+	if e.headerLen-key.Len() > 0 {
+		e.spaces(e.headerLen-key.Len(), true)
+	}
+
+	e.buf.WriteString(s)
+}
+
+func (e *entry) WriteTo(wr io.Writer) (int64, error) {
+	// TODO: append offset in case of UnlimitedKeySize
+	n, err := wr.Write(e.buf.Bytes())
+	return int64(n), err
+}
+
+func (e *entry) spaces(n int, alreadyGrown bool) {
+	if !alreadyGrown {
+		e.buf.Grow(n)
+	}
+	for i := 0; i < n; i++ {
+		e.buf.WriteByte(' ')
+	}
+}

fblog/internal/misc/queue.go

@@ -0,0 +1,70 @@
+// Package misc provides miscellaneous data types and functions
+// for better processing of log entries.
+package misc
+
+const minCap = 4
+
+// Queue is an implementation of the list data structure,
+// it is a FIFO (first in, first out) data structure over a slice.
+type Queue[T any] struct {
+	l   []T
+	idx int
+	end int
+}
+
+// NewQueue returns a new Queue.
+func NewQueue[T any](capacity int) *Queue[T] {
+	// assume always that the amount of attrs is not less than minCap
+	if capacity < minCap {
+		capacity = minCap
+	}
+
+	return &Queue[T]{l: make([]T, 0, capacity)}
+}
+
+// Len returns the length of the queue.
+func (q *Queue[T]) Len() int { return q.end - q.idx }
+
+// PushBack adds an element to the end of the queue.
+func (q *Queue[T]) PushBack(e T) {
+	if q.end < len(q.l) {
+		q.l[q.end] = e
+	} else {
+		q.l = append(q.l, e)
+	}
+	q.end++
+}
+
+// PopFront removes the first element from the queue and returns it.
+func (q *Queue[T]) PopFront() T {
+	if q.idx >= q.end {
+		panic("pop from empty queue")
+	}
+	e := q.l[q.idx]
+	q.idx++
+
+	// if the index is too far from the beginning of the slice
+	// (half of the slice or more), then we need to copy the
+	// remaining elements to the beginning of the slice and reset
+	// the index, to avoid memory leaks.
+	if q.idx >= cap(q.l)/2 {
+		q.shift()
+	}
+
+	return e
+}
+
+// shift moves the remaining elements to the beginning of the slice
+// and resets the index.
+func (q *Queue[T]) shift() {
+	if q.end-q.idx == 0 {
+		q.idx, q.end = 0, 0
+		return
+	}
+
+	for i := 0; i < q.end-q.idx; i++ {
+		q.l[i] = q.l[q.idx+i]
+	}
+	q.end -= q.idx
+	q.idx = 0
+}

fblog/internal/misc/queue_test.go

@@ -0,0 +1,66 @@
+package misc
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestQueue(t *testing.T) {
+	t.Run("simple rotation", func(t *testing.T) {
+		q := NewQueue[int](9)
+		q.idx = 3
+		q.end = 8
+		q.l = []int{1, 2, 3, 4, 5, 6, 7, 8, 9}
+		assert.Equal(t, 4, q.PopFront())
+		assert.Equal(t, 0, q.idx)
+		assert.Equal(t, []int{5, 6, 7, 8, 5, 6, 7, 8, 9}, q.l)
+		assert.Equal(t, 4, q.end)
+	})
+
+	t.Run("from the end to start", func(t *testing.T) {
+		q := NewQueue[int](6)
+		q.l = []int{0, 1, 2, 3, 4, 5}
+		q.idx = 4
+		q.end = 6
+		g := q.PopFront()
+		assert.Equal(t, 4, g)
+		assert.Equal(t, []int{5, 1, 2, 3, 4, 5}, q.l)
+		assert.Equal(t, 1, q.end)
+		assert.Equal(t, 0, q.idx)
+	})
+
+	t.Run("push-pop", func(t *testing.T) {
+		q := NewQueue[int](6)
+		q.PushBack(1)
+		q.PushBack(2)
+		q.PushBack(3)
+		assert.Equal(t, 3, q.Len())
+		assert.Equal(t, 1, q.PopFront())
+		assert.Equal(t, 2, q.PopFront())
+		assert.Equal(t, 3, q.PopFront())
+	})
+
+	t.Run("push to rotated", func(t *testing.T) {
+		q := NewQueue[int](2)
+		q.PushBack(1)
+		q.PushBack(2)
+		assert.Equal(t, 2, q.Len())
+		assert.Equal(t, 1, q.PopFront())
+		q.PushBack(3)
+		assert.Equal(t, 2, q.PopFront())
+		assert.Equal(t, 3, q.PopFront())
+		q.PushBack(4)
+		assert.Equal(t, 4, q.PopFront())
+	})
+
+	t.Run("pop from empty queue", func(t *testing.T) {
+		q := NewQueue[int](6)
+		assert.Panics(t, func() { q.PopFront() })
+	})
+
+	t.Run("min cap always preset", func(t *testing.T) {
+		q := NewQueue[int](-10)
+		assert.Equal(t, minCap, cap(q.l))
+	})
+}