uptrace / opentelemetry-go-extra

OpenTelemetry instrumentations for Go
https://uptrace.dev/get/instrument/
BSD 2-Clause "Simplified" License
314 stars 72 forks source link

Otelzap never emits #128

Closed zergeborg closed 4 months ago

zergeborg commented 5 months ago

I was trying to use otelzap

I set it up like this:

    otellog := otelzap.New(logger.NewLogger(),
        otelzap.WithMinLevel(zap.DebugLevel),
        otelzap.WithErrorStatusLevel(zap.ErrorLevel),
    )

Then I use this logger in an echo handler like this:

    ctx, span := g.Tracer.Start(c.Request().Context(), "HandleRequest", trace.WithAttributes(attribute.String(echo.HeaderXRequestID, requestTrackingID)))
    defer span.End()

        g.Log.Ctx(ctx).Info("Handling request")

I can see that the otelzap logger tries calling the otel logger Emit method, but whenever it does so, the emit functions does absolutely nothing.

I confirmed this by putting a breakpoint in otel/internal/global/log.go and started debugging my code. So basically the Emit method which looks like this:

    if del, ok := l.delegate.Load().(log.Logger); ok {
        del.Emit(ctx, r)
    }

so this method never enters the ok case.

If I understand correctly this delegate is instantiated and configured by otelzap so I wonder, why is the delegate no loaded?

vmihailenco commented 5 months ago

You probably don't have tracing configured and/or span created. For some reason, OpenTelemetry logger ignores the log record if the context does not contain a valid span/trace id. It is probably just an overlook of the current implementation. Might be worth it reporting to opentelemetry-go.

zergeborg commented 5 months ago

@vmihailenco Thanks for the quick response. I am not sure if the context does not contain a valid span/trace id is the issue here, but I also cannot exclude that possibility.

The thing is, these traces are sent to GCP and they show up in Trace Explorer without any issue. So I would assume that indicates that the span/trace IDs are correct.

I will keep debugging to see what can I find. I will also take a look at the repo you recommended.

zergeborg commented 5 months ago

BTW, the more time I spend with the code I noticed that even if I pass a ctx to the *otelzap.Logger Ctx() function, the span is properly resolved from the ctx (i.e. trace.SpanFromContext(ctx) works), but the attributes inside the span are disregarded.

I guess this is more of a feature request, but would it be possible to add those span attributes as extra fields when the logFields function is executed?

vmihailenco commented 5 months ago

I guess this is more of a feature request, but would it be possible to add those span attributes as extra fields when the logFields function is executed?

AFAIR OpenTelemetry does not allow to read attributes from spans so it should not be possible.

zergeborg commented 4 months ago

Thank you @vmihailenco , understood. BTW, it seems the problem I experienced was caused by the fact that I didn't create my own LoggerProvider. It might be worth adding to otelzap's documentation a small note that logs are only emitted when the LoggerProvider is created and probably configured. I will close this ticket for this reason