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

282 lines
8.1 KiB
Go
Raw Normal View History

// 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) {
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]: https://github.com/open-telemetry/opentelemetry-go-contrib/blob/af75717ac4fb3ba13eaea83b88301723122060cf/bridges/otelslog/handler.go#L206-L211 [^5]: https://github.com/open-telemetry/opentelemetry-go-contrib/blob/d0309ddd8c5714af1cd9dbe8b39b7e8f10485679/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
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) {
log: Introduce EnabledParameters (#5791) Fixes https://github.com/open-telemetry/opentelemetry-go/issues/5769 Related spec PR: https://github.com/open-telemetry/opentelemetry-specification/pull/4203 Remark: A follow-up in contrib is required and afterwards here to fix the `example/dice`. Benchstat results for `sdk/log` (`log` has no benchmarks related to Enabled): ``` goos: linux goarch: amd64 pkg: go.opentelemetry.io/otel/sdk/log cpu: Intel(R) Core(TM) i9-10885H CPU @ 2.40GHz │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ BatchProcessorOnEmit-16 398.8n ± 10% 395.6n ± 12% ~ (p=0.971 n=10) Processor/Simple-16 882.2n ± 8% 869.8n ± 9% ~ (p=0.811 n=10) Processor/Batch-16 1.478µ ± 3% 1.485µ ± 5% ~ (p=0.646 n=10) Processor/SetTimestampSimple-16 847.8n ± 1% 844.6n ± 3% ~ (p=0.247 n=10) Processor/SetTimestampBatch-16 1.480µ ± 3% 1.473µ ± 4% ~ (p=0.700 n=10) Processor/AddAttributesSimple-16 930.0n ± 1% 933.8n ± 1% ~ (p=0.172 n=10) Processor/AddAttributesBatch-16 1.624µ ± 2% 1.639µ ± 2% ~ (p=0.839 n=10) Processor/SetAttributesSimple-16 903.4n ± 1% 895.1n ± 1% ~ (p=0.190 n=10) Processor/SetAttributesBatch-16 1.554µ ± 4% 1.529µ ± 3% ~ (p=0.159 n=10) LoggerNewRecord/5_attributes-16 346.0n ± 2% 343.3n ± 2% ~ (p=0.448 n=10) LoggerNewRecord/10_attributes-16 1.608µ ± 6% 1.503µ ± 2% -6.53% (p=0.007 n=10) LoggerEnabled-16 34.305n ± 8% 6.706n ± 1% -80.45% (p=0.000 n=10) LoggerProviderLogger-16 636.9n ± 10% 605.8n ± 3% ~ (p=0.105 n=10) WalkAttributes/1_attributes-16 5.363n ± 3% 4.540n ± 14% -15.34% (p=0.002 n=10) WalkAttributes/10_attributes-16 5.436n ± 7% 4.461n ± 2% -17.95% (p=0.000 n=10) WalkAttributes/100_attributes-16 5.126n ± 9% 4.465n ± 1% -12.90% (p=0.000 n=10) WalkAttributes/1000_attributes-16 5.316n ± 9% 4.502n ± 5% -15.32% (p=0.002 n=10) SetAddAttributes/SetAttributes-16 220.5n ± 18% 192.6n ± 11% -12.67% (p=0.007 n=10) SetAddAttributes/AddAttributes-16 165.3n ± 21% 127.3n ± 22% -22.96% (p=0.011 n=10) SimpleProcessorOnEmit-16 2.159n ± 9% 2.167n ± 9% ~ (p=0.739 n=10) geomean 178.3n 154.5n -13.31% │ old.txt │ new.txt │ │ B/s │ B/s vs base │ BatchProcessorOnEmit-16 76.52Mi ± 11% 77.14Mi ± 14% ~ (p=0.971 n=10) │ old.txt │ new.txt │ │ B/op │ B/op vs base │ BatchProcessorOnEmit-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/Simple-16 417.0 ± 0% 417.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/Batch-16 1.093Ki ± 1% 1.088Ki ± 1% ~ (p=0.254 n=10) Processor/SetTimestampSimple-16 417.0 ± 0% 417.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampBatch-16 1.095Ki ± 1% 1.084Ki ± 2% ~ (p=0.361 n=10) Processor/AddAttributesSimple-16 417.0 ± 0% 417.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesBatch-16 1.085Ki ± 1% 1.086Ki ± 1% ~ (p=1.000 n=10) Processor/SetAttributesSimple-16 465.0 ± 0% 465.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesBatch-16 1.129Ki ± 1% 1.125Ki ± 1% ~ (p=0.084 n=10) LoggerNewRecord/5_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerNewRecord/10_attributes-16 610.0 ± 0% 610.0 ± 0% ~ (p=1.000 n=10) ¹ LoggerEnabled-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerProviderLogger-16 359.0 ± 6% 346.0 ± 3% ~ (p=0.117 n=10) WalkAttributes/1_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/10_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/100_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/1000_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SetAddAttributes/SetAttributes-16 48.00 ± 0% 48.00 ± 0% ~ (p=1.000 n=10) ¹ SetAddAttributes/AddAttributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SimpleProcessorOnEmit-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ geomean ² -0.27% ² ¹ all samples are equal ² summaries must be >0 to compute geomean │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ BatchProcessorOnEmit-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/Simple-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/Batch-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampSimple-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampBatch-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesSimple-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesBatch-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesSimple-16 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesBatch-16 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerNewRecord/5_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerNewRecord/10_attributes-16 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerEnabled-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ LoggerProviderLogger-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/1_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/10_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/100_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ WalkAttributes/1000_attributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SetAddAttributes/SetAttributes-16 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ SetAddAttributes/AddAttributes-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SimpleProcessorOnEmit-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ geomean ² +0.00% ² ¹ all samples are equal ² summaries must be >0 to compute geomean ```
2024-09-13 06:35:01 +02:00
assert.Equal(t, tc.expected, tc.logger.Enabled(tc.ctx, log.EnabledParameters{}))
})
}
}