Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TraceID and SpanID are both "00000...." in otel log export #6114

Open
seriouspoop opened this issue Dec 24, 2024 · 3 comments
Open

TraceID and SpanID are both "00000...." in otel log export #6114

seriouspoop opened this issue Dec 24, 2024 · 3 comments
Labels
bug Something isn't working response needed Waiting on user input before progress can be made

Comments

@seriouspoop
Copy link

Description

I'm using a otelzap bridge for logging and for testing purposes I've configures a console exporter for both traces and metrics
while logging I manually extract traceID and spanID from the context and add them as zap fields, but when otel exports the logs to console I can see that the traceIDs and spanIDs are added as attributes but the keys TraceID and SpanID are both zeros everytime. I've no idea why is that so.

Environment

  • OS: Fedora 41
  • Architecture: x86
  • Go Version: 1.23.4
  • opentelemetry-go version: whatever is

Expected behavior

Zap Logs:

{

"L": "INFO",

"T": "2024-12-24T11:53:54.758+0530",

"C": "logging/trace.go:36",

"M": "targeting rules retrieved from db",

"service": "delivery-ms",

"TraceID": "564fda5048b0e8651e5f0341008d1240",

"SpanID": "38024b8d30fd704b"

},
{

"L": "DEBUG",

"T": "2024-12-24T11:53:54.758+0530",

"C": "logging/trace.go:29",

"M": "campaign IDs found for the given target",

"service": "delivery-ms",

"TraceID": "564fda5048b0e8651e5f0341008d1240",

"SpanID": "7bacdf0e43bb48a4",

"target": {

"app": "com.abc.xyz",

"country": "germany",

"os": "android"

},

"campaign_ids": [

"d2d29867-3d0b-d497-9191-18a9d8ee7830"

]

} 

Otel Logs:

{

"Timestamp": "2024-12-24T11:53:54.758782459+05:30",

"ObservedTimestamp": "2024-12-24T11:53:54.758836288+05:30",

"Severity": 9,

"SeverityText": "info",

"Body": {

"Type": "String",

"Value": "targeting rules retrieved from db"

},

"Attributes": [

{

"Key": "TraceID",

"Value": {

"Type": "String",

"Value": "564fda5048b0e8651e5f0341008d1240"

}

},

{

"Key": "SpanID",

"Value": {

"Type": "String",

"Value": "38024b8d30fd704b"

}

},

{

"Key": "code.filepath",

"Value": {

"Type": "String",

"Value": "/home/harshit/greedygame/go-common/logging/trace.go"

}

},

{

"Key": "code.lineno",

"Value": {

"Type": "Int64",

"Value": 36

}

},

{

"Key": "code.function",

"Value": {

"Type": "String",

"Value": "Info"

}

},

{

"Key": "code.namespace",

"Value": {

"Type": "String",

"Value": "seriouspoop/greedygame/go-common/logging.(*LoggerWithCtx)"

}

}

],

"TraceID": "00000000000000000000000000000000",

"SpanID": "0000000000000000",

"TraceFlags": "00",

"Resource": [

{

"Key": "service.name",

"Value": {

"Type": "STRING",

"Value": "seriouspoop/greedygame"

}

},

{

"Key": "telemetry.sdk.language",

"Value": {

"Type": "STRING",

"Value": "go"

}

},

{

"Key": "telemetry.sdk.name",

"Value": {

"Type": "STRING",

"Value": "opentelemetry"

}

},

{

"Key": "telemetry.sdk.version",

"Value": {

"Type": "STRING",

"Value": "1.33.0"

}

}

],

"Scope": {

"Name": "seriouspoop/greedygame",

"Version": "",

"SchemaURL": "",

"Attributes": {}

},

"DroppedAttributes": 0

}

