AuthorizationException caused by ConflictingInsertionException

zonradkuse · August 11, 2019, 2:07pm

We are experiencing problems causing irregularly user-facing errors. Mostly the user’s menu will not load completely or a macro will fail because of this. Unfortunately, I am not aware how to reproduce this problem consistently but within the last 48 hours less than five regular users caused this error to happen 183 times. The distribution looks interesting as if something is blocking the security cache in the background sometimes.

Does anyone have any hint on how to solve this? We are running XWiki 11.6 docker.

org.xwiki.security.authorization.AuthorizationException: Failed to load the cache in 5 attempts. Giving up. when checking  access to [xwiki:[redacted].WebHome] for user [xwiki:XWiki.[redacted]]
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCacheLoader.load(DefaultSecurityCacheLoader.java:168)
at org.xwiki.security.authorization.DefaultAuthorizationManager.getAccess(DefaultAuthorizationManager.java:209)
at org.xwiki.security.authorization.DefaultAuthorizationManager.evaluateSecurityAccess(DefaultAuthorizationManager.java:159)
at org.xwiki.security.authorization.DefaultAuthorizationManager.hasSecurityAccess(DefaultAuthorizationManager.java:152)
at org.xwiki.security.authorization.DefaultAuthorizationManager.hasAccess(DefaultAuthorizationManager.java:109)
at org.xwiki.query.solr.internal.SolrQueryExecutor.isAllowed(SolrQueryExecutor.java:273)
at org.xwiki.query.solr.internal.SolrQueryExecutor.filterResponse(SolrQueryExecutor.java:244)
at org.xwiki.query.solr.internal.SolrQueryExecutor.execute(SolrQueryExecutor.java:146)
at org.xwiki.query.internal.DefaultQueryExecutorManager.execute(DefaultQueryExecutorManager.java:72)
at org.xwiki.query.internal.SecureQueryExecutorManager.execute(SecureQueryExecutorManager.java:67)
at org.xwiki.query.internal.DefaultQuery.execute(DefaultQuery.java:306)
at org.xwiki.query.internal.ScriptQuery.execute(ScriptQuery.java:252)
at jdk.internal.reflect.GeneratedMethodAccessor613.invoke()
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:566)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(UberspectImpl.java:395)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(UberspectImpl.java:384)
at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:173)
at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280)
at org.apache.velocity.runtime.parser.node.ASTReference.value(ASTReference.java:567)
at org.apache.velocity.runtime.parser.node.ASTExpression.value(ASTExpression.java:71)
at org.apache.velocity.runtime.parser.node.ASTSetDirective.render(ASTSetDirective.java:142)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluateInternal(DefaultVelocityEngine.java:259)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate(DefaultVelocityEngine.java:222)
at com.xpn.xwiki.render.DefaultVelocityManager.evaluate(DefaultVelocityManager.java:358)
at org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString(VelocityMacro.java:131)
at org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString(VelocityMacro.java:52)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.evaluateBlock(AbstractScriptMacro.java:286)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.execute(AbstractScriptMacro.java:182)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.execute(AbstractScriptMacro.java:58)
at org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transform(MacroTransformation.java:297)
at org.xwiki.rendering.internal.transformation.DefaultRenderingContext.transformInContext(DefaultRenderingContext.java:183)
at org.xwiki.rendering.async.internal.block.AbstractBlockAsyncRenderer.transform(AbstractBlockAsyncRenderer.java:59)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.tranform(DefaultBlockAsyncRenderer.java:155)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.render(DefaultBlockAsyncRenderer.java:123)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.render(DefaultBlockAsyncRenderer.java:51)
at org.xwiki.uiextension.internal.WikiUIExtension.render(WikiUIExtension.java:179)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor$DecoratorWrapper.render(DefaultBlockAsyncRendererExecutor.java:66)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor$DecoratorWrapper.render(DefaultBlockAsyncRendererExecutor.java:48)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.lambda$syncRender$0(DefaultAsyncRendererExecutor.java:257)
at com.xpn.xwiki.internal.security.authorization.DefaultAuthorExecutor.call(DefaultAuthorExecutor.java:98)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.syncRender(DefaultAsyncRendererExecutor.java:257)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.render(DefaultAsyncRendererExecutor.java:240)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor.execute(DefaultBlockAsyncRendererExecutor.java:119)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor.execute(DefaultBlockAsyncRendererExecutor.java:107)
at org.xwiki.uiextension.internal.AbstractWikiUIExtension.execute(AbstractWikiUIExtension.java:112)
at jdk.internal.reflect.GeneratedMethodAccessor285.invoke()
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:566)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(UberspectImpl.java:395)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(UberspectImpl.java:384)
at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:173)
at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280)
at org.apache.velocity.runtime.parser.node.ASTReference.value(ASTReference.java:567)
at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:151)
at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280)
at org.apache.velocity.runtime.parser.node.ASTReference.render(ASTReference.java:369)
at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72)
at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:87)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluateInternal(DefaultVelocityEngine.java:259)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate(DefaultVelocityEngine.java:222)
at com.xpn.xwiki.render.DefaultVelocityManager.evaluate(DefaultVelocityManager.java:358)
at org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString(VelocityMacro.java:131)
at org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString(VelocityMacro.java:52)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.evaluateBlock(AbstractScriptMacro.java:286)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.execute(AbstractScriptMacro.java:182)
at org.xwiki.rendering.macro.script.AbstractScriptMacro.execute(AbstractScriptMacro.java:58)
at org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transform(MacroTransformation.java:297)
at org.xwiki.rendering.internal.transformation.DefaultRenderingContext.transformInContext(DefaultRenderingContext.java:183)
at org.xwiki.rendering.async.internal.block.AbstractBlockAsyncRenderer.transform(AbstractBlockAsyncRenderer.java:59)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.tranform(DefaultBlockAsyncRenderer.java:155)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.render(DefaultBlockAsyncRenderer.java:123)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRenderer.render(DefaultBlockAsyncRenderer.java:51)
at org.xwiki.uiextension.internal.WikiUIExtension.render(WikiUIExtension.java:179)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor$DecoratorWrapper.render(DefaultBlockAsyncRendererExecutor.java:66)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor$DecoratorWrapper.render(DefaultBlockAsyncRendererExecutor.java:48)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.lambda$syncRender$0(DefaultAsyncRendererExecutor.java:257)
at com.xpn.xwiki.internal.security.authorization.DefaultAuthorExecutor.call(DefaultAuthorExecutor.java:98)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.syncRender(DefaultAsyncRendererExecutor.java:257)
at org.xwiki.rendering.async.internal.DefaultAsyncRendererExecutor.render(DefaultAsyncRendererExecutor.java:240)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor.execute(DefaultBlockAsyncRendererExecutor.java:119)
at org.xwiki.rendering.async.internal.block.DefaultBlockAsyncRendererExecutor.execute(DefaultBlockAsyncRendererExecutor.java:107)
at org.xwiki.uiextension.internal.AbstractWikiUIExtension.execute(AbstractWikiUIExtension.java:112)
at jdk.internal.reflect.GeneratedMethodAccessor285.invoke()
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:566)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(UberspectImpl.java:395)
at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(UberspectImpl.java:384)
at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:173)
at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280)
at org.apache.velocity.runtime.parser.node.ASTReference.value(ASTReference.java:567)
at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:151)
at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280)
at org.apache.velocity.runtime.parser.node.ASTReference.render(ASTReference.java:369)
at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72)
at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:420)
at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:207)
at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72)
at org.apache.velocity.runtime.directive.VelocimacroProxy.render(VelocimacroProxy.java:216)
at org.apache.velocity.runtime.directive.RuntimeMacro.render(RuntimeMacro.java:311)
at org.apache.velocity.runtime.directive.RuntimeMacro.render(RuntimeMacro.java:230)
at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:207)
at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342)
at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:106)
at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342)
at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:106)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluateInternal(DefaultVelocityEngine.java:259)
at org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate(DefaultVelocityEngine.java:222)
at com.xpn.xwiki.render.DefaultVelocityManager.evaluate(DefaultVelocityManager.java:358)
at com.xpn.xwiki.internal.template.InternalTemplateManager.evaluateContent(InternalTemplateManager.java:884)
at com.xpn.xwiki.internal.template.InternalTemplateManager.render(InternalTemplateManager.java:755)
at com.xpn.xwiki.internal.template.InternalTemplateManager.lambda$renderFromSkin$0(InternalTemplateManager.java:730)
at com.xpn.xwiki.internal.security.authorization.DefaultAuthorExecutor.call(DefaultAuthorExecutor.java:98)
at com.xpn.xwiki.internal.template.InternalTemplateManager.renderFromSkin(InternalTemplateManager.java:729)
at com.xpn.xwiki.internal.template.InternalTemplateManager.renderFromSkin(InternalTemplateManager.java:708)
at com.xpn.xwiki.internal.template.InternalTemplateManager.render(InternalTemplateManager.java:694)
at com.xpn.xwiki.internal.template.DefaultTemplateManager.render(DefaultTemplateManager.java:78)
at com.xpn.xwiki.XWiki.evaluateTemplate(XWiki.java:2479)
at com.xpn.xwiki.web.Utils.parseTemplate(Utils.java:179)
at com.xpn.xwiki.web.Utils.parseTemplate(Utils.java:88)
at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:508)
at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:215)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:425)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:228)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:112)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:109)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:132)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:660)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:679)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:808)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:834)

Caused by: org.xwiki.security.authorization.cache.ConflictingInsertionException
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCache.addEntry(DefaultSecurityCache.java:642)
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCache.internalAdd(DefaultSecurityCache.java:760)
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCache.add(DefaultSecurityCache.java:736)
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCacheLoader.loadAccessEntries(DefaultSecurityCacheLoader.java:231)
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCacheLoader.loadRequiredEntries(DefaultSecurityCacheLoader.java:197)
at org.xwiki.security.authorization.cache.internal.DefaultSecurityCacheLoader.load(DefaultSecurityCacheLoader.java:150)
... 170 more

slauriere · August 13, 2019, 7:25am

Hello @zonradkuse, This sounds a bit tricky… I have no specific investigation idea about this, just ccing @dgervalle in case he has one (and time)

Cheers

dgervalle · August 13, 2019, 8:43pm

This is definitely an unexpected issue that could only happen in very loaded environment when thread concurrency is an issue or the number of users/groups is too high for the security cache size. I would suggest two potential ways to improve the situation:

increase the resources allocated to the container
increase the size of the security cache (Infinispan cache with id platform.security.authorization.cache)

I hope these suggestions will help.
Regards,

zonradkuse · August 16, 2019, 6:24pm

Hi @dgervalle, @slauriere,

Thanks for the quick replies and the hints! The JVM is allowed to use up to 1.6G and according to glowroot the MemoryUsage is around 900MB.

I am going to try to increase the inifinispan cache. Interestingly, the errors seem to decrease over time. In other words we didn’t experience such a massive spike in cache errors again. Throughout a day we might experience 5 to no exceptions of this kind. However, I haven’t restarted XWiki since.

I’ll keep you updated. Have a good weekend.

Best
Johannes

DenisF · September 2, 2022, 8:25am

Hello @dgervalle !

Where is settings for security cache(Infinispan cache with id platform.security.authorization.cache)

dgervalle · September 2, 2022, 11:52am

Hi @DenisF,

You may find the infinity span settings in the webapp folder WEB-INF/cache/infinispan

Best
Denis

DenisF · September 5, 2022, 5:58am

Hi @dgervalle, thanks!

using memory analyzer I see the following state

by default, no values are set for the security.authorization.cache

Please tell me what are the correct values to start with for my system

dgervalle · September 5, 2022, 7:49am

Hi @DenisF

I am sorry, but there is not much I can tell from a static snapshot of the system. The security cache is a very dynamic stuff, you can get some more interesting statistics from JMX statistics (needs to be enabled), but even with that, there is no established rules and each environment might need a very different logic depending on the right structure of the wiki itself (users, groups, documents and rights relationships). To better understand the behaviour of the security cache in a specific environment, I have built an extension (Security Inspector Application (XWiki.org)), but it’s not easy to setup, nor to use, so I do not really advice to use it unless anything else failed, and a deep expertise will be required anyway.

For your information, the default cache size is ten thousands entries, and entries are documents (including groups and users), right objects (rules), and access decisions (right given to a user on a document recently). Be careful that the cache is it self constrained by the JVM ressources, so when increasing it, you need to care about the JVM as well. Trial and error is probably the best bet regarding the issue described here, unless you have a deep technical knowledge of the cache itself.

Hope this help anyway.