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

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

    XMLWordPrintable

Details

    Description

      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]

      Attachments

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: