Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1987

Log4J JUL Bridge and RMI Security Manager causes access denied ("java.util.logging.LoggingPermission" "control")

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.7, 2.8.2
    • Fix Version/s: 2.9.0
    • Component/s: log4j 1.2 emulation
    • Labels:
    • Environment:

      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?

        Activity

        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 5aa2163cf9daaacd23bb7f620931b8f592be6fc7 in logging-log4j2's branch refs/heads/master from Gary Gregory
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=5aa2163 ]

        LOG4J2-1987 Log4J JUL Bridge and RMI Security Manager causes access
        denied ("java.util.logging.LoggingPermission" "control")

        Show
        jira-bot ASF subversion and git services added a comment - Commit 5aa2163cf9daaacd23bb7f620931b8f592be6fc7 in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=5aa2163 ] LOG4J2-1987 Log4J JUL Bridge and RMI Security Manager causes access denied ("java.util.logging.LoggingPermission" "control")
        Hide
        garydgregory Gary Gregory added a comment - - edited

        I fixed the one call site at org.apache.logging.log4j.jul.ApiLogger.<init>(ApiLogger.java:50) 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.

        Show
        garydgregory Gary Gregory added a comment - - edited I fixed the one call site at org.apache.logging.log4j.jul.ApiLogger.<init>(ApiLogger.java:50) 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.
        Hide
        Andreas F Andreas Felder added a comment -

        This patch seems to work for me. At least I was unable to reproduce the error above.

        Show
        Andreas F Andreas Felder added a comment - This patch seems to work for me. At least I was unable to reproduce the error above.
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 5aa2163cf9daaacd23bb7f620931b8f592be6fc7 in logging-log4j2's branch refs/heads/LOG4J2-1986 from Gary Gregory
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=5aa2163 ]

        LOG4J2-1987 Log4J JUL Bridge and RMI Security Manager causes access
        denied ("java.util.logging.LoggingPermission" "control")

        Show
        jira-bot ASF subversion and git services added a comment - Commit 5aa2163cf9daaacd23bb7f620931b8f592be6fc7 in logging-log4j2's branch refs/heads/ LOG4J2-1986 from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=5aa2163 ] LOG4J2-1987 Log4J JUL Bridge and RMI Security Manager causes access denied ("java.util.logging.LoggingPermission" "control")

          People

          • Assignee:
            Unassigned
            Reporter:
            Andreas F Andreas Felder
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development