{

"Timestamp": "2024-12-24T11:53:54.758901513+05:30",

"ObservedTimestamp": "2024-12-24T11:53:54.758906331+05:30",

"Severity": 5,

"SeverityText": "debug",

"Body": {

"Type": "String",

"Value": "campaign IDs found for the given target"

},

"Attributes": [

{

"Key": "TraceID",

"Value": {

"Type": "String",

"Value": "564fda5048b0e8651e5f0341008d1240"

}

},

{

"Key": "SpanID",

"Value": {

"Type": "String",

"Value": "7bacdf0e43bb48a4"

}

},

{

"Key": "target",

"Value": {

"Type": "Map",

"Value": [

{

"Key": "app",

"Value": {

"Type": "String",

"Value": "com.abc.xyz"

}

},

{

"Key": "country",

"Value": {

"Type": "String",

"Value": "germany"

}

},

{

"Key": "os",

"Value": {

"Type": "String",

"Value": "android"

}

}

]

}

},

{

"Key": "code.filepath",

"Value": {

"Type": "String",

"Value": "/home/harshit/greedygame/go-common/logging/trace.go"

}

},

{

"Key": "code.lineno",

"Value": {

"Type": "Int64",

"Value": 29

}

},

{

"Key": "code.function",

"Value": {

"Type": "String",

"Value": "Debug"

}

},

{

"Key": "code.namespace",

"Value": {

"Type": "String",

"Value": "seriouspoop/greedygame/go-common/logging.(*LoggerWithCtx)"

}

},

{

"Key": "campaign_ids",

"Value": {

"Type": "Slice",

"Value": [

{

"Type": "String",

"Value": "d2d29867-3d0b-d497-9191-18a9d8ee7830"

}

]

}

}

],

"TraceID": "00000000000000000000000000000000",

"SpanID": "0000000000000000",

"TraceFlags": "00",

"Resource": [

{

"Key": "service.name",

"Value": {

"Type": "STRING",

"Value": "seriouspoop/greedygame"

}

},

{

"Key": "telemetry.sdk.language",

"Value": {

"Type": "STRING",

"Value": "go"

}

},

{

"Key": "telemetry.sdk.name",

"Value": {

"Type": "STRING",

"Value": "opentelemetry"

}

},

{

"Key": "telemetry.sdk.version",

"Value": {

"Type": "STRING",

"Value": "1.33.0"

}

}

],

"Scope": {

"Name": "seriouspoop/greedygame",

"Version": "",

"SchemaURL": "",

"Attributes": {}

},

"DroppedAttributes": 0

} 
@seriouspoop seriouspoop added the bug Something isn't working label Dec 24, 2024
@seriouspoop
Copy link
Author

@MrAlias can you please help?

@pellared
Copy link
Member

Missing repro steps

@pellared pellared added the response needed Waiting on user input before progress can be made label Dec 24, 2024
@seriouspoop
Copy link
Author

@pellared

I'm sorry for the delay.

Here are the steps for repro.

  1. Resource initialization
func newResource(name string) (*resource.Resource, error) {
	return resource.Merge(
		resource.Default(),
		resource.NewWithAttributes(
			semconv.SchemaURL,
			semconv.ServiceName(name),
		),
	)
}
  1. Tracer initialization
func NewTracer(ctx context.Context, name string, ex *Exporter) (*Tracer, error) {
	// setup exporter based on service choice
	e, err := setupTraceExporter(ctx, ex)
	if err != nil {
		return nil, err
	}
	provider, err := newTraceProvider(e, name)
	if err != nil {
		return nil, err
	}
	// set global provider for all libraries using otel - otelmux etc.
	otel.SetTracerProvider(provider)
	otel.SetTextMapPropagator(propagation.TraceContext{})
	tracer := provider.Tracer(name)
	return &Tracer{name: name, tracer: tracer, provider: provider}, nil
}

func newTraceProvider(exp sdktrace.SpanExporter, name string) (*sdktrace.TracerProvider, error) {
	r, err := newResource(name)
	if err != nil {
		return nil, err
	}

	return sdktrace.NewTracerProvider(
		sdktrace.WithSampler(sdktrace.AlwaysSample()),
		sdktrace.WithBatcher(exp),
		sdktrace.WithResource(r),
	), nil
}

func setupTraceExporter(ctx context.Context, ex *Exporter) (e sdktrace.SpanExporter, err error) {
	switch ex.Type {
	case ConsoleExporter:
		e, err = newTraceConsoleExporter()
	case OTLPHttpExporter:
		e, err = newTraceOTLPHttpExporter(ctx, ex.HttpEndpoint)
	case OTLPGrpcExporter:
		e, err = newTraceOTLPGrpcExporter(ctx, ex.GrcpEndpoint)
	default:
		e, err = newTraceConsoleExporter()
	}
	if err != nil {
		return nil, err
	}
	return
}

func newTraceOTLPHttpExporter(ctx context.Context, otlpEndpoint string) (sdktrace.SpanExporter, error) {
	insecureOpts := otlptracehttp.WithInsecure()
	endpoint := otlptracehttp.WithEndpoint(otlpEndpoint)
	return otlptracehttp.New(ctx, endpoint, insecureOpts)
}

func newTraceOTLPGrpcExporter(ctx context.Context, otlpEndpoint string) (sdktrace.SpanExporter, error) {
	insecureOpts := otlptracegrpc.WithInsecure()
	endpoint := otlptracegrpc.WithEndpoint(otlpEndpoint)
	return otlptracegrpc.New(ctx, endpoint, insecureOpts)
}

func newTraceConsoleExporter() (sdktrace.SpanExporter, error) {
	return stdouttrace.New(stdouttrace.WithPrettyPrint())
}
  1. Logger initialization
func NewLogger(ctx context.Context, name string, exp *Exporter) (*Logger, error) {
	ex, err := setupLogExporter(ctx, exp)
	if err != nil {
		return nil, err
	}
	provider, err := newLogProvider(ex, name)
	if err != nil {
		return nil, err
	}
	return &Logger{name: name, provider: provider}, nil
}

