Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug] HTTP 504 Gateway Timeout and "action completed with multiple threads" when starting a recording #538

Closed
andrewazores opened this issue Jun 27, 2024 · 3 comments
Closed

[Bug] HTTP 504 Gateway Timeout and "action completed with multiple threads" when starting a recording #538

andrewazores opened this issue Jun 27, 2024 · 3 comments
Labels
bug Something isn't working

Comments

@andrewazores
Copy link
Member

Current Behavior

When attempting to create a new recording on a target application, Cryostat responded with an HTTP 504 Gateway Timeout response and the recording was not created. The Cryostat pod logs show an odd stack trace.

Expected Behavior

The recording should be successfully created on the target.

Steps To Reproduce

No response

Environment

No response

Anything else?

2024-06-27 17:04:25,812 INFO  [io.qua.htt.access-log] (executor-thread-1839) 10.22.8.104 - - [27/Jun/2024:17:04:25 +0000] "POST /api/v1/targets/service%3Ajmx%3Armi%3A%2F%2F%2Fjndi%2Frmi%3A%2F%2F10-130-0-175.namespace.pod%3A9091%2Fjmxrmi/recordings HTTP/1.1" 308 -
2024-06-27 17:04:26,029 WARN  [io.cry.tar.TargetConnectionManager] (executor-thread-1839) java.io.IOException: The client has been closed.
2024-06-27 17:04:33,639 INFO  [io.qua.htt.access-log] (executor-thread-1848) 10.129.0.1 - - [27/Jun/2024:17:04:33 +0000] "GET /health/liveness HTTP/1.1" 204 -
2024-06-27 17:04:36,039 WARN  [com.arj.ats.arjuna] (executor-thread-1839) ARJUNA012095: Abort of action id 0:ffff0a8100d7:9219:667b2756:2e3d8 invoked while multiple threads active within it.
2024-06-27 17:04:36,047 WARN  [com.arj.ats.arjuna] (executor-thread-1839) ARJUNA012381: Action id 0:ffff0a8100d7:9219:667b2756:2e3d8 completed with multiple threads - thread executor-thread-1846 was in progress with java.base@17.0.11/jdk.internal.misc.Unsafe.park(Native Method)
java.base@17.0.11/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
java.base@17.0.11/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:717)
java.base@17.0.11/java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1074)
java.base@17.0.11/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:276)
io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:63)
io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:65)
io.cryostat.targets.TargetConnectionManager.executeConnectedTask(TargetConnectionManager.java:207)
io.cryostat.targets.TargetConnectionManager_ClientProxy.executeConnectedTask(Unknown Source)
io.cryostat.recordings.RecordingOptionsBuilderFactory.create(RecordingOptionsBuilderFactory.java:36)
io.cryostat.recordings.RecordingOptionsBuilderFactory_ClientProxy.create(Unknown Source)
io.cryostat.recordings.RecordingHelper.lambda$startRecordingImpl$10(RecordingHelper.java:360)
io.cryostat.recordings.RecordingHelper$$Lambda$2417/0x00007f3fbfdae000.execute(Unknown Source)
io.cryostat.targets.TargetConnectionManager.lambda$executeConnectedTaskUni$1(TargetConnectionManager.java:201)
io.cryostat.targets.TargetConnectionManager$$Lambda$2333/0x00007f3fbfd43580.apply(Unknown Source)
io.smallrye.mutiny.unchecked.UncheckedFunction.lambda$toFunction$0(UncheckedFunction.java:45)
io.smallrye.mutiny.unchecked.UncheckedFunction$$Lambda$2334/0x00007f3fbfd437d8.apply(Unknown Source)
io.smallrye.context.impl.wrappers.SlowContextualFunction.apply(SlowContextualFunction.java:21)
io.smallrye.mutiny.operators.uni.UniOnItemTransform$UniOnItemTransformProcessor.onItem(UniOnItemTransform.java:36)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription$$Lambda$2335/0x00007f3fbfd4c000.accept(Unknown Source)
java.base@17.0.11/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
java.base@17.0.11/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)
java.base@17.0.11/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)
java.base@17.0.11/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:144)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forward(UniCreateFromCompletionStage.java:51)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage.subscribe(UniCreateFromCompletionStage.java:35)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnItemTransform.subscribe(UniOnItemTransform.java:22)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnFailureTransform.subscribe(UniOnFailureTransform.java:31)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnItemConsume.subscribe(UniOnItemConsume.java:30)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnFailureTransform.subscribe(UniOnFailureTransform.java:31)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnFailureTransform.subscribe(UniOnFailureTransform.java:31)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnFailureTransform.subscribe(UniOnFailureTransform.java:31)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniOnFailureTransform.subscribe(UniOnFailureTransform.java:31)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.converters.uni.UniToMultiPublisher$UniToMultiSubscription.request(UniToMultiPublisher.java:73)
io.smallrye.mutiny.subscription.SwitchableSubscriptionSubscriber.setOrSwitchUpstream(SwitchableSubscriptionSubscriber.java:205)
io.smallrye.mutiny.subscription.SwitchableSubscriptionSubscriber.onSubscribe(SwitchableSubscriptionSubscriber.java:107)
io.smallrye.mutiny.converters.uni.UniToMultiPublisher.subscribe(UniToMultiPublisher.java:25)
io.smallrye.mutiny.groups.MultiCreate$1.subscribe(MultiCreate.java:165)
io.smallrye.mutiny.operators.multi.MultiRetryWhenOp$RetryWhenOperator.resubscribe(MultiRetryWhenOp.java:157)
io.smallrye.mutiny.operators.multi.MultiRetryWhenOp$TriggerSubscriber.onNext(MultiRetryWhenOp.java:188)
io.smallrye.mutiny.helpers.HalfSerializer.onNext(HalfSerializer.java:30)
io.smallrye.mutiny.helpers.StrictMultiSubscriber.onItem(StrictMultiSubscriber.java:84)
io.smallrye.mutiny.operators.multi.MultiConcatMapOp$ConcatMapMainSubscriber.tryEmit(MultiConcatMapOp.java:182)
io.smallrye.mutiny.operators.multi.MultiConcatMapOp$ConcatMapInner.onItem(MultiConcatMapOp.java:285)
io.smallrye.mutiny.subscription.MultiSubscriber.onNext(MultiSubscriber.java:61)
io.smallrye.mutiny.converters.uni.UniToMultiPublisher$UniToMultiSubscription.onItem(UniToMultiPublisher.java:92)
io.smallrye.mutiny.operators.uni.UniDelayOnItem$UniDelayOnItemProcessor.lambda$onItem$0(UniDelayOnItem.java:53)
io.smallrye.mutiny.operators.uni.UniDelayOnItem$UniDelayOnItemProcessor$$Lambda$2969/0x00007f3fbff3b210.run(Unknown Source)
org.jboss.threads.EnhancedQueueExecutor$RunnableScheduledFuture.performTask(EnhancedQueueExecutor.java:2892)
org.jboss.threads.EnhancedQueueExecutor$RunnableScheduledFuture.performTask(EnhancedQueueExecutor.java:2883)
org.jboss.threads.EnhancedQueueExecutor$AbstractScheduledFuture.run(EnhancedQueueExecutor.java:2741)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base@17.0.11/java.lang.Thread.run(Thread.java:840)

2024-06-27 17:04:36,047 WARN  [com.arj.ats.arjuna] (executor-thread-1839) ARJUNA012381: Action id 0:ffff0a8100d7:9219:667b2756:2e3d8 completed with multiple threads - thread executor-thread-1839 was in progress with java.base/java.lang.Thread.getStackTrace(Thread.java:1619)
com.arjuna.ats.arjuna.coordinator.BasicAction.createStackTraces(BasicAction.java:3406)
com.arjuna.ats.arjuna.coordinator.BasicAction.checkChildren(BasicAction.java:3443)
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1672)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1377)
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:145)
io.quarkus.narayana.jta.runtime.NotifyingTransactionManager.rollback(NotifyingTransactionManager.java:94)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:404)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:175)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
io.cryostat.recordings.Recordings_Subclass.createRecording(Unknown Source)
io.cryostat.recordings.Recordings$quarkusrestinvoker$createRecording_3a6d003fcdb6a24416e86a17a2a45440af6f87f7.invoke(Unknown Source)
org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base/java.lang.Thread.run(Thread.java:840)

2024-06-27 17:04:36,047 WARN  [com.arj.ats.arjuna] (executor-thread-1839) ARJUNA012381: Action id 0:ffff0a8100d7:9219:667b2756:2e3d8 completed with multiple threads - thread executor-thread-1849 was in progress with io.cryostat.targets.TargetConnectionManager.lambda$executeConnectedTaskUni$1(TargetConnectionManager.java:199)
io.cryostat.targets.TargetConnectionManager$$Lambda$2333/0x00007f3fbfd43580.apply(Unknown Source)
io.smallrye.mutiny.unchecked.UncheckedFunction.lambda$toFunction$0(UncheckedFunction.java:45)
io.smallrye.mutiny.unchecked.UncheckedFunction$$Lambda$2334/0x00007f3fbfd437d8.apply(Unknown Source)
io.smallrye.context.impl.wrappers.SlowContextualFunction.apply(SlowContextualFunction.java:21)
io.smallrye.mutiny.operators.uni.UniOnItemTransform$UniOnItemTransformProcessor.onItem(UniOnItemTransform.java:36)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription.forwardResult(UniCreateFromCompletionStage.java:63)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromCompletionStage$CompletionStageUniSubscription$$Lambda$2335/0x00007f3fbfd4c000.accept(Unknown Source)
java.base@17.0.11/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
java.base@17.0.11/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
java.base@17.0.11/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
java.base@17.0.11/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base@17.0.11/java.lang.Thread.run(Thread.java:840)

2024-06-27 17:04:36,047 WARN  [com.arj.ats.arjuna] (executor-thread-1839) ARJUNA012108: CheckedAction::check - atomic action 0:ffff0a8100d7:9219:667b2756:2e3d8 aborting with 3 threads active!
2024-06-27 17:04:36,055 WARN  [com.arj.ats.jta] (executor-thread-1839) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff0a8100d7:9219:667b2756:2e3d8, node_name=quarkus, branch_uid=0:ffff0a8100d7:9219:667b2756:2e3db, subordinatenodename=null, eis_name=0 > (io.agroal.narayana.LocalXAResource@1d0011fd) failed with exception code XAException.XAER_RMERR: javax.transaction.xa.XAException: Error trying to transactionRollback local transaction: Enlisted connection used without active transaction
	at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:140)
	at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:134)
	at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:88)
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3037)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3016)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1679)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
	at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1377)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:145)
	at io.quarkus.narayana.jta.runtime.NotifyingTransactionManager.rollback(NotifyingTransactionManager.java:94)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:404)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:175)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
	at io.cryostat.recordings.Recordings_Subclass.createRecording(Unknown Source)
	at io.cryostat.recordings.Recordings$quarkusrestinvoker$createRecording_3a6d003fcdb6a24416e86a17a2a45440af6f87f7.invoke(Unknown Source)
	at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
	at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
	at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.sql.SQLException: Enlisted connection used without active transaction
	at io.agroal.pool.ConnectionHandler.verifyEnlistment(ConnectionHandler.java:398)
	at io.agroal.pool.ConnectionHandler.transactionRollback(ConnectionHandler.java:366)
	at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:85)
	... 31 more

2024-06-27 17:04:36,056 WARN  [io.cry.ExceptionMappers] (executor-thread-1839) io.smallrye.mutiny.TimeoutException
2024-06-27 17:04:36,057 INFO  [io.qua.htt.access-log] (executor-thread-1839) 10.22.8.104 - - [27/Jun/2024:17:04:36 +0000] "POST /api/v3/targets/1/recordings HTTP/1.1" 504 -
@andrewazores andrewazores added the bug Something isn't working label Jun 27, 2024
@andrewazores
Copy link
Member Author

Looks similar: quarkusio/quarkus#38913

According to this, the "multiple threads" message may just be a side effect of how the actual operation timeout is reported.

@andrewazores
Copy link
Member Author

andrewazores commented Jun 27, 2024 •
edited
Loading

After this error, trying to create another recording with the same name fails:

2024-06-27 17:20:43,812 WARN [io.cry.ExceptionMappers] (executor-thread-1856) io.cryostat.util.EntityExistsException: Recording with name continue already exists. Try again with a different name
2024-06-27 17:20:43,812 INFO [io.qua.htt.access-log] (executor-thread-1856) 10.22.8.104 - - [27/Jun/2024:17:20:43 +0000] "POST /api/v3/targets/1/recordings HTTP/1.1" 409 76

and upon further investigation, the original request actually did result in a new recording being created on the target. Re-visiting the active recordings table results in Cryostat re-querying the target and finding that the recording does exist. However, since this is re-discovered after the fact, Cryostat thinks this recording was created externally and it has no labels associated with it.

@andrewazores
Copy link
Member Author

I haven't observed this in a long time, and I think part of #689 also addresses the root cause here. Closing for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@andrewazores