Log files are not getting rolled over with log4j 1.2.17 and java8u162

Question

We are facing a problem in production Environment where in some situations log files are not getting rolled over. We are using Log4j version 1.2.17 along with apache.commons-logging. A custom appender is created to roll over the files. The appender is extending the FileAppender of Log4j. Here is the algorithm of subAppend(LoggingEvent event) method:

long n = System.currentTimeMillis();
// Has the time come to roll the log file?
if (n >= nextCheck)
{
 now.setTime(n);
    nextCheck = rc.getNextCheckMillis(now);

    rollOver();
    reachedMaxSize = false;

 else
 {
     File f = new File(getFile());

     // Has the log file has exceeded its maximum size?
     if (!reachedMaxSize && f.length() > maxFileSize)
     {
         // Log file has reached it maximum size.
         reachedMaxSize = true;

         // Log one last message to the file stating the max has been reached.
         LoggingEvent exeededEvent = new LoggingEvent(
                      getClass().getName(),
                      Logger.getLogger(getClass().getName()),
                      Priority.ERROR,
                      "Maximum log file size has been reached ("+maxFileSize/1024+"KB)",
                      null);
       super.subAppend(exeededEvent);
     }

 // If the log has not reached its max size, write it. Otherwise,
 // send log event to stdout.
 if (!reachedMaxSize)
 {
     super.subAppend(event);
 }
 else
 {
     System.out.println(event.getRenderedMessage());
 }

Here is the Log4j.properties file

log4j.rootLogger=INFO,RCFLog

log4j.appender.RCFLog=com.ge.medit.util.logging.MaxFileSizeRollingFileAppender
log4j.appender.RCFLog.File=runtime/logs/rcf.log
log4j.appender.RCFLog.DatePattern=yyyyMMdd'_'{0}
log4j.appender.RCFLog.Encoding=UTF-8
log4j.appender.RCFLog.Append=true

log4j.appender.ConsoleLog=org.apache.log4j.ConsoleAppender
log4j.appender.ConsoleLog.layout=org.apache.log4j.PatternLayout
log4j.appender.ConsoleLog.layout.ConversionPattern=%p [%t] %c{1}: %m%n

log4j.appender.RCFLog.layout=org.apache.log4j.PatternLayout
log4j.appender.RCFLog.layout.ConversionPattern=@%d{yyyyMMdd HH:mm:ss.SSS}@ %p {%t} %c{1}: %m%n

log4j.logger.GUIEVT=INFO

As per the observation, there was a date change on the system. The date was set as 3 months before the current date.

Current Date- 10th May 2018
nextCheck - 11th May 2018 00:00
Changed Date- 10th March 2018
No backup is created as a condition at line 3 failed.

After 12 hours again on 11th May, the date was changed to the current date. By that time the timestamp of the file was changed to 10th March. Since there was no RollOver the next check was still 11th May 2018 00:00. But On 12th May at 00:00 the file should have been rolled over as per the condition at line 3 and a new file should have been created which didn't happen. Also, the file had reached the maximum size. From then there were no logs until the system was rebooted.

The Java version is java8u162. Though I couldn't find any post which says if it is related to java.

The same scenario I tried to reproduce in the test environment but there everything is working as expected.

Has anyone ever faced such kind of issue with Log4j? Please share your inputs. Thanks in advance.

Answer 1

I believe the best way is just to debug the code, log4j can be debugged just like any other code, without this we can only speculate.

I see from your configurations, that you're using com.ge.medit.util.logging.MaxFileSizeRollingFileAppender which is not a standard rolling file appender of log4j (probably your company's custom appender that can be buggy).

If you cannot debug it, I can only provide a couple of hints, that can hopefully help.

1. Modify the appender and use org.apache.log4j.helpers.LogLog to print some information about the work of appender itself, it's like "logging inside the log4j" - something that goes to System.out/System.err depending on a severity level

2. Usually rolling over (see "rollover" function) is implemented as a series of "renames" of files. I've seen once (again, only speculating) that this method will work only if:

   • you have permissions on files
   • your application posses the only handle on file (especially relevant for windows OS).

It's easy to track in debug because technically the renaming is probably done with java.io.File#renameTo that returns true/false depending on whether the renaming operation has succeeded or failed.

In order to simulate this situation, you can deploy the "hidden" code that just "floods" the log with messages (you can use A JMX, internal web servlet/message handler - whatever you want, but inside it can contain a plethora of log messages (fake) in a loop, something like this:

class MyHiddenMBean {
    Logger logger = ...
    public void doLogManyTimes(int times) {
         for(int i = 0; i < times; i++) {
             logger.info("Artificial Logging Message : " + i);
         }
    } 
}

You'll immediately reach the max file (of course you can put it intentionally ridiculously small to simulate faster) and then you'll be able to see why renameTo doesn't work

Answer 2

I got the reason why files were not backed up. There were multiple date changes. It was observed that the date was first changed to 10/05/2036 then later changed to 2021 and changed back to 10/03/2018 after which we finally changed the date to the current date on 11/05/2018.

So when the date was changed to future date 10/05/2036. nextCheck date was updated to 11/05/2036. Again when date was changed back to the current date the above if condition failed(now (11/05/2018 >= 11/05/2036). So the backup will take place only when the date will be changed to 11/05/2036 or more.

Need to change the condition if (n >= nextCheck) to if if (n >= nextCheck || nextCheck - n > TimeConstants.MILLISECONDS_PER_DAY. This change is yet to be tested.

Thanks @ Mark Bramnik for the quick response.