1
0
mirror of https://github.com/open-telemetry/opentelemetry-go.git synced 2025-11-27 22:49:15 +02:00
Files
opentelemetry-go/sdk/log/logger_test.go
Robert Pająk 1ee7c79b73 sdk/log: Add FilterProcessor and EnabledParameters (#6317)
Per
https://github.com/open-telemetry/opentelemetry-go/pull/6271#issuecomment-2657554647

> We agreed that we can move `FilterProcessor` directly to `sdk/log` as
Logs SDK does not look to be stabilized soon.

- Add the possibility to filter based on the resource and scope which is
available for the SDK. The scope information is the most important as it
gives the possibility to e.g. filter out logs emitted for a given
logger. Thus e.g.
https://github.com/open-telemetry/opentelemetry-specification/issues/4364
is not necessary. See
https://github.com/open-telemetry/opentelemetry-specification/pull/4290#discussion_r1927546170
for more context.
- It is going be an example for
https://github.com/open-telemetry/opentelemetry-specification/issues/4363

There is a little overhead (IMO totally acceptable) because of data
transformation. Most importantly, there is no new heap allocation.

```
goos: linux
goarch: amd64
pkg: go.opentelemetry.io/otel/sdk/log
cpu: 13th Gen Intel(R) Core(TM) i7-13800H
                 │   old.txt   │                 new.txt                  │
                 │   sec/op    │     sec/op      vs base                  │
LoggerEnabled-20   4.589n ± 1%   319.750n ± 16%  +6867.75% (p=0.000 n=10)

                 │   old.txt    │             new.txt             │
                 │     B/op     │     B/op       vs base          │
LoggerEnabled-20   0.000Ki ± 0%   1.093Ki ± 13%  ? (p=0.000 n=10)

                 │  old.txt   │            new.txt             │
                 │ allocs/op  │ allocs/op   vs base            │
LoggerEnabled-20   0.000 ± 0%   0.000 ± 0%  ~ (p=1.000 n=10) ¹
¹ all samples are equal
```

`Logger.Enabled` is still more efficient than `Logger.Emit` (benchmarks
from https://github.com/open-telemetry/opentelemetry-go/pull/6315).

```
goos: linux
goarch: amd64
pkg: go.opentelemetry.io/otel/sdk/log
cpu: 13th Gen Intel(R) Core(TM) i7-13800H
BenchmarkLoggerEmit/5_attributes-20               559934              2391 ns/op           39088 B/op          1 allocs/op
BenchmarkLoggerEmit/10_attributes-20             1000000              5910 ns/op           49483 B/op          5 allocs/op
BenchmarkLoggerEnabled-20                        1605697               968.7 ns/op          1272 B/op          0 allocs/op
PASS
ok      go.opentelemetry.io/otel/sdk/log        10.789s
```

Prior art:
- https://github.com/open-telemetry/opentelemetry-go/pull/6271
- https://github.com/open-telemetry/opentelemetry-go/pull/6286

I also created for tracking purposes:
- https://github.com/open-telemetry/opentelemetry-go/issues/6328
2025-02-18 22:35:14 +01:00

310 lines
9.2 KiB
Go

// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
package log // import "go.opentelemetry.io/otel/sdk/log"
import (
"context"
"errors"
"testing"
"time"
"github.com/stretchr/testify/assert"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/log"
"go.opentelemetry.io/otel/sdk/instrumentation"
"go.opentelemetry.io/otel/sdk/resource"
"go.opentelemetry.io/otel/trace"
)
func TestLoggerEmit(t *testing.T) {
nowDate := time.Date(2010, time.January, 1, 0, 0, 0, 0, time.UTC)
nowSwap := now
t.Cleanup(func() {
now = nowSwap
})
now = func() time.Time {
return nowDate
}
p0, p1, p2WithError := newProcessor("0"), newProcessor("1"), newProcessor("2")
p2WithError.Err = errors.New("error")
r := log.Record{}
r.SetEventName("testing.name")
r.SetTimestamp(time.Date(2000, time.January, 1, 0, 0, 0, 0, time.UTC))
r.SetBody(log.StringValue("testing body value"))
r.SetSeverity(log.SeverityInfo)
r.SetSeverityText("testing text")
r.AddAttributes(
log.String("k1", "str"),
log.Float64("k2", 1.0),
)
r.SetObservedTimestamp(time.Date(2001, time.January, 1, 0, 0, 0, 0, time.UTC))
rWithNoObservedTimestamp := r
rWithNoObservedTimestamp.SetObservedTimestamp(time.Time{})
contextWithSpanContext := trace.ContextWithSpanContext(context.Background(), trace.NewSpanContext(trace.SpanContextConfig{
TraceID: trace.TraceID{0o1},
SpanID: trace.SpanID{0o2},
TraceFlags: 0x1,
}))
testCases := []struct {
name string
logger *logger
ctx context.Context
record log.Record
expectedRecords []Record
}{
{
name: "NoProcessors",
logger: newLogger(NewLoggerProvider(), instrumentation.Scope{}),
ctx: context.Background(),
record: r,
},
{
name: "WithProcessors",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithAttributeValueLengthLimit(3),
WithAttributeCountLimit(2),
WithResource(resource.NewSchemaless(attribute.String("key", "value"))),
), instrumentation.Scope{Name: "scope"}),
ctx: context.Background(),
record: r,
expectedRecords: []Record{
{
eventName: r.EventName(),
timestamp: r.Timestamp(),
body: r.Body(),
severity: r.Severity(),
severityText: r.SeverityText(),
observedTimestamp: r.ObservedTimestamp(),
resource: resource.NewSchemaless(attribute.String("key", "value")),
attributeValueLengthLimit: 3,
attributeCountLimit: 2,
scope: &instrumentation.Scope{Name: "scope"},
front: [attributesInlineCount]log.KeyValue{
log.String("k1", "str"),
log.Float64("k2", 1.0),
},
nFront: 2,
},
},
},
{
name: "WithProcessorsWithError",
logger: newLogger(NewLoggerProvider(
WithProcessor(p2WithError),
WithAttributeValueLengthLimit(3),
WithAttributeCountLimit(2),
WithResource(resource.NewSchemaless(attribute.String("key", "value"))),
), instrumentation.Scope{Name: "scope"}),
ctx: context.Background(),
},
{
name: "WithTraceSpanInContext",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithAttributeValueLengthLimit(3),
WithAttributeCountLimit(2),
WithResource(resource.NewSchemaless(attribute.String("key", "value"))),
), instrumentation.Scope{Name: "scope"}),
ctx: contextWithSpanContext,
record: r,
expectedRecords: []Record{
{
eventName: r.EventName(),
timestamp: r.Timestamp(),
body: r.Body(),
severity: r.Severity(),
severityText: r.SeverityText(),
observedTimestamp: r.ObservedTimestamp(),
resource: resource.NewSchemaless(attribute.String("key", "value")),
attributeValueLengthLimit: 3,
attributeCountLimit: 2,
scope: &instrumentation.Scope{Name: "scope"},
front: [attributesInlineCount]log.KeyValue{
log.String("k1", "str"),
log.Float64("k2", 1.0),
},
nFront: 2,
traceID: trace.TraceID{0o1},
spanID: trace.SpanID{0o2},
traceFlags: 0x1,
},
},
},
{
name: "WithNilContext",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithAttributeValueLengthLimit(3),
WithAttributeCountLimit(2),
WithResource(resource.NewSchemaless(attribute.String("key", "value"))),
), instrumentation.Scope{Name: "scope"}),
ctx: context.Background(),
record: r,
expectedRecords: []Record{
{
eventName: r.EventName(),
timestamp: r.Timestamp(),
body: r.Body(),
severity: r.Severity(),
severityText: r.SeverityText(),
observedTimestamp: r.ObservedTimestamp(),
resource: resource.NewSchemaless(attribute.String("key", "value")),
attributeValueLengthLimit: 3,
attributeCountLimit: 2,
scope: &instrumentation.Scope{Name: "scope"},
front: [attributesInlineCount]log.KeyValue{
log.String("k1", "str"),
log.Float64("k2", 1.0),
},
nFront: 2,
},
},
},
{
name: "NoObservedTimestamp",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithAttributeValueLengthLimit(3),
WithAttributeCountLimit(2),
WithResource(resource.NewSchemaless(attribute.String("key", "value"))),
), instrumentation.Scope{Name: "scope"}),
ctx: context.Background(),
record: rWithNoObservedTimestamp,
expectedRecords: []Record{
{
eventName: rWithNoObservedTimestamp.EventName(),
timestamp: rWithNoObservedTimestamp.Timestamp(),
body: rWithNoObservedTimestamp.Body(),
severity: rWithNoObservedTimestamp.Severity(),
severityText: rWithNoObservedTimestamp.SeverityText(),
observedTimestamp: nowDate,
resource: resource.NewSchemaless(attribute.String("key", "value")),
attributeValueLengthLimit: 3,
attributeCountLimit: 2,
scope: &instrumentation.Scope{Name: "scope"},
front: [attributesInlineCount]log.KeyValue{
log.String("k1", "str"),
log.Float64("k2", 1.0),
},
nFront: 2,
},
},
},
}
for _, tc := range testCases {
t.Run(tc.name, func(t *testing.T) {
// Clean up the records before the test.
p0.records = nil
p1.records = nil
tc.logger.Emit(tc.ctx, tc.record)
assert.Equal(t, tc.expectedRecords, p0.records)
assert.Equal(t, tc.expectedRecords, p1.records)
})
}
}
func TestLoggerEnabled(t *testing.T) {
p0 := newFltrProcessor("0", true)
p1 := newFltrProcessor("1", true)
p2WithDisabled := newFltrProcessor("2", false)
emptyResource := resource.Empty()
res := resource.NewSchemaless(attribute.String("key", "value"))
testCases := []struct {
name string
logger *logger
ctx context.Context
expected bool
expectedP0Params []EnabledParameters
expectedP1Params []EnabledParameters
expectedP2Params []EnabledParameters
}{
{
name: "NoProcessors",
logger: newLogger(NewLoggerProvider(), instrumentation.Scope{}),
ctx: context.Background(),
expected: false,
},
{
name: "WithProcessors",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithResource(res),
), instrumentation.Scope{Name: "scope"}),
ctx: context.Background(),
expected: true,
expectedP0Params: []EnabledParameters{{
Resource: *res,
InstrumentationScope: instrumentation.Scope{Name: "scope"},
}},
expectedP1Params: nil,
},
{
name: "WithDisabledProcessors",
logger: newLogger(NewLoggerProvider(
WithProcessor(p2WithDisabled),
WithResource(emptyResource),
), instrumentation.Scope{}),
ctx: context.Background(),
expected: false,
expectedP2Params: []EnabledParameters{{}},
},
{
name: "ContainsDisabledProcessor",
logger: newLogger(NewLoggerProvider(
WithProcessor(p2WithDisabled),
WithProcessor(p0),
WithResource(emptyResource),
), instrumentation.Scope{}),
ctx: context.Background(),
expected: true,
expectedP2Params: []EnabledParameters{{}},
expectedP0Params: []EnabledParameters{{}},
},
{
name: "WithNilContext",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
WithResource(emptyResource),
), instrumentation.Scope{}),
ctx: nil,
expected: true,
expectedP0Params: []EnabledParameters{{}},
expectedP1Params: nil,
},
}
for _, tc := range testCases {
t.Run(tc.name, func(t *testing.T) {
// Clean up the records before the test.
p0.params = nil
p1.params = nil
p2WithDisabled.params = nil
assert.Equal(t, tc.expected, tc.logger.Enabled(tc.ctx, log.EnabledParameters{}))
assert.Equal(t, tc.expectedP0Params, p0.params)
assert.Equal(t, tc.expectedP1Params, p1.params)
assert.Equal(t, tc.expectedP2Params, p2WithDisabled.params)
})
}
}