search

gentics / mesh

Gentics Mesh - The open source headless CMS for developers
https://getmesh.io
Apache License 2.0
572 stars 115 forks source link

Lock in writes is throwing blocking thread errors in logs #1049

Open cschockaert opened 4 years ago

cschockaert commented 4 years ago

Gentics Mesh Version, operating system, or hardware.

Problem

When a topology lock timeout is define (for example 60 000ms) AND node is entering in backup process AND we are modifying node we can see theses errors logs:

getmesh-staging-master-0 getmesh 14:14:44.308 WARN  [vertx-blocked-thread-checker] [i.v.c.i.BlockedThreadChecker] - Thread Thread[vert.x-eventloop-thread-3,5,main]=Thread[vert.x-eventloop-thread-3,5,main] has been blocked for 46755 ms, time limit is 2000 ms
getmesh-staging-master-0 getmesh io.vertx.core.VertxException: Thread blocked
getmesh-staging-master-0 getmesh    at java.base@11.0.5/java.lang.Thread.sleep(Native Method)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.graphdb.OrientDBDatabase.blockingTopologyLockCheck(OrientDBDatabase.java:391)
getmesh-staging-master-0 getmesh    at app//com.syncleus.ferma.ext.orientdb3.OrientDBTx.close(OrientDBTx.java:61)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.graphdb.OrientDBDatabase.tx(OrientDBDatabase.java:417)
getmesh-staging-master-0 getmesh    at app//com.gentics.madl.tx.TxFactory.tx(TxFactory.java:70)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.handler.MeshAnonymousAuthHandler.handle(MeshAnonymousAuthHandler.java:85)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshAuthChain.lambda$secure$1(MeshAuthChain.java:48)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshAuthChain$$Lambda$587/0x0000000100b51040.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:95)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshOAuth2ServiceImpl.lambda$secure$2(MeshOAuth2ServiceImpl.java:147)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshOAuth2ServiceImpl$$Lambda$582/0x0000000100b50040.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:95)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshOAuth2ServiceImpl.lambda$secure$0(MeshOAuth2ServiceImpl.java:132)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshOAuth2ServiceImpl$$Lambda$577/0x0000000100b45840.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:95)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.handler.MeshJWTAuthHandler.handleJWTAuth(MeshJWTAuthHandler.java:139)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.handler.MeshJWTAuthHandler.handle(MeshJWTAuthHandler.java:89)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshAuthChain.lambda$secure$0(MeshAuthChain.java:40)
getmesh-staging-master-0 getmesh    at app//com.gentics.mesh.auth.MeshAuthChain$$Lambda$572/0x0000000100b46040.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:162)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouterImpl.handleContext(RouterImpl.java:235)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteImpl$$Lambda$556/0x0000000100b41040.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:39)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.CookieHandlerImpl.handle(CookieHandlerImpl.java:35)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:296)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:276)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.BodyHandlerImpl.lambda$handle$0(BodyHandlerImpl.java:87)
getmesh-staging-master-0 getmesh    at app//io.vertx.ext.web.handler.impl.BodyHandlerImpl$$Lambda$1444/0x0000000100de2c40.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.HttpServerRequestImpl.onEnd(HttpServerRequestImpl.java:530)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.HttpServerRequestImpl.handleEnd(HttpServerRequestImpl.java:516)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.Http1xServerConnection.handleEnd(Http1xServerConnection.java:176)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:138)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.net.impl.VertxHandler$$Lambda$1429/0x0000000100de7040.handle(Unknown Source)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:369)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:232)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:173)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
getmesh-staging-master-0 getmesh    at app//io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:102)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
getmesh-staging-master-0 getmesh    at app//io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
getmesh-staging-master-0 getmesh    at app//io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
getmesh-staging-master-0 getmesh    at app//io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:328)
getmesh-staging-master-0 getmesh    at app//io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:302)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61)
getmesh-staging-master-0 getmesh    at app//io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:483)
getmesh-staging-master-0 getmesh    at app//io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:383)
getmesh-staging-master-0 getmesh    at app//io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044)
getmesh-staging-master-0 getmesh    at app//io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
getmesh-staging-master-0 getmesh    at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
getmesh-staging-master-0 getmesh    at java.base@11.0.5/java.lang.Thread.run(Unknown Source)

Reproducer

Start a node in cluster mode, and with topology lock timeout setted to a large value, launch a backup, then modify a node. the lock wait mechanism is throwing error in logs

Expected behaviour and actual behaviour

no errors in logs.

Seems that the lock mechanism is working fine, but the lock is not 'reactive'

Jotschi commented 4 years ago

Vert.x will always log blocked threads. This works as designed. We hope to use a dedicated worker thread for transactions and thus be able to configure the logs.

Additionally I noticed that MeshAuthChain is running a tx in the eventloop. This should not happen. We need to address this.