Details
-
Bug
-
Status: Closed
-
Major
-
Resolution: Fixed
-
2.7, 2.8.2
-
Windows Server 2008 and Windows Server 2012
Java SE 1.7.0_80
Description
We've the following setup:
1. A web application run inside Apache Tomcat, which starts an external process
2. This external process set it's security manager to RMISecurityManager and starts up a RMI server
3. If the external process is running, the web application tries to connect via RMI to the external process.
This works fine with Log4J 1.x. Currently we try to migrate to Log4J 2.7 (2.8.2 also testet). Sometimes the following exception is thrown during step 2:
10:23:38,549 [DEBUG] ExternalRMIServer - new server started. 10:23:38,565 [DEBUG] ExternalRMIServer - Port : 10000 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.io.FilePermission" "<path>\Test.class" "read") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.util.logging.LoggingPermission" "control") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access denied ("java.util.logging.LoggingPermission" "control") 10:23:43,065 [ERROR] EmptyingStreamThread - java.lang.Exception: Stack trace 10:23:43,065 [ERROR] EmptyingStreamThread - at java.lang.Thread.dumpStack(Thread.java:1365) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.security.AccessControlContext.checkPermission(AccessControlContext.java:362) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.security.AccessController.checkPermission(AccessController.java:559) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.lang.SecurityManager.checkPermission(SecurityManager.java:549) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.LogManager.checkPermission(LogManager.java:1414) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.checkPermission(Logger.java:309) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.setLevel(Logger.java:1268) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.ApiLogger.<init>(ApiLogger.java:50) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLogger.<init>(CoreLogger.java:41) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLoggerAdapter.newLogger(CoreLoggerAdapter.java:39) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLoggerAdapter.newLogger(CoreLoggerAdapter.java:31) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48) 10:23:43,065 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:89) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.LogManager.demandSystemLogger(LogManager.java:475) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.demandLogger(Logger.java:343) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.getLogger(Logger.java:393) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.runtime.Log$LoggerLogFactory.createLog(Log.java:171) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.runtime.Log.getLog(Log.java:138) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.server.LoaderHandler.<clinit>(LoaderHandler.java:78) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.rmi.server.RMIClassLoader$2.getClassAnnotation(RMIClassLoader.java:657) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.rmi.server.RMIClassLoader.getClassAnnotation(RMIClassLoader.java:381) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.server.MarshalOutputStream.annotateClass(MarshalOutputStream.java:93) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeNonProxyDesc(ObjectOutputStream.java:1289) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeClassDesc(ObjectOutputStream.java:1230) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1426) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1177) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:347) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.Transport.serviceCall(Transport.java:248) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:567) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:828) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(TCPTransport.java:619) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:684) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:681) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.security.AccessController.doPrivileged(Native Method) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:681) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.lang.Thread.run(Thread.java:745) 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.util.PropertyPermission" "java.util.logging.manager" "write") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.security.SecurityPermission" "getPolicy") 10:23:43,065 [ERROR] EmptyingStreamThread - access: domain that failed ProtectionDomain null 10:23:43,065 [ERROR] EmptyingStreamThread - null 10:23:43,065 [ERROR] EmptyingStreamThread - <no principals> 10:23:43,065 [ERROR] EmptyingStreamThread - java.security.Permissions@2e5e7733 ( 10:23:43,065 [ERROR] EmptyingStreamThread - ) 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.util.PropertyPermission" "connector.profile.name" "read") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.util.PropertyPermission" "sun.net.maxDatagramSockets" "read") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.lang.RuntimePermission" "getClassLoader") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.io.FilePermission" "<path>\Configuration.class" "read") 10:23:43,065 [ERROR] EmptyingStreamThread - access: access allowed ("java.lang.RuntimePermission" "setContextClassLoader") 10:23:43,065 [ERROR] EmptyingStreamThread - Exception in thread "RMI TCP Connection(idle)" java.lang.ExceptionInInitializerError 10:23:43,065 [ERROR] EmptyingStreamThread - at java.rmi.server.RMIClassLoader$2.getClassAnnotation(RMIClassLoader.java:657) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.rmi.server.RMIClassLoader.getClassAnnotation(RMIClassLoader.java:381) 10:23:43,065 [DEBUG] [test@192.168.1.120] RMISessionServerFactory - Lookup in RMI registry failed, message was: Error unmarshaling return header; nested exception is: java.io.EOFException 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.server.MarshalOutputStream.annotateClass(MarshalOutputStream.java:93) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeNonProxyDesc(ObjectOutputStream.java:1289) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeClassDesc(ObjectOutputStream.java:1230) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1426) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1177) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:347) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.Transport.serviceCall(Transport.java:248) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:567) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:828) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(TCPTransport.java:619) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:684) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:681) 10:23:43,065 [ERROR] EmptyingStreamThread - at java.security.AccessController.doPrivileged(Native Method) 10:23:43,065 [ERROR] EmptyingStreamThread - at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:681) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.lang.Thread.run(Thread.java:745) 10:23:43,080 [ERROR] EmptyingStreamThread - Caused by: java.security.AccessControlException: access denied ("java.util.logging.LoggingPermission" "control") 10:23:43,080 [ERROR] EmptyingStreamThread - at java.security.AccessControlContext.checkPermission(AccessControlContext.java:372) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.security.AccessController.checkPermission(AccessController.java:559) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.lang.SecurityManager.checkPermission(SecurityManager.java:549) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.LogManager.checkPermission(LogManager.java:1414) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.checkPermission(Logger.java:309) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.setLevel(Logger.java:1268) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.ApiLogger.<init>(ApiLogger.java:50) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLogger.<init>(CoreLogger.java:41) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLoggerAdapter.newLogger(CoreLoggerAdapter.java:39) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.CoreLoggerAdapter.newLogger(CoreLoggerAdapter.java:31) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48) 10:23:43,080 [ERROR] EmptyingStreamThread - at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:89) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.LogManager.demandSystemLogger(LogManager.java:475) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.demandLogger(Logger.java:343) 10:23:43,080 [ERROR] EmptyingStreamThread - at java.util.logging.Logger.getLogger(Logger.java:393) 10:23:43,080 [ERROR] EmptyingStreamThread - at sun.rmi.runtime.Log$LoggerLogFactory.createLog(Log.java:171) 10:23:43,080 [ERROR] EmptyingStreamThread - at sun.rmi.runtime.Log.getLog(Log.java:138) 10:23:43,080 [ERROR] EmptyingStreamThread - at sun.rmi.server.LoaderHandler.<clinit>(LoaderHandler.java:78) 10:23:43,080 [ERROR] EmptyingStreamThread - ... 19 more 10:23:43,065 [DEBUG] [test@192.168.1.120] RMISessionServerFactory - Lookup in RMI registry failed, message was: Error unmarshaling return header; nested exception is: java.io.EOFException 10:23:43,065 [DEBUG] [test@192.168.1.120] RMISessionServerFactory - Lookup in RMI registry failed, message was: Error unmarshaling return header; nested exception is: java.io.EOFException
I've used various security policies (given as system property on startup, the stack was also printed when using permission java.security.AllPermission;. Please mind that LoggingPermission "control" was first accepted and then denied. Class EmptyingStreamThread collects stderr output of our external RMI server.
If i remove Log4J 2.x from classpath the error didn't occur. Any ideas what could be wrong?