camel-quarkus-opentelemetry gives empty traceId in the logs

[ffbilsel]

Bug description

Hello. We use camel kafka quarkus in our project with these dependencies `

org.apache.camel.quarkus

<artifactId>camel-quarkus-opentelemetry</artifactId>

io.quarkus

<artifactId>quarkus-opentelemetry</artifactId>

`

And the logger is configured in the application.properties file by this line %quarkus.log.console.format=%d{HH:mm:ss} %-5p traceId=%X{traceId}, spanId=%X{spanId} [%c{2.}] (%t) %s%e%n

Since I added the camel-quarkus-opentelemetry dependency, I see a trace created when a camel route is triggered (using jaeger). But all the logs that are created has empty traceId and spanId.

Sample code from our apllication : @ApplicationScoped public class Routes extends RouteBuilder { @Override public void configure() throws Exception { from("kafka:{{kafka.x.in.topic.name}}").routeId("x") .log("Received : \"${body}\"").etc }

Sample output: 12:48:13 INFO traceId=, spanId= [x] (Camel (camel-1) thread #17 - KafkaConsumer[x.topic.in]) Received : "{ "payload": { ... }, "time": "2023-06-05T07:00:07Z" }"

[jamesnetherton]

Have you enabled MDC logging in Camel?

[ffbilsel]

Yes, this time the output is INFO traceId=00000000000000000000000000000000, spanId=0000000000000000 ...

[jamesnetherton]

See the notes in the documentation here:

https://camel.apache.org/components/3.20.x/others/opentelemetry.html#_mdc_logging

The keys are trace_id & span_id.

[ffbilsel]

Thank you @jamesnetherton. I didn't notice the keys were different. It works. But now there is another issue. We also use opentelemetry jdbc dependecy: `

io.opentelemetry.instrumentation opentelemetry-jdbc

`.

When a camel route is triggered there are some sql queries that we run. I expect these queries to be shown in the same trace with the camel route. But instead they are in a new and different trace.

[jamesnetherton]

Some questions:

• Which Quarkus version are you using?
• How do you run the SQL queries? Are they run from a custom bean that you invoke in a Camel route?

[ffbilsel]

1.quarkus 3.1.1 final 2.yes (we use PanacheRepository)

[jamesnetherton]

It probably depends on how the PanacheRepository is invoked.

E.g something like this may work:

@Singleton
@Named("databaseBean");
public class DatabaseBean {

    @Inject
    MyPanacheRepository panacheRepository;

    @WithSpan
    public void runQueries() {
        // Do something with panacheRepository
    }
}

public class MyRoutes extends RouteBuilder {
    @Override
    public void configure() {
        from("direct:query")
        .to("bean:databaseBean");
    }
}

[ffbilsel]

I did what you suggested. The result is that there are two traces again. The first one consists of route info. And the second one has three spans first of which is the function that I annotated with @Withspan, then database connection, then the query itself. I asked the same question in this thread: https://github.com/quarkusio/quarkus/issues/33991 and @brunobat 's response is interesting : "That looks like a context propagation issue to me. Do you have a sample project? We have tests on Quarkus proving the OTel context propagation to the JDBC layer. Most likely 'camel-quarkus-opentelemetry' is not propagating the context properly. Can you please, after the event is received from kafka, can you call another method, annotated with @WithSpan in different service? Just to make sure it will also be split. If that's the case, you need to report this issue on the camel side."

[jamesnetherton]

We have tests on Quarkus proving the OTel context propagation to the JDBC layer

We have something similar in this project (but not using Panache).

If you can share a project demonstrating the problem, it'd help to investigate further.

[brunobat]

These are the integration tests for OTel and JDBC spans: https://github.com/quarkusio/quarkus/tree/main/integration-tests/opentelemetry-jdbc-instrumentation As a reference, the context storage is handled here: https://github.com/quarkusio/quarkus/blob/main/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/QuarkusContextStorage.java

[ffbilsel]

@jamesnetherton I created a demo project to demonstrate the issue. Here is the link https://github.com/ffbilsel/camel-quarkus-demo

[jamesnetherton]

@ffbilsel I played with the code a bit. Is this the span hierarchy you expect?

[ffbilsel]

Yes, exactly.

[jamesnetherton]

It's like I said previously, you must invoke the service bean with the bean: endpoint instead of inside of the processor. It's a limitation that we need to solve in Camel:

https://camel.apache.org/camel-quarkus/next/reference/extensions/opentelemetry.html#extensions-opentelemetry-usage-tracing-cdi-bean-method-execution

Here's a Git patch of the changes I made:

camel-quarkus-otel.txt

Also, it's best to not mix BOM imports & versions. It should be enough to import the same version of quarkus-bom and quarkus-camel-bom. If you mix versions, then you can get unpredictable results.

[ffbilsel]

Thank you for your fast and effective responses. The thing is there are routes that have very complex logic in the process( org.apache.camel.Processor processor ) function. For example sometimes we set exchange.getMessage().setBody(outMessage); according to the response of the function in the bean. So it is not possible for us to make the changes that you suggested.

"It's like I said previously, you must invoke the service bean with the bean: endpoint instead of inside of the processor. It's a limitation that we need to solve in Camel". Are there any efforts for now?

[jamesnetherton]

So it is not possible for us to make the changes that you suggested

Exchange is available to any bean invoked by Camel. You just need to specify it as a method argument and Camel will automatically provide it.

Are there any efforts for now

I will try to get some issues opened with Camel. I need to dig into the issue a bit more before doing that.

[jamesnetherton]

I tested a little bit more and there is definitely some goofiness depending on how routes are structured. Probably related to work being done synchronously Vs asynchronously.

1. This will create an orphan span for kafka:test:

from("kafka:test")
    .process(exchange -> {
        // Do useful work here
    });

It behaves the same way if timer is used instead of kafka.

2. This also creates orphan spans

from("timer:tick?period=5s")
    .to("seda:start");

from("seda:start")
    .process(exchange -> {
        // Do useful work here
    });

3. This creates the expected span hierarchy:

from("kafka:test")
    .to("direct:start");

from("direct:start")
    .process(exchange -> {
        // Do useful work here
    });

I guess it works in this case because direct acts synchronously.

[jamesnetherton]

https://issues.apache.org/jira/browse/CAMEL-19469

[ffbilsel]

Thank you. I was waiting to see if there would be any problems in production to reply. It seems everything is okay when it is done the way you told. Also thank you for the new issue.

[avsoskerem]

We solved the problem by making beans. But sometimes we experience a problem like this (duplicate trace Id). https://github.com/apache/camel-quarkus/issues/5379