Code sample for axon, spring boot, opentelemetry

Axon Framework
,
1

Is there a sample code for axon, spring boot and opentelemetry? I tried to implement a project on spring boot 3.0 and axon 4.7. For some reason traceId and spanId are not passed to the query. On calling RestController identifiers are generated but not passed to the query. It seems to me that a code example would help many developers. Below is the log of my application, where you can see that the identifiers are not passed to the metadata of the query.

{"@timestamp":"2023-02-15T22:41:44.02+03:00","@version":"1","message":"Got a request","logger_name":"ru.foris.crm.controller.MyController","thread_name":"http-nio-7656-exec-1","level":"INFO","level_value":20000,"traceId":"860e6ba8e517688c7ae6c8ac7e25cedb","spanId":"615148b7d857d9bc","caller_class_name":"ru.foris.crm.controller.MyController","caller_method_name":"userName","caller_file_name":"MyController.kt","caller_line_number":18}
{"@timestamp":"2023-02-15T22:41:44.031+03:00","@version":"1","message":"Dispatched message: [GetActiveServicesByPhoneNumberQuery(phone=79161472285, serviceCodes=[])], metaData: []","logger_name":"org.axonframework.extensions.logging.LoggingInterceptor","thread_name":"http-nio-7656-exec-1","level":"TRACE","level_value":5000,"traceId":"860e6ba8e517688c7ae6c8ac7e25cedb","spanId":"615148b7d857d9bc","caller_class_name":"org.axonframework.extensions.logging.LoggingInterceptor","caller_method_name":"lambda$handle$0","caller_file_name":"LoggingInterceptor.java","caller_line_number":60}
{"@timestamp":"2023-02-15T22:41:44.113+03:00","@version":"1","message":"on entry getProductOfferingsService with 79161472285 Bearer 4e57dd07-4443-336e-b39a-6cdd1bf1969f PAPI_SUPERTEST","logger_name":"ru.foris.crm.port.adapter.publicapi.PublicApiAdapter","thread_name":"QueryProcessor-0","level":"DEBUG","level_value":10000,"traceId":"00000000000000000000000000000000","spanId":"0000000000000000","caller_class_name":"ru.foris.crm.port.adapter.publicapi.PublicApiAdapter","caller_method_name":"getProductOfferingsService","caller_file_name":"PublicApiAdapter.kt","caller_line_number":12}
2

Hello @mymatve5! The reason there’s no code sample currently, is that there is no code to show. It should work out-of-the-box when adding the axon-tracing-opentelemetry module.

Important to note here is that metadata is only added to a message if it will be sent over the wire! Because only then, the OpenTelemetry context is lost and needs to be manually propagated.
This happens at the latest possible moment, during sending in the AxonServer*Bus implementations. If you just use a SimpleQueryBus, no context is added to the message since it’s not needed; execution will remain in the same thread.

Reading your logs, I see that the context is indeed sent over the wire, so it should be present. However, I would not expect it during the second log line yet, since the message is still being intercepted. Adding the span id comes later. I would expect the id to be present when intercepting it on the handling side though.
For now, I think what you show here should be working. I will do some tests of my own.

3

I’m back with news, @mymatve5. Apparently the 4.7.x release of Axon Framework breaks OpenTelemetry at the moment. I will start work on a fix and report here when it’s done.

1 Like
4

Hello @mymatve5 , I am back with news again. After some digging, I found what’s happening to be the case if you don’t run the JVM with the OpenTelemetry auto-instrumentation agent. See the Github issue I issued for your predicament here: OpenTelemetry support does not work properly without agent · Issue #2610 · AxonFramework/AxonFramework · GitHub

By running with the OpenTelemetry agent, you issue should be alleviated. We will check whether it’s feasible to change the framework to be able to work without.
Thanks for your patience, and let me know if adding the agent fixes your issue!

5

Thanks for your reply. Running the app with javaagent improved the situation. Now when handling a query, a new traceId and spanId are created. This is not exactly the expected behavior, I would like the same traceId and spanId to be used as when the query was sent. Below is the log using javaagent. The third entry refers to the handling of the query.

