Andreas Felder created LOG4J2-1987:
--------------------------------------
Summary: Log4J JUL Bridge seems to be not working with RMI
Security Manager
Key: LOG4J2-1987
URL: https://issues.apache.org/jira/browse/LOG4J2-1987
Project: Log4j 2
Issue Type: Bug
Components: log4j 1.2 emulation
Affects Versions: 2.8.2, 2.7
Environment: Windows Server 2008 and Windows Server 2012
Java SE 1.7.0_80
Reporter: Andreas Felder
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:
{code}
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] [[email protected]] 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] [[email protected]] RMISessionServerFactory - Lookup in
RMI registry failed, message was: Error unmarshaling return header; nested
exception is:
java.io.EOFException
10:23:43,065 [DEBUG] [[email protected]] RMISessionServerFactory - Lookup in
RMI registry failed, message was: Error unmarshaling return header; nested
exception is:
java.io.EOFException
{code}
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?
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
