Problem with distributing tracing for Jakarta 10 and payara 6

Elastic Observability APM
1

Hi,

I have a problem with distributing tracing after migration of my application (few microservices) from Payara 5.201 to 6.2024.12. During migration we have already updated application to Jakarta 10 (previous Java EE 8), to JDK 21 (previous JDK 11).

Kibana version: v 8.17.0

Elasticsearch version: v 8.17.0

APM Server version: v 8.17.0

APM Agent language and version: 1.52.1

In Kibana - distributed tracing is broken for transaction. I see only this transaction.name like - ServletContainer#doPost or ServletContainer#doGet

After clicking on transaction I cannot see other REST api calls or database span and other spans which were related to this transaction.

Elastic APM agent is attached to payara via jvm options and data are sent to apm server directly.

Previously my distributing traces in Kibana:

Screenshot 2025-01-03 at 12.49.12
Screenshot 2025-01-03 at 12.49.122282×559 59.7 KB

Now - No spans

When I start my Payara server with application, I see in my payara server.log this error:

2024-12-19 14:31:34,684 [http-thread-pool::http-listener-1(23)] WARN  co.elastic.apm.agent.impl.transaction.AbstractSpanImpl - End has already been called: 'ServletContainer#doGet' 00-fce4d5a73d9730ceda1fa9dfa23a6cb6-38d98ac57c88f2bd-01 (55550545)
java.lang.Throwable: null
	at co.elastic.apm.agent.impl.transaction.AbstractSpanImpl.end(AbstractSpanImpl.java:582) ~[elastic-apm-agent-1.52.1.jar:1.52.1]
	at co.elastic.apm.agent.impl.transaction.AbstractSpanImpl.end(AbstractSpanImpl.java:549) ~[elastic-apm-agent-1.52.1.jar:1.52.1]
	at co.elastic.apm.agent.servlet.ServletTransactionHelper.onAfter(ServletTransactionHelper.java:248) ~[elastic-apm-agent-1.52.1.jar:1.52.1]
	at co.elastic.apm.agent.servlet.ServletApiAdvice.onExitServlet(ServletApiAdvice.java:277) ~[elastic-apm-agent-1.52.1.jar:1.52.1]
	at co.elastic.apm.agent.servlet.JakartaServletApiAdvice.onExitServletService(JakartaServletApiAdvice.java:45) ~[elastic-apm-agent-1.52.1.jar:1.52.1]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:213) ~[web-core.jar:?]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:257) ~[web-core.jar:?]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:166) ~[web-core.jar:?]
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:757) ~[web-core.jar:?]
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:577) ~[web-core.jar:?]
	at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99) ~[web-glue.jar:?]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:158) ~[web-core.jar:?]
	at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:372) ~[web-core.jar:?]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:239) ~[web-core.jar:?]
	at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:520) ~[kernel.jar:?]
	at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:217) ~[kernel.jar:?]
	at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:174) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:153) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:196) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:88) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:246) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:178) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:118) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:96) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:51) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:510) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:82) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:83) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:101) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535) ~[nucleus-grizzly-all.jar:?]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515) ~[nucleus-grizzly-all.jar:?]
	at java.lang.Thread.run(Thread.java:1583) [?:?]
2024-12-19 14:31:40,493 [http-thread-pool::http-listener-1(24)]

I found in elastic java agent documentation that Payara 6 is not supported or tested. How to resolve this issue? Is there any option how to fix this issue?

Thanks in advance.

2

Hi, thanks for reporting this !

The error message here indicates that there could be a bug in the agent, in particular it seems that the lifecycle of the transaction (which is here from servlet instrumentation) does not match what we usually expect, hence the message about already ended span/transaction.

This is very probably related to your update of Payara 6.

  • Can you easily reproduce it ?
  • Is there anything special with this particular transaction or does it happens with all of them ? For example, this may happen only on async servlets, or there is something special in the servlet/filter configuration.
  • can you provide a simple application that helps reproduce it ?
3

I have already prepared simple application where you can reproduce this issue.

For simplicity - 1 transaction and 1 span (via @Traced annotation)

APM with Payara 5:

Screenshot 2025-01-08 at 15.53.12
Screenshot 2025-01-08 at 15.53.122672×1462 450 KB

APM with payara 6:

Screenshot 2025-01-08 at 15.17.00
Screenshot 2025-01-08 at 15.17.002672×1462 445 KB

I can summary here what is not working on payara 6.

  1. transaction.name - only see ServletContane#doGet instead of proper name of resource#method
  2. traced annotation is not visible
  3. in response header - (see TraceIdHeaderResponseFilter) - for async REST call the header X-Trace-Id is always empty (on payara 5 - trace id is always added to response header)

Thanks.

4

I have managed to reproduce your setup, I have observed the following regarding transaction name:

  • the first invocation of HelloResource#hello after the domain startup is properly named
  • the following invocations the same URL are all captured as ServletContainer#doGet

Restarting the domain allows to reproduce this behavior.

In both cases, the method annotated with @Traced is not being captured as it should, and I don't know yet why.

5

I think that I've found the issue for the transaction name:

You are using JAX-RS to create your endpoints, which is most often executed within a servlet container.

For the first invocation of the JAX-RS resource, a "servlet transaction" is captured and the JAZ-RS instrumentation overrides the name of the transaction.

For the next invocations, there is no such "servlet transaction" created as the invocation of the JAX-RS resource is made directly, however the agent does not currently creates transactions for such "stand-alone JAX-RS" execution as described in this issue and as written in the comments fixing that could be tricky.

For the method annotated with @Traced this is still unexpected, as even in the first method invocation we can't see the method properly traced, whereas it should be.

As an alternative approach here I tried doing the same with the opentelemetry-java-instrumentation project without any success, when adding the -javaagent with the agent jar it prevents the server from starting and I did not managed to get any hint on the pausible cause.

As yet another alternative, it seems there is a partial support for otel tracing directly into Payara which can be enabled with <jvm-options>-Dotel.sdk.disabled=false</jvm-options> in the JVM options, using otel.exporter.otlp.endpoint and otel.exporter.otlp.headers to provide apm-server URL and authentication did not allowed me to send any data to apm-server however.

6

Hi @Sylvain_Juge.

I have the same behaviour for elastic apm agent. Name for first transaction is ok, other transactions have broken name.

I tried open-telemetry agent. I have no problem to start Payara with this agent, as you mentioned before. Distributing tracing is not working for 100%, I still have a issue with asynchronous requests... but this is another topic. :slight_smile:

I have a question about elastic java agent and this issue which is in this thread. Should I raise some ticket for Elastic Team or what is your opinion how to resolve this bug? Or Could you share this bug with your team members?

Thanks.

7

I've opened Paraya 6 JAX-RS invalid transaction name + no span captured with @Trace · Issue #3943 · elastic/apm-agent-java · GitHub to track those issues and not to forget about it.

From what I understand this might be limited to JAX-RS resources deployed in payara, which could explain why it wasn't reported earlier. If you have other jax-rs applications that are using a servlet architecture (and not the one provided by the container), it could be worth to investigate if those are also affected or if it's only for this particular use-case.

When using opentelemetry java agent, if there are any issues I would recommend filing an issue in the opentelemetry java instrumentation repository where the instrumentation is being done. Providing ready-to-use examples like you already did here to reproduce issues is key to ensure they are quickly fixed.