1
0
mirror of https://github.com/open-telemetry/opentelemetry-go.git synced 2025-02-03 13:11:53 +02:00
opentelemetry-go/sdk/log/logger_test.go
Tyler Yahn 002c0a4c03
Move log.Processor.Enabled to independent FilterProcessor interfaced type (#5692)
Closes #5425 

Our current log `Processor` interface contains more functionality than
the [OTel
spec](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/sdk.md#logrecordprocessor-operations).
The additional functionality allows processors to report back to the API
if a Record should be constructed and emitted or not, which is quite
helpful[^1][^2][^3][^4][^5].

This removes the `Enabled` method from the `Processor` type. It adds
this functionality a new optional and experimental `FilterProcessor`
interface type. The logger and provider are updated to check for this
optional interface to be implemented with the configured processors and
uses them to back the `Logger.Enabled` method, preserving existing
functionality.

By making this change:

- The `Processor` interface is now compliant with the OTel spec and does
not contain any additional unspecified behavior.
- All `Processor` implementations are no longer required to implement an
`Enabled` method. The default, when they do not implement this method,
is to assume they are enabled.

### Benchmark

```terminal
goos: linux
goarch: amd64
pkg: go.opentelemetry.io/otel/sdk/log
cpu: Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz
                │   old.txt    │              new7.txt               │
                │    sec/op    │   sec/op     vs base                │
LoggerEnabled-8   133.30n ± 3%   32.36n ± 3%  -75.72% (p=0.000 n=10)

                │  old.txt   │            new7.txt            │
                │    B/op    │    B/op     vs base            │
LoggerEnabled-8   0.000 ± 0%   0.000 ± 0%  ~ (p=1.000 n=10) ¹
¹ all samples are equal

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

This is a significant performance improvement due to the `Record` no
longer being converted from the API version to the SDK version.

[^1]: https://pkg.go.dev/go.opentelemetry.io/contrib/processors/minsev
[^2]:
https://pkg.go.dev/go.opentelemetry.io/otel/sdk/log#BatchProcessor.Enabled
[^3]:
https://pkg.go.dev/go.opentelemetry.io/otel/sdk/log#SimpleProcessor.Enabled
[^4]:
af75717ac4/bridges/otelslog/handler.go (L206-L211)
[^5]:
d0309ddd8c/bridges/otelzap/core.go (L142-L146)

---------

Co-authored-by: Robert Pająk <pellared@hotmail.com>
Co-authored-by: Sam Xie <sam@samxie.me>
2024-08-22 09:12:23 -07:00

298 lines
8.3 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.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{
{
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{
{
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{
{
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{
{
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)
testCases := []struct {
name string
logger *logger
ctx context.Context
expected bool
}{
{
name: "NoProcessors",
logger: newLogger(NewLoggerProvider(), instrumentation.Scope{}),
ctx: context.Background(),
expected: false,
},
{
name: "WithProcessors",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
), instrumentation.Scope{}),
ctx: context.Background(),
expected: true,
},
{
name: "WithDisabledProcessors",
logger: newLogger(NewLoggerProvider(
WithProcessor(p2WithDisabled),
), instrumentation.Scope{}),
ctx: context.Background(),
expected: false,
},
{
name: "ContainsDisabledProcessor",
logger: newLogger(NewLoggerProvider(
WithProcessor(p2WithDisabled),
WithProcessor(p0),
), instrumentation.Scope{}),
ctx: context.Background(),
expected: true,
},
{
name: "WithNilContext",
logger: newLogger(NewLoggerProvider(
WithProcessor(p0),
WithProcessor(p1),
), instrumentation.Scope{}),
ctx: nil,
expected: true,
},
}
for _, tc := range testCases {
t.Run(tc.name, func(t *testing.T) {
assert.Equal(t, tc.expected, tc.logger.Enabled(tc.ctx, log.Record{}))
})
}
}
func BenchmarkLoggerEnabled(b *testing.B) {
provider := NewLoggerProvider(
WithProcessor(newFltrProcessor("0", false)),
WithProcessor(newFltrProcessor("1", true)),
)
logger := provider.Logger("BenchmarkLoggerEnabled")
ctx, r := context.Background(), log.Record{}
r.SetSeverityText("test")
var enabled bool
b.ReportAllocs()
b.ResetTimer()
for n := 0; n < b.N; n++ {
enabled = logger.Enabled(ctx, r)
}
_ = enabled
}