]
Dan Berindei updated ISPN-9482:
-------------------------------
Sprint: DataGrid Sprint #30
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}