Elastic APM - Java Spring Webflux - java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade

Elastic Observability APM
1

If you are asking about a problem you are experiencing, please use the following template, as it will help us help you. If you have a different problem, please delete all of this text :slight_smile:

TIP 1: select at least one tag that further categorizes your topic. For example server for APM Server related questions, java for questions regarding the Elastic APM Java agent, or ui for questions about the APM App within Kibana.

TIP 2: Check out the troubleshooting guide first. Not only will it help you to resolve common problems faster but it also explains in more detail which information we need before we can properly help you.

APM Server version: 8.10.4

APM Agent language and version: Java 17

Browser version:

Original install method (e.g. download page, yum, deb, from source, etc.) and version:

Fresh install or upgraded from other version?

Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
We are using Java APM Agent version 1.43.0 in a Spring boot Webflux application. The application is run in a container in K8s as POD. The application uses spring boot actuators. The health check endpoints are exposed as //health/readiness and /health/liveness.

On a periodic basis we see a dump in the application's pod log. The stack trace is attached below.

note: The webflux application does not use the annotation - @EnableWebFlux

Could you let us know if there is any missing configuration which is causing this periodic exception.

The APM Java agent is attached to the application using the java code

ElasticApmAttacher.attach();

Provide logs and/or server output (if relevant):


||at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:122)|
|---|---|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.Operators$BaseFluxToMonoOperator.completePossiblyEmpty(Operators.java:2071)|
||at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:145)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onComplete(TracedSubscriber.java:141)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:847)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:609)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:895)|
||at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:998)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onComplete(TracedSubscriber.java:141)|
||at reactor.core.publisher.MonoZip$ZipCoordinator.signal(MonoZip.java:294)|
||at reactor.core.publisher.MonoZip$ZipInner.onNext(MonoZip.java:474)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onNext(MonoSubscribeOn.java:146)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.MonoCallable$MonoCallableSubscription.request(MonoCallable.java:156)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onSubscribe(TracedSubscriber.java:85)|
||at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:48)|
||at reactor.core.publisher.Mono.subscribe(Mono.java:4495)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126)|
||at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)|
||at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)|
||at java.base/java.util.concurrent.FutureTask.run(Unknown Source)|
||at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)|
||at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)|
||at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)|
||at java.base/java.lang.Thread.run(Unknown Source)|
2

Is there an error header that you haven't included in that stack trace?

3

I activated the log level to DEBUG and could find more information. I am attaching few log statements just before the exception.

{"@timestamp":"2024-01-05T09:33:29.984Z","log.level":"DEBUG","message":"Activating 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) on thread 105", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.ActiveStack"}

{"@timestamp":"2024-01-05T09:33:29.984Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (73)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.984Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (74)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.984Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (75)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.984Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (76)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (77)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (78)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (79)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (80)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (81)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (82)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (83)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (84)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (85)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (86)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (87)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"increment references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (88)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"decrement references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (87)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"decrement references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (86)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

{"@timestamp":"2024-01-05T09:33:29.985Z","log.level":"DEBUG","message":"decrement references to 'GET unknown route' 00-48a645500e44ad10f2263c194a8f4a18-d5c5ff2afc40da3f-00 (627b2554) (85)", "ecs.version": "1.2.0","event.dataset":"ob.apm-agent","process.thread.name":"boundedElastic-1","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}

2024-01-05 09:33:29 boundedElastic-2 ERROR - Operator called default onErrorDropped

java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade
|at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:122)|
|---|---|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137)|
||at reactor.core.publisher.Operators$BaseFluxToMonoOperator.completePossiblyEmpty(Operators.java:2071)|
||at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:145)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onComplete(TracedSubscriber.java:141)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:847)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:609)|
||at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:895)|
||at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:998)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onComplete(TracedSubscriber.java:141)|
||at reactor.core.publisher.MonoZip$ZipCoordinator.signal(MonoZip.java:294)|
||at reactor.core.publisher.MonoZip$ZipInner.onNext(MonoZip.java:474)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onNext(MonoSubscribeOn.java:146)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onNext(TracedSubscriber.java:106)|
||at reactor.core.publisher.MonoCallable$MonoCallableSubscription.request(MonoCallable.java:156)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134)|
||at co.elastic.apm.agent.reactor.TracedSubscriber.onSubscribe(TracedSubscriber.java:85)|
||at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:48)|
||at reactor.core.publisher.Mono.subscribe(Mono.java:4495)|
||at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126)|
||at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)|
||at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)|
||at java.base/java.util.concurrent.FutureTask.run(Unknown Source)|
||at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)|
||at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)|
||at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)|
||at java.base/java.lang.Thread.run(Unknown Source)|
4

Hmm, okay I'll need your help to interpret this. This looks like a stream is being processed and hits an error during processing, then on resuming after handling the error it hits the recycling error and throws that stack. The recycling error is from reactor not the agent. So assuming that you agree that's what happening here, does this happen also when there is no agent installed, or is does stack trace only happen with the agent?

If it's only with the agent, I would guess we need to handle the error-thrown case to not continue the onNext() call, which kind of makes sense

5

I removed the line ElasticApmAttacher.attach(); from the application. Now i dont observe the periodic failure. So it looks like the issue occurs only when we attach the apm java agent.

6

I think the fact that the error only occurs only with elastic might be simply a side effect of a slightly increased runtime of the async operation:

The error

java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade

to my knowledge actually comes from the underlying servlet container, when you are using a javax.servlet.ServletRequest (or the jakrata one) after the request and response have actually been processed.

So I think you are actually using the ServletRequest in your asynchronous operation beyond it's lifetime: The problem surfaces most likely due to a different latency of the async operation with the agent enabled, because it is a race condition.

7

The spring java application that we have does not expose any APIs over HTTP (No Servlets configured or no @RESTController annotated classes) other than the health check - exposed via Spring Actuators. The java application that we have is mainly used as a worker for processing incoming requests via gRPC. The application starts a gRPC server and processes the incoming requests and sends the response back to the caller.

So i am not sure if this error keeps happening on a periodic basis; is to do with the polling of health check endpoints ?

8

So i am not sure if this error keeps happening on a periodic basis; is to do with the polling of health check endpoints ?

I guess that seems the most likey, that there is something wrong with your health check implementations. But as the source of the problem is most likely not really related to the apm java agent, but to your application, we can't help you any further here.

9

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.