Bug 49693 - Intermittently Log4j fails to bind with log file
Intermittently Log4j fails to bind with log file
Status: NEW
Product: Log4j
Classification: Unclassified
Component: Appender
1.2
Sun Solaris
: P2 critical
: 1.2.18
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-08-03 10:53 UTC by chirag desai
Modified: 2013-04-02 16:08 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description chirag desai 2010-08-03 10:53:11 UTC
Hi,

We face a strange problem on our environments that when sometimes application is started in Tomcat (v5.5.26) we see following error:

INFO: Deploying web application archive Xyz.war
log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: ../logs/xyz/xyz.log (No such file or directory)
        at java.io.FileOutputStream.openAppend(Native Method)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:177)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:102)
        at org.apache.log4j.FileAppender.setFile(FileAppender.java:272)
        at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:151)
        at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:206)

Due to this although application starts properly and can be used by users, it fails to update log file and also does not use daily rolling feature.

However if Tomcat is stopped and then started this problem goes away. Therefore the issue is intermittent and only surfaces randomly when Tomcat is restarted,

We investigated this issue in detail and have verified that path/permissions for the log file and folder is correct.

Could you please confirm is this is a bug in this version (1.2.8) or something else needs correcting?

Any views/comments/experience on this would be much appreciated!

Regards,
Chirag Desai
Comment 1 Jacob Kjome 2010-08-03 23:49:03 UTC
Have you tested with a newer version of Log4j?  The latest is 1.2.16.  It's entirely possible this used to be an issue, but has since been fixed.

Jake
Comment 2 Fabrice 2013-04-02 15:56:41 UTC
Hi,

I came accross this issue while researching a similar behavior on our systems.

When rolling at midnight (using companions, we create a folder based on date) we intermittently lose the logs.

Bascially the appender gets broken in a way a no new log file is created.

Looking at the code there is a race condition in FileAppender in the following block:

String parentName = new File(fileName).getParent();
      if (parentName != null) {
        File parentDir = new File(parentName);
        if ((!parentDir.exists()) && (parentDir.mkdirs()))
          ostream = new FileOutputStream(fileName, append);
        else
          throw ex;
      }

This is run when a new folder structure must be created by the appender. If two different appenders try to create the parent directory at the same time, then both will get "false" when testing for parent dir existence, but only one will get "true" upon directory creation. The second appender will then fail and rethrow the original exception, and log4j presumably closes the appender after that, which prevents any further attempt to write to the appender.

Only solution so far is to reload log4j configuration.

My assumption is that this code tries to protect against errors while trying to create the directories. To keep the protection a double check pattern should be added to re-test for parent dir existence and only fail if it does not exist during the second test. Another option would be to synchronize on a static monitor object at the FileAppender level so that two different appenders could not enter that section at the same time.
Comment 3 Fabrice 2013-04-02 16:08:08 UTC
Even easier actually, change the code to:

if (!parentDir.exists())) {
    parentDir.mkdirs();
}
ostream = new FileOutputStream(fileName, append);

And the stream constructor will throw again an exception it it has to.