func newLogProvider(exp sdklogs.Exporter, name string) (*sdklogs.LoggerProvider, error) {
	r, err := newResource(name)
	if err != nil {
		return nil, err
	}

	processor := sdklogs.NewBatchProcessor(exp)

	// TODO - add sampling option
	return sdklogs.NewLoggerProvider(
		sdklogs.WithResource(r),
		sdklogs.WithProcessor(processor),
	), nil
}

func setupLogExporter(ctx context.Context, ex *Exporter) (e sdklogs.Exporter, err error) {
	switch ex.Type {
	case ConsoleExporter:
		e, err = newLogConsoleExporter()
	case OTLPHttpExporter:
		e, err = newLogOTLPHttpExporter(ctx, ex.HttpEndpoint)
	case OTLPGrpcExporter:
		e, err = newLogOTLPGrpcExporter(ctx, ex.GrcpEndpoint)
	default:
		e, err = newLogConsoleExporter()
	}
	if err != nil {
		return nil, err
	}
	return
}

func newLogOTLPHttpExporter(ctx context.Context, otlpEndpoint string) (sdklogs.Exporter, error) {
	insecureOpts := otlploghttp.WithInsecure()
	endpoint := otlploghttp.WithEndpoint(otlpEndpoint)
	return otlploghttp.New(ctx, endpoint, insecureOpts)
}

func newLogOTLPGrpcExporter(ctx context.Context, otlpEndpoint string) (sdklogs.Exporter, error) {
	insecureOpts := otlploggrpc.WithInsecure()
	endpoint := otlploggrpc.WithEndpoint(otlpEndpoint)
	return otlploggrpc.New(ctx, endpoint, insecureOpts)
}

func newLogConsoleExporter() (sdklogs.Exporter, error) {
	return stdoutlog.New(stdoutlog.WithPrettyPrint())
}
  1. Generating a logger core for zap
func (l *Logger) NewLoggerCore() *otelzap.Core {
	core := otelzap.NewCore(l.name, otelzap.WithLoggerProvider(l.provider))
	return core
}
  1. Appending otelzap core to zap
func NewWithService(service, logLevel string, core ...zapcore.Core) (*Logger, error) {
	level, err := zap.ParseAtomicLevel(logLevel)
	if err != nil {
		return nil, err
	}

	config := zap.Config{
		Level:             level,
		Encoding:          "json",
		OutputPaths:       []string{"stdout"},
		ErrorOutputPaths:  []string{"stderr"},
		InitialFields:     map[string]interface{}{"service": service},
		EncoderConfig:     zap.NewProductionEncoderConfig(),
		DisableStacktrace: true,
	}

	if level.Level() == zap.DebugLevel {
		config.EncoderConfig = zap.NewDevelopmentEncoderConfig()
	}

	log, err := config.Build()
	if err != nil {
		return nil, err
	}

	if len(core) > 0 {
		otelCore := zap.WrapCore(func(c zapcore.Core) zapcore.Core {
			core = append(core, c)
			return zapcore.NewTee(core...)
		})
		log = log.WithOptions(otelCore)
	}
	return &Logger{log}, nil
}

Then using the logger throughout the service

Another thing also worth mentioning is that, I have built custom wrappers on top of zap to inject trace events on Logging a event.

type LoggerWithCtx struct {
	ctx context.Context
	l   *Logger
}

func (l *Logger) Ctx(ctx context.Context) *LoggerWithCtx {
	span := trace.SpanContextFromContext(ctx)
	traceID := zap.String("trace_id", span.TraceID().String())
	spanID := zap.String("span_id", span.SpanID().String())
	fields := []zap.Field{traceID, spanID}
	return &LoggerWithCtx{ctx, &Logger{l.logger.With(fields...)}}
}

func (l *LoggerWithCtx) Debug(msg string, fields ...zap.Field) {
	if span := trace.SpanFromContext(l.ctx); span.IsRecording() {
		span.AddEvent(msg)
	}
	l.l.logger.Debug(msg, fields...)
}

func (l *LoggerWithCtx) Info(msg string, fields ...zap.Field) {
	if span := trace.SpanFromContext(l.ctx); span.IsRecording() {
		span.AddEvent(msg)
	}
	l.l.logger.Info(msg, fields...)
}

func (l *LoggerWithCtx) Error(msg string, fields ...zap.Field) {
	if span := trace.SpanFromContext(l.ctx); span.IsRecording() {
		span.SetStatus(codes.Error, msg)
	}
	l.l.logger.Error(msg, fields...)
}

func (l *LoggerWithCtx) Log(level zapcore.Level, msg string, fields ...zap.Field) {
	l.l.logger.Log(level, msg, fields...)
}

func (l *LoggerWithCtx) With(fields ...zap.Field) *LoggerWithCtx {
	log := l.l.logger.With(fields...)
	return &LoggerWithCtx{l.ctx, &Logger{logger: log}}
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working response needed Waiting on user input before progress can be made
Projects
None yet
Development

No branches or pull requests

2 participants