Hot CPUs on data nodes: action.ActionListener$1.onResponse is called recurisvely

larryzhu · November 17, 2020, 6:33am

we are seeing high CPUs on data nodes and the hot thread stacks suggest action.ActionListener$1.onResponse is called recursively. we are using "elastic" user and it should have access to all the indices. Is there any way we can tweak the configuration so that this code is smarter not to compute all the authorized indices recursively as shown below?

    << cut due to limits of characters, ActionListener$1.onResponse is repeated many times on the stack>>
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.RBACEngine.buildIndicesAccessControl(RBACEngine.java:523)
       org.elasticsearch.xpack.security.authz.RBACEngine.lambda$authorizeIndexAction$3(RBACEngine.java:314)
       org.elasticsearch.xpack.security.authz.RBACEngine$$Lambda$4813/0x00007f18d1ae0db0.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeBulkItems$20(AuthorizationService.java:535)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4865/0x00007f18d1b66858.getAsync(Unknown Source)
       org.elasticsearch.xpack.security.authz.RBACEngine.lambda$authorizeIndexAction$4(RBACEngine.java:306)
       org.elasticsearch.xpack.security.authz.RBACEngine$$Lambda$4811/0x00007f18d1fc4c40.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.RBACEngine.authorizeIndexActionName(RBACEngine.java:330)
       org.elasticsearch.xpack.security.authz.RBACEngine.authorizeIndexAction(RBACEngine.java:303)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeBulkItems$22(AuthorizationService.java:534)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4864/0x00007f18d1b65db0.accept(Unknown Source)
       java.base@14.0.1/java.util.HashMap.forEach(HashMap.java:1425)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeBulkItems$23(AuthorizationService.java:531)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4858/0x00007f18d1b61040.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier.getAsync(AuthorizationService.java:668)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeBulkItems$24(AuthorizationService.java:466)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4856/0x00007f18d1b4bc40.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       <cutt> org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier.lambda$getAsync$0(AuthorizationService.java:665)
       org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier$$Lambda$4815/0x00007f18d1ae24b0.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.AuthorizationService.resolveIndexNames(AuthorizationService.java:566)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeAction$6(AuthorizationService.java:259)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4817/0x00007f18d1ae3d60.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier.lambda$getAsync$0(AuthorizationService.java:665)
       org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier$$Lambda$4815/0x00007f18d1ae24b0.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.RBACEngine.loadAuthorizedIndices(RBACEngine.java:345)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeAction$5(AuthorizationService.java:255)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4807/0x00007f18d1fca108.getAsync(Unknown Source)
       org.elasticsearch.xpack.security.authz.AuthorizationService$CachingAsyncSupplier.getAsync(AuthorizationService.java:663)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorizeAction$8(AuthorizationService.java:258)
       <<cut>>
       org.elasticsearch.xpack.security.authz.AuthorizationService.maybeAuthorizeRunAs(AuthorizationService.java:234)
       org.elasticsearch.xpack.security.authz.AuthorizationService.lambda$authorize$1(AuthorizationService.java:199)
       org.elasticsearch.xpack.security.authz.AuthorizationService$$Lambda$4588/0x00007f1c822c7960.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       app//org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:43)
       org.elasticsearch.xpack.security.authz.RBACEngine.lambda$resolveAuthorizationInfo$1(RBACEngine.java:121)
       org.elasticsearch.xpack.security.authz.RBACEngine$$Lambda$4590/0x00007f1c822c5908.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authz.store.CompositeRolesStore.getRoles(CompositeRolesStore.java:250)
       org.elasticsearch.xpack.security.authz.RBACEngine.getRoles(RBACEngine.java:127)
       org.elasticsearch.xpack.security.authz.RBACEngine.resolveAuthorizationInfo(RBACEngine.java:115)
       org.elasticsearch.xpack.security.authz.AuthorizationService.authorize(AuthorizationService.java:201)
       org.elasticsearch.xpack.security.transport.ServerTransportFilter$NodeProfile.lambda$inbound$1(ServerTransportFilter.java:129)
       org.elasticsearch.xpack.security.transport.ServerTransportFilter$NodeProfile$$Lambda$4509/0x00007f1c82202d68.accept(Unknown Source)
       app//org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$authenticateAsync$2(AuthenticationService.java:323)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator$$Lambda$4511/0x00007f1c822014b0.accept(Unknown Source)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$lookForExistingAuthentication$6(AuthenticationService.java:385)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator$$Lambda$4512/0x00007f1c822708b0.run(Unknown Source)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lookForExistingAuthentication(AuthenticationService.java:396)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.authenticateAsync(AuthenticationService.java:320)
       org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.access$000(AuthenticationService.java:261)
       org.elasticsearch.xpack.security.authc.AuthenticationService.authenticate(AuthenticationService.java:173)
       org.elasticsearch.xpack.security.transport.ServerTransportFilter$NodeProfile.inbound(ServerTransportFilter.java:120)
       org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler.messageReceived(SecurityServerTransportInterceptor.java:313)
       app//org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
       app//org.elasticsearch.transport.InboundHandler$RequestHandler.doRun(InboundHandler.java:263)
       app//org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
       app//org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:226)
       app//org.elasticsearch.transport.InboundHandler.handleRequest(InboundHandler.java:176)
       app//org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:93)
       app//org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:78)
       app//org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:692)
       org.elasticsearch.transport.netty4.Netty4MessageChannelHandler$$Lambda$4372/0x00007f1c832f00b0.accept(Unknown Source)
       app//org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:142)
       app//org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:117)
       app//org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:82)
       org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:73)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
       io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
       io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
       io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
       io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1518)
       io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1267)
       io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1314)
       io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:501)
       io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:440)
       io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
       io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
       io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
       io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
       io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
       io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
       io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
       io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
       io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
       io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
       io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
       io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)

ikakavas · November 17, 2020, 7:18am

This is not what the stack shows. ActionListener is an interface and what you see there is the onResponse method of different implementations of that interface being called, which is perfectly normal for the authorization code path.

larryzhu · November 17, 2020, 7:56am

hi Ikakava, The onResponse is shown repeatedly on the stack. Is that expected? You can see the full stack here: https://1drv.ms/t/s!Ag-w-0iTBE54gpIhVkpaXBUaRpgR_w

the message limit on the character counts here makes it impossible for me to share the full stack without this link to onedrive.

ikakavas · November 17, 2020, 8:03am

As I explained above, this is not a recursive call, it's just the onResponse() method of different classes that implement the ActionListener interface being called. This is not a problem/error in itself.

Analyzing hot threads and performance issues is a slightly more involved task that usually is not a good fit for these forums. Do you have a support contract? If so I'd suggest you start a discussion with your support engineer where you can share more information about your setup, your role definitions and your use of DLS/FLS and get some suggestions on how to optimise these.

system · December 15, 2020, 8:04am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.