[Spike] NullPointerException being thrown while trying to link an async token #2002
Comments
kford-newrelic
added this to the Java Agent - FY25Q2 KTLO & Core Instrumentation Improvements milestone
|
@dhilpipre This is very curious. The transactionTime should never be null there. Is there any chance you can get us a repro app? |
|
@jbedell-newrelic I do not and haven't been able to reproduce it myself. Let me reach out to the user to see if we can find some way to reproduce it. |
|
@jbedell-newrelic The customer did not have code that they were willing to share but they did provide some errors that were in the agent logs related to inconsistent tracer where the tracer finishing was not the same as the last tracer. That might have lead to the scenario causing this problem. I think it may come from the Kotlin Coroutine instrumentation where I am using a TracerFactory in order to track a certain type of method in Kotlin. I have also think I know how it might happen and have sent an update to the customer to test. If it gets rid of the problem then I could just close this issue. |
|
@dhilpipre Ah. Looks like this may be a duplicate of #1076 then? |
|
@jbedell-newrelic 2024-07-02T11:48:08,622+0200 [482499 1] com.newrelic INFO: JRE vendor Amazon.com Inc. version 17.0.8.1 2024-07-02T11:50:01,146+0200 [482499 89] com.newrelic ERROR: Tracer Debug: Inconsistent state! tracer (actual tracer popped off stack) != lastTracer (pointer to top of stack) for com.newrelic.agent.TransactionActivity@7fffffff (com.newrelic.agent.tracers.OtherRootTracer@d75d02a != com.newrelic.agent.tracers.DefaultTracer@6888c6bb) |
|
One other thing that we have found in the logs are stackgtraces like this one where there is a TransactionActivity is gone error 2024-08-14T12:24:42,536+0200 [175109 147] com.newrelic.agent.instrumentation.ClassTransformerServiceImpl FINEST: createTracer(Continuation at io.ktor.client.engine.HttpClientEngine$DefaultImpls.executeWithinCallContext(HttpClientEngine.kt:100), 315, null) |
|
One thing that I found in the log that the customer sent me was an UnsupportedOperationException. This happens when the agent is attempting to create a tracer 2024-08-29T15:43:57,594+0200 [68739 101] com.newrelic.agent.instrumentation.ClassTransformerServiceImpl FINEST: createTracer(Continuation at io.ktor.server.netty.cio.NettyHttpResponsePipeline$respondWithBigBody$2.invokeSuspend(NettyHttpResponsePipeline.kt:328), 246, null) The only way that I can see that happening is that the TransactionActivity startAsyncTracerLimitCleanup() method, it is setting the tracers field to Collections.emptyList(). The list returned by emptyList would throw an UnsupportedOperationException. Not sure what the flow is that causes this but it seems to be some weird combination of Kotlin Coroutines and Ktor because I have plenty of customers using the Coroutines instrumentation without this problem. BTW Ktor is built on top of Coroutines. |
|
Unable to reproduce. Will re-engage on this later in the quarter to try and reproduce. Kotlin/Ktor related. |
|
Thread with ASM https://gitlab.ow2.org/asm/asm/-/issues/318024 |
kmudduluru
added
the
jan-mar qtr
kanderson250
changed the title
|
Closing as a Spike, to be completed with #2201 |
github-project-automation
bot
moved this from In Sprint
to Code Complete/Done
in Java Engineering Board
In certain cases where the link method is being called on the Token class, a NullPointerException is being thrown.
It appears that the problem arises when the code reaches the com.newrelic.agent.Transaction.linkTxOnThread(TokenImpl) method. In this code there is this call: oldTx.checkFinishTransaction(oldTxa, oldTxaId);
In checkFinishTransaction, it turns out that this line is called
transactionTime.markTxaFinishTime(txa.getRootTracer());
The transactionTime field is null and this results in an uncaught exception to the application.
At the least, there should be a null check here.
It would also be nice to find out why the transactionTime has not been initialized when it reaches this point.
I am not able to reproduce this error as it was pointed out by a customer using the Labs Ktor instrumentation. Note that Ktor and the underlying Kotlin Coroutines are Kotlin language based if that makes a difference.
Here is a stacktrace of the error
2024-08-08 09:41:59.153 [OperatorApi] [eventLoopGroupProxy-4-6 @call-handler#670] ERROR ktor.application - Unhandled exception caught for CoroutineName(call-handler)
kotlinx.coroutines.CoroutinesInternalError: Fatal exception in coroutines machinery for DispatchedContinuation[NettyDispatcher@55ab96eb, Continuation at io.sparetech.api.TypedApiKt$registerRoutes$2$1$1$1$1.invokeSuspend(TypedApi.kt:175)@468f50cd]. Please read KDoc to 'handleFatalException' method and report this incident to maintainers
at kotlinx.coroutines.DispatchedTask.handleFatalException$kotlinx_coroutines_core(DispatchedTask.kt:142)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:113)
at kotlinx.coroutines.EventLoop.processUnconfinedEvent(EventLoop.common.kt:65)
at kotlinx.coroutines.internal.DispatchedContinuation.resumeWith(DispatchedContinuation.kt:343)
at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:146)
at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:120)
at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:11)
at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:70)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.ktor.server.netty.EventLoopGroupProxy$Companion.create$lambda$1$lambda$0(NettyApplicationEngine.kt:296)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.NullPointerException: Cannot invoke "com.newrelic.agent.transaction.TransactionTimer.markTxaFinishTime(com.newrelic.agent.tracers.Tracer)" because "this.transactionTime" is null
at com.newrelic.agent.Transaction.checkFinishTransaction(Transaction.java:2451)
at com.newrelic.agent.Transaction.linkTxOnThread(Transaction.java:1497)
at com.newrelic.agent.TokenImpl.link(TokenImpl.java:91)
at com.newrelic.instrumentation.kotlin.coroutines_17.NRContinuationWrapper.resumeWith(NRContinuationWrapper.java:44)
at kotlinx.coroutines.UndispatchedCoroutine.afterResume(CoroutineContext.kt:266)
at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:99)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
at com.newrelic.instrumentation.kotlin.coroutines_17.NRContinuationWrapper.resumeWith(NRContinuationWrapper.java:47)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
... 17 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "com.newrelic.agent.transaction.TransactionTimer.markTxaFinishTime(com.newrelic.agent.tracers.Tracer)" because "this.transactionTime" is null
The text was updated successfully, but these errors were encountered: