OpenTelemetry support for Panache

[tarric1]

Description

Quarkus has the ambition of being a cloud native application framework, so full observability support is a must. From this perspective, I believe that a serious lack of Quarkus is the support for OpenTelemetry for accesses made to the DB (SQL and NoSQL, reactive and not) via Panache.

Implementation ideas

My ideas are related to my use case: access to MongoDB using reactive repository pattern.

1st: MongoDB command listener

The problem with this solution is that I was unable to retrieve the parent span.

package io.tarric1.quickndirty;

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.TimeUnit;

import com.mongodb.MongoClientSettings;.CommandFailedEvent;
import com.mongodb.event.CommandListener;
import com.mongodb.event.CommandStartedEvent;
import com.mongodb.event.CommandSucceededEvent;

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanKind;
import io.opentelemetry.api.trace.Tracer;
import io.opentelemetry.context.Context;
import io.quarkus.arc.lookup.LookupIfProperty;
import io.quarkus.logging.Log;
import jakarta.enterprise.context.ApplicationScoped;
import jakarta.enterprise.context.RequestScoped;
import jakarta.inject.Inject;

@ApplicationScoped
@LookupIfProperty(name = "mongo-tracing.enabled", stringValue = "true")
public class MongoDbTracing implements CommandListener {
    private Tracer tracer;

    private final Map<Integer, Span> requestMap;

    @Inject
    MongoDbTracing(Tracer tracer) {
        this.tracer = tracer;
        requestMap = new ConcurrentHashMap<>();
    }

    @Override
    public void commandStarted(CommandStartedEvent event) {
        Log.debug("COMMAND STARTED");

        String name = null;
        Span span = tracer.spanBuilder(name)
            .setParent(Context.current().with(Span.current()))
            .setSpanKind(SpanKind.CLIENT)
            .setAttribute("db.system", "mongodb")
            .setAttribute("db.name", event.getDatabaseName())
            .setAttribute("db.operation", event.getCommandName())
            .setAttribute("db.mongodb.connection-id", event.getConnectionDescription().getConnectionId().toString())
            .setAttribute("db.mongodb.server-address", event.getConnectionDescription().getServerAddress().toString())
            .setAttribute("db.mongodb.server-type", event.getConnectionDescription().getServerType().toString())
            .setAttribute("db.mongodb.request-id", event.getRequestId())
            .setAttribute("db.mongodb.operation-id", event.getOperationId())
            .setAttribute("db.mongodb.command", event.getCommand().toJson())
            .startSpan();

        requestMap.put(event.getRequestId(), span);
    }

    @Override
    public void commandSucceeded(CommandSucceededEvent event) {
        Log.debug("COMMAND SUCCEEDED");
        Span span = requestMap.get(event.getRequestId());
        if (span != null) {
            span.setAttribute("db.mongodb.elapsed-time", event.getElapsedTime(TimeUnit.MILLISECONDS))
                .setAttribute("db.mongodb.response", event.getResponse().toJson())
                .end();
        }
    }

    @Override
    public void commandFailed(CommandFailedEvent event) {
        Log.debug("COMMAND FAILED");
        Span span = requestMap.get(event.getRequestId());
        if (span != null) {
            span.setAttribute("db.mongodb.elapsed-time", event.getElapsedTime(TimeUnit.MILLISECONDS))
                .setAttribute("db.mongodb.throwable", event.getThrowable().toString())
                .end();
        }
    }
}

2nd: Interceptor for repository class

The problem with this solution (that is a draft) is that I was unable to retrieve the statement.

The following annotation is used on repository class to intercept invocations:

package io.tarric1.quickndirty;

import java.lang.annotation.ElementType;
import java.lang.annotation.Inherited;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

import jakarta.interceptor.InterceptorBinding;

@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
@Target({
    ElementType.TYPE, ElementType.METHOD, ElementType.CONSTRUCTOR
})
@Inherited
public @interface Trace {
}

The interceptor:

package io.tarric1.quickndirty;

import java.lang.reflect.Method;

import org.eclipse.microprofile.config.ConfigProvider;

import com.mongodb.MongoNamespace;

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanKind;
import io.opentelemetry.api.trace.Tracer;
import io.opentelemetry.context.Context;
import io.opentelemetry.semconv.SemanticAttributes;
import io.quarkus.logging.Log;
import io.quarkus.mongodb.panache.common.MongoEntity;
import io.quarkus.mongodb.panache.reactive.ReactivePanacheMongoRepositoryBase;
import io.quarkus.mongodb.reactive.ReactiveMongoCollection;
import jakarta.inject.Inject;
import jakarta.interceptor.AroundInvoke;
import jakarta.interceptor.Interceptor;
import jakarta.interceptor.InvocationContext;

