Lock in writes is throwing blocking thread errors in logs
- Dominant language
- Java
- Stars
- 593
- Forks
- 123
- Avg merge
- 2d 18h
- Merged PRs (30d)
- 4
Description
## Gentics Mesh Version, operating system, or hardware.
- v1.4.4.
## 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'
Contributor guide
Research direction
Start with OrientDBDatabase.blockingTopologyLockCheck at line 391 and follow its call from OrientDBDatabase.tx at line 417 through OrientDBTx.close. Reproduce the issue in cluster mode during a backup with a large topology lock timeout while modifying a node. Done means the write no longer produces Vert.x blocked-thread errors in the logs.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- backend, databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 25/100