Get Elastic APM working with Micronaut

[dniel]

It seems like the Elastic APM java agent has a "OTEL bridge" feature but its a little bit complicated to understand what they mean by that. I have interpreted it like the Elastic APM java agent in addition to instrumenting and creating metrics from the JVM it also can instrument the otel-api and annotations. By using this you could get the best worlds of additional JVM instrumentation of the Elastic APM and also the micronaut tracing instrumentation.

It seems like there is at least three different approaches to integrate micronaut and Elastic APM.

• using the Elastic APM java agent
• using the default otel java agent.
• using no agent at all and configure the otel-exporter to send otel data directly to the otel compatible endpoint at Elastic APM.

This is my repo that I'm experimenting in https://github.com/nsbno/trafficinfo-baseline-micronaut

[dniel]

For reference:

• Netty instrumentation elastic/apm-agent-java#860
• https://www.elastic.co/guide/en/apm/guide/current/open-telemetry.html
• https://www.elastic.co/guide/en/apm/agent/java/master/opentelemetry-bridge.html

[dniel]

My elasticapm agent is reporting jvm metrics to Elastic APM, so it seems the agent is configured correctly and sending data. When looking the the logs of the agent I found

2022-08-22 16:07:37,462 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.opentelemetry.GlobalOpenTelemetryInstrumentation
2022-08-22 16:07:37,462 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.opentelemetry.ContextStorageInstrumentation
2022-08-22 16:07:37,462 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.opentelemetry.ArrayBasedContextInstrumentation

Even though I have added alle the opentelemetry depenendencies think is needed to micronaut

annotationProcessor("io.micronaut.tracing:micronaut-tracing-opentelemetry-annotation")
implementation("io.opentelemetry:opentelemetry-api")
implementation("io.opentelemetry:opentelemetry-exporter-otlp")

Even if I enable opentelemetry with https://www.elastic.co/guide/en/apm/agent/java/master/config-core.html#config-enable-instrumentations configuration it always say "not applying excluded instrumentation"

Found this config https://www.elastic.co/guide/en/apm/agent/java/master/config-core.html#config-enable-experimental-instrumentations and tried it just to see if anything happens, and now found some new loglines in the agent log! Seems that it enabled the opentelemetry instrumentation!

2022-08-22 16:35:48,028 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=e09ed7a5b9b34d87c1093f22999d432d, spanId=f9950afd74d268a1, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178948027882990, endEpochNanos=0}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357337568045490}, opentelemetry-traces-local-root-span=SdkSpan{traceId=e09ed7a5b9b34d87c1093f22999d432d, spanId=f9950afd74d268a1, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178948027882990, endEpochNanos=0}}] on thread 90
2022-08-22 16:35:48,028 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=e09ed7a5b9b34d87c1093f22999d432d, spanId=f9950afd74d268a1, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178948027882990, endEpochNanos=1661178948028762784}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357337568045490}, opentelemetry-traces-local-root-span=SdkSpan{traceId=e09ed7a5b9b34d87c1093f22999d432d, spanId=f9950afd74d268a1, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178948027882990, endEpochNanos=1661178948028762784}}] on thread 90
2022-08-22 16:35:49,029 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=550b634a4b4d121331eca0424b41ca69, spanId=c869c6e94f8159e2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178949029327592, endEpochNanos=0}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357338569481160}, opentelemetry-traces-local-root-span=SdkSpan{traceId=550b634a4b4d121331eca0424b41ca69, spanId=c869c6e94f8159e2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178949029327592, endEpochNanos=0}}] on thread 90
2022-08-22 16:35:49,029 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=550b634a4b4d121331eca0424b41ca69, spanId=c869c6e94f8159e2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178949029327592, endEpochNanos=1661178949029857429}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357338569481160}, opentelemetry-traces-local-root-span=SdkSpan{traceId=550b634a4b4d121331eca0424b41ca69, spanId=c869c6e94f8159e2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178949029327592, endEpochNanos=1661178949029857429}}] on thread 90
2022-08-22 16:35:50,030 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=3118ba95bee143cdae65985e9c00e03b, spanId=4e6b3f2cb09d2090, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178950030253507, endEpochNanos=0}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357339570402024}, opentelemetry-traces-local-root-span=SdkSpan{traceId=3118ba95bee143cdae65985e9c00e03b, spanId=4e6b3f2cb09d2090, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178950030253507, endEpochNanos=0}}] on thread 90
2022-08-22 16:35:50,030 [scheduled-executor-thread-26] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=3118ba95bee143cdae65985e9c00e03b, spanId=4e6b3f2cb09d2090, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178950030253507, endEpochNanos=1661178950030616103}, http-client-request-metrics-state=State{startAttributes={}, startTimeNanos=357339570402024}, opentelemetry-traces-local-root-span=SdkSpan{traceId=3118ba95bee143cdae65985e9c00e03b, spanId=4e6b3f2cb09d2090, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=ChangeEventCreateJob.createEvent, kind=INTERNAL, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661178950030253507, endEpochNanos=1661178950030616103}}] on thread 90

Now got lots of this stuff in the agent log, but cant find anything in the Elastic APM where I hoped they should show up as transactions.

Seems like the WithSpan opentelemetry annotations was discovered but something is preventing them being reported.
Using the Micronaut @NewSpan didn't change anything, still no transactions shown.

[dniel]

