trace.NewTracerProvider logs configuration before storing spanProcessors

[kmai]

Description

TracerProvider creation logs incomplete configuration, leaving out defined SpanProcessor structs.

Environment

• OS: MacOS
• Architecture: x86_64
• Go Version: 1.19
• opentelemetry-go version: v1.11.2

Steps To Reproduce

1. Configure a logr compatible logger with verbosity set higher than 5 (as per OTEL documentation, to enable debug logging).
2. Create a TraceProvider by using go.opentelemetry.io/otel/sdk/trace.NewTracerProvider(), with a configured SpanProcessor
3. The log emitted after the provider is created will be incorrect because it will display SpanProcessors as empty.

Expected behavior

The log message should promptly display the full configuration of the TraceProvider struct.

Comments

I believe the offending block of code is the following:

// NewTracerProvider returns a new and configured TracerProvider.
//
// By default the returned TracerProvider is configured with:
//   - a ParentBased(AlwaysSample) Sampler
//   - a random number IDGenerator
//   - the resource.Default() Resource
//   - the default SpanLimits.
//
// The passed opts are used to override these default values and configure the
// returned TracerProvider appropriately.
func NewTracerProvider(opts ...TracerProviderOption) *TracerProvider {
	o := tracerProviderConfig{
		spanLimits: NewSpanLimits(),
	}
	o = applyTracerProviderEnvConfigs(o)

	for _, opt := range opts {
		o = opt.apply(o)
	}

	o = ensureValidTracerProviderConfig(o)

	tp := &TracerProvider{
		namedTracer: make(map[instrumentation.Scope]*tracer),
		sampler:     o.sampler,
		idGenerator: o.idGenerator,
		spanLimits:  o.spanLimits,
		resource:    o.resource,
	}
	global.Info("TracerProvider created", "config", o)

	spss := spanProcessorStates{}
	for _, sp := range o.processors {
		spss = append(spss, newSpanProcessorState(sp))
	}
	tp.spanProcessors.Store(spss)

	return tp
}

As you can see, tp.spanProcessors.Store(spss) is called after the log entry has been created. For that reason, the spanProcessors attribute is empty on the log message.

[PalanQu]

May I help with this? @MrAlias

[hanyuancheung]

Thanks for ur advice! @kmai

I've tested the issue as you mentioned above. All of the config msg(such as spanProcessor, sampler) are stored in tracerProviderConfig, it seems like the spanProcessors wouldn't be left out in the log message.

It's also possible that I misunderstood. Could you please offer more info to point out where the problem is? Thanks.

[kmai]

Hi @hanyuancheung! When I start my application with the following snippet (just to try out logging when dealing with some troubleshooting):

	// Initialize Subsystems
	logRus := providers.LoggingInit()

	var logger logr.Logger

	if zapLogger, err := zap.NewDevelopment(); err != nil {
		logRus.Panic(fmt.Errorf("error while instantiating logger for OTEL: %w", err))
	} else {
		logger = zapr.NewLogger(zapLogger)
	}

	otel.SetLogger(logger)

	ctx, cancel := context.WithCancel(context.Background())
	defer cancel()

	tracerProvider, err := providers.TracerInit()
	if err != nil {
		logRus.Warnf("error while initializing tracing subsystem: %v", err)
	}

	defer middleware.TracingShutdownSignal(ctx, tracerProvider)

	// Register our TracerProvider as the global so any imported
	// instrumentation in the future will default to using it.
	otel.SetTracerProvider(tracerProvider)
	otel.SetTextMapPropagator(b3.New(b3.WithInjectEncoding(b3.B3MultipleHeader)))

I instantiate the TracerProvider with a Prometheus Exporter. The debug log dumps the struct configuration, but it shows the spanProcessors empty, while I should see a single one with my configured exporter:

{
  "config": {
    "SpanProcessors": [
      {}
    ],
    "SamplerType": "trace.alwaysOnSampler",
    "IDGeneratorType": "*trace.randomIDGenerator",
    "SpanLimits": {
      "AttributeValueLengthLimit": -1,
      "AttributeCountLimit": 128,
      "EventCountLimit": 128,
      "LinkCountLimit": 128,
      "AttributePerEventCountLimit": 128,
      "AttributePerLinkCountLimit": 128
    },
    "Resource": [
      {
        "Key": "deployment.environment",
        "Value": {
          "Type": "STRING",
          "Value": "development"
        }
      },
      {
        "Key": "host.name",
        "Value": {
          "Type": "STRING",
          "Value": "192-168-0-74.static.private.lan"
        }
      },
      {
        "Key": "process.command_args",
        "Value": {
          "Type": "STRINGSLICE",
          "Value": [
            "/private/var/folders/p5/n87t8_wj24q7jg6r6dqjb2hr0000gn/T/GoLand/___Build_Server"
          ]
        }
      },
      {
        "Key": "process.executable.name",
        "Value": {
          "Type": "STRING",
          "Value": "___Build_Server"
        }
      },
      {
        "Key": "process.executable.path",
        "Value": {
          "Type": "STRING",
          "Value": "/private/var/folders/p5/n87t8_wj24q7jg6r6dqjb2hr0000gn/T/GoLand/___Build_Server"
        }
      },
      {
        "Key": "process.owner",
        "Value": {
          "Type": "STRING",
          "Value": "kmai"
        }
      },
      {
        "Key": "process.pid",
        "Value": {
          "Type": "INT64",
          "Value": 42386
        }
      },
      {
        "Key": "process.runtime.description",
        "Value": {
          "Type": "STRING",
          "Value": "go version go1.19.4 darwin/arm64"
        }
      },
      {
        "Key": "process.runtime.name",
        "Value": {
          "Type": "STRING",
          "Value": "go"
        }
      },
      {
        "Key": "process.runtime.version",
        "Value": {
          "Type": "STRING",
          "Value": "go1.19.4"
        }
      },
      {
        "Key": "service.name",
        "Value": {
          "Type": "STRING",
          "Value": "example-service"
        }
      }
    ]
  }
}

I expected to see my exporter configured, but I don't! Let me know if you need the full codebase.

[MadVikingGod]

This looks to be zapr not respecting the MarshalLog interface for slices. Here is a playground that shows how stdr does show the appropriate data, but zapr only will display {} for span processors: https://go.dev/play/p/BmKiLbhfNRY

I think the fix would be:
A) Add a work around for zapr, probably something akin to BatchSpanProcessor.MarshalLog() for the config, or for the []SpanProcessor type
B) Upstream a patch that fixes this behavior. It has been a while but I recall the first time I looked into this there is a closed issue with zapr around this behavior.
C) Add a workaround for zapr, find zap's MarshalLog equivalent and add that so it marshals correctly.