You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Gary Gregory (JIRA)" <ji...@apache.org> on 2017/07/24 18:11:00 UTC
[jira] [Resolved] (LOG4J2-1987) Log4J JUL Bridge and RMI Security
Manager causes access denied ("java.util.logging.LoggingPermission"
"control")
[ https://issues.apache.org/jira/browse/LOG4J2-1987?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gary Gregory resolved LOG4J2-1987.
----------------------------------
Resolution: Fixed
Fix Version/s: 2.9
I fixed the one call site but there could be many others. Please try a 2.9-SNAPSHOT build from https://repository.apache.org/content/repositories/snapshots/
If that fixes it, please close this issue.
> 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] [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)