@Trace
@Interceptor
public class TraceInterceptor {
    private Tracer tracer;

    @Inject
    TraceInterceptor(Tracer tracer) {
        this.tracer = tracer;
    }

    @AroundInvoke
    Object trace(InvocationContext context) throws Exception {
        try {
            ReactivePanacheMongoRepositoryBase<?, ?> repository = (ReactivePanacheMongoRepositoryBase<?, ?>) (context.getTarget());

            Class<?> clazz = context.getTarget().getClass();
            Method method = context.getMethod();

            if (!method.getName().equals("mongoCollection")) {
                ReactiveMongoCollection<?> mongoCollection = repository.mongoCollection();

                /*
                 * Resolving connection string.
                 */
                Class<?> documentClass = mongoCollection.getDocumentClass();
                MongoEntity mongoEntity = documentClass.getAnnotation(MongoEntity.class);

                String clientName = null;
                if (mongoEntity != null) {
                    clientName = mongoEntity.clientName();
                }

                String connectionString = null;
                if (clientName == null || clientName.isEmpty()) {
                    connectionString = ConfigProvider.getConfig().getOptionalValue("quarkus.mongodb.connection-string", String.class).orElse(null);
                } else {
                    connectionString = ConfigProvider.getConfig().getOptionalValue(String.format("quarkus.mongodb.%s.connection-string", clientName), String.class).orElse(null);
                    if (connectionString == null) {
                        connectionString = ConfigProvider.getConfig().getOptionalValue("quarkus.mongodb.connection-string", String.class).orElse(null);
                    }
                }

                MongoNamespace mongoNamespace = mongoCollection.getNamespace();

                Span span = tracer.spanBuilder(clazz.getSimpleName() + "." + method.getName())
                    .setParent(Context.current().with(Span.current()))
                    .setSpanKind(SpanKind.CLIENT)
                    .setAttribute(SemanticAttributes.DB_SYSTEM.getKey(), SemanticAttributes.DbSystemValues.MONGODB)
                    .setAttribute(SemanticAttributes.DB_OPERATION.getKey(), method.getName())
                    .setAttribute(SemanticAttributes.DB_NAME.getKey(), mongoNamespace.getDatabaseName())
                    .setAttribute(SemanticAttributes.DB_MONGODB_COLLECTION.getKey(), mongoNamespace.getCollectionName())
                    .setAttribute(SemanticAttributes.DB_CONNECTION_STRING.getKey(), connectionString != null ? connectionString : "")
                    .startSpan();

                Object ret = context.proceed();

                span.end();

                return ret;
            } else {
                Log.info("mongoCollection() invocation has been intercepted. Ignore it!");
                return context.proceed();
            }
        } catch (ClassCastException e) {
            Log.warn("Did you use @Trace with a class which doesn't implement ReactivePanacheMongoRepositoryBase?");
            return context.proceed();
        }
    }
}

[quarkus-bot[bot]]

/cc @FroMage (panache), @brunobat (opentelemetry), @loicmathieu (panache), @radcortez (opentelemetry)

[loicmathieu]

@tarric1 this will soon be natif to MongoDB with Panache, see #40191

There also exist an instrumentation for JDBC: https://quarkus.io/guides/opentelemetry#jdbc And you can create a span with an annotation in all CDI beans methods (you can use it easily if using the repository pattern): https://quarkus.io/guides/opentelemetry#cdi

So there is everything needed to instrument Panache method.

[tarric1]

@loicmathieu thanks for your feedback but the problem with #40191 (that is my 1st idea) is that you cannot set the right parent span because it is a listener and it hasn't che context. Regarding the annotations, I know that they exist but using only them you cannot set some attributes like the connection string and some collectors, like Azure Application Insights, doesn't interpret correctly the span, for this reason I'm using the 2nd idea.

[brunobat]

Panache is a utility lib, pretty much like Mutiny is and we don't instrument it with OTel. We chose to instrument in the JDBC (like @loicmathieu mentioned) and DB clients because only them have data about the connections and will get us instrumentation regardless of the way you ware interacting with the DB. @tarric1, did the instrumentation of the Mongo DB fixed the issue for you? What do you mean by "you cannot set the right parent span"? Do you see detached spans? if so, it's a bug in the implementation of the instrumentation.