{"@timestamp":"2023-02-16T19:55:22.885+03:00","@version":"1","message":"Got a request","logger_name":"ru.foris.crm.controller.MyController","thread_name":"http-nio-7656-exec-1","level":"INFO","level_value":20000,"traceId":"92eece259a377bb96875c7ce05f681fb","spanId":"1b2d1eff52ba88bd","trace_id":"92eece259a377bb96875c7ce05f681fb","trace_flags":"01","span_id":"3a72934838f6f45c","caller_class_name":"ru.foris.crm.controller.MyController","caller_method_name":"userName","caller_file_name":"MyController.kt","caller_line_number":18}
{"@timestamp":"2023-02-16T19:55:22.943+03:00","@version":"1","message":"Dispatched message: [GetActiveServicesByPhoneNumberQuery(phone=79161472285, serviceCodes=[])], metaData: []","logger_name":"org.axonframework.extensions.logging.LoggingInterceptor","thread_name":"http-nio-7656-exec-1","level":"TRACE","level_value":5000,"traceId":"92eece259a377bb96875c7ce05f681fb","spanId":"1b2d1eff52ba88bd","trace_id":"92eece259a377bb96875c7ce05f681fb","trace_flags":"01","span_id":"3a72934838f6f45c","caller_class_name":"org.axonframework.extensions.logging.LoggingInterceptor","caller_method_name":"lambda$handle$0","caller_file_name":"LoggingInterceptor.java","caller_line_number":60}
{"@timestamp":"2023-02-16T19:55:23.802+03:00","@version":"1","message":"on entry getProductOfferingsService with 79161472285 Bearer 4e57dd07-4443-336e-b39a-6cdd1bf1969f PAPI_SUPERTEST","logger_name":"ru.foris.crm.port.adapter.publicapi.PublicApiAdapter","thread_name":"QueryProcessor-0","level":"DEBUG","level_value":10000,"trace_id":"9786ec61c8f149f14e152cb940ba7560","trace_flags":"01","span_id":"861c4278453bd630","caller_class_name":"ru.foris.crm.port.adapter.publicapi.PublicApiAdapter","caller_method_name":"getProductOfferingsService","caller_file_name":"PublicApiAdapter.kt","caller_line_number":12}

The project now has these dependencies related to opentelemetry. Maybe some dependencies are missing?

<dependency>
	<groupId>io.micrometer</groupId>
	<artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
	<groupId>org.axonframework</groupId>
	<artifactId>axon-tracing-opentelemetry</artifactId>
</dependency>
6

Thanks for the additional information, that’s not ideal yet.
Starting tomorrow I am going to produce a sample repository for various tracing solutions, as other customers are having issues as well. Turns out, how the tracing works depends a lot on the provider you’re using.
What platform are you using for the traces? An example of what I mean is Google cloud tracing. And how did you configure it? It will give me a starting point to fix either the framework or provide a well working sample.

I do need to manage some expectations though, doing this will take some time. I will notify you once its done, but I cannot promise a timeline currently

7

So @mymatve5, while doing my chores this evening I was recalling our conversation here and I figured out why you see separate traces happening. This is the default behavior of our SpanFactory for OpenTelemetry.
By default, it links handler traces to dispatch traces. It doesn’t keep it in the same trace as the dispatcher.

You can add the following property in Spring Boot to enforce this:

axon.tracing.nested-handlers=true

I have another reporting from a user, adding this worked. However, there is some detail lost in the children spans. I am not entirely sure why yet, but will come back on that matter to you.

8

hi @Morlack
is this fixed ? i am using 4.7.2 verison but still traceId and spanId is not propagated properly from controller to command handler

2023-03-09 13:31:15,888 [reactor-http-nio-6] INFO [auth,87960998f4dd0c32563dd721cf0ad096,fc07590600df9ded,,] com.example.auth.device.DeviceController - test 1
2023-03-09 13:31:21,570 [CommandProcessor-0] INFO [auth,00000000000000000000000000000000,0000000000000000,,] com.example.auth.device.DeviceAggregate - test 1
9

Hello @github4sanjay and @mymatve5 . This issue has been fixed in Axon Framework 4.6.6 and 4.7.2. I have also published a repository containing configuration samples here: GitHub - AxonFramework/opentelemetry-samples: Samples for using OpenTelemetry with Axon Framework 4.6+

10

Hi @Morlack, I’m encountering a similar issue with my Spring Boot v2.7 app using Axon Framework v4.6.7 and Datadog as my provider. Is there a way to resolve this without relying on the OpenTelemetry agent?