Specific log4j version: 1.2.8 We have experienced several times a SecurityException from log4j logging methods (i.e. debug, info, warn, etc) when the rolling file appender needs to switch to a new log file. This occurs in our environment (a proprietary application server) when unprivileged "user" classes are on the stack. We have basically segments our classes into two primary privileged - system/server and user and setup security policy (SecurityManager) permissions that generally do not allow reading/write/open/close on arbitrary files for the user space. I am surprised this has not come up before. I did a search on this bugzilla and found some references to SecurityException for applet sandbox (bug 30294) and a couple of others, but none referenced a case with problems during actual logging as this. This occurs infrequently, but when it does, it can be difficult to protect from this situation -- particularly as the log4j logging methods themselves are by design not supposed to throw any exception. In our case, this can cause internal pool 'leaks' and other memory problems since we are relying on the logging methods to not fail. Here is one of the stack dumps: 2006-01-23 21:53:25,527 [RequestProcessor[2]] ERROR com.wiseb2b.server.Processor[7]:GET_EAD - access denied (java.io.FilePermission ERPDev/server.log.5 read) java.security.AccessControlException: access denied (java.io.FilePermission ERPDev/server.log.5 read) at java.security.AccessControlContext.checkPermission(AccessControlContext.java:269) at java.security.AccessController.checkPermission(AccessController.java:401) at java.lang.SecurityManager.checkPermission(SecurityManager.java:524) at java.lang.SecurityManager.checkRead(SecurityManager.java:863) at java.io.File.exists(File.java:678) at org.apache.log4j.RollingFileAppender.rollOver(RollingFileAppender.java:119) at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:228) at org.apache.log4j.WriterAppender.append(WriterAppender.java:150) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57) at org.apache.log4j.Category.callAppenders(Category.java:187) at org.apache.log4j.Category.forcedLog(Category.java:372) at org.apache.log4j.Category.debug(Category.java:241) at com.wiseb2b.pool.Pool.getInternal(Pool.java:379) at com.wiseb2b.pool.Pool.get(Pool.java:224) at com.wiseb2b.pool.Pool.get(Pool.java:214) at com.wiseb2b.jdbc.DataSourceImpl.getConnection(DataSourceImpl.java:94) at com.wiseb2b.server.AbstractSessionContext.getJdbcConnection(AbstractSessionContext.java:233) at com.wiseb2b.compatibility.QueryClassTools.getJdbcConnection(QueryClassTools.java:115) at com.wiseb2b.compatibility.QueryClassTools.getJdbcConnection(QueryClassTools.java:108) at GetEad.query0000(GetEad.java:100) at GetEad.execute(GetEad.java:90) at com.wiseb2b.server.Processor.executeRequest(Processor.java:419) at com.wiseb2b.server.corba.Connection.requestCString(Connection.java:181) at com.wiseb2b.ERP_Adapter._ConnectionImplBase._invoke(_ConnectionImplBase.java:118) at com.sun.corba.se.internal.corba.ServerDelegate.dispatch(ServerDelegate.java:353) at com.sun.corba.se.internal.iiop.ORB.process(ORB.java:280) at com.sun.corba.se.internal.iiop.RequestProcessor.process(RequestProcessor.java:81) at com.sun.corba.se.internal.orbutil.ThreadPool$PooledThread.run(ThreadPool.java:106) Note that "GetEad" class is a "user" space class. The "Pool.getInternal" method is the one doing the logging; here to indicate which pool entry was retrieved on behalf of the user request. Unfortunately, in this case, the connection object was "lost" since this unchecked exception was not expected. I recommend one of two approaches, either catch all SecurityException(s) in the logging methods themselves or execute the file switch (rollOver) method within an AccessController.doPrivileged call. Both methods would be good. The former to prevent any SecurityException from other appends causing this same problem (possible logging this to the log4j internal log - LogLog) and the later to allow the roll over to work properly as long as the log4j .jar file had sufficient privileges. Here are some patches for both of the above recommendations. RollingFileAppender (privileged execution): diff -u orig/RollingFileAppender.java bug/RollingFileAppender.java --- orig/RollingFileAppender.java 2006-01-23 22:33:45.000000000 -0500 +++ bug/RollingFileAppender.java 2006-01-23 22:36:21.000000000 -0500 @@ -104,8 +104,19 @@ <code>File</code> is truncated with no backup files created. */ - public // synchronization not necessary since doAppend is alreasy synched + + public void rollOver() { + AccessController.doPrivileged(new PrivilegedAction() { + public Object run() { + rollOver0(); + return null; + } + }); + } + + public // synchronization not necessary since doAppend is alreasy synched + void rollOver0() { File target; File file; Category (catch SecurityException for all logging events): diff -u orig/Category.java bug/Category.java --- orig/Category.java 2006-01-23 22:33:15.000000000 -0500 +++ bug/Category.java 2006-01-23 22:31:26.000000000 -0500 @@ -24,6 +24,7 @@ import org.apache.log4j.spi.AppenderAttachable; import org.apache.log4j.spi.LoggingEvent; import org.apache.log4j.spi.LoggerRepository; +import org.apache.log4j.helpers.LogLog; import org.apache.log4j.helpers.NullEnumeration; import org.apache.log4j.helpers.AppenderAttachableImpl; @@ -369,7 +370,11 @@ without further checks. */ protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) { - callAppenders(new LoggingEvent(fqcn, this, level, message, t)); + try { + callAppenders(new LoggingEvent(fqcn, this, level, message, t)); + } catch (SecurityException e) { + LogLog.error("security exception during logging", e); + } } If possible (with your bugzilla), I will attach a .tar.gz containing an entire running example. This includes a security policy file, some Linux bash scripts to run the examples, the server sample source and user sample user, and the "fixed" log4j code. I have two scripts, one to demo the problem as reported ("run.with.bug") and one to run the same classes using the fixed log4j classes ("run.with.fix"). Note that "run.with.fix" will run forever in this case as the user class attempts to write to the log forever. In the former case, it will very quickly abort with a SecurityException.
Created attachment 17491 [details] Full test case with bug and sample fix Extract this to any directory then you will need to change the first two paths in the example.policy file to match your directory. You must cd to the root of this example directory then you should be able to run either of the tests: ./run.with.bug ./run.with.fix [runs forever] These code was compiled with Eclipse set to output Java 1.4 byte code
As I was thinking about this some more... I think that org.apache.log4j.Category forcedLog method should probably catch RuntimeException to ensure that any other kinds of unchecked exceptions, in addition to SecurityException, are kept from being propogated to the caller.
This should be considered if appropriate to have in 1.2.16
Adding a try block around callAppenders could have performance implications. Also, in a perfect world, you would not want the failure of one appender to cause the rest to fail, so if you were going to do that, you'd want to do in within callAppenders. The implicit appender contract is that Appenders don't let anything percolate out of their append method. The RFAs are particular prone to to SecurityExceptions due to their file renaming. However, it probably would be best just to fix this in org.apache.log4j.rolling.RFA in the extras and not in DRFA and RFA since there are known problems in them that are fixed in o.a.l.r.RFA and they offer no functionality not in o.a.l.r.RFA. However, if someone wants to submit a patch against o.a.l.RFA and DRFA that is fairly clean, I would not object.
In Apache Clerezza we are using log4j and this is a major issue, users want to be able to use the rolling file appender, but if they do so things usually seem to work and start but then theses security-exception occur. The issue seem to have been assigned for a long time now, any chance a release will fix this in the near future?