[tarric1]

Hello @brunobat, thanks for your feedback!

For me it's ok to instrument the client or the driver, my problem is that currently I see a detached span when I use the following solution:

package io.tarric1.quickndirty;

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.TimeUnit;

import com.mongodb.MongoClientSettings;.CommandFailedEvent;
import com.mongodb.event.CommandListener;
import com.mongodb.event.CommandStartedEvent;
import com.mongodb.event.CommandSucceededEvent;

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanKind;
import io.opentelemetry.api.trace.Tracer;
import io.opentelemetry.context.Context;
import io.quarkus.arc.lookup.LookupIfProperty;
import io.quarkus.logging.Log;
import jakarta.enterprise.context.ApplicationScoped;
import jakarta.enterprise.context.RequestScoped;
import jakarta.inject.Inject;

@ApplicationScoped
@LookupIfProperty(name = "mongo-tracing.enabled", stringValue = "true")
public class MongoDbTracing implements CommandListener {
    private Tracer tracer;

    private final Map<Integer, Span> requestMap;

    @Inject
    MongoDbTracing(Tracer tracer) {
        this.tracer = tracer;
        requestMap = new ConcurrentHashMap<>();
    }

    @Override
    public void commandStarted(CommandStartedEvent event) {
        Log.debug("COMMAND STARTED");

        String name = null;
        Span span = tracer.spanBuilder(name)
            .setParent(Context.current().with(Span.current()))
            .setSpanKind(SpanKind.CLIENT)
            .setAttribute("db.system", "mongodb")
            .setAttribute("db.name", event.getDatabaseName())
            .setAttribute("db.operation", event.getCommandName())
            .setAttribute("db.mongodb.connection-id", event.getConnectionDescription().getConnectionId().toString())
            .setAttribute("db.mongodb.server-address", event.getConnectionDescription().getServerAddress().toString())
            .setAttribute("db.mongodb.server-type", event.getConnectionDescription().getServerType().toString())
            .setAttribute("db.mongodb.request-id", event.getRequestId())
            .setAttribute("db.mongodb.operation-id", event.getOperationId())
            .setAttribute("db.mongodb.command", event.getCommand().toJson())
            .startSpan();

        requestMap.put(event.getRequestId(), span);
    }

    @Override
    public void commandSucceeded(CommandSucceededEvent event) {
        Log.debug("COMMAND SUCCEEDED");
        Span span = requestMap.get(event.getRequestId());
        if (span != null) {
            span.setAttribute("db.mongodb.elapsed-time", event.getElapsedTime(TimeUnit.MILLISECONDS))
                .setAttribute("db.mongodb.response", event.getResponse().toJson())
                .end();
        }
    }

    @Override
    public void commandFailed(CommandFailedEvent event) {
        Log.debug("COMMAND FAILED");
        Span span = requestMap.get(event.getRequestId());
        if (span != null) {
            span.setAttribute("db.mongodb.elapsed-time", event.getElapsedTime(TimeUnit.MILLISECONDS))
                .setAttribute("db.mongodb.throwable", event.getThrowable().toString())
                .end();
        }
    }
}

Is there another way that I don't know or is there a bug in my implementation?

To avoid this problem, currently I'm using the following solution: https://github.com/pagopa/mil-common/tree/main/src/main/java/it/pagopa/swclient/mil/observability

I use TraceReactivePanacheMongoRepository to annotate the repositories that I want to trace: https://github.com/pagopa/mil-payment-notice/blob/quarkus_3_10_0/src/main/java/it/pagopa/swclient/mil/paymentnotice/dao/PaymentTransactionRepository.java

Thanks a lot!

[brunobat]

You are using the low level API to create spans. You need to start a scope, make the span current and make sure it is ended in a finally block.

[tarric1]

I'm sorry @brunobat but I didn't understand.

The command listener is executed on a thread which doesn't belong to the same otel context that is generated (automatically) when a REST invocation is done to my controller (that invokes my Mongo repository), so, in my opinion, with this approch there is no chance to include the span that traces the operations on Mongo to the parent span.

I tried also with this:

https://github.com/quarkusio/quarkus/blob/main/extensions/mongodb-client/runtime/src/main/java/io/quarkus/mongodb/tracing/MongoTracingCommandListener.java

and the result is the same I see a detached span for Mongo operations.

What I'm doing wrong?