diff --git a/log/event.go b/log/event.go new file mode 100644 index 00000000000..7b69e8144ca --- /dev/null +++ b/log/event.go @@ -0,0 +1,129 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +package log // import "go.opentelemetry.io/otel/log" + +import ( + "slices" + "time" +) + +// eventAttributesInlineCount is the number of attributes that are efficiently +// stored in an array within an Event. +const eventAttributesInlineCount = 5 + +// Event represents an event record. +type Event struct { + // Ensure forward compatibility by explicitly making this not comparable. + noCmp [0]func() //nolint: unused // This is indeed used. + + timestamp time.Time + observedTimestamp time.Time + severity Severity + severityText string + body Value + + // The fields below are for optimizing the implementation of Attributes and + // AddAttributes. This design is borrowed from the slog Record type: + // https://cs.opensource.google/go/go/+/refs/tags/go1.22.0:src/log/slog/record.go;l=20 + + // Allocation optimization: an inline array sized to hold + // the majority of event calls (based on examination of + // OpenTelemetry Semantic Conventions for Events). + // It holds the start of the list of attributes. + front [eventAttributesInlineCount]KeyValue + + // The number of attributes in front. + nFront int + + // The list of attributes except for those in front. + // Invariants: + // - len(back) > 0 if nFront == len(front) + // - Unused array elements are zero-ed. Used to detect mistakes. + back []KeyValue +} + +// Timestamp returns the time when the event occurred. +func (r *Event) Timestamp() time.Time { + return r.timestamp +} + +// SetTimestamp sets the time when the event occurred. +func (r *Event) SetTimestamp(t time.Time) { + r.timestamp = t +} + +// ObservedTimestamp returns the time when the event was observed. +func (r *Event) ObservedTimestamp() time.Time { + return r.observedTimestamp +} + +// SetObservedTimestamp sets the time when the event was observed. +func (r *Event) SetObservedTimestamp(t time.Time) { + r.observedTimestamp = t +} + +// Severity returns the [Severity] of the event. +func (r *Event) Severity() Severity { + return r.severity +} + +// SetSeverity sets the [Severity] level of the event. +func (r *Event) SetSeverity(level Severity) { + r.severity = level +} + +// SeverityText returns severity (also known as log level) text. This is the +// original string representation of the severity as it is known at the source. +func (r *Event) SeverityText() string { + return r.severityText +} + +// SetSeverityText sets severity (also known as log level) text. This is the +// original string representation of the severity as it is known at the source. +func (r *Event) SetSeverityText(text string) { + r.severityText = text +} + +// Body returns the body of the event. +func (r *Event) Body() Value { + return r.body +} + +// SetBody sets the body of the event. +func (r *Event) SetBody(v Value) { + r.body = v +} + +// WalkAttributes walks all attributes the event holds by calling f for +// each on each [KeyValue] in the [Record]. Iteration stops if f returns false. +func (r *Event) WalkAttributes(f func(KeyValue) bool) { + for i := 0; i < r.nFront; i++ { + if !f(r.front[i]) { + return + } + } + for _, a := range r.back { + if !f(a) { + return + } + } +} + +// AddAttributes adds attributes to the event. +func (r *Event) AddAttributes(attrs ...KeyValue) { + var i int + for i = 0; i < len(attrs) && r.nFront < len(r.front); i++ { + a := attrs[i] + r.front[r.nFront] = a + r.nFront++ + } + + r.back = slices.Grow(r.back, len(attrs[i:])) + r.back = append(r.back, attrs[i:]...) +} + +// AttributesLen returns the number of attributes in the event. +func (r *Event) AttributesLen() int { + return r.nFront + len(r.back) +} diff --git a/log/event_bench_test.go b/log/event_bench_test.go new file mode 100644 index 00000000000..b7dd8b072b1 --- /dev/null +++ b/log/event_bench_test.go @@ -0,0 +1,109 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +package log_test + +import ( + "testing" + "time" + + "go.opentelemetry.io/otel/log" +) + +func BenchmarkEvent(b *testing.B) { + var ( + tStamp time.Time + sev log.Severity + text string + body log.Value + attr log.KeyValue + n int + ) + + b.Run("Timestamp", func(b *testing.B) { + b.ReportAllocs() + for n := 0; n < b.N; n++ { + var e log.Event + e.SetTimestamp(y2k) + tStamp = e.Timestamp() + } + }) + + b.Run("ObservedTimestamp", func(b *testing.B) { + b.ReportAllocs() + for n := 0; n < b.N; n++ { + var e log.Event + e.SetObservedTimestamp(y2k) + tStamp = e.ObservedTimestamp() + } + }) + + b.Run("Severity", func(b *testing.B) { + b.ReportAllocs() + for n := 0; n < b.N; n++ { + var e log.Event + e.SetSeverity(log.SeverityDebug) + sev = e.Severity() + } + }) + + b.Run("SeverityText", func(b *testing.B) { + b.ReportAllocs() + for n := 0; n < b.N; n++ { + var e log.Event + e.SetSeverityText("text") + text = e.SeverityText() + } + }) + + bodyVal := log.BoolValue(true) + b.Run("Body", func(b *testing.B) { + b.ReportAllocs() + for n := 0; n < b.N; n++ { + var e log.Event + e.SetBody(bodyVal) + body = e.Body() + } + }) + + attrs10 := []log.KeyValue{ + log.Bool("b1", true), + log.Int("i1", 324), + log.Float64("f1", -230.213), + log.String("s1", "value1"), + log.Map("m1", log.Slice("slice1", log.BoolValue(true))), + log.Bool("b2", false), + log.Int("i2", 39847), + log.Float64("f2", 0.382964329), + log.String("s2", "value2"), + log.Map("m2", log.Slice("slice2", log.BoolValue(false))), + } + attrs5 := attrs10[:5] + walk := func(kv log.KeyValue) bool { + attr = kv + return true + } + b.Run("Attributes", func(b *testing.B) { + b.Run("5", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + var e log.Event + e.AddAttributes(attrs5...) + n = e.AttributesLen() + e.WalkAttributes(walk) + } + }) + b.Run("10", func(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + var e log.Event + e.AddAttributes(attrs10...) + n = e.AttributesLen() + e.WalkAttributes(walk) + } + }) + }) + + // Convince the linter these values are used. + _, _, _, _, _, _ = tStamp, sev, text, body, attr, n +} diff --git a/log/event_test.go b/log/event_test.go new file mode 100644 index 00000000000..6115814e5e6 --- /dev/null +++ b/log/event_test.go @@ -0,0 +1,152 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +package log_test + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "go.opentelemetry.io/otel/log" +) + +func TestEventTimestamp(t *testing.T) { + var e log.Event + e.SetTimestamp(y2k) + assert.Equal(t, y2k, e.Timestamp()) +} + +func TestEventObservedTimestamp(t *testing.T) { + var e log.Event + e.SetObservedTimestamp(y2k) + assert.Equal(t, y2k, e.ObservedTimestamp()) +} + +func TestEventSeverity(t *testing.T) { + var e log.Event + e.SetSeverity(log.SeverityInfo) + assert.Equal(t, log.SeverityInfo, e.Severity()) +} + +func TestEventSeverityText(t *testing.T) { + const text = "testing text" + + var e log.Event + e.SetSeverityText(text) + assert.Equal(t, text, e.SeverityText()) +} + +func TestEventBody(t *testing.T) { + body := log.StringValue("testing body value") + + var e log.Event + e.SetBody(body) + assert.Equal(t, body, e.Body()) +} + +func TestEventAttributes(t *testing.T) { + attrs := []log.KeyValue{ + log.String("k1", "str"), + log.Float64("k2", 1.0), + log.Int("k3", 2), + log.Bool("k4", true), + log.Bytes("k5", []byte{1}), + log.Slice("k6", log.IntValue(3)), + log.Map("k7", log.Bool("sub1", true)), + log.String("k8", "str"), + log.Float64("k9", 1.0), + log.Int("k10", 2), + log.Bool("k11", true), + log.Bytes("k12", []byte{1}), + log.Slice("k13", log.IntValue(3)), + log.Map("k14", log.Bool("sub1", true)), + {}, // Empty. + } + + var e log.Event + e.AddAttributes(attrs...) + require.Equal(t, len(attrs), e.AttributesLen()) + + t.Run("Correctness", func(t *testing.T) { + var i int + e.WalkAttributes(func(kv log.KeyValue) bool { + assert.Equal(t, attrs[i], kv) + i++ + return true + }) + }) + + t.Run("WalkAttributes/Filtering", func(t *testing.T) { + for i := 1; i <= len(attrs); i++ { + var j int + e.WalkAttributes(func(log.KeyValue) bool { + j++ + return j < i + }) + assert.Equal(t, i, j, "number of attributes walked incorrect") + } + }) +} + +func TestEventAllocationLimits(t *testing.T) { + const runs = 5 + + // Assign testing results to external scope so the compiler doesn't + // optimize away the testing statements. + var ( + tStamp time.Time + sev log.Severity + text string + body log.Value + n int + attr log.KeyValue + ) + + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.SetTimestamp(y2k) + tStamp = e.Timestamp() + }), "Timestamp") + + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.SetObservedTimestamp(y2k) + tStamp = e.ObservedTimestamp() + }), "ObservedTimestamp") + + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.SetSeverity(log.SeverityDebug) + sev = e.Severity() + }), "Severity") + + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.SetSeverityText("severity text") + text = e.SeverityText() + }), "SeverityText") + + bodyVal := log.BoolValue(true) + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.SetBody(bodyVal) + body = e.Body() + }), "Body") + + attrVal := []log.KeyValue{log.Bool("k", true), log.Int("i", 1)} + assert.Equal(t, 0.0, testing.AllocsPerRun(runs, func() { + var e log.Event + e.AddAttributes(attrVal...) + n = e.AttributesLen() + e.WalkAttributes(func(kv log.KeyValue) bool { + attr = kv + return true + }) + }), "Attributes") + + // Convince the linter these values are used. + _, _, _, _, _, _ = tStamp, sev, text, body, n, attr +} diff --git a/log/internal/global/log.go b/log/internal/global/log.go index d97ee966350..76269ed684a 100644 --- a/log/internal/global/log.go +++ b/log/internal/global/log.go @@ -102,6 +102,20 @@ func (l *logger) Enabled(ctx context.Context, param log.EnabledParameters) bool return enabled } +func (l *logger) EmitEvent(ctx context.Context, eventName string, e log.Event) { + if del, ok := l.delegate.Load().(log.Logger); ok { + del.EmitEvent(ctx, eventName, e) + } +} + +func (l *logger) EnabledEvent(ctx context.Context, eventName string, param log.EnabledEventParameters) bool { + var enabled bool + if del, ok := l.delegate.Load().(log.Logger); ok { + enabled = del.EnabledEvent(ctx, eventName, param) + } + return enabled +} + func (l *logger) setDelegate(provider log.LoggerProvider) { l.delegate.Store(provider.Logger(l.name, l.options...)) } diff --git a/log/internal/global/log_test.go b/log/internal/global/log_test.go index ae2c5b2a6dd..7f702ace53a 100644 --- a/log/internal/global/log_test.go +++ b/log/internal/global/log_test.go @@ -99,7 +99,7 @@ func (p *testLoggerProvider) Logger(name string, _ ...log.LoggerOption) log.Logg } type testLogger struct { - embedded.Logger + log.Logger emitN, enabledN int } diff --git a/log/logger.go b/log/logger.go index 0773a49b608..a562d04de04 100644 --- a/log/logger.go +++ b/log/logger.go @@ -33,8 +33,8 @@ type Logger interface { // Is should not be used for writing instrumentation. Emit(ctx context.Context, record Record) - // Enabled returns whether the Logger emits for the given context and - // param. + // Enabled returns whether the Logger emits a log record for the given + // context and param. // // The passed param is likely to be a partial record with only the // bridge-relevant information being provided (e.g a param with only the @@ -57,6 +57,36 @@ type Logger interface { // Notice: Enabled is intended to be used by log bridges. // Is should not be used for writing instrumentation. Enabled(ctx context.Context, param EnabledParameters) bool + + // EmitEvent emits an event. + // + // The event may be held by the implementation. Callers should not mutate + // the event after passed. + // + // Implementations of this method need to be safe for a user to call + // concurrently. + // + // Notice: EmitEvent is intended to be used for writing instrumentation. + EmitEvent(ctx context.Context, eventName string, event Event) + + // EnabledEvent returns whether the Logger emits an event for the given + // context, eventName, and param. + // + // The returned value will be true when the Logger will emit for the + // provided context and param, and will be false if the Logger will not + // emit. The returned value may be true or false in an indeterminate state. + // An implementation should default to returning true for an indeterminate + // state, but may return false if valid reasons in particular circumstances + // exist (e.g. performance, correctness). + // + // The param should not be held by the implementation. A copy should be + // made if the record needs to be held after the call returns. + // + // Implementations of this method need to be safe for a user to call + // concurrently. + // + // Notice: EnabledEvent is intended to be used for writing instrumentation. + EnabledEvent(ctx context.Context, eventName string, param EnabledEventParameters) bool } // LoggerOption applies configuration options to a [Logger]. @@ -140,3 +170,8 @@ func WithSchemaURL(schemaURL string) LoggerOption { type EnabledParameters struct { Severity Severity } + +// EnabledEventParameters represents payload for [Logger]'s Enabled method. +type EnabledEventParameters struct { + Severity Severity +} diff --git a/log/logtest/recorder.go b/log/logtest/recorder.go index fd986c9afc4..3a7d4f4c39d 100644 --- a/log/logtest/recorder.go +++ b/log/logtest/recorder.go @@ -73,6 +73,10 @@ type ScopeRecords struct { // Records are the log records, and their associated context this // instrumentation scope recorded. Records []EmittedRecord + + // Events are the events, and their associated context this + // instrumentation scope recorded. + Events []EmittedEvent } // EmittedRecord holds a log record the instrumentation received, alongside its @@ -88,6 +92,25 @@ func (rwc EmittedRecord) Context() context.Context { return rwc.ctx } +// EmittedEvent holds an event the instrumentation received, alongside its +// context and event name. +type EmittedEvent struct { + log.Event + + ctx context.Context + eventName string +} + +// Context provides the context emitted with the event. +func (rwc EmittedEvent) Context() context.Context { + return rwc.ctx +} + +// EventName provides the context emitted with the event. +func (rwc EmittedEvent) EventName() string { + return rwc.eventName +} + // Recorder is a recorder that stores all received log records // in-memory. type Recorder struct { @@ -182,3 +205,17 @@ func (l *logger) Reset() { l.scopeRecord.Records = nil } + +// Enabled indicates whether a specific event should be stored. +func (l *logger) EnabledEvent(ctx context.Context, eventName string, opts log.EnabledEventParameters) bool { + // TODO: + return true +} + +// EmitEvent stores the event. +func (l *logger) EmitEvent(ctx context.Context, eventName string, event log.Event) { + l.mu.Lock() + defer l.mu.Unlock() + + l.scopeRecord.Events = append(l.scopeRecord.Events, EmittedEvent{event, ctx, eventName}) +} diff --git a/log/noop/noop.go b/log/noop/noop.go index f45a7c7e0b3..4f850e065a1 100644 --- a/log/noop/noop.go +++ b/log/noop/noop.go @@ -48,3 +48,9 @@ func (Logger) Emit(context.Context, log.Record) {} // Enabled returns false. No log records are ever emitted. func (Logger) Enabled(context.Context, log.EnabledParameters) bool { return false } + +// EmitEvent does nothing. +func (Logger) EmitEvent(context.Context, string, log.Event) {} + +// EnabledEvent returns false. No events are ever emitted. +func (Logger) EnabledEvent(context.Context, string, log.EnabledEventParameters) bool { return false } diff --git a/sdk/log/logger.go b/sdk/log/logger.go index d6ca2ea41aa..e4b87071496 100644 --- a/sdk/log/logger.go +++ b/sdk/log/logger.go @@ -58,6 +58,31 @@ func (l *logger) Enabled(ctx context.Context, param log.EnabledParameters) bool return len(l.provider.processors) > len(fltrs) || anyEnabled(ctx, param, fltrs) } +func (l *logger) EmitEvent(ctx context.Context, eventName string, r log.Event) { + newRecord := l.newEvent(ctx, eventName, r) + for _, p := range l.provider.processors { + if err := p.OnEmit(ctx, &newRecord); err != nil { + otel.Handle(err) + } + } +} + +// EnabledEvent returns true if at least one Processor held by the LoggerProvider +// that created the logger will process param for the provided context and param. +// +// If it is not possible to definitively determine the param will be +// processed, true will be returned by default. A value of false will only be +// returned if it can be positively verified that no Processor will process. +func (l *logger) EnabledEvent(ctx context.Context, eventName string, param log.EnabledEventParameters) bool { + fltrs := l.provider.filterProcessors() + // If there are more Processors than FilterProcessors we cannot be sure + // that all Processors will drop the record. Therefore, return true. + // + // If all Processors are FilterProcessors, check if any is enabled. + + return len(l.provider.processors) > len(fltrs) || anyEnabled(ctx, log.EnabledParameters(param), fltrs) +} + func anyEnabled(ctx context.Context, param log.EnabledParameters, fltrs []x.FilterProcessor) bool { for _, f := range fltrs { if f.Enabled(ctx, param) { @@ -101,3 +126,38 @@ func (l *logger) newRecord(ctx context.Context, r log.Record) Record { return newRecord } + +func (l *logger) newEvent(ctx context.Context, name string, e log.Event) Record { + sc := trace.SpanContextFromContext(ctx) + + newRecord := Record{ + eventName: name, + + timestamp: e.Timestamp(), + observedTimestamp: e.ObservedTimestamp(), + severity: e.Severity(), + severityText: e.SeverityText(), + body: e.Body(), + + traceID: sc.TraceID(), + spanID: sc.SpanID(), + traceFlags: sc.TraceFlags(), + + resource: l.provider.resource, + scope: &l.instrumentationScope, + attributeValueLengthLimit: l.provider.attributeValueLengthLimit, + attributeCountLimit: l.provider.attributeCountLimit, + } + + // This field SHOULD be set once the event is observed by OpenTelemetry. + if newRecord.observedTimestamp.IsZero() { + newRecord.observedTimestamp = now() + } + + e.WalkAttributes(func(kv log.KeyValue) bool { + newRecord.AddAttributes(kv) + return true + }) + + return newRecord +} diff --git a/sdk/log/record.go b/sdk/log/record.go index 155e4cad2b6..b0b0f10adbf 100644 --- a/sdk/log/record.go +++ b/sdk/log/record.go @@ -50,6 +50,8 @@ type Record struct { // Do not embed the log.Record. Attributes need to be overwrite-able and // deep-copying needs to be possible. + eventName string + timestamp time.Time observedTimestamp time.Time severity log.Severity @@ -104,6 +106,18 @@ func (r *Record) setDropped(n int) { r.dropped = n } +// EventName returns the event name. +// A log record with non-empty event name is interpreted as an event record. +func (r *Record) EventName() string { + return r.eventName +} + +// SetEventName sets the event name. +// A log record with non-empty event name is interpreted as an event record. +func (r *Record) SetEventName(s string) { + r.eventName = s +} + // Timestamp returns the time when the log record occurred. func (r *Record) Timestamp() time.Time { return r.timestamp