2022-08-22 20:21:34,990 [default-nioEventLoopGroup-1-2] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={http.method=GET, net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.flavor=1.1, net.transport=ip_tcp, http.server_name=localhost}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=0}, opentelemetry-http-server-route-key=io.opentelemetry.instrumentation.api.internal.HttpRouteState@7c2047fa, http-server-request-metrics-state=State{startAttributes={http.method=GET, net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.flavor=1.1, net.transport=ip_tcp, http.server_name=localhost}, startTimeNanos=368122076594065}, opentelemetry-traces-local-root-span=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={http.method=GET, net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.flavor=1.1, net.transport=ip_tcp, http.server_name=localhost}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=0}, opentelemetry-traces-span-key-http-server=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={http.method=GET, net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.flavor=1.1, net.transport=ip_tcp, http.server_name=localhost}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=0}}] on thread 65
2022-08-22 20:21:35,091 [default-nioEventLoopGroup-1-2] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating OTelBridgeContext[{opentelemetry-trace-span-key=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.flavor=1.1, net.transport=ip_tcp, http.request_content_length=-1, http.method=GET, http.status_code=200, http.response_content_length=-1, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.server_name=localhost}, capacity=128, totalAddedValues=13}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=1661192495090706133}, opentelemetry-http-server-route-key=io.opentelemetry.instrumentation.api.internal.HttpRouteState@7c2047fa, http-server-request-metrics-state=State{startAttributes={http.method=GET, net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.flavor=1.1, net.transport=ip_tcp, http.server_name=localhost}, startTimeNanos=368122076594065}, opentelemetry-traces-local-root-span=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.flavor=1.1, net.transport=ip_tcp, http.request_content_length=-1, http.method=GET, http.status_code=200, http.response_content_length=-1, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.server_name=localhost}, capacity=128, totalAddedValues=13}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=1661192495090706133}, opentelemetry-traces-span-key-http-server=SdkSpan{traceId=7806ad8f8f72f6d60d1080a1849019c1, spanId=ea8cf1f450f24b79, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=GET - /changes, kind=SERVER, attributes=AttributesMap{data={net.peer.ip=127.0.0.1, http.host=localhost:8080, net.peer.port=51628, http.target=/changes, http.flavor=1.1, net.transport=ip_tcp, http.request_content_length=-1, http.method=GET, http.status_code=200, http.response_content_length=-1, http.route=GET - /changes, http.user_agent=curl/7.81.0, http.server_name=localhost}, capacity=128, totalAddedValues=13}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1661192494975657156, endEpochNanos=1661192495090706133}}] on thread 65

This is a call to a micronaut controller endpoint without any special annotations, but also when adding WithSpan opentelemetry annotations to scheduled jbs they where discovered as well but not reported. Using the Micronaut @NewSpan didn't change anything, still no transactions shown.

[dniel]

all required attributes seems to be there?

[dniel]

Changed Java agent from Elastic APM java agent to OpentTelemetry Java Agent and configured it like described on https://www.elastic.co/guide/en/apm/guide/current/open-telemetry.html worked on first try, but the drawback is that no more JVM metrics is reported from the agent.

Unfortunately the agent throws the following warning, most probably you could try to get the instance from the agent and return instead.

[otel.javaagent 2022-08-22 22:18:09:229 +0200] [scheduled-executor-thread-2] WARN io.opentelemetry.api.GlobalOpenTelemetry - You are currently using the OpenTelemetry Instrumentation Java Agent; all GlobalOpenTelemetry.set calls are ignored - the agent provides the global OpenTelemetry object used by your application.
java.lang.Throwable
	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:97)
	at io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdkBuilder.build(AutoConfiguredOpenTelemetrySdkBuilder.java:370)
	at io.micronaut.tracing.opentelemetry.DefaultOpenTelemetryFactory.defaultOpenTelemetry(DefaultOpenTelemetryFactory.java:97)
	at io.micronaut.tracing.opentelemetry.$DefaultOpenTelemetryFactory$DefaultOpenTelemetry0$Definition.build(Unknown Source)

[dniel]

Just for info, I configured Micronaut 3.6.0 integrated open telemetry feature which run the opentelemetry-exporter in Micronaut.
With the dependencies

implementation("io.micronaut.tracing:micronaut-tracing-core")
implementation("io.micronaut.tracing:micronaut-tracing-opentelemetry-http")
implementation("io.opentelemetry:opentelemetry-extension-annotations")
implementation("io.opentelemetry:opentelemetry-api")
implementation("io.opentelemetry:opentelemetry-exporter-otlp")

and I configured the opentelemetry-exporter like the official otel docs describes by setting the environment variables to my application like below.

OTEL_EXPORTER_OTLP_ENDPOINT=https://xxxxx.apm.eu-west-1.aws.cloud.es.io:443;
OTEL_EXPORTER_OTLP_HEADERS=Authorization=Bearer xxxxxx;
OTEL_METRICS_EXPORTER=otlp;
OTEL_RESOURCE_ATTRIBUTES=service.name=checkoutService,service.version=1.1,deployment.environment=local

This sends OTEL transactions directly to Elastic APM without any agent and using both Otel Annotations and manual transactions to send traces to Elasti APM. I didnt get any stacktraces reported under errors and no JVM metrics is reported but otherwise requests to the controllers and methods annotated with WithSpan is reported without any workaround or extra code in Micronaut and without any running agents.

[dniel]

I wonder if the environment variables could have been provided through application.yaml or the distributed config system isntead of environment variables?

[dniel]

This is the most standard Micronaut way of getting otel data to with as much details (like failed transactions, http controller transactions) I have managed without any extra workarounds in code. This was just done with adding standard config to micronaut.