Skip to content

sdk/log: Dedup and limits are not concurrent safe #7364

@varkey98

Description

@varkey98

Component

Instrumentation: host

Describe the issue you're facing

Let me apologize first for marking the wrong component, couldn't find the right one from the list.

Getting a data race flagged when building custom otel-collector with otelzap bridge exporting the log.

Full stack trace:

WARNING: DATA RACE
Read at 0x00c000233ae0 by main goroutine:
  go.opentelemetry.io/otel/sdk/log.dedup()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:349 +0x140
  go.opentelemetry.io/otel/sdk/log.(*Record).applyValueLimits()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:448 +0x180
  go.opentelemetry.io/otel/sdk/log.(*Record).applyAttrLimits()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:425 +0x150
  go.opentelemetry.io/otel/sdk/log.(*Record).addAttrs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:297 +0x48
  go.opentelemetry.io/otel/sdk/log.(*Record).AddAttributes()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:267 +0x3f4
  go.opentelemetry.io/otel/sdk/log.(*logger).newRecord.func1()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:135 +0x574
  go.opentelemetry.io/otel/log.(*Record).WalkAttributes()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/[email protected]/record.go:117 +0x4d4
  go.opentelemetry.io/otel/sdk/log.(*logger).newRecord()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:134 +0x4cc
  go.opentelemetry.io/otel/sdk/log.(*logger).Emit()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:61 +0x74
  go.opentelemetry.io/contrib/bridges/otelzap.(*Core).Write()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/contrib/bridges/[email protected]/core.go:238 +0x4e0
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /Users/varkeychanjacob/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:253 +0x158
  go.uber.org/zap.(*Logger).Info()
      /Users/varkeychanjacob/go/pkg/mod/go.uber.org/[email protected]/logger.go:247 +0x5c
  go.opentelemetry.io/collector/otelcol.(*Collector).Run()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/collector.go:358 +0x5f4
  go.opentelemetry.io/collector/otelcol.(*Collector).Run()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/collector.go:312 +0x44
  main.main()
      /Users/varkeychanjacob/Projects/gologgertest/main.go:46 +0x6dc

Previous write at 0x00c000233ae0 by goroutine 64:
  go.opentelemetry.io/otel/sdk/log.(*Record).applyValueLimits()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:452 +0x43c
  go.opentelemetry.io/otel/sdk/log.(*Record).applyAttrLimits()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:425 +0x150
  go.opentelemetry.io/otel/sdk/log.(*Record).addAttrs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:297 +0x48
  go.opentelemetry.io/otel/sdk/log.(*Record).AddAttributes()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/record.go:267 +0x3f4
  go.opentelemetry.io/otel/sdk/log.(*logger).newRecord.func1()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:135 +0x574
  go.opentelemetry.io/otel/log.(*Record).WalkAttributes()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/[email protected]/record.go:117 +0x4d4
  go.opentelemetry.io/otel/sdk/log.(*logger).newRecord()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:134 +0x4cc
  go.opentelemetry.io/otel/sdk/log.(*logger).Emit()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/otel/sdk/[email protected]/logger.go:61 +0x74
  go.opentelemetry.io/contrib/bridges/otelzap.(*Core).Write()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/contrib/bridges/[email protected]/core.go:238 +0x4e0
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /Users/varkeychanjacob/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:253 +0x158
  go.uber.org/zap.(*Logger).Info()
      /Users/varkeychanjacob/go/pkg/mod/go.uber.org/[email protected]/logger.go:247 +0x5c
  go.opentelemetry.io/collector/exporter/debugexporter.(*debugExporter).pushLogs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/exporter.go:101 +0x244
  go.opentelemetry.io/collector/exporter/debugexporter.(*debugExporter).pushLogs-fm()
      <autogenerated>:1 +0x5c
  go.opentelemetry.io/collector/consumer.ConsumeLogsFunc.ConsumeLogs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/logs.go:27 +0x58
  go.opentelemetry.io/collector/exporter/exporterhelper.NewLogs.requestConsumeFromLogs.func2()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/logs.go:160 +0x74
  go.opentelemetry.io/collector/exporter/exporterhelper/internal/sender.(*sender[go.shape.interface { BytesSize() int; ItemsCount() int; MergeSplit(context.Context, int, go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.SizerType, go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request) ([]go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request, error) }]).Send()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/internal/sender/sender.go:31 +0x6c
  go.opentelemetry.io/collector/exporter/exporterhelper/internal/sender.(*sender[go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request]).Send()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/internal/sender/sender.go:30 +0x20
  go.opentelemetry.io/collector/exporter/exporterhelper/internal.(*obsReportSender[go.shape.interface { BytesSize() int; ItemsCount() int; MergeSplit(context.Context, int, go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.SizerType, go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request) ([]go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request, error) }]).Send()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/internal/obs_report_sender.go:92 +0xbc
  go.opentelemetry.io/collector/exporter/exporterhelper/internal.(*obsReportSender[go.opentelemetry.io/collector/exporter/exporterhelper/internal/request.Request]).Send()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/internal/obs_report_sender.go:86 +0x58
  go.opentelemetry.io/collector/exporter/exporterhelper/internal.(*BaseExporter).Send()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/internal/base_exporter.go:112 +0x84
  go.opentelemetry.io/collector/exporter/exporterhelper.NewLogsRequest.newConsumeLogs.func1()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/exporter/[email protected]/logs.go:215 +0x23c
  go.opentelemetry.io/collector/consumer.ConsumeLogsFunc.ConsumeLogs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/logs.go:27 +0x74
  go.opentelemetry.io/collector/consumer.(*baseLogs).ConsumeLogs()
      <autogenerated>:1 +0x28
  go.opentelemetry.io/collector/exporter/exporterhelper.(*logsExporter).ConsumeLogs()
      <autogenerated>:1 +0x78
  go.opentelemetry.io/collector/service/internal/refconsumer.refLogs.ConsumeLogs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/internal/refconsumer/logs.go:29 +0x118
  go.opentelemetry.io/collector/service/internal/refconsumer.(*refLogs).ConsumeLogs()
      <autogenerated>:1 +0x6c
  go.opentelemetry.io/collector/consumer.Logs.ConsumeLogs-fm()
      <autogenerated>:1 +0x70
  go.opentelemetry.io/collector/consumer.ConsumeLogsFunc.ConsumeLogs()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/logs.go:27 +0x74
  go.opentelemetry.io/collector/service/internal/graph.(*capabilitiesNode).ConsumeLogs()
      <autogenerated>:1 +0x28
  go.opentelemetry.io/collector/receiver/otlpreceiver/internal/logs.(*Receiver).Export()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/receiver/[email protected]/internal/logs/otlp.go:41 +0xbc
  go.opentelemetry.io/collector/pdata/plog/plogotlp.rawLogsServer.Export()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/plog/plogotlp/grpc.go:87 +0x1a8
  go.opentelemetry.io/collector/pdata/plog/plogotlp.(*rawLogsServer).Export()
      <autogenerated>:1 +0x5c
  go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/logs/v1._LogsService_Export_Handler.func1()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/internal/data/protogen/collector/logs/v1/logs_service.pb.go:307 +0xbc
  go.opentelemetry.io/collector/config/configgrpc.(*ServerConfig).getGrpcServerOptions.enhanceWithClientInformation.func9()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/config/[email protected]/configgrpc.go:576 +0x60
  go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/logs/v1._LogsService_Export_Handler()
      /Users/varkeychanjacob/go/pkg/mod/go.opentelemetry.io/collector/[email protected]/internal/data/protogen/collector/logs/v1/logs_service.pb.go:309 +0x1a0
  google.golang.org/grpc.(*Server).processUnaryRPC()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1431 +0x14c0
  google.golang.org/grpc.(*Server).processUnaryRPC()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1387 +0x1044
  google.golang.org/grpc.(*Server).handleStream()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1842 +0xe48
  google.golang.org/grpc.(*Server).serveStreams.func2.1()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1061 +0xe8

Goroutine 64 (finished) created at:
  google.golang.org/grpc.(*Server).serveStreams.func2()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1072 +0x1e4
  google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:663 +0x2efc
  google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:704 +0x2a0
  google.golang.org/grpc.(*Server).serveStreams()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:1055 +0x4d0
  google.golang.org/grpc.(*Server).handleRawConn.func1()
      /Users/varkeychanjacob/go/pkg/mod/google.golang.org/[email protected]/server.go:989 +0x7c
==================

Expected behavior

No data race flagged by go race detector.

Steps to Reproduce

Full code including config is here: https://github.com/varkey98/gologgertest

main.go

func main() {

	shutdownFn := initOtelGo()
	defer shutdownFn()

	logger, err := zap.NewProduction()
	if err != nil {
		log.Fatalf("can't initialize zap logger: %v", err)
	}
	logger.Info("log line 1")
	logger = logger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core {
		return zapcore.NewTee(core, otelzap.NewCore("test-collector"))
	}))

	logger = logger.With(zap.String("service", "collector"))
	logger.Info("log line 2")
	for i := range 10 {
		go func() {
			loggertemp := logger.With(zap.Int("temp", i))
			loggertemp.Info("current loop", zap.Int("val", i))
		}()
	}

	settings, err := initialize(logger)
	if err != nil {
		logger.Fatal("failed to initialize otel settings", zap.Error(err))
	}

	app, err := otelcol.NewCollector(settings)
	if err != nil {
		logger.Fatal("failed to create otel collector", zap.Error(err))
	}

	err = app.Run(context.Background())
	if err != nil {
		logger.Fatal("failed to start otel collector", zap.Error(err))
	}
}

collector is initialized in collector.go like

func initialize(logger *zap.Logger) (otelcol.CollectorSettings, error) {

	cfgProviderSettings := otelcol.ConfigProviderSettings{
		ResolverSettings: confmap.ResolverSettings{
			URIs: []string{getConfigFlag(os.Args[1:])},
			ProviderFactories: []confmap.ProviderFactory{
				fileprovider.NewFactory(),
				envprovider.NewFactory(),
			},
			ConverterSettings: confmap.ConverterSettings{Logger: logger},
		},
	}

	settings := otelcol.CollectorSettings{
		BuildInfo: component.BuildInfo{
			Command:     "test-collector",
			Description: "Test Collector",
			Version:     "1.0.0",
		},
		Factories:              getFactories,
		ConfigProviderSettings: cfgProviderSettings,
		LoggingOptions: []zap.Option{
			zap.WrapCore(func(zapcore.Core) zapcore.Core {
				return logger.Core()
			}),
		},
	}

	return settings, nil
}

Build it using command go build -o app.o -race .. On startup there are no issues, but on sending sigterm (ctrl + c), the race gets flagged. On our actual collector impl the race is getting flagged immediately on startup.

Operating System

MacOS 15.6

Device Architecture

ARM64

Go Version

1.24.4

Component Version

go.opentelemetry.io/contrib/bridges/otelzap v0.13.0

Metadata

Metadata

Assignees

Labels

area:logsPart of OpenTelemetry logsbugSomething isn't workingpkg:SDKRelated to an SDK package

Type

No type

Projects

Status

In Progress

Status

Needs triage

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions