LDAP intermittent ConcurrentModification Exception


#1

Hi

readonlyrest-1.16.33_es6.5.4

I sometimes get these errors in the ES log and my users get FORBIDDEN upon simple search requests
This happens around 10 times per day on random LDAP-using rules (I have several of them).

Stacktrace example

[2019-02-15T09:15:05,298][ERROR][t.b.r.a.b.Block ] [es-balancing-instance] My LDAP rule: ldap_auth rule matching got an error java.util.ConcurrentModificationException
java.util.concurrent.CompletionException: java.util.ConcurrentModificationException
at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:604) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:614) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1983) ~[?:1.8.0_161]
at tech.beshu.ror.acl.blocks.rules.impl.LdapAuthorizationAsyncRule.authorize(LdapAuthorizationAsyncRule.java:65) ~[?:?]
at tech.beshu.ror.acl.blocks.rules.AsyncAuthorization.match(AsyncAuthorization.java:46) ~[?:?]
at tech.beshu.ror.acl.blocks.rules.impl.LdapAuthAsyncRule.lambda$match$1(LdapAuthAsyncRule.java:74) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.acl.blocks.rules.impl.LdapAuthAsyncRule.match(LdapAuthAsyncRule.java:73) ~[?:?]
at tech.beshu.ror.acl.blocks.Block.lambda$checkAsyncRulesInSequence$4(Block.java:141) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:52) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:34) ~[?:?]
at tech.beshu.ror.acl.blocks.Block.checkAsyncRulesInSequence(Block.java:139) ~[?:?]
at tech.beshu.ror.acl.blocks.Block.checkAsyncRules(Block.java:129) ~[?:?]
at tech.beshu.ror.acl.blocks.Block.check(Block.java:115) ~[?:?]
at tech.beshu.ror.acl.ACL.lambda$doCheck$6(ACL.java:241) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:52) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.lambda$runInSeqUntilConditionIsUndone$2(FuturesSequencer.java:58) ~[?:?]
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_161]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:53) ~[?:?]
at tech.beshu.ror.utils.FuturesSequencer.runInSeqUntilConditionIsUndone(FuturesSequencer.java:41) ~[?:?]
at tech.beshu.ror.acl.ACL.doCheck(ACL.java:237) ~[?:?]
at tech.beshu.ror.acl.ACL.check(ACL.java:185) ~[?:?]
at tech.beshu.ror.es.IndexLevelActionFilter.handleRequest(IndexLevelActionFilter.java:158) ~[?:?]
at tech.beshu.ror.es.IndexLevelActionFilter.lambda$apply$1(IndexLevelActionFilter.java:134) ~[?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_161]
at tech.beshu.ror.es.IndexLevelActionFilter.apply(IndexLevelActionFilter.java:130) ~[?:?]
at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:139) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:81) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.client.node.NodeClient.executeLocally(NodeClient.java:87) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.client.node.NodeClient.doExecute(NodeClient.java:76) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:395) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.client.support.AbstractClient.multiSearch(AbstractClient.java:552) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.rest.action.search.RestMultiSearchAction.lambda$prepareRequest$0(RestMultiSearchAction.java:75) ~[elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.rest.BaseRestHandler.handleRequest(BaseRestHandler.java:97) ~[elasticsearch-6.5.4.jar:6.5.4]
at tech.beshu.ror.es.ReadonlyRestPlugin.lambda$null$5(ReadonlyRestPlugin.java:197) ~[?:?]
at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:239) [elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.rest.RestController.tryAllHandlers(RestController.java:335) [elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:173) [elasticsearch-6.5.4.jar:6.5.4]
at org.elasticsearch.http.netty4.Netty4HttpServerTransport.dispatchRequest(Netty4HttpServerTransport.java:545) [transport-netty4-client-6.5.4.jar:6.5.4]
at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:137) [transport-netty4-client-6.5.4.jar:6.5.4]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:68) [transport-netty4-client-6.5.4.jar:6.5.4]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at org.elasticsearch.http.netty4.cors.Netty4CorsHandler.channelRead(Netty4CorsHandler.java:86) [transport-netty4-client-6.5.4.jar:6.5.4]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297) [netty-codec-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [netty-handler-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:544) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458) [netty-transport-4.1.30.Final.jar:4.1.30.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) [netty-common-4.1.30.Final.jar:4.1.30.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
Caused by: java.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.remove(HashMap.java:1456) ~[?:1.8.0_161]
at java.util.AbstractCollection.retainAll(AbstractCollection.java:410) ~[?:1.8.0_161]
at tech.beshu.ror.acl.blocks.rules.impl.LdapAuthorizationAsyncRule.checkWhatConfiguredGroupsUserHasAccess(LdapAuthorizationAsyncRule.java:107) ~[?:?]
at tech.beshu.ror.acl.blocks.rules.impl.LdapAuthorizationAsyncRule.lambda$authorize$3(LdapAuthorizationAsyncRule.java:66) ~[?:?]
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_161]
… 131 more


(Simone Scarduzio) #2

Hi @metsaviha, in a 2-3 weeks we’ll have a completely rewritten, more efficient version of LDAP connector. This will go away.