Noticed that my k8s pod was unexpectedly restarting while under load after a few minutes of REST traffic. k8s showed that my probes were not responding to my HTTP health checks (q/health/live and q/health/ready). Application logs started to show the following:
2021-10-12 19:49:38,542 WARN [io.net.boo.ServerBootstrap] (vert.x-acceptor-thread-0) Failed to register an accepted channel: [id: 0xc6f17976, L:0.0.0.0/0.0.0.0:9090]: java.lang.IllegalStateException
at io.vertx.core.net.impl.VertxEventLoopGroup.next(VertxEventLoopGroup.java:37)
at io.vertx.core.net.impl.VertxEventLoopGroup.register(VertxEventLoopGroup.java:53)
at io.netty.bootstrap.ServerBootstrap$ServerBootstrapAcceptor.channelRead(ServerBootstrap.java:215)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:97)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:484)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:829)
at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:567)
at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
These are repeated over and over again until this message is logged:
2021-10-12 19:49:38,913 ERROR [io.qua.ver.cor.run.VertxCoreRecorder] (vert.x-eventloop-thread-1) Uncaught exception received by Vert.x: java.lang.IllegalStateException: Client is closed
at io.vertx.core.net.impl.NetClientImpl.checkClosed(NetClientImpl.java:175)
at io.vertx.core.net.impl.NetClientImpl.connectInternal(NetClientImpl.java:219)
at io.vertx.core.net.impl.NetClientImpl.connect(NetClientImpl.java:206)
at io.vertx.core.net.impl.NetClientImpl.connect(NetClientImpl.java:185)
at io.vertx.core.net.impl.NetClientImpl.connect(NetClientImpl.java:191)
at io.vertx.redis.client.impl.RedisConnectionManager$RedisConnectionProvider.connect(RedisConnectionManager.java:141)
at io.vertx.core.net.impl.pool.SimpleConnectionPool.connect(SimpleConnectionPool.java:240)
at io.vertx.core.net.impl.pool.SimpleConnectionPool$Remove.lambda$execute$0(SimpleConnectionPool.java:390)
at io.vertx.core.net.impl.pool.CombinerExecutor.pollAndExecute(CombinerExecutor.java:55)
at io.vertx.core.net.impl.pool.CombinerExecutor.submit(CombinerExecutor.java:43)
at io.vertx.core.net.impl.pool.SimpleConnectionPool.execute(SimpleConnectionPool.java:231)
at io.vertx.core.net.impl.pool.SimpleConnectionPool.remove(SimpleConnectionPool.java:456)
at io.vertx.core.net.impl.pool.SimpleConnectionPool.access$000(SimpleConnectionPool.java:79)
at io.vertx.core.net.impl.pool.SimpleConnectionPool$Slot.onRemove(SimpleConnectionPool.java:138)
at io.vertx.redis.client.impl.RedisStandaloneConnection.evict(RedisStandaloneConnection.java:360)
at io.vertx.redis.client.impl.RedisStandaloneConnection.end(RedisStandaloneConnection.java:323)
at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:389)
at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:81)
at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:173)
at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:51)
at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:211)
at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)
at io.vertx.core.Promise.complete(Promise.java:66)
at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605)
at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96)
at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78)
at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73)
at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:380)
at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:382)
at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:144)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:831)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:829)
at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:567)
at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
Running the same load mix against a non-native image build did NOT have the same problem.
I am using the quarkus redis client created programmatically -- i.e. not @Inject into my app, but doing the following:
RedisClient defaultRedisClient = RedisClient.createClient();
Not sure if redis has anything to do with it, but seeing vert.x in the call-stack made me think of it. Also not sure what "Failed to register an accepted channel" might mean.
If I scale-back the traffic, I don't see this problem which leads me to think the app cannot handle the load. If that is the case, seems like there should be a way to detect this condition rather than having a slew of exceptions followed by k8s restarting the pod.
My worry is that there might be some underlying issue that I'm missing "going native" as I don't see this with a non-native build.
Thanks.