Logger: make sure to pass along base loggers context when using With (#113)

* Logger: make sure to pass along base loggers context when using With

* fixed otel context not propagating issue

* suggested improvements

* improvement in test

Author: jhaynie

logger/console_test.go

@@ -146,6 +146,29 @@ func TestConsoleLoggerWithMetadata(t *testing.T) {
 	assert.Contains(t, output, `"key2":"value2"`)
 }
 
+func TestConsoleLoggerWithMergesMetadata(t *testing.T) {
+	logger := NewConsoleLogger().(*consoleLogger)
+
+	baseLogger := logger.With(map[string]interface{}{
+		"base_key": "base_value",
+		"shared":   "from_base",
+	}).(*consoleLogger)
+
+	extendedLogger := baseLogger.With(map[string]interface{}{
+		"extra_key": "extra_value",
+		"shared":    "from_extended",
+	}).(*consoleLogger)
+
+	output := captureOutput(func() {
+		extendedLogger.Info("Test message")
+	})
+
+	assert.Contains(t, output, "Test message")
+	assert.Contains(t, output, `"base_key":"base_value"`)
+	assert.Contains(t, output, `"extra_key":"extra_value"`)
+	assert.Contains(t, output, `"shared":"from_extended"`)
+}
+
 func TestConsoleLoggerSinkTraceLevel(t *testing.T) {
 	logger := NewConsoleLogger().(*consoleLogger)
 	logger.SetLogLevel(LevelTrace)

logger/json.go

@@ -104,16 +104,16 @@ func (c *jsonLogger) WithPrefix(prefix string) Logger {
 
 func (c *jsonLogger) With(newFields map[string]interface{}) Logger {
 	clone := c.clone()
-	if trace, ok := newFields["trace"].(string); ok {
+	for k, v := range newFields {
+		clone.metadata[k] = v
+	}
+	if trace, ok := clone.metadata["trace"].(string); ok {
 		clone.traceID = trace
-		delete(newFields, "trace")
+		delete(clone.metadata, "trace")
 	}
-	if comp, ok := newFields["component"].(string); ok {
+	if comp, ok := clone.metadata["component"].(string); ok {
 		clone.component = comp
-		delete(newFields, "component")
-	}
-	for k, v := range newFields {
-		clone.metadata[k] = v
+		delete(clone.metadata, "component")
 	}
 	if c.child != nil {
 		clone.child = c.child.With(newFields)

logger/json_test.go

@@ -148,6 +148,32 @@ func TestJSONLoggerWith(t *testing.T) {
 	assert.Equal(t, float64(42), metadata["key2"]) // JSON numbers are float64
 }
 
+func TestJSONLoggerWithMergesMetadata(t *testing.T) {
+	sink := &testSink{}
+	logger := NewJSONLoggerWithSink(sink, LevelTrace)
+
+	baseLogger := logger.With(map[string]interface{}{
+		"base_key": "base_value",
+		"shared":   "from_base",
+	})
+
+	extendedLogger := baseLogger.With(map[string]interface{}{
+		"extra_key": "extra_value",
+		"shared":    "from_extended",
+	})
+
+	extendedLogger.Info("Test message")
+
+	var parsed map[string]interface{}
+	err := json.Unmarshal(sink.buf, &parsed)
+	assert.NoError(t, err)
+
+	metadata := parsed["metadata"].(map[string]interface{})
+	assert.Equal(t, "base_value", metadata["base_key"])
+	assert.Equal(t, "extra_value", metadata["extra_key"])
+	assert.Equal(t, "from_extended", metadata["shared"])
+}
+
 func TestJSONLoggerLog(t *testing.T) {
 	sink := &testSink{}
 

logger/otel.go

@@ -50,6 +50,7 @@ func (o *otelLogger) clone() *otelLogger {
 		logLevel:   o.logLevel,
 		otelLogger: o.otelLogger,
 		child:      o.child,
+		context:    o.context,
 	}
 }
 
@@ -59,8 +60,14 @@ func toLogValue(unknown interface{}) otelLog.Value {
 		return otelLog.StringValue(v)
 	case int:
 		return otelLog.IntValue(v)
+	case int32:
+		return otelLog.IntValue(int(v))
+	case int64:
+		return otelLog.Int64Value(v)
 	case bool:
 		return otelLog.BoolValue(v)
+	case float32:
+		return otelLog.Float64Value(float64(v))
 	case float64:
 		return otelLog.Float64Value(v)
 	case []byte:

logger/otel_test.go

@@ -0,0 +1,237 @@
+package logger
+
+import (
+	"context"
+	"sync"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.opentelemetry.io/otel/log"
+	"go.opentelemetry.io/otel/log/embedded"
+	"go.opentelemetry.io/otel/log/noop"
+	sdktrace "go.opentelemetry.io/otel/sdk/trace"
+	"go.opentelemetry.io/otel/trace"
+)
+
+func TestOtelLoggerWithMergesMetadata(t *testing.T) {
+	noopLogger := noop.NewLoggerProvider().Logger("test")
+
+	logger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: noopLogger,
+		context:    context.Background(),
+	}
+
+	baseLogger := logger.With(map[string]interface{}{
+		"base_key": "base_value",
+		"shared":   "from_base",
+	}).(*otelLogger)
+
+	extendedLogger := baseLogger.With(map[string]interface{}{
+		"extra_key": "extra_value",
+		"shared":    "from_extended",
+	}).(*otelLogger)
+
+	// Verify baseLogger.metadata stayed unchanged (immutability)
+	assert.Equal(t, 2, len(baseLogger.metadata))
+	assert.Equal(t, "base_value", baseLogger.metadata["base_key"].AsString())
+	assert.Equal(t, "from_base", baseLogger.metadata["shared"].AsString())
+
+	assert.Equal(t, 3, len(extendedLogger.metadata))
+	assert.Equal(t, "base_value", extendedLogger.metadata["base_key"].AsString())
+	assert.Equal(t, "extra_value", extendedLogger.metadata["extra_key"].AsString())
+	assert.Equal(t, "from_extended", extendedLogger.metadata["shared"].AsString())
+}
+
+type mockOtelLogger struct {
+	embedded.Logger
+	mu       sync.Mutex
+	contexts []context.Context
+}
+
+func (m *mockOtelLogger) Emit(ctx context.Context, record log.Record) {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+	m.contexts = append(m.contexts, ctx)
+}
+
+func (m *mockOtelLogger) Enabled(ctx context.Context, param log.EnabledParameters) bool {
+	return true
+}
+
+func (m *mockOtelLogger) getContexts() []context.Context {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+	return append([]context.Context{}, m.contexts...)
+}
+
+func TestOtelLoggerWithContextPreservesSpanContext(t *testing.T) {
+	mockLogger := &mockOtelLogger{}
+
+	tp := sdktrace.NewTracerProvider()
+	tracer := tp.Tracer("test-tracer")
+
+	ctx, span := tracer.Start(context.Background(), "test-span")
+	defer span.End()
+
+	logger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger,
+		context:    ctx,
+	}
+
+	logger.Info("test message")
+
+	contexts := mockLogger.getContexts()
+	require.Len(t, contexts, 1)
+
+	spanContext := trace.SpanContextFromContext(contexts[0])
+	assert.True(t, spanContext.IsValid())
+	assert.Equal(t, span.SpanContext().TraceID(), spanContext.TraceID())
+	assert.Equal(t, span.SpanContext().SpanID(), spanContext.SpanID())
+}
+
+func TestOtelLoggerWithContextMultipleTimes(t *testing.T) {
+	mockLogger := &mockOtelLogger{}
+
+	tp := sdktrace.NewTracerProvider()
+	tracer := tp.Tracer("test-tracer")
+
+	ctx1, span1 := tracer.Start(context.Background(), "span-1")
+	defer span1.End()
+
+	ctx2, span2 := tracer.Start(ctx1, "span-2")
+	defer span2.End()
+
+	ctx3, span3 := tracer.Start(ctx2, "span-3")
+	defer span3.End()
+
+	baseLogger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger,
+		context:    ctx1,
+	}
+
+	logger2 := baseLogger.WithContext(ctx2)
+	logger3 := logger2.WithContext(ctx3)
+
+	logger3.Info("test message")
+
+	contexts := mockLogger.getContexts()
+	require.Len(t, contexts, 1)
+
+	spanContext := trace.SpanContextFromContext(contexts[0])
+	assert.True(t, spanContext.IsValid())
+	assert.Equal(t, span3.SpanContext().TraceID(), spanContext.TraceID())
+	assert.Equal(t, span3.SpanContext().SpanID(), spanContext.SpanID())
+}
+
+func TestOtelLoggerWithContextChainedLoggers(t *testing.T) {
+	mockLogger1 := &mockOtelLogger{}
+	mockLogger2 := &mockOtelLogger{}
+
+	tp := sdktrace.NewTracerProvider()
+	tracer := tp.Tracer("test-tracer")
+
+	ctx, span := tracer.Start(context.Background(), "test-span")
+	defer span.End()
+
+	childLogger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger2,
+		context:    context.Background(),
+	}
+
+	parentLogger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger1,
+		context:    context.Background(),
+		child:      childLogger,
+	}
+
+	loggerWithCtx := parentLogger.WithContext(ctx)
+	loggerWithCtx.Info("test message")
+
+	contexts1 := mockLogger1.getContexts()
+	require.Len(t, contexts1, 1)
+	spanContext1 := trace.SpanContextFromContext(contexts1[0])
+	assert.True(t, spanContext1.IsValid())
+	assert.Equal(t, span.SpanContext().TraceID(), spanContext1.TraceID())
+
+	contexts2 := mockLogger2.getContexts()
+	require.Len(t, contexts2, 1)
+	spanContext2 := trace.SpanContextFromContext(contexts2[0])
+	assert.True(t, spanContext2.IsValid())
+	assert.Equal(t, span.SpanContext().TraceID(), spanContext2.TraceID())
+}
+
+func TestOtelLoggerWithContextPreservesOriginalLogger(t *testing.T) {
+	mockLogger := &mockOtelLogger{}
+
+	tp := sdktrace.NewTracerProvider()
+	tracer := tp.Tracer("test-tracer")
+
+	ctx1, span1 := tracer.Start(context.Background(), "span-1")
+	defer span1.End()
+
+	ctx2, span2 := tracer.Start(ctx1, "span-2")
+	defer span2.End()
+
+	baseLogger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger,
+		context:    ctx1,
+	}
+
+	newLogger := baseLogger.WithContext(ctx2)
+
+	baseLogger.Info("original context")
+	newLogger.Info("new context")
+
+	contexts := mockLogger.getContexts()
+	require.Len(t, contexts, 2)
+
+	spanContext1 := trace.SpanContextFromContext(contexts[0])
+	assert.Equal(t, span1.SpanContext().SpanID(), spanContext1.SpanID())
+
+	spanContext2 := trace.SpanContextFromContext(contexts[1])
+	assert.Equal(t, span2.SpanContext().SpanID(), spanContext2.SpanID())
+}
+
+func TestOtelLoggerWithContextAndMetadata(t *testing.T) {
+	mockLogger := &mockOtelLogger{}
+
+	tp := sdktrace.NewTracerProvider()
+	tracer := tp.Tracer("test-tracer")
+
+	ctx, span := tracer.Start(context.Background(), "test-span")
+	defer span.End()
+
+	baseLogger := &otelLogger{
+		metadata:   make(map[string]log.Value),
+		logLevel:   LevelTrace,
+		otelLogger: mockLogger,
+		context:    context.Background(),
+	}
+
+	loggerWithMetadata := baseLogger.With(map[string]interface{}{
+		"key": "value",
+	})
+
+	loggerWithCtx := loggerWithMetadata.WithContext(ctx)
+	loggerWithCtx.Info("test message")
+
+	contexts := mockLogger.getContexts()
+	require.Len(t, contexts, 1)
+
+	spanContext := trace.SpanContextFromContext(contexts[0])
+	assert.True(t, spanContext.IsValid())
+	assert.Equal(t, span.SpanContext().TraceID(), spanContext.TraceID())
+}