search

newrelic-experimental / newrelic-java-ktor

New Relic Java Instrumentation for the Ktor server and client frameworks
Apache License 2.0
0 stars 0 forks source link

Application Timed Out #7

Open Saimamunir opened 2 months ago

Saimamunir commented 2 months ago

Hi New Relic Team,

I raised the issue earlier from previous version that the transactions couldn't be seen in New Relic. Thanks for resolving that with new version v2. I downloaded the new jars for ktor and kotlin coroutines and now able to see Transactions in New Relic. However ,after downloading new jars , our application is timing out like 2 out of 3 requests are timed out (if I remove these jars, the app works fine). Sharing the logs with you, if they could help in locating the problem.

2024-08-05 16:32:12.099 +1000 [39mDEBUG[0;39m [32mprogram='DefaultDispatcher-worker-8'[0;39m [36mclass='a.c.a.i.b.InMemoryIDPAuthenticationServiceImpl'[0;39m [32mtraceId=\Root=1-66b071ec-0cf54c433a6319553e17229d[0;39m Using cached token 2024-08-05T16:32:12,786+1000 [19 85] 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@71c3658c != com.newrelic.agent.tracers.DefaultTracer@20835589) 2024-08-05T16:32:12,788+1000 [19 85] com.newrelic ERROR: Tracer Debug: An error occurred calling Transaction.tracerFinished() for class kotlin.coroutines.jvm.internal.BaseContinuationImpl : java.lang.NullPointerException : this Tracer = com.newrelic.agent.tracers.OtherRootTracer@71c3658c 2024-08-05T16:32:12,788+1000 [19 85] 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@414babe4 != com.newrelic.agent.tracers.DefaultTracer@2f4a0ccd) 2024-08-05T16:32:12,788+1000 [19 85] com.newrelic ERROR: Tracer Debug: An error occurred calling Transaction.tracerFinished() for class kotlin.coroutines.jvm.internal.BaseContinuationImpl : java.lang.NullPointerException : this Tracer = com.newrelic.agent.tracers.OtherRootTracer@414babe4 2024-08-05T16:32:12,791+1000 [19 67] 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@7688bc92 != com.newrelic.agent.tracers.DefaultTracer@3c92cfa) 2024-08-05T16:32:12,791+1000 [19 67] com.newrelic ERROR: Tracer Debug: An error occurred calling Transaction.tracerFinished() for class kotlin.coroutines.jvm.internal.BaseContinuationImpl : java.lang.NullPointerException : this Tracer = com.newrelic.agent.tracers.OtherRootTracer@7688bc92

2024-08-05 16:41:19.890 +1000 [1;31mERROR[0;39m [32mprogram='DefaultDispatcher-worker-13'[0;39m [36mclass='Application'[0;39m [32m[0;39m Unhandled exception caught for CoroutineName(servlet) kotlinx.coroutines.CoroutinesInternalError: Fatal exception in coroutines machinery for DispatchedContinuation[Dispatchers.Unconfined, Continuation at io.ktor.utils.io.ByteBufferChannel.writeSuspend(ByteBufferChannel.kt:1439)@7676cbdd]. Please read KDoc to 'handleFatalException' method and report this incident to maintainers at kotlinx.coroutines.DispatchedTask.handleFatalException(DispatchedTask.kt:144) at kotlinx.coroutines.internal.DispatchedContinuation.resumeWith(DispatchedContinuation.kt:352) at io.ktor.utils.io.internal.CancellableReusableContinuation.resumeWith(CancellableReusableContinuation.kt:93) at io.ktor.utils.io.ByteBufferChannel.resumeWriteOp(ByteBufferChannel.kt:2128) at io.ktor.utils.io.ByteBufferChannel.bytesRead(ByteBufferChannel.kt:906) at io.ktor.utils.io.ByteBufferChannel.readAsMuchAsPossible(ByteBufferChannel.kt:556) at io.ktor.utils.io.ByteBufferChannel.readAvailable$suspendImpl(ByteBufferChannel.kt:678) at io.ktor.utils.io.ByteBufferChannel.readAvailable(ByteBufferChannel.kt) at io.ktor.utils.io.ByteReadChannelKt.readAvailable(ByteReadChannel.kt:235) at io.ktor.server.servlet.ServletWriter.loop(ServletWriter.kt:79) at io.ktor.server.servlet.ServletWriter.access$loop(ServletWriter.kt:37) at io.ktor.server.servlet.ServletWriter$loop$1.invokeSuspend(ServletWriter.kt) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:115) at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:100) at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684) Caused by: java.lang.NullPointerException: null

SebastianSidortschuck commented 2 months ago

We're having the same issues as mentioned here when using the newest version. We did not validate the request timeout, but locally could see the same errors in the newrelic_agent.log and a similar fatal exception in our application log.

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
dhilpipre commented 2 months ago

There appears to be a bug in the Java Agent that causes this problem. There should be a check to make sure that that particular field has been set. In the meantime I can put safety checks into the instrumentation code so we avoid the null pointer. It should be ready next week. I will send you an update via your New Relic Sales Engineer to verify that it works before releasing.