[2025-08-31T08:34:24.372Z] Running test renaissance-finagle-http_0 ... [2025-08-31T08:34:24.372Z] =============================================== [2025-08-31T08:34:24.372Z] renaissance-finagle-http_0 Start Time: Sun Aug 31 08:34:24 2025 Epoch Time (ms): 1756629264269 [2025-08-31T08:34:24.372Z] variation: NoOptions [2025-08-31T08:34:24.372Z] JVM_OPTIONS: [2025-08-31T08:34:24.372Z] { \ [2025-08-31T08:34:24.372Z] echo ""; echo "TEST SETUP:"; \ [2025-08-31T08:34:24.372Z] echo "Nothing to be done for setup."; \ [2025-08-31T08:34:24.372Z] mkdir -p "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../TKG/output_17566292638285/renaissance-finagle-http_0"; \ [2025-08-31T08:34:24.372Z] cd "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../TKG/output_17566292638285/renaissance-finagle-http_0"; \ [2025-08-31T08:34:24.372Z] echo ""; echo "TESTING:"; \ [2025-08-31T08:34:24.372Z] "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/jdkbinary/j2sdk-image/bin/java" --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/java.util.concurrent=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED --add-opens java.base/sun.nio.ch=ALL-UNNAMED --add-opens java.base/java.lang.invoke=ALL-UNNAMED -jar "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../../jvmtest/perf/renaissance/renaissance.jar" --json ""/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../TKG/output_17566292638285/renaissance-finagle-http_0"/finagle-http.json" finagle-http; \ [2025-08-31T08:34:24.372Z] if [ $? -eq 0 ]; then echo "-----------------------------------"; echo "renaissance-finagle-http_0""_PASSED"; echo "-----------------------------------"; cd /home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/..; rm -f -r "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../TKG/output_17566292638285/renaissance-finagle-http_0"; else echo "-----------------------------------"; echo "renaissance-finagle-http_0""_FAILED"; echo "-----------------------------------"; fi; \ [2025-08-31T08:34:24.372Z] echo ""; echo "TEST TEARDOWN:"; \ [2025-08-31T08:34:24.372Z] echo "Nothing to be done for teardown."; \ [2025-08-31T08:34:24.372Z] } 2>&1 | tee -a "/home/jenkins/workspace/Test_openjdk21_hs_extended.perf_riscv64_linux_rerun/aqa-tests/TKG/../TKG/output_17566292638285/TestTargetResult"; [2025-08-31T08:34:24.372Z] [2025-08-31T08:34:24.372Z] TEST SETUP: [2025-08-31T08:34:24.372Z] Nothing to be done for setup. [2025-08-31T08:34:24.372Z] [2025-08-31T08:34:24.372Z] TESTING: [2025-08-31T08:34:40.230Z] finagle-http on :35829 spawning 4 client and default number of server workers. [2025-08-31T08:34:40.230Z] ====== finagle-http (web) [default], iteration 0 started ====== [2025-08-31T08:34:40.230Z] GC before operation: completed in 143.819 ms, heap usage 12.897 MB -> 10.743 MB. [2025-08-31T08:35:28.398Z] [2025-08-31T08:35:20.308+0000] monitor (com.twitter.util.RootMonitor$$anonfun$2 applyOrElse) [2025-08-31T08:35:28.398Z] SEVERE: Exception propagated to the root monitor! [2025-08-31T08:35:28.398Z] [2025-08-31T08:35:28.398Z] java.lang.IllegalMonitorStateException: attempt to unlock read lock, not locked by current thread [2025-08-31T08:35:28.398Z] at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.unmatchedUnlockException(ReentrantReadWriteLock.java:448) [2025-08-31T08:35:28.398Z] at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:432) [2025-08-31T08:35:28.398Z] at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1180) [2025-08-31T08:35:28.398Z] at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:897) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.Closables.register(Closables.scala:49) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.ListeningStackServer$$anon$1.$anonfun$underlying$1(ListeningStackServer.scala:110) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.ListeningStackServer$$anon$1.$anonfun$underlying$1$adapted(ListeningStackServer.scala:108) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.StdStackServer.mkSession$1(StdStackServer.scala:97) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.StdStackServer.$anonfun$newListeningServer$3(StdStackServer.scala:103) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.StdStackServer.$anonfun$newListeningServer$3$adapted(StdStackServer.scala:101) [2025-08-31T08:35:28.398Z] at com.twitter.util.ConstFuture.com$twitter$util$ConstFuture$$$anonfun$respond$1(ConstFuture.scala:30) [2025-08-31T08:35:28.398Z] at com.twitter.util.ConstFuture$$anonfun$respond$2.doRun(ConstFuture.scala:21) [2025-08-31T08:35:28.398Z] at com.twitter.util.FiberTask.run(FiberTask.scala:14) [2025-08-31T08:35:28.398Z] at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:167) [2025-08-31T08:35:28.398Z] at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:126) [2025-08-31T08:35:28.398Z] at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:243) [2025-08-31T08:35:28.398Z] at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:78) [2025-08-31T08:35:28.398Z] at com.twitter.util.Fiber$$anon$1.submitTask(Fiber.scala:22) [2025-08-31T08:35:28.398Z] at com.twitter.util.ConstFuture.respond(ConstFuture.scala:21) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.StdStackServer.$anonfun$newListeningServer$1(StdStackServer.scala:101) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.server.StdStackServer.$anonfun$newListeningServer$1$adapted(StdStackServer.scala:83) [2025-08-31T08:35:28.398Z] at com.twitter.finagle.netty4.channel.ServerBridge.channelActive(ServerBridge.scala:21) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:260) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) [2025-08-31T08:35:28.398Z] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelActive(DefaultChannelPipeline.java:1345) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:258) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) [2025-08-31T08:35:28.398Z] at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:844) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.AbstractHttp2StreamChannel$Http2ChannelUnsafe.register(AbstractHttp2StreamChannel.java:686) [2025-08-31T08:35:28.398Z] at io.netty.channel.SingleThreadEventLoop.register(SingleThreadEventLoop.java:89) [2025-08-31T08:35:28.398Z] at io.netty.channel.SingleThreadEventLoop.register(SingleThreadEventLoop.java:83) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2MultiplexHandler.userEventTriggered(Http2MultiplexHandler.java:252) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:398) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:376) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:368) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2FrameCodec.onHttp2StreamStateChanged(Http2FrameCodec.java:713) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2FrameCodec.onStreamActive0(Http2FrameCodec.java:503) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2FrameCodec.access$700(Http2FrameCodec.java:146) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2FrameCodec$ConnectionListener.onStreamActive(Http2FrameCodec.java:518) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.addToActiveStreams(DefaultHttp2Connection.java:1022) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.activate(DefaultHttp2Connection.java:977) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultStream.activate(DefaultHttp2Connection.java:504) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:781) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:685) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onHeadersRead(DefaultHttp2ConnectionDecoder.java:360) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onHeadersRead(DefaultHttp2ConnectionDecoder.java:350) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2FrameReader$2.processFragment(DefaultHttp2FrameReader.java:475) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readHeadersFrame(DefaultHttp2FrameReader.java:483) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:247) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:164) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:186) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:61) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:61) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:391) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:451) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) [2025-08-31T08:35:28.398Z] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [2025-08-31T08:35:28.398Z] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) [2025-08-31T08:35:28.398Z] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [2025-08-31T08:35:28.398Z] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868) [2025-08-31T08:35:28.398Z] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [2025-08-31T08:35:28.398Z] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) [2025-08-31T08:35:28.398Z] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) [2025-08-31T08:35:28.398Z] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) [2025-08-31T08:35:28.399Z] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) [2025-08-31T08:35:28.399Z] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [2025-08-31T08:35:28.399Z] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [2025-08-31T08:35:28.399Z] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) [2025-08-31T08:35:28.399Z] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) [2025-08-31T08:35:28.399Z] at com.twitter.finagle.util.BlockingTimeTrackingThreadFactory$$anon$1.run(BlockingTimeTrackingThreadFactory.scala:23) [2025-08-31T08:35:28.399Z] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [2025-08-31T08:35:28.399Z] at java.base/java.lang.Thread.run(Thread.java:1583) [2025-08-31T08:36:26.267Z] ====== finagle-http (web) [default], iteration 0 completed (107511.442 ms) ====== [2025-08-31T08:36:26.267Z] ====== finagle-http (web) [default], iteration 1 started ====== [2025-08-31T08:36:26.267Z] GC before operation: completed in 559.908 ms, heap usage 151.580 MB -> 14.381 MB. [2025-08-31T08:37:35.571Z] ====== finagle-http (web) [default], iteration 1 completed (60021.453 ms) ====== [2025-08-31T08:37:35.571Z] ====== finagle-http (web) [default], iteration 2 started ====== [2025-08-31T08:37:35.571Z] GC before operation: completed in 546.975 ms, heap usage 68.529 MB -> 14.753 MB. [2025-08-31T08:38:03.352Z] ====== finagle-http (web) [default], iteration 2 completed (35830.243 ms) ====== [2025-08-31T08:38:03.352Z] ====== finagle-http (web) [default], iteration 3 started ====== [2025-08-31T08:38:03.352Z] GC before operation: completed in 396.317 ms, heap usage 88.346 MB -> 14.434 MB. [2025-08-31T08:38:43.510Z] ====== finagle-http (web) [default], iteration 3 completed (35997.027 ms) ====== [2025-08-31T08:38:43.510Z] ====== finagle-http (web) [default], iteration 4 started ====== [2025-08-31T08:38:43.510Z] GC before operation: completed in 361.846 ms, heap usage 119.718 MB -> 14.652 MB. [2025-08-31T08:39:16.878Z] ====== finagle-http (web) [default], iteration 4 completed (35032.974 ms) ====== [2025-08-31T08:39:16.878Z] ====== finagle-http (web) [default], iteration 5 started ====== [2025-08-31T08:39:16.878Z] GC before operation: completed in 379.903 ms, heap usage 94.195 MB -> 14.567 MB. [2025-08-31T08:39:56.971Z] ====== finagle-http (web) [default], iteration 5 completed (35668.676 ms) ====== [2025-08-31T08:39:56.971Z] ====== finagle-http (web) [default], iteration 6 started ====== [2025-08-31T08:39:56.971Z] GC before operation: completed in 365.584 ms, heap usage 100.799 MB -> 14.406 MB. [2025-08-31T08:40:24.827Z] ====== finagle-http (web) [default], iteration 6 completed (32846.341 ms) ====== [2025-08-31T08:40:24.827Z] ====== finagle-http (web) [default], iteration 7 started ====== [2025-08-31T08:40:24.827Z] GC before operation: completed in 339.450 ms, heap usage 40.717 MB -> 14.609 MB. [2025-09-01T09:28:15.930Z] Cancelling nested steps due to timeout [2025-09-01T09:28:15.952Z] Sending interrupt signal to process [2025-09-01T09:28:30.923Z] ----------------------------------- [2025-09-01T09:28:30.923Z] renaissance-finagle-http_0_FAILED [2025-09-01T09:28:30.923Z] ----------------------------------- [2025-09-01T09:28:30.923Z] [2025-09-01T09:28:30.923Z] TEST TEARDOWN: [2025-09-01T09:28:30.923Z] Nothing to be done for teardown. [2025-09-01T09:28:30.923Z] renaissance-finagle-http_0 Finish Time: Mon Sep 1 09:28:17 2025 Epoch Time (ms): 1756718897464