[
https://issues.apache.org/jira/browse/LOG4J2-1987?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andreas Felder closed LOG4J2-1987.
----------------------------------
> Log4J JUL Bridge and RMI Security Manager causes access denied
> ("java.util.logging.LoggingPermission" "control")
> ----------------------------------------------------------------------------------------------------------------
>
> 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.7, 2.8.2
> Environment: Windows Server 2008 and Windows Server 2012
> Java SE 1.7.0_80
> Reporter: Andreas Felder
> Labels: newbie, rmic
> Fix For: 2.9
>
>
> 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)
