[infinispan-issues] [JBoss JIRA] (ISPN-9482) Authorization exceptions are never sent to the client if access logging is enabled

Authorization exceptions are never sent to the client if access logging is enabled ---------------------------------------------------------------------------------- Key: ISPN-9482 URL: https://issues.jboss.org/browse/ISPN-9482 Project: Infinispan Issue Type: Bug Components: Server, Test Suite - Server Affects Versions: 9.4.0.CR1 Reporter: Dan Berindei Assignee: Dan Berindei Priority: Major Labels: testsuite_stability I've noticed the problem when running {{AuthenticationTest.testAuthenticationFailNoAuth}} with trace logging enabled. The server never sends the authorization exception to the client because logging the exception also performs a security check. On the server side, Netty logs an unhandled exception: {noformat} 19:43:22,617 DEBUG (HotRod-ServerIO-3-1) [BaseDecoder] Exception caught io.netty.handler.codec.DecoderException: java.lang.SecurityException: ISPN006017: Unauthorized operation at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459) ~[netty-codec-4.1.22.Final.jar:4.1.22.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265) ~[netty-codec-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at org.infinispan.server.core.transport.StatsChannelHandler.channelRead(StatsChannelHandler.java:26) [classes/:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945) [netty-transport-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:806) [netty-transport-native-epoll-4.1.22.Final-linux-x86_64.jar:4.1.22.Final] at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404) [netty-transport-native-epoll-4.1.22.Final-linux-x86_64.jar:4.1.22.Final] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304) [netty-transport-native-epoll-4.1.22.Final-linux-x86_64.jar:4.1.22.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886) [netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.22.Final.jar:4.1.22.Final] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171] Caused by: java.lang.SecurityException: ISPN006017: Unauthorized operation at org.infinispan.server.hotrod.Authentication.getSubject(Authentication.java:152) ~[classes/:?] at org.infinispan.server.hotrod.HotRodDecoder.getHeader(HotRodDecoder.java:133) ~[classes/:?] at org.infinispan.server.hotrod.HotRodDecoder.exceptionally(HotRodDecoder.java:3327) ~[classes/:?] at org.infinispan.server.hotrod.HotRodDecoder.decode(HotRodDecoder.java:145) ~[classes/:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489) ~[netty-codec-4.1.22.Final.jar:4.1.22.Final] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428) ~[netty-codec-4.1.22.Final.jar:4.1.22.Final] ... 19 more {noformat} On the client side, nothing is received, and the test eventually times out: {noformat} 19:43:25,192 ERROR (testng-Test) [TestSuiteProgress] Test failed: org.infinispan.client.hotrod.AuthenticationTest.testAuthenticationFailNoAuth org.infinispan.client.hotrod.exceptions.TransportException: java.net.SocketTimeoutException: PutOperation{(default), key=[B0x033E0161, value=[B0x033E0161, flags=6} timed out after 3000 ms at org.infinispan.client.hotrod.impl.Util.rewrap(Util.java:54) ~[classes/:?] at org.infinispan.client.hotrod.impl.Util.await(Util.java:27) ~[classes/:?] at org.infinispan.client.hotrod.impl.RemoteCacheImpl.put(RemoteCacheImpl.java:264) ~[classes/:?] at org.infinispan.client.hotrod.impl.RemoteCacheSupport.put(RemoteCacheSupport.java:79) ~[classes/:?] at org.infinispan.client.hotrod.AuthenticationTest.testAuthenticationFailNoAuth(AuthenticationTest.java:71) ~[test-classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_171] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_171] at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85) ~[testng-6.9.9.jar:?] at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:196) ~[testng-6.9.9.jar:?] at org.infinispan.commons.test.TestNGLongTestsHook.run(TestNGLongTestsHook.java:24) ~[classes/:?] at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:208) ~[testng-6.9.9.jar:?] at org.testng.internal.Invoker.invokeMethod(Invoker.java:635) [testng-6.9.9.jar:?] at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:816) [testng-6.9.9.jar:?] at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1124) [testng-6.9.9.jar:?] at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125) [testng-6.9.9.jar:?] at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108) [testng-6.9.9.jar:?] at org.testng.TestRunner.privateRun(TestRunner.java:774) [testng-6.9.9.jar:?] at org.testng.TestRunner.run(TestRunner.java:624) [testng-6.9.9.jar:?] at org.testng.SuiteRunner.runTest(SuiteRunner.java:359) [testng-6.9.9.jar:?] at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:354) [testng-6.9.9.jar:?] at org.testng.SuiteRunner.privateRun(SuiteRunner.java:312) [testng-6.9.9.jar:?] at org.testng.SuiteRunner.run(SuiteRunner.java:261) [testng-6.9.9.jar:?] at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52) [testng-6.9.9.jar:?] at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86) [testng-6.9.9.jar:?] at org.testng.TestNG.runSuitesSequentially(TestNG.java:1215) [testng-6.9.9.jar:?] at org.testng.TestNG.runSuitesLocally(TestNG.java:1140) [testng-6.9.9.jar:?] at org.testng.TestNG.run(TestNG.java:1048) [testng-6.9.9.jar:?] at org.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:72) [testng-plugin.jar:?] at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:123) [testng-plugin.jar:?] Caused by: java.net.SocketTimeoutException: PutOperation{(default), key=[B0x033E0161, value=[B0x033E0161, flags=6} timed out after 3000 ms at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:172) ~[classes/:?] at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:125) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:309) ~[netty-transport-native-epoll-4.1.22.Final-linux-x86_64.jar:4.1.22.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886) ~[netty-common-4.1.22.Final.jar:4.1.22.Final] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_171] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_171] at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_171] {noformat}