You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Andreas Felder (JIRA)" <ji...@apache.org> on 2017/07/24 08:45:00 UTC
[jira] [Created] (LOG4J2-1987) Log4J JUL Bridge seems to be not
working with RMI Security Manager
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] [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
{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)