Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging: performance update + stub and interface for testing #27

Merged
merged 4 commits into from
Jul 9, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 0 additions & 48 deletions clog/attrs.go

This file was deleted.

55 changes: 20 additions & 35 deletions clog/clog.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,67 +8,52 @@ import (
"sync"
)

func NewCustomLogger(dest io.Writer, level slog.Level, addSource bool) *CustomLogger {
func NewCustomLogger(dest io.Writer, level Level, addSource bool) *CustomLogger {
return &CustomLogger{
Logger: slog.New(slog.NewJSONHandler(
dest,
&slog.HandlerOptions{
AddSource: addSource,
Level: level,
})),
ctxKeys: []fieldKey{},
Logger: slog.New(
slog.NewJSONHandler(
dest,
&slog.HandlerOptions{
AddSource: addSource,
Level: slog.Level(level),
})),
mu: &sync.RWMutex{},
}
}

type CustomLogger struct {
*slog.Logger

mu sync.RWMutex
ctxKeys []fieldKey
mu *sync.RWMutex
}

// ErrorCtx logs an error message with fmt.SprintF()
func (l *CustomLogger) ErrorCtx(ctx context.Context, err error, msg string, args ...any) {
l.With(ConvertToAttrs(l.fromCtx(ctx))...).With(slog.String("error", err.Error())).ErrorContext(ctx, fmt.Sprintf(msg, args...))
l.With(convertToAttrs(l.fieldsFromCtx(ctx))...).With(slog.String("error", err.Error())).ErrorContext(ctx, fmt.Sprintf(msg, args...))
}

// InfoCtx logs an informational message with fmt.SprintF()
func (l *CustomLogger) InfoCtx(ctx context.Context, msg string, args ...any) {
l.With(ConvertToAttrs(l.fromCtx(ctx))...).InfoContext(ctx, fmt.Sprintf(msg, args...))
l.With(convertToAttrs(l.fieldsFromCtx(ctx))...).InfoContext(ctx, fmt.Sprintf(msg, args...))
}

// DebugCtx logs a debug message with fmt.SprintF()
func (l *CustomLogger) DebugCtx(ctx context.Context, msg string, args ...any) {
l.With(ConvertToAttrs(l.fromCtx(ctx))...).DebugContext(ctx, fmt.Sprintf(msg, args...))
l.With(convertToAttrs(l.fieldsFromCtx(ctx))...).DebugContext(ctx, fmt.Sprintf(msg, args...))
}

// WarnCtx logs a debug message with fmt.SprintF()
func (l *CustomLogger) WarnCtx(ctx context.Context, msg string, args ...any) {
l.With(ConvertToAttrs(l.fromCtx(ctx))...).WarnContext(ctx, fmt.Sprintf(msg, args...))
l.With(convertToAttrs(l.fieldsFromCtx(ctx))...).WarnContext(ctx, fmt.Sprintf(msg, args...))
}

func (l *CustomLogger) AddKeysValuesToCtx(ctx context.Context, kv map[string]interface{}) context.Context {
l.mu.Lock()
defer l.mu.Unlock()
// convertToAttrs converts a map of custom fields to a slice of slog.Attr
func convertToAttrs(fields map[string]interface{}) []any {
var attrs []any

for k, v := range kv {
ctx = context.WithValue(ctx, fieldKey(k), v)
l.ctxKeys = append(l.ctxKeys, fieldKey(k))
for k, v := range fields {
attrs = append(attrs, slog.Any(k, v))
}

return ctx
}

func (l *CustomLogger) fromCtx(ctx context.Context) Fields {
l.mu.Lock()
defer l.mu.Unlock()

f := make(Fields)
for _, ctxKey := range l.ctxKeys {
if ctx.Value(ctxKey) != nil {
f[ctxKey] = ctx.Value(ctxKey)
}
}

return f
return attrs
}
4 changes: 2 additions & 2 deletions clog/clog_benchmark_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (

func BenchmarkCustomLogger(b *testing.B) {
var buf bytes.Buffer

logger := clog.NewCustomLogger(&buf, clog.LevelDebug, true)

ctx := logger.AddKeysValuesToCtx(context.Background(), map[string]interface{}{
Expand All @@ -22,7 +23,6 @@ func BenchmarkCustomLogger(b *testing.B) {

b.ResetTimer()
for i := 0; i < b.N; i++ {
buf.Reset()
logger.InfoCtx(ctx, "User %d logged in", 12345)
logger.InfoCtx(ctx, "Some test message")
}
}
191 changes: 16 additions & 175 deletions clog/clog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@ import (
"encoding/json"
"errors"
"fmt"
"log/slog"
"sync"
"testing"
"time"
Expand All @@ -21,7 +20,7 @@ const msgKey = "msg"
func TestCustomLogger(t *testing.T) {
var buf bytes.Buffer

logger := clog.NewCustomLogger(&buf, slog.LevelDebug, true)
logger := clog.NewCustomLogger(&buf, clog.LevelDebug, true)

ctx := context.Background()
ctx = logger.AddKeysValuesToCtx(ctx, map[string]interface{}{"user": "testUser"})
Expand Down Expand Up @@ -85,7 +84,7 @@ func TestCustomLogger(t *testing.T) {
func TestCustomLogger_Level(t *testing.T) {
var buf bytes.Buffer

logger := clog.NewCustomLogger(&buf, slog.LevelInfo, true)
logger := clog.NewCustomLogger(&buf, clog.LevelInfo, true)

ctx := context.Background()
ctx = logger.AddKeysValuesToCtx(ctx, map[string]interface{}{"user": "testUser"})
Expand Down Expand Up @@ -116,189 +115,31 @@ func TestCustomLogger_Level(t *testing.T) {
}
}

func TestConvertToAttrsConcurrentAccess(t *testing.T) {
testFields := clog.Fields{
"user": "testUser",
"session": "xyz123",
"role": "admin",
}
func TestAddKeysValuesToCtxConcurrentAccess(t *testing.T) {
var buffer bytes.Buffer
ctx := context.Background()

logger := clog.NewCustomLogger(&buffer, clog.LevelInfo, true)

var wg sync.WaitGroup

repeat := 100
wg.Add(repeat)

for i := 0; i < repeat; i++ {
go func() {
go func(ctx context.Context) {
defer wg.Done()
_ = clog.ConvertToAttrs(testFields)
}()
}

wg.Wait()
}
ctx = logger.AddKeysValuesToCtx(ctx, map[string]interface{}{
"timestamp": time.Now(),
})

func TestIsZeroValue(t *testing.T) {
tcs := []struct {
name string
value any
expected bool
}{
{
"non-empty string",
"abc",
false,
},
{
"empty string",
"",
true,
},
{
"empty slice",
[]int{},
true,
},
{
"non-empty slice",
[]int{1, 2, 3},
false,
},
{
"nil slice",
([]int)(nil),
true,
},
{
"empty map",
map[string]int{},
true,
},
{
"non-empty map",
map[string]int{"key": 1},
false,
},
{
"nil map",
(map[string]int)(nil),
true,
},
{
"zero int",
0,
true,
},
{
"non-zero int",
42,
false,
},
{
"zero float",
0.0,
true,
},
{
"non-zero float",
3.14,
false,
},
{
"empty struct",
struct{}{},
true,
},
{
"non-zero struct",
struct{ A int }{A: 1},
false,
},
{
"zero struct with fields",
struct{ A int }{A: 0},
true,
},
{
"nil pointer",
(*int)(nil),
true,
},
{
"non-nil pointer",
func() *int { v := 42; return &v }(),
false,
},
{
"nil interface",
(interface{})(nil),
true,
},
{
"non-nil interface",
interface{}(42),
false,
},
{
"nil channel",
(chan int)(nil),
true,
},
{
"non-nil channel",
make(chan int),
true,
},
{
"nil function",
(func())(nil),
true,
},
{
"non-nil function",
func() {},
false,
},
{
"zero struct with multiple fields",
struct {
A int
B string
}{A: 0, B: ""},
true,
},
{
"non-zero struct with multiple fields",
struct {
A int
B string
}{A: 1, B: "non-zero"},
false,
},
{
"nested zero struct",
struct {
A int
B struct{ C int }
}{A: 0, B: struct{ C int }{C: 0}},
true,
},
{
"nested non-zero struct",
struct {
A int
B struct{ C int }
}{A: 0, B: struct{ C int }{C: 1}},
false,
},
}
logger.InfoCtx(ctx, "sample log message")

for _, tc := range tcs {
t.Run(tc.name, func(t *testing.T) {
out := clog.IsZeroOfUnderlyingType(tc.value)
require.Equal(t, tc.expected, out)
})
}(ctx)
}

wg.Wait()
}

type testStruct struct {
Expand All @@ -308,7 +149,7 @@ type testStruct struct {

func TestCustomLoggerWithContext(t *testing.T) {
var buf bytes.Buffer
logger := clog.NewCustomLogger(&buf, slog.LevelInfo, true)
logger := clog.NewCustomLogger(&buf, clog.LevelInfo, true)

testCh := make(chan int, 1)
testCh <- 0
Expand Down
Loading
Loading