Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-9482

Authorization exceptions are never sent to the client if access logging is enabled

XMLWordPrintable

      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:

      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
      

      On the client side, nothing is received, and the test eventually times out:

      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]
      

            dberinde@redhat.com Dan Berindei (Inactive)
            dberinde@redhat.com Dan Berindei (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: