From b3eeda2e5ed262facb68d3ad8490a9dd97724612 Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 12 Sep 2024 23:22:45 +1200 Subject: [PATCH 1/8] otellogr: Implement Logsink Info and conversions --- bridges/otellogr/convert.go | 153 +++++++++++++++ bridges/otellogr/convert_test.go | 312 +++++++++++++++++++++++++++++++ bridges/otellogr/logsink.go | 130 +++++++++++-- bridges/otellogr/logsink_test.go | 178 ++++++++++++++++++ 4 files changed, 753 insertions(+), 20 deletions(-) create mode 100644 bridges/otellogr/convert.go create mode 100644 bridges/otellogr/convert_test.go diff --git a/bridges/otellogr/convert.go b/bridges/otellogr/convert.go new file mode 100644 index 00000000000..0e4b33bf311 --- /dev/null +++ b/bridges/otellogr/convert.go @@ -0,0 +1,153 @@ +package otellogr // import "go.opentelemetry.io/contrib/bridges/otellogr" + +import ( + "context" + "fmt" + "math" + "reflect" + "strconv" + "time" + + "go.opentelemetry.io/otel/log" +) + +// convertKVs converts a list of key-value pairs to a list of [log.KeyValue]. +// The last [context.Context] value is returned as the context. +// If no context is found, the original context is returned. +func convertKVs(ctx context.Context, keysAndValues ...any) (context.Context, []log.KeyValue) { + if len(keysAndValues) == 0 { + return ctx, nil + } + if len(keysAndValues)%2 != 0 { + // Ensure an odd number of items here does not corrupt the list + keysAndValues = append(keysAndValues, nil) + } + + kvs := make([]log.KeyValue, 0, len(keysAndValues)/2) + for i := 0; i < len(keysAndValues); i += 2 { + k, ok := keysAndValues[i].(string) + if !ok { + // Ensure that the key is a string + k = fmt.Sprintf("%v", keysAndValues[i]) + } + + v := keysAndValues[i+1] + if vCtx, ok := v.(context.Context); ok { + // Special case when a field is of context.Context type. + ctx = vCtx + continue + } + + kvs = append(kvs, log.KeyValue{ + Key: k, + Value: convertValue(v), + }) + } + + return ctx, kvs +} + +func convertValue(v any) log.Value { + // Handling the most common types without reflect is a small perf win. + switch val := v.(type) { + case bool: + return log.BoolValue(val) + case string: + return log.StringValue(val) + case int: + return log.Int64Value(int64(val)) + case int8: + return log.Int64Value(int64(val)) + case int16: + return log.Int64Value(int64(val)) + case int32: + return log.Int64Value(int64(val)) + case int64: + return log.Int64Value(val) + case uint: + return convertUintValue(uint64(val)) + case uint8: + return log.Int64Value(int64(val)) + case uint16: + return log.Int64Value(int64(val)) + case uint32: + return log.Int64Value(int64(val)) + case uint64: + return convertUintValue(val) + case uintptr: + return convertUintValue(uint64(val)) + case float32: + return log.Float64Value(float64(val)) + case float64: + return log.Float64Value(val) + case time.Duration: + return log.Int64Value(val.Nanoseconds()) + case complex64: + r := log.Float64("r", real(complex128(val))) + i := log.Float64("i", imag(complex128(val))) + return log.MapValue(r, i) + case complex128: + r := log.Float64("r", real(val)) + i := log.Float64("i", imag(val)) + return log.MapValue(r, i) + case time.Time: + return log.Int64Value(val.UnixNano()) + case []byte: + return log.BytesValue(val) + case error: + return log.StringValue(val.Error()) + } + + t := reflect.TypeOf(v) + if t == nil { + return log.Value{} + } + val := reflect.ValueOf(v) + switch t.Kind() { + case reflect.Struct: + return log.StringValue(fmt.Sprintf("%+v", v)) + case reflect.Slice, reflect.Array: + items := make([]log.Value, 0, val.Len()) + for i := 0; i < val.Len(); i++ { + items = append(items, convertValue(val.Index(i).Interface())) + } + return log.SliceValue(items...) + case reflect.Map: + kvs := make([]log.KeyValue, 0, val.Len()) + for _, k := range val.MapKeys() { + var key string + // If the key is a struct, use %+v to print the struct fields. + if k.Kind() == reflect.Struct { + key = fmt.Sprintf("%+v", k.Interface()) + } else { + key = fmt.Sprintf("%v", k.Interface()) + } + kvs = append(kvs, log.KeyValue{ + Key: key, + Value: convertValue(val.MapIndex(k).Interface()), + }) + } + return log.MapValue(kvs...) + case reflect.Ptr, reflect.Interface: + if val.IsNil() { + return log.Value{} + } + return convertValue(val.Elem().Interface()) + } + + // Try to handle this as gracefully as possible. + // + // Don't panic here. it is preferable to have user's open issue + // asking why their attributes have a "unhandled: " prefix than + // say that their code is panicking. + return log.StringValue(fmt.Sprintf("unhandled: (%s) %+v", t, v)) +} + +// convertUintValue converts a uint64 to a log.Value. +// If the value is too large to fit in an int64, it is converted to a string. +func convertUintValue(v uint64) log.Value { + if v > math.MaxInt64 { + return log.StringValue(strconv.FormatUint(v, 10)) + } + return log.Int64Value(int64(v)) +} diff --git a/bridges/otellogr/convert_test.go b/bridges/otellogr/convert_test.go new file mode 100644 index 00000000000..ed5f5b41fa5 --- /dev/null +++ b/bridges/otellogr/convert_test.go @@ -0,0 +1,312 @@ +package otellogr + +import ( + "context" + "errors" + "fmt" + "testing" + "time" + + "github.com/stretchr/testify/assert" + + "go.opentelemetry.io/otel/log" +) + +func TestConvertKVs(t *testing.T) { + ctx := context.WithValue(context.Background(), "key", "value") // nolint: revive,staticcheck // test context + + for _, tt := range []struct { + name string + kvs []any + wantKVs []log.KeyValue + wantCtx context.Context + }{ + { + name: "empty", + kvs: []any{}, + }, + { + name: "single_value", + kvs: []any{"key", "value"}, + wantKVs: []log.KeyValue{ + log.String("key", "value"), + }, + }, + { + name: "multiple_values", + kvs: []any{"key1", "value1", "key2", "value2"}, + wantKVs: []log.KeyValue{ + log.String("key1", "value1"), + log.String("key2", "value2"), + }, + }, + { + name: "missing_value", + kvs: []any{"key1", "value1", "key2"}, + wantKVs: []log.KeyValue{ + log.String("key1", "value1"), + {Key: "key2", Value: log.Value{}}, + }, + }, + { + name: "key_not_string", + kvs: []any{42, "value"}, + wantKVs: []log.KeyValue{ + log.String("42", "value"), + }, + }, + { + name: "context", + kvs: []any{"ctx", ctx, "key", "value"}, + wantKVs: []log.KeyValue{log.String("key", "value")}, + wantCtx: ctx, + }, + { + name: "last_context", + kvs: []any{"key", context.Background(), "ctx", ctx}, + wantKVs: []log.KeyValue{}, + wantCtx: ctx, + }, + } { + t.Run(tt.name, func(t *testing.T) { + ctx, kvs := convertKVs(nil, tt.kvs...) // nolint: staticcheck // pass nil context + assert.Equal(t, tt.wantKVs, kvs) + assert.Equal(t, tt.wantCtx, ctx) + }) + } +} + +func TestConvertValue(t *testing.T) { + now := time.Now() + + for _, tt := range []struct { + name string + value any + wantValue log.Value + }{ + { + name: "bool", + value: true, + wantValue: log.BoolValue(true), + }, + { + name: "string", + value: "value", + wantValue: log.StringValue("value"), + }, + { + name: "int", + value: 10, + wantValue: log.Int64Value(10), + }, + { + name: "int8", + value: int8(127), + wantValue: log.Int64Value(127), + }, + { + name: "int16", + value: int16(32767), + wantValue: log.Int64Value(32767), + }, + { + name: "int32", + value: int32(2147483647), + wantValue: log.Int64Value(2147483647), + }, + { + name: "int64", + value: int64(9223372036854775807), + wantValue: log.Int64Value(9223372036854775807), + }, + { + name: "uint", + value: uint(42), + wantValue: log.Int64Value(42), + }, + { + name: "uint8", + value: uint8(255), + wantValue: log.Int64Value(255), + }, + { + name: "uint16", + value: uint16(65535), + wantValue: log.Int64Value(65535), + }, + { + name: "uint32", + value: uint32(4294967295), + wantValue: log.Int64Value(4294967295), + }, + { + name: "uint64", + value: uint64(9223372036854775807), + wantValue: log.Int64Value(9223372036854775807), + }, + { + name: "uint64-max", + value: uint64(18446744073709551615), + wantValue: log.StringValue("18446744073709551615"), + }, + { + name: "uintptr", + value: uintptr(12345), + wantValue: log.Int64Value(12345), + }, + { + name: "float64", + value: float64(3.14159), + wantValue: log.Float64Value(3.14159), + }, + { + name: "time.Duration", + value: time.Second, + wantValue: log.Int64Value(1_000_000_000), + }, + { + name: "complex64", + value: complex64(complex(float32(1), float32(2))), + wantValue: log.MapValue(log.Float64("r", 1), log.Float64("i", 2)), + }, + { + name: "complex128", + value: complex(float64(3), float64(4)), + wantValue: log.MapValue(log.Float64("r", 3), log.Float64("i", 4)), + }, + { + name: "time.Time", + value: now, + wantValue: log.Int64Value(now.UnixNano()), + }, + { + name: "[]byte", + value: []byte("hello"), + wantValue: log.BytesValue([]byte("hello")), + }, + { + name: "error", + value: errors.New("test error"), + wantValue: log.StringValue("test error"), + }, + { + name: "error", + value: errors.New("test error"), + wantValue: log.StringValue("test error"), + }, + { + name: "error-nested", + value: fmt.Errorf("test error: %w", errors.New("nested error")), + wantValue: log.StringValue("test error: nested error"), + }, + { + name: "nil", + value: nil, + wantValue: log.Value{}, + }, + { + name: "nil_ptr", + value: (*int)(nil), + wantValue: log.Value{}, + }, + { + name: "int_ptr", + value: func() *int { i := 93; return &i }(), + wantValue: log.Int64Value(93), + }, + { + name: "string_ptr", + value: func() *string { s := "hello"; return &s }(), + wantValue: log.StringValue("hello"), + }, + { + name: "bool_ptr", + value: func() *bool { b := true; return &b }(), + wantValue: log.BoolValue(true), + }, + { + name: "int_empty_array", + value: []int{}, + wantValue: log.SliceValue([]log.Value{}...), + }, + { + name: "int_array", + value: []int{1, 2, 3}, + wantValue: log.SliceValue([]log.Value{ + log.Int64Value(1), + log.Int64Value(2), + log.Int64Value(3), + }...), + }, + { + name: "key_value_map", + value: map[string]int{"one": 1}, + wantValue: log.MapValue( + log.Int64("one", 1), + ), + }, + { + name: "int_string_map", + value: map[int]string{1: "one"}, + wantValue: log.MapValue( + log.String("1", "one"), + ), + }, + { + name: "nested_map", + value: map[string]map[string]int{"nested": {"one": 1}}, + wantValue: log.MapValue( + log.Map("nested", + log.Int64("one", 1), + ), + ), + }, + { + name: "struct_key_map", + value: map[struct{ Name string }]int{ + {Name: "John"}: 42, + }, + wantValue: log.MapValue( + log.Int64("{Name:John}", 42), + ), + }, + { + name: "struct", + value: struct { + Name string + Age int + }{ + Name: "John", + Age: 42, + }, + wantValue: log.StringValue("{Name:John Age:42}"), + }, + { + name: "struct_ptr", + value: &struct { + Name string + Age int + }{ + Name: "John", + Age: 42, + }, + wantValue: log.StringValue("{Name:John Age:42}"), + }, + { + name: "ctx", + value: context.Background(), + wantValue: log.StringValue("context.Background"), + }, + } { + t.Run(tt.name, func(t *testing.T) { + assert.Equal(t, convertValue(tt.value), tt.wantValue) + }) + } +} + +func TestConvertValueFloat32(t *testing.T) { + value := convertValue(float32(3.14)) + want := log.Float64Value(3.14) + + assert.InDelta(t, value.AsFloat64(), want.AsFloat64(), 0.0001) +} diff --git a/bridges/otellogr/logsink.go b/bridges/otellogr/logsink.go index 0a2270e4056..39caf77580b 100644 --- a/bridges/otellogr/logsink.go +++ b/bridges/otellogr/logsink.go @@ -4,10 +4,58 @@ // Package otellogr provides a [LogSink], a [logr.LogSink] implementation that // can be used to bridge between the [logr] API and [OpenTelemetry]. // +// # Record Conversion +// +// The logr records are converted to OpenTelemetry [log.Record] in the following +// way: +// +// - Time is set as the current time of conversion. +// - Message is set as the Body using a [log.StringValue]. +// - Level is transformed and set as the Severity. The SeverityText is not +// set. +// - KeyAndValues are transformed and set as Attributes. +// - Name is logged as an additional attribute with the key "logger". +// - The [context.Context] value in KeyAndValues is propagated to OpenTelemetry +// log record. All non-nested [context.Context] values are ignored and not +// added as attributes. If there are multiple [context.Context] the last one +// is used. +// +// The Level is transformed by using the [WithLevels] option. If the option is +// not provided, all logr levels will be mapped to [log.SeverityInfo]. +// The levels are mapped in order, with the first level in the list corresponding +// to the logr level 0, the second level corresponding to logr level 1, and so on. +// If the logr level is greater than the number of levels provided, it will be +// mapped to [log.SeverityInfo]. +// +// KeysAndValues values are transformed based on their type. The following types are +// supported: +// +// - [bool] are transformed to [log.BoolValue]. +// - [string] are transformed to [log.StringValue]. +// - [int], [int8], [int16], [int32], [int64] are transformed to +// [log.Int64Value]. +// - [uint], [uint8], [uint16], [uint32], [uint64], [uintptr] are transformed +// to [log.Int64Value] or [log.StringValue] if the value is too large. +// - [float32], [float64] are transformed to [log.Float64Value]. +// - [time.Duration] are transformed to [log.Int64Value] with the nanoseconds. +// - [complex64], [complex128] are transformed to [log.MapValue] with the keys +// "r" and "i" for the real and imaginary parts. The values are +// [log.Float64Value]. +// - [time.Time] are transformed to [log.Int64Value] with the nanoseconds. +// - [[]byte] are transformed to [log.BytesValue]. +// - [error] are transformed to [log.StringValue] with the error message. +// - [nil] are transformed to an empty [log.Value]. +// - [struct] are transformed to [log.StringValue] with the struct fields. +// - [slice], [array] are transformed to [log.SliceValue] with the elements. +// - [map] are transformed to [log.MapValue] with the key-value pairs. +// - [pointer], [interface] are transformed to the dereferenced value. +// // [OpenTelemetry]: https://opentelemetry.io/docs/concepts/signals/logs/ package otellogr // import "go.opentelemetry.io/contrib/bridges/otellogr" import ( + "context" + "github.com/go-logr/logr" "go.opentelemetry.io/otel/log" @@ -18,6 +66,7 @@ type config struct { provider log.LoggerProvider version string schemaURL string + levels []log.Severity } func newConfig(options []Option) config { @@ -33,17 +82,6 @@ func newConfig(options []Option) config { return c } -func (c config) logger(name string) log.Logger { - var opts []log.LoggerOption - if c.version != "" { - opts = append(opts, log.WithInstrumentationVersion(c.version)) - } - if c.schemaURL != "" { - opts = append(opts, log.WithSchemaURL(c.schemaURL)) - } - return c.provider.Logger(name, opts...) -} - // Option configures a [LogSink]. type Option interface { apply(config) config @@ -85,15 +123,42 @@ func WithLoggerProvider(provider log.LoggerProvider) Option { }) } +// WithLevels returns an [Option] that configures the mapping of logr levels to +// OpenTelemetry log levels. The levels are mapped in order, with the first +// level in the list corresponding to the logr level 0, the second level +// corresponding to logr level 1, and so on. +// +// By default if this Option is not provided, all logr levels will be mapped to +// Info level in OpenTelemetry. +// LoggerProvider. +func WithLevels(l []log.Severity) Option { + return optFunc(func(c config) config { + c.levels = l + return c + }) +} + // NewLogSink returns a new [LogSink] to be used as a [logr.LogSink]. // // If [WithLoggerProvider] is not provided, the returned LogSink will use the // global LoggerProvider. func NewLogSink(name string, options ...Option) *LogSink { c := newConfig(options) + + var opts []log.LoggerOption + if c.version != "" { + opts = append(opts, log.WithInstrumentationVersion(c.version)) + } + if c.schemaURL != "" { + opts = append(opts, log.WithSchemaURL(c.schemaURL)) + } + return &LogSink{ - name: name, - logger: c.logger(name), + name: name, + provider: c.provider, + logger: c.provider.Logger(name, opts...), + opts: opts, + levels: c.levels, } } @@ -103,8 +168,13 @@ type LogSink struct { // Ensure forward compatibility by explicitly making this not comparable. noCmp [0]func() //nolint: unused // This is indeed used. - name string - logger log.Logger + name string + provider log.LoggerProvider + logger log.Logger + opts []log.LoggerOption + levels []log.Severity + attr []log.KeyValue + ctx context.Context } // Compile-time check *Handler implements logr.LogSink. @@ -114,8 +184,9 @@ var _ logr.LogSink = (*LogSink)(nil) // For example, commandline flags might be used to set the logging // verbosity and disable some info logs. func (l *LogSink) Enabled(level int) bool { - // TODO - return true + var record log.Record + record.SetSeverity(l.convertLevel(level)) + return l.logger.Enabled(context.Background(), record) } // Error logs an error, with the given message and key/value pairs. @@ -125,7 +196,16 @@ func (l *LogSink) Error(err error, msg string, keysAndValues ...any) { // Info logs a non-error message with the given key/value pairs. func (l *LogSink) Info(level int, msg string, keysAndValues ...any) { - // TODO + var record log.Record + record.SetBody(log.StringValue(msg)) + record.SetSeverity(l.convertLevel(level)) + + record.AddAttributes(l.attr...) + + ctx, attr := convertKVs(l.ctx, keysAndValues...) + record.AddAttributes(attr...) + + l.logger.Emit(ctx, record) } // Init initializes the LogSink. @@ -135,12 +215,22 @@ func (l *LogSink) Init(info logr.RuntimeInfo) { // WithName returns a new LogSink with the specified name appended. func (l LogSink) WithName(name string) logr.LogSink { - // TODO + l.logger = l.provider.Logger(l.name+"/"+name, l.opts...) return &l } // WithValues returns a new LogSink with additional key/value pairs. func (l LogSink) WithValues(keysAndValues ...any) logr.LogSink { - // TODO + ctx, attr := convertKVs(l.ctx, keysAndValues...) + l.attr = append(l.attr, attr...) + l.ctx = ctx return &l } + +func (l *LogSink) convertLevel(level int) log.Severity { + if len(l.levels) <= level { + return log.SeverityInfo + } + + return l.levels[level] +} diff --git a/bridges/otellogr/logsink_test.go b/bridges/otellogr/logsink_test.go index 59fa5bc7589..f5f1198041d 100644 --- a/bridges/otellogr/logsink_test.go +++ b/bridges/otellogr/logsink_test.go @@ -3,13 +3,18 @@ package otellogr import ( + "context" "testing" + "time" + "github.com/go-logr/logr" "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/global" + "go.opentelemetry.io/otel/log/logtest" ) type mockLoggerProvider struct { @@ -57,6 +62,17 @@ func TestNewConfig(t *testing.T) { provider: customLoggerProvider, }, }, + { + name: "with a custom levels", + options: []Option{ + WithLevels([]log.Severity{log.SeverityFatal, log.SeverityError, log.SeverityWarn, log.SeverityInfo}), + }, + + wantConfig: config{ + levels: []log.Severity{log.SeverityFatal, log.SeverityError, log.SeverityWarn, log.SeverityInfo}, + provider: global.GetLoggerProvider(), + }, + }, } { t.Run(tt.name, func(t *testing.T) { assert.Equal(t, tt.wantConfig, newConfig(tt.options)) @@ -96,3 +112,165 @@ func TestNewLogSink(t *testing.T) { }) } } + +type wantRecord struct { + Body log.Value + Severity log.Severity + Attributes []log.KeyValue +} + +func TestLogSink(t *testing.T) { + now := time.Now() + + for _, tt := range []struct { + name string + f func(*logr.Logger) + wantLoggerCount int + wantRecords []wantRecord + }{ + { + name: "info", + f: func(l *logr.Logger) { + l.Info("info message") + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("info message"), + Severity: log.SeverityInfo, + }, + }, + }, + { + name: "info_multi_attrs", + f: func(l *logr.Logger) { + l.Info("msg", + "struct", struct{ data int64 }{data: 1}, + "bool", true, + "duration", time.Minute, + "float64", 3.14159, + "int64", -2, + "string", "str", + "time", now, + "uint64", uint64(3), + ) + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("msg"), + Severity: log.SeverityInfo, + Attributes: []log.KeyValue{ + log.String("struct", "{data:1}"), + log.Bool("bool", true), + log.Int64("duration", 60_000_000_000), + log.Float64("float64", 3.14159), + log.Int64("int64", -2), + log.String("string", "str"), + log.Int64("time", now.UnixNano()), + log.Int64("uint64", 3), + }, + }, + }, + }, + { + name: "info_with_name", + f: func(l *logr.Logger) { + l.WithName("test").Info("info message with name") + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("info message with name"), + Severity: log.SeverityInfo, + }, + }, + }, + { + name: "info_with_name_nested", + f: func(l *logr.Logger) { + l.WithName("test").WithName("test").Info("info message with name") + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("info message with name"), + Severity: log.SeverityInfo, + }, + }, + }, + { + name: "info_with_attrs", + f: func(l *logr.Logger) { + l.WithValues("key", "value").Info("info message with attrs") + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("info message with attrs"), + Severity: log.SeverityInfo, + Attributes: []log.KeyValue{ + log.String("key", "value"), + }, + }, + }, + }, + { + name: "info_with_attrs_nested", + f: func(l *logr.Logger) { + l.WithValues("key1", "value1").Info("info message with attrs", "key2", "value2") + }, + wantRecords: []wantRecord{ + { + Body: log.StringValue("info message with attrs"), + Severity: log.SeverityInfo, + Attributes: []log.KeyValue{ + log.String("key1", "value1"), + log.String("key2", "value2"), + }, + }, + }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + rec := logtest.NewRecorder() + ls := NewLogSink("name", WithLoggerProvider(rec)) + l := logr.New(ls) + tt.f(&l) + + last := len(rec.Result()) - 1 + + assert.Len(t, rec.Result()[last].Records, len(tt.wantRecords)) + for i, record := range rec.Result()[last].Records { + assert.Equal(t, tt.wantRecords[i].Body, record.Body()) + assert.Equal(t, tt.wantRecords[i].Severity, record.Severity()) + + var attributes []log.KeyValue + record.WalkAttributes(func(kv log.KeyValue) bool { + attributes = append(attributes, kv) + return true + }) + assert.Equal(t, tt.wantRecords[i].Attributes, attributes) + } + }) + } +} + +func TestLogSinkWithName(t *testing.T) { + rec := logtest.NewRecorder() + ls := NewLogSink("name", WithLoggerProvider(rec)) + lsWithName := ls.WithName("test") + require.NotEqual(t, ls, lsWithName) + require.Equal(t, lsWithName, ls.WithName("test")) +} + +func TestLogSinkEnabled(t *testing.T) { + rec := logtest.NewRecorder( + logtest.WithEnabledFunc(func(ctx context.Context, record log.Record) bool { + return record.Severity() == log.SeverityInfo + }), + ) + ls := NewLogSink( + "name", + WithLoggerProvider(rec), + WithLevels([]log.Severity{log.SeverityDebug, log.SeverityInfo}), + ) + + assert.False(t, ls.Enabled(0)) + assert.True(t, ls.Enabled(1)) +} From 0aa232dccb87d16f437f9d44f0555d91396968b3 Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 12 Sep 2024 23:28:45 +1200 Subject: [PATCH 2/8] Add missing license --- bridges/otellogr/convert.go | 3 +++ bridges/otellogr/convert_test.go | 3 +++ 2 files changed, 6 insertions(+) diff --git a/bridges/otellogr/convert.go b/bridges/otellogr/convert.go index 0e4b33bf311..794e12729ba 100644 --- a/bridges/otellogr/convert.go +++ b/bridges/otellogr/convert.go @@ -1,3 +1,6 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + package otellogr // import "go.opentelemetry.io/contrib/bridges/otellogr" import ( diff --git a/bridges/otellogr/convert_test.go b/bridges/otellogr/convert_test.go index ed5f5b41fa5..90018be212a 100644 --- a/bridges/otellogr/convert_test.go +++ b/bridges/otellogr/convert_test.go @@ -1,3 +1,6 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + package otellogr import ( From d3b2bdd70697b3361bbc0f3dab8ff86ded59eaa0 Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 19 Sep 2024 20:21:28 +1200 Subject: [PATCH 3/8] Remove level and implement nits --- bridges/otellogr/logsink.go | 54 ++------- bridges/otellogr/logsink_test.go | 182 +++++++++++++++---------------- 2 files changed, 95 insertions(+), 141 deletions(-) diff --git a/bridges/otellogr/logsink.go b/bridges/otellogr/logsink.go index 39caf77580b..1acd6c55e56 100644 --- a/bridges/otellogr/logsink.go +++ b/bridges/otellogr/logsink.go @@ -9,24 +9,14 @@ // The logr records are converted to OpenTelemetry [log.Record] in the following // way: // -// - Time is set as the current time of conversion. // - Message is set as the Body using a [log.StringValue]. -// - Level is transformed and set as the Severity. The SeverityText is not -// set. +// - TODO: Level // - KeyAndValues are transformed and set as Attributes. -// - Name is logged as an additional attribute with the key "logger". // - The [context.Context] value in KeyAndValues is propagated to OpenTelemetry // log record. All non-nested [context.Context] values are ignored and not // added as attributes. If there are multiple [context.Context] the last one // is used. // -// The Level is transformed by using the [WithLevels] option. If the option is -// not provided, all logr levels will be mapped to [log.SeverityInfo]. -// The levels are mapped in order, with the first level in the list corresponding -// to the logr level 0, the second level corresponding to logr level 1, and so on. -// If the logr level is greater than the number of levels provided, it will be -// mapped to [log.SeverityInfo]. -// // KeysAndValues values are transformed based on their type. The following types are // supported: // @@ -66,7 +56,6 @@ type config struct { provider log.LoggerProvider version string schemaURL string - levels []log.Severity } func newConfig(options []Option) config { @@ -92,7 +81,7 @@ type optFunc func(config) config func (f optFunc) apply(c config) config { return f(c) } // WithVersion returns an [Option] that configures the version of the -// [log.Logger] used by a [Hook]. The version should be the version of the +// [log.Logger] used by a [LogSink]. The version should be the version of the // package that is being logged. func WithVersion(version string) Option { return optFunc(func(c config) config { @@ -102,7 +91,7 @@ func WithVersion(version string) Option { } // WithSchemaURL returns an [Option] that configures the semantic convention -// schema URL of the [log.Logger] used by a [Hook]. The schemaURL should be +// schema URL of the [log.Logger] used by a [LogSink]. The schemaURL should be // the schema URL for the semantic conventions used in log records. func WithSchemaURL(schemaURL string) Option { return optFunc(func(c config) config { @@ -123,24 +112,9 @@ func WithLoggerProvider(provider log.LoggerProvider) Option { }) } -// WithLevels returns an [Option] that configures the mapping of logr levels to -// OpenTelemetry log levels. The levels are mapped in order, with the first -// level in the list corresponding to the logr level 0, the second level -// corresponding to logr level 1, and so on. -// -// By default if this Option is not provided, all logr levels will be mapped to -// Info level in OpenTelemetry. -// LoggerProvider. -func WithLevels(l []log.Severity) Option { - return optFunc(func(c config) config { - c.levels = l - return c - }) -} - // NewLogSink returns a new [LogSink] to be used as a [logr.LogSink]. // -// If [WithLoggerProvider] is not provided, the returned LogSink will use the +// If [WithLoggerProvider] is not provided, the returned [LogSink] will use the // global LoggerProvider. func NewLogSink(name string, options ...Option) *LogSink { c := newConfig(options) @@ -158,7 +132,6 @@ func NewLogSink(name string, options ...Option) *LogSink { provider: c.provider, logger: c.provider.Logger(name, opts...), opts: opts, - levels: c.levels, } } @@ -172,7 +145,6 @@ type LogSink struct { provider log.LoggerProvider logger log.Logger opts []log.LoggerOption - levels []log.Severity attr []log.KeyValue ctx context.Context } @@ -184,9 +156,8 @@ var _ logr.LogSink = (*LogSink)(nil) // For example, commandline flags might be used to set the logging // verbosity and disable some info logs. func (l *LogSink) Enabled(level int) bool { - var record log.Record - record.SetSeverity(l.convertLevel(level)) - return l.logger.Enabled(context.Background(), record) + // TODO + return true } // Error logs an error, with the given message and key/value pairs. @@ -198,7 +169,7 @@ func (l *LogSink) Error(err error, msg string, keysAndValues ...any) { func (l *LogSink) Info(level int, msg string, keysAndValues ...any) { var record log.Record record.SetBody(log.StringValue(msg)) - record.SetSeverity(l.convertLevel(level)) + record.SetSeverity(log.SeverityInfo) // TODO: level record.AddAttributes(l.attr...) @@ -215,7 +186,8 @@ func (l *LogSink) Init(info logr.RuntimeInfo) { // WithName returns a new LogSink with the specified name appended. func (l LogSink) WithName(name string) logr.LogSink { - l.logger = l.provider.Logger(l.name+"/"+name, l.opts...) + l.name = l.name + "/" + name + l.logger = l.provider.Logger(l.name, l.opts...) return &l } @@ -226,11 +198,3 @@ func (l LogSink) WithValues(keysAndValues ...any) logr.LogSink { l.ctx = ctx return &l } - -func (l *LogSink) convertLevel(level int) log.Severity { - if len(l.levels) <= level { - return log.SeverityInfo - } - - return l.levels[level] -} diff --git a/bridges/otellogr/logsink_test.go b/bridges/otellogr/logsink_test.go index f5f1198041d..0ff5dd91227 100644 --- a/bridges/otellogr/logsink_test.go +++ b/bridges/otellogr/logsink_test.go @@ -3,7 +3,6 @@ package otellogr import ( - "context" "testing" "time" @@ -62,17 +61,6 @@ func TestNewConfig(t *testing.T) { provider: customLoggerProvider, }, }, - { - name: "with a custom levels", - options: []Option{ - WithLevels([]log.Severity{log.SeverityFatal, log.SeverityError, log.SeverityWarn, log.SeverityInfo}), - }, - - wantConfig: config{ - levels: []log.Severity{log.SeverityFatal, log.SeverityError, log.SeverityWarn, log.SeverityInfo}, - provider: global.GetLoggerProvider(), - }, - }, } { t.Run(tt.name, func(t *testing.T) { assert.Equal(t, tt.wantConfig, newConfig(tt.options)) @@ -82,16 +70,15 @@ func TestNewConfig(t *testing.T) { func TestNewLogSink(t *testing.T) { const name = "test_logsink" - provider := global.GetLoggerProvider() for _, tt := range []struct { - name string - options []Option - wantLogger log.Logger + name string + options []Option + wantScopeRecords *logtest.ScopeRecords }{ { - name: "with default options", - wantLogger: provider.Logger(name), + name: "with default options", + wantScopeRecords: &logtest.ScopeRecords{Name: name}, }, { name: "with version and schema URL", @@ -99,44 +86,56 @@ func TestNewLogSink(t *testing.T) { WithVersion("1.0"), WithSchemaURL("https://example.com"), }, - wantLogger: provider.Logger(name, - log.WithInstrumentationVersion("1.0"), - log.WithSchemaURL("https://example.com"), - ), + wantScopeRecords: &logtest.ScopeRecords{ + Name: name, + Version: "1.0", + SchemaURL: "https://example.com", + }, }, } { t.Run(tt.name, func(t *testing.T) { - hook := NewLogSink(name, tt.options...) - assert.NotNil(t, hook) - assert.Equal(t, tt.wantLogger, hook.logger) + provider := logtest.NewRecorder() + + var l *LogSink + require.NotPanics(t, func() { + l = NewLogSink(name, append( + tt.options, + WithLoggerProvider(provider), + )...) + }) + require.NotNil(t, l) + require.Len(t, provider.Result(), 1) + + got := provider.Result()[0] + assert.Equal(t, tt.wantScopeRecords, got) }) } } -type wantRecord struct { - Body log.Value - Severity log.Severity - Attributes []log.KeyValue -} - func TestLogSink(t *testing.T) { + const name = "name" now := time.Now() for _, tt := range []struct { - name string - f func(*logr.Logger) - wantLoggerCount int - wantRecords []wantRecord + name string + f func(*logr.Logger) + wantRecords map[string][]log.Record }{ + { + name: "no_log", + f: func(l *logr.Logger) {}, + wantRecords: map[string][]log.Record{ + name: {}, + }, + }, { name: "info", f: func(l *logr.Logger) { - l.Info("info message") + l.Info("msg") }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("info message"), - Severity: log.SeverityInfo, + wantRecords: map[string][]log.Record{ + name: { + buildRecord(log.StringValue("msg"), time.Time{}, log.SeverityInfo, nil), }, }, }, @@ -154,11 +153,9 @@ func TestLogSink(t *testing.T) { "uint64", uint64(3), ) }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("msg"), - Severity: log.SeverityInfo, - Attributes: []log.KeyValue{ + wantRecords: map[string][]log.Record{ + name: { + buildRecord(log.StringValue("msg"), time.Time{}, log.SeverityInfo, []log.KeyValue{ log.String("struct", "{data:1}"), log.Bool("bool", true), log.Int64("duration", 60_000_000_000), @@ -167,7 +164,7 @@ func TestLogSink(t *testing.T) { log.String("string", "str"), log.Int64("time", now.UnixNano()), log.Int64("uint64", 3), - }, + }), }, }, }, @@ -176,10 +173,9 @@ func TestLogSink(t *testing.T) { f: func(l *logr.Logger) { l.WithName("test").Info("info message with name") }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("info message with name"), - Severity: log.SeverityInfo, + wantRecords: map[string][]log.Record{ + name + "/test": { + buildRecord(log.StringValue("info message with name"), time.Time{}, log.SeverityInfo, nil), }, }, }, @@ -188,10 +184,9 @@ func TestLogSink(t *testing.T) { f: func(l *logr.Logger) { l.WithName("test").WithName("test").Info("info message with name") }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("info message with name"), - Severity: log.SeverityInfo, + wantRecords: map[string][]log.Record{ + name + "/test/test": { + buildRecord(log.StringValue("info message with name"), time.Time{}, log.SeverityInfo, nil), }, }, }, @@ -200,13 +195,11 @@ func TestLogSink(t *testing.T) { f: func(l *logr.Logger) { l.WithValues("key", "value").Info("info message with attrs") }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("info message with attrs"), - Severity: log.SeverityInfo, - Attributes: []log.KeyValue{ + wantRecords: map[string][]log.Record{ + name: { + buildRecord(log.StringValue("info message with attrs"), time.Time{}, log.SeverityInfo, []log.KeyValue{ log.String("key", "value"), - }, + }), }, }, }, @@ -215,14 +208,12 @@ func TestLogSink(t *testing.T) { f: func(l *logr.Logger) { l.WithValues("key1", "value1").Info("info message with attrs", "key2", "value2") }, - wantRecords: []wantRecord{ - { - Body: log.StringValue("info message with attrs"), - Severity: log.SeverityInfo, - Attributes: []log.KeyValue{ + wantRecords: map[string][]log.Record{ + name: { + buildRecord(log.StringValue("info message with attrs"), time.Time{}, log.SeverityInfo, []log.KeyValue{ log.String("key1", "value1"), log.String("key2", "value2"), - }, + }), }, }, }, @@ -233,44 +224,43 @@ func TestLogSink(t *testing.T) { l := logr.New(ls) tt.f(&l) - last := len(rec.Result()) - 1 + for k, v := range tt.wantRecords { + found := false + + want := make([]logtest.EmittedRecord, len(v)) + for i := range want { + want[i] = logtest.EmittedRecord{Record: v[i]} + } - assert.Len(t, rec.Result()[last].Records, len(tt.wantRecords)) - for i, record := range rec.Result()[last].Records { - assert.Equal(t, tt.wantRecords[i].Body, record.Body()) - assert.Equal(t, tt.wantRecords[i].Severity, record.Severity()) + for _, s := range rec.Result() { + if k == s.Name { + assertRecords(t, want, s.Records) + found = true + } + } - var attributes []log.KeyValue - record.WalkAttributes(func(kv log.KeyValue) bool { - attributes = append(attributes, kv) - return true - }) - assert.Equal(t, tt.wantRecords[i].Attributes, attributes) + assert.Truef(t, found, "want to find records with a scope named %q", k) } }) } } -func TestLogSinkWithName(t *testing.T) { - rec := logtest.NewRecorder() - ls := NewLogSink("name", WithLoggerProvider(rec)) - lsWithName := ls.WithName("test") - require.NotEqual(t, ls, lsWithName) - require.Equal(t, lsWithName, ls.WithName("test")) +func buildRecord(body log.Value, timestamp time.Time, severity log.Severity, attrs []log.KeyValue) log.Record { + var record log.Record + record.SetBody(body) + record.SetTimestamp(timestamp) + record.SetSeverity(severity) + record.AddAttributes(attrs...) + + return record } -func TestLogSinkEnabled(t *testing.T) { - rec := logtest.NewRecorder( - logtest.WithEnabledFunc(func(ctx context.Context, record log.Record) bool { - return record.Severity() == log.SeverityInfo - }), - ) - ls := NewLogSink( - "name", - WithLoggerProvider(rec), - WithLevels([]log.Severity{log.SeverityDebug, log.SeverityInfo}), - ) +func assertRecords(t *testing.T, want, got []logtest.EmittedRecord) { + t.Helper() - assert.False(t, ls.Enabled(0)) - assert.True(t, ls.Enabled(1)) + assert.Equal(t, len(want), len(got)) + + for i, j := range want { + logtest.AssertRecordEqual(t, j.Record, got[i].Record) + } } From 52d467a9ca7abcf17ab94ad93c6ea4109f6dcbae Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 19 Sep 2024 20:26:13 +1200 Subject: [PATCH 4/8] use time.Unix const --- bridges/otellogr/convert_test.go | 6 ++---- bridges/otellogr/logsink_test.go | 5 ++--- 2 files changed, 4 insertions(+), 7 deletions(-) diff --git a/bridges/otellogr/convert_test.go b/bridges/otellogr/convert_test.go index 90018be212a..bec3f4c4405 100644 --- a/bridges/otellogr/convert_test.go +++ b/bridges/otellogr/convert_test.go @@ -80,8 +80,6 @@ func TestConvertKVs(t *testing.T) { } func TestConvertValue(t *testing.T) { - now := time.Now() - for _, tt := range []struct { name string value any @@ -179,8 +177,8 @@ func TestConvertValue(t *testing.T) { }, { name: "time.Time", - value: now, - wantValue: log.Int64Value(now.UnixNano()), + value: time.Unix(1000, 1000), + wantValue: log.Int64Value(time.Unix(1000, 1000).UnixNano()), }, { name: "[]byte", diff --git a/bridges/otellogr/logsink_test.go b/bridges/otellogr/logsink_test.go index 0ff5dd91227..0f8f55af1ea 100644 --- a/bridges/otellogr/logsink_test.go +++ b/bridges/otellogr/logsink_test.go @@ -114,7 +114,6 @@ func TestNewLogSink(t *testing.T) { func TestLogSink(t *testing.T) { const name = "name" - now := time.Now() for _, tt := range []struct { name string @@ -149,7 +148,7 @@ func TestLogSink(t *testing.T) { "float64", 3.14159, "int64", -2, "string", "str", - "time", now, + "time", time.Unix(1000, 1000), "uint64", uint64(3), ) }, @@ -162,7 +161,7 @@ func TestLogSink(t *testing.T) { log.Float64("float64", 3.14159), log.Int64("int64", -2), log.String("string", "str"), - log.Int64("time", now.UnixNano()), + log.Int64("time", time.Unix(1000, 1000).UnixNano()), log.Int64("uint64", 3), }), }, From 3fe7bb8189cff6beb877e6932521eec30a3adfdf Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 19 Sep 2024 20:27:46 +1200 Subject: [PATCH 5/8] Fix name --- bridges/otellogr/logsink_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/bridges/otellogr/logsink_test.go b/bridges/otellogr/logsink_test.go index 0f8f55af1ea..8b47f871313 100644 --- a/bridges/otellogr/logsink_test.go +++ b/bridges/otellogr/logsink_test.go @@ -69,7 +69,7 @@ func TestNewConfig(t *testing.T) { } func TestNewLogSink(t *testing.T) { - const name = "test_logsink" + const name = "name" for _, tt := range []struct { name string @@ -219,7 +219,7 @@ func TestLogSink(t *testing.T) { } { t.Run(tt.name, func(t *testing.T) { rec := logtest.NewRecorder() - ls := NewLogSink("name", WithLoggerProvider(rec)) + ls := NewLogSink(name, WithLoggerProvider(rec)) l := logr.New(ls) tt.f(&l) From ade9f4050f66bea9ce0e93a1ae1c9747145f4a69 Mon Sep 17 00:00:00 2001 From: CZ Date: Thu, 19 Sep 2024 22:54:29 +1200 Subject: [PATCH 6/8] optimise k.Kind() = string --- bridges/otellogr/convert.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/bridges/otellogr/convert.go b/bridges/otellogr/convert.go index 794e12729ba..31f65fca6cc 100644 --- a/bridges/otellogr/convert.go +++ b/bridges/otellogr/convert.go @@ -119,11 +119,11 @@ func convertValue(v any) log.Value { kvs := make([]log.KeyValue, 0, val.Len()) for _, k := range val.MapKeys() { var key string - // If the key is a struct, use %+v to print the struct fields. - if k.Kind() == reflect.Struct { + switch k.Kind() { + case reflect.String: + key = k.String() + default: key = fmt.Sprintf("%+v", k.Interface()) - } else { - key = fmt.Sprintf("%v", k.Interface()) } kvs = append(kvs, log.KeyValue{ Key: key, From d983fbe3563d4536870d79651efc2cea0c5fbb57 Mon Sep 17 00:00:00 2001 From: CZ Date: Fri, 20 Sep 2024 00:26:07 +1200 Subject: [PATCH 7/8] Update bridges/otellogr/convert.go MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Robert Pająk --- bridges/otellogr/convert.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bridges/otellogr/convert.go b/bridges/otellogr/convert.go index 31f65fca6cc..efbebb40c53 100644 --- a/bridges/otellogr/convert.go +++ b/bridges/otellogr/convert.go @@ -22,7 +22,7 @@ func convertKVs(ctx context.Context, keysAndValues ...any) (context.Context, []l return ctx, nil } if len(keysAndValues)%2 != 0 { - // Ensure an odd number of items here does not corrupt the list + // Ensure an odd number of items here does not corrupt the list. keysAndValues = append(keysAndValues, nil) } From aa0a7cb226da0dc8b0d974b548e4bda64b73958f Mon Sep 17 00:00:00 2001 From: CZ Date: Fri, 20 Sep 2024 00:26:14 +1200 Subject: [PATCH 8/8] Update bridges/otellogr/convert.go MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Robert Pająk --- bridges/otellogr/convert.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bridges/otellogr/convert.go b/bridges/otellogr/convert.go index efbebb40c53..35a79e5248f 100644 --- a/bridges/otellogr/convert.go +++ b/bridges/otellogr/convert.go @@ -30,7 +30,7 @@ func convertKVs(ctx context.Context, keysAndValues ...any) (context.Context, []l for i := 0; i < len(keysAndValues); i += 2 { k, ok := keysAndValues[i].(string) if !ok { - // Ensure that the key is a string + // Ensure that the key is a string. k = fmt.Sprintf("%v", keysAndValues[i]) }