gentics / gentics/mesh

Lock in writes is throwing blocking thread errors in logs

Open
#1,049 1 comment 0 reactions 0 assignees View on GitHub
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.