logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Stadelmann Josef" <josef.stadelm...@axa-winterthur.ch>
Subject AW: log4j rollover in est timezone not working as expected
Date Wed, 15 Feb 2012 10:17:40 GMT
Hi Paul,

 

I am not an expert on log4j, but use it and frequently build it from sources.

So I found the following in code which might get you some light into shadow.

 

This is at the DailyRollingFileAppender.java

 

 

   DailyRollingFileAppender extends {@link FileAppender} so that the

   underlying file is rolled over at a user chosen frequency.

   

   DailyRollingFileAppender has been observed to exhibit 

   synchronization issues and data loss.  The log4j extras

   companion includes alternatives which should be considered

   for new deployments and which are discussed in the documentation

   for org.apache.log4j.rolling.RollingFileAppender.

 

 

 

below is first the DailyRollingFileAppender.java (3 methods)

 

 

 

a.) to understand, "what triggers the rollover?"

 

  /**

     Rollover the current file to a new file.

  */

  void rollOver() throws IOException {

 

    /* Compute filename, but only if datePattern is specified */

    if (datePattern == null) {

      errorHandler.error("Missing DatePattern option in rollOver().");

      return;

    }

 

    String datedFilename = fileName+sdf.format(now);

    // It is too early to roll over because we are still within the

    // bounds of the current interval. Rollover will occur once the

    // next interval is reached.

    if (scheduledFilename.equals(datedFilename)) {

      return;

    }

 

    // close current file, and rename it to datedFilename

    this.closeFile();

 

    File target  = new File(scheduledFilename);

    if (target.exists()) {

      target.delete();

    }

 

    File file = new File(fileName);

    boolean result = file.renameTo(target);

    if(result) {

      LogLog.debug(fileName +" -> "+ scheduledFilename);

    } else {

      LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");

    }

 

    try {

      // This will also close the file. This is OK since multiple

      // close operations are safe.

      this.setFile(fileName, true, this.bufferedIO, this.bufferSize);

    }

    catch(IOException e) {

      errorHandler.error("setFile("+fileName+", true) call failed.");

    }

    scheduledFilename = datedFilename;

  }

 

 

b.) how is the computation done? "all in GMT starting at epoch"

 

  // This method computes the roll over period by looping over the

  // periods, starting with the shortest, and stopping when the r0 is

  // different from from r1, where r0 is the epoch formatted according

  // the datePattern (supplied by the user) and r1 is the

  // epoch+nextMillis(i) formatted according to datePattern. All date

  // formatting is done in GMT and not local format because the test

  // logic is based on comparisons relative to 1970-01-01 00:00:00

  // GMT (the epoch).

 

  int computeCheckPeriod() {

    RollingCalendar rollingCalendar = new RollingCalendar(gmtTimeZone, Locale.getDefault());

    // set sate to 1970-01-01 00:00:00 GMT

    Date epoch = new Date(0);

    if(datePattern != null) {

      for(int i = TOP_OF_MINUTE; i <= TOP_OF_MONTH; i++) {

      SimpleDateFormat simpleDateFormat = new SimpleDateFormat(datePattern);

      simpleDateFormat.setTimeZone(gmtTimeZone); // do all date formatting in GMT

      String r0 = simpleDateFormat.format(epoch);

      rollingCalendar.setType(i);

      Date next = new Date(rollingCalendar.getNextCheckMillis(epoch));

      String r1 =  simpleDateFormat.format(next);

      //System.out.println("Type = "+i+", r0 = "+r0+", r1 = "+r1);

      if(r0 != null && r1 != null && !r0.equals(r1)) {

        return i;

      }

      }

    }

    return TOP_OF_TROUBLE; // Deliberately head for trouble...

  }

 

be aware that rollingCalendar is a helper to computeCheckPeriod to help in calculating the
next intervall

 

 

 

b.)what adds to the scheduledFilename which plays a major role to trigger the rolover

 

Also this mightbe of help/insight to you. What is returned in sdf? below.

Because sdf forms part of the new scheduledFilename. And because the rollover 

takes place when the currentFilename matches the scheduledFilename.

 

  public void activateOptions() {

    super.activateOptions();

    if(datePattern != null && fileName != null) {

      now.setTime(System.currentTimeMillis());

      sdf = new SimpleDateFormat(datePattern);

      int type = computeCheckPeriod();

      printPeriodicity(type);

      rc.setType(type);

      File file = new File(fileName);

      scheduledFilename = fileName+sdf.format(new Date(file.lastModified()));

 

    } else {

      LogLog.error("Either File or DatePattern options are not set for appender ["

               +name+"].");

    }

  }

 

AND printPeriodicity() will for sure never printout what you are looking for. 

i.e. 5 hours after midnight.

 

  void printPeriodicity(int type) {

    switch(type) {

    case TOP_OF_MINUTE:

      LogLog.debug("Appender ["+name+"] to be rolled every minute.");

      break;

    case TOP_OF_HOUR:

      LogLog.debug("Appender ["+name

               +"] to be rolled on top of every hour.");

      break;

    case HALF_DAY:

      LogLog.debug("Appender ["+name

               +"] to be rolled at midday and midnight.");

      break;

    case TOP_OF_DAY:

      LogLog.debug("Appender ["+name

               +"] to be rolled at midnight.");

      break;

    case TOP_OF_WEEK:

      LogLog.debug("Appender ["+name

               +"] to be rolled at start of week.");

      break;

    case TOP_OF_MONTH:

      LogLog.debug("Appender ["+name

               +"] to be rolled at start of every month.");

      break;

    default:

      LogLog.warn("Unknown periodicity for appender ["+name+"].");

    }

  }

 

 

 

My mind, take down sources down from 

$ svn co http://svn.apache.org/repos/asf/logging/log4j/trunk log4j

and invest some time executing the 

 

/**

   Exhaustive test of the DailyRollingFileAppender compute algorithm.

 

   @author Ceki G&uuml;lc&uuml;

   @author Curt Arnold

*/

public class DRFATestCase extends TestCase {

 

so look at DRFATestCase.java

 

 

I think what you want could work if we master to add an offset to get a new scheduledFilename

in example to rollover at GMT+5h, this will definitly trigger the rollover at GMT+5h.

 

But reagarding the pattern to format the events I can not make any statements. 

 

 

Maybe a other idea:

What you can think of is: forget the DailyRollingFileAppender.java and

look at log4j code for ExternallyRolledFileAppender.java

 

This file appender listens on a socket given in the pattern, 

and it will rollover when it receives a signal from the Roller.java 

apps which can be remotely. So your apps controls the rollover()

 

/**

   A simple application to send roll over messages to a potentially

   remote {@link ExternallyRolledFileAppender}. 

 

   <p>It takes two arguments, the <code>host_name</code> and

   <code>port_number</code> where the

   <code>ExternallyRolledFileAppender</code> is listening.

   

 

   @author Ceki G&uuml;lc&uuml;

   @since version 0.9.0 */

 

 

regards

Josef

 

 

 

 

 

 

 

-----Urspr√ľngliche Nachricht-----
Von: Paul [mailto:ppage4@yahoo.com] 
Gesendet: Montag, 13. Februar 2012 17:15
An: log4j-user@logging.apache.org
Betreff: log4j rollover in est timezone not working as expected

 

 

Initially I setup log4j to rollover at midnight using the default machine (linux) timezone
which is GMT and everything worked correctly. I could see the timestamps before and after
rollover were correct. I then changed the time output to be in EST (log4j extras) but the
rollover still happens at midnight GMT or 5 hours too early. How can I get both time display
and rollover to work the same based on EST?

 

This is my current test property file:

 

log4j.appender.appender1=org.apache.log4j.DailyRollingFileAppender 

log4j.appender.appender1.File=report.log

log4j.appender.appender1.layout=org.apache.log4j.EnhancedPatternLayout

log4j.appender.appender1.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS}{EST} [%p] %c:%L
- %m%n

log4j.appender.appender1.DatePattern = '.'yyyy-MM-dd-HH-mm

 

When I look in the log file I can see the entries are in EST - so far so good. But when I
look at the last entry before rollover, I see:

 

INFO 2012-02-09 18:56:06 ...

 

so, we have a rollover around 7pm EST or midnight GMT but I want the rollover to happen at
midnight EST or 5 hours later. Right now the day boundaries are showing across two files which
makes troubleshooting application errors more difficult.

 

 

BTW, I'm using the 1.2.16 log4j binary and 1.1 extras.

 

thanks, Paul.

 

 

---------------------------------------------------------------------

To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org

For additional commands, e-mail: log4j-user-help@logging.apache.org

 


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message