Please pardon our appearance - we're working on migrating this blogger to AngularJS

Notice Me!!

Content Tab 1 Content Tab 2 Active Tab: {{model.activeTab}}

Friday, July 25, 2008

Improving the Log4j DailyRollingFileAppender

The log4j DailyRollingFileAppender is an absolute blessing - it lets us create logs that roll over each day, which is really handy when you are trouble shooting, and you would think, would keep our log directories nice and clean just like the RollingFileAppender.

Unfotunately, it doesn't = there's a lot of room for improvement - the DailyRollingFileAppender doesn't give us the option to specify how many files to keep and it doesn't clean up after itself.

Wouldn't it be great if it could .zip up the log file at the end of each day and optionally delete old log files that we don't need?

Well, hell! Let's change it so it can! (in case you're in a rush, here's the completed class - link fixed 2011-03-21)

I'd have liked to be able to extend the existing DailyRollingFileAppender - override the existing rollover() method and be done with it, but the Log4j team didn't make it that simple - the relevant methods aren't public or protected - they have package-level access - so we have to start from scratch! Or, a little more easily, start over with what they've already written, and make a couple of changes to rename and repackage it (changes are highlighted in red):

/**
* CustodianDailyRollingFileAppender.java
* Adapted from the Apache Log4j DailyRollingFileAppender to extend the functionality
* of the existing class so that the user can limit the number of log backups
* and compress the backups to conserve disk space.
* @author Ryan Kimber

* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements.  See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to You under the Apache License, Version 2.0
* (the "License"); you may not use this file except in compliance with
* the License.  You may obtain a copy of the License at
* 
*      http://www.apache.org/licenses/LICENSE-2.0
* 
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/



package ca.justtechnologies.utils.logging;

import java.io.IOException;
import java.io.File;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.GregorianCalendar;
import java.util.Calendar;
import java.util.TimeZone;
import java.util.Locale;

//We have to import the log4j package because this class used to be in it and references other classes in that package.
import org.apache.log4j.*;
import org.apache.log4j.helpers.LogLog;
import org.apache.log4j.spi.LoggingEvent;

/**
CustodianDailyRollingFileAppender is based on {@link  org.apache.log4j.appender.DailyRollingFileAppender} so most of the configuration options can be taken from the documentation on that class. 
*/
public class CustodianDailyRollingFileAppender extends FileAppender
{
// The code assumes that the following constants are in a increasing
// sequence.
static final int TOP_OF_TROUBLE=-1;
static final int TOP_OF_MINUTE = 0;
static final int TOP_OF_HOUR   = 1;
static final int HALF_DAY      = 2;
static final int TOP_OF_DAY    = 3;
static final int TOP_OF_WEEK   = 4;
static final int TOP_OF_MONTH  = 5;


/**
The date pattern. By default, the pattern is set to
"'.'yyyy-MM-dd" meaning daily rollover.
*/
private String datePattern = "'.'yyyy-MM-dd";

/**
The log file will be renamed to the value of the
scheduledFilename variable when the next interval is entered. For
example, if the rollover period is one hour, the log file will be
renamed to the value of "scheduledFilename" at the beginning of
the next hour. 

The precise time when a rollover occurs depends on logging
activity. 
*/
private String scheduledFilename;

/**
The next time we estimate a rollover should occur. */
private long nextCheck = System.currentTimeMillis () - 1;

Date now = new Date();

SimpleDateFormat sdf;

RollingCalendar rc = new RollingCalendar();

int checkPeriod = TOP_OF_TROUBLE;

// The gmtTimeZone is used only in computeCheckPeriod() method.
static final TimeZone gmtTimeZone = TimeZone.getTimeZone("GMT");


/**
The default constructor does nothing. */
public CustodianDailyRollingFileAppender() {
}

/**
Instantiate a CustodianDailyRollingFileAppender and open the
file designated by filename. The opened filename will
become the ouput destination for this appender.

*/
public CustodianDailyRollingFileAppender (Layout layout, String filename,
String datePattern) throws IOException {
super(layout, filename, true);
this.datePattern = datePattern;
activateOptions();
}

/**
The DatePattern takes a string in the same format as
expected by {@link SimpleDateFormat}. This options determines the
rollover schedule.
*/
public void setDatePattern(String pattern) {
datePattern = pattern;
}

/** Returns the value of the DatePattern option. */
public String getDatePattern() {
return datePattern;
}

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+"].");
}
}

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+"].");
}
}


// 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.ENGLISH);
// 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...
}

/**
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, false, this.bufferedIO, this.bufferSize);
}
catch(IOException e) {
errorHandler.error("setFile("+fileName+", false) call failed.");
}
scheduledFilename = datedFilename;
}

/**
* This method differentiates DailyRollingFileAppender from its
* super class.
*
* 
Before actually logging, this method will check whether it is
* time to do a rollover. If it is, it will schedule the next
* rollover time and then rollover.
* */
protected void subAppend(LoggingEvent event) {
long n = System.currentTimeMillis();
if (n >= nextCheck) {
now.setTime(n);
nextCheck = rc.getNextCheckMillis(now);
try {
rollOver();
}
catch(IOException ioe) {
LogLog.error("rollOver() failed.", ioe);
}
}
super.subAppend(event);
}
}

/**
*  RollingCalendar is a helper class to DailyRollingFileAppender.
*  Given a periodicity type and the current time, it computes the
*  start of the next interval.  
* */
class RollingCalendar extends GregorianCalendar {
private static final long serialVersionUID = -3560331770601814177L;

int type = CustodianDailyRollingFileAppender.TOP_OF_TROUBLE;

RollingCalendar() {
super();
}  

RollingCalendar(TimeZone tz, Locale locale) {
super(tz, locale);
}  

void setType(int type) {
this.type = type;
}

public long getNextCheckMillis(Date now) {
return getNextCheckDate(now).getTime();
}

public Date getNextCheckDate(Date now) {
this.setTime(now);

switch(type) {
case CustodianDailyRollingFileAppender.TOP_OF_MINUTE:
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.MINUTE, 1);
break;
case CustodianDailyRollingFileAppender.TOP_OF_HOUR:
this.set(Calendar.MINUTE, 0);
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.HOUR_OF_DAY, 1);
break;
case CustodianDailyRollingFileAppender.HALF_DAY:
this.set(Calendar.MINUTE, 0);
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
int hour = get(Calendar.HOUR_OF_DAY);
if(hour < 12) {
this.set(Calendar.HOUR_OF_DAY, 12);
} else {
this.set(Calendar.HOUR_OF_DAY, 0);
this.add(Calendar.DAY_OF_MONTH, 1);
}
break;
case CustodianDailyRollingFileAppender.TOP_OF_DAY:
this.set(Calendar.HOUR_OF_DAY, 0);
this.set(Calendar.MINUTE, 0);
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.DATE, 1);
break;
case CustodianDailyRollingFileAppender.TOP_OF_WEEK:
this.set(Calendar.DAY_OF_WEEK, getFirstDayOfWeek());
this.set(Calendar.HOUR_OF_DAY, 0);
this.set(Calendar.MINUTE, 0);
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.WEEK_OF_YEAR, 1);
break;
case CustodianDailyRollingFileAppender.TOP_OF_MONTH:
this.set(Calendar.DATE, 1);
this.set(Calendar.HOUR_OF_DAY, 0);
this.set(Calendar.MINUTE, 0);
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.MONTH, 1);
break;
default:
throw new IllegalStateException("Unknown periodicity type.");
}
return getTime();
}
}



Now that we have a working DailyRollingFileAppender that has a new name and is in our own package we can start adding some new features to it. First, lets add a couple of new properties that we will use to configure the class. In the class member declaration, just after the "datePattern" variable, lets add properties for turning .zip compression on and off, and for how many days worth of files backups we want to keep, along with appropriate getters and setters. Log4j will look after setting these properties for us if we put values for them in our log4j configuration file (make sure you add this code to the CustodianDailyRollingFileAppender and not the RollingCalendar helper class):
public class CustodianDailyRollingFileAppender extends FileAppender
{
...
/**
* The date pattern. By default, the pattern is set to "'.'yyyy-MM-dd" meaning daily rollover.
*/
private String datePattern = "'.'yyyy-MM-dd";
private String compressBackups = "false";
private String maxNumberOfDays = "7";

...

public String getCompressBackups()
{
return compressBackups;
}

public void setCompressBackups(String compressBackups)
{
this.compressBackups = compressBackups;
}

public String getMaxNumberOfDays()
{
return maxNumberOfDays;
}

public void setMaxNumberOfDays(String maxNumberOfDays)
{
this.maxNumberOfDays = maxNumberOfDays;
}
}


Of course, we're going to need some code that makes use of these properties. The DailyRollingFileAppender makes use of the rollover() method to rollover it's files. We don't want to change any of that functionality, but we're going to want to have the opportunity clean up any old files that shouldn't be there any more before we rollover to a new one. Add the following method and the StartsWithFileFilter as an inner class:


/*
* This method checks to see if we're exceeding the number of log backups
* that we are supposed to keep, and if so, deletes the offending files.
* It then delegates to the rollover method to rollover to a new file if 
* required.
*/
protected void cleanupAndRollOver() throws IOException
{
//Check to see if there are already 5 files
File file = new File(fileName);
Calendar cal = Calendar.getInstance();
int maxDays = 7;
try
{
maxDays = Integer.parseInt(getMaxNumberOfDays());
} 
catch(Exception e)
{
//just leave it at 7.
}
cal.add(Calendar.DATE, -maxDays);
Date cutoffDate = cal.getTime();
if (file.getParentFile().exists())
{
File[] files = file.getParentFile().listFiles(
new StartsWithFileFilter(file.getName(), false));
int nameLength = file.getName().length();
for (int i = 0; i < files.length; i++)
{
String datePart = null;
try
{
datePart = files[i].getName().substring(nameLength);
Date date = sdf.parse(datePart);
if (date.before(cutoffDate))
{
files[i].delete();
}
}
catch (Exception pe)
{
//This isn't a file we should touch (it isn't named correctly) 
}
}
}
rollOver();
}

class StartsWithFileFilter implements FileFilter
{
private String startsWith;
private boolean inclDirs = false;
/**
* 
*/
public StartsWithFileFilter(String startsWith, boolean includeDirectories)
{
super();
this.startsWith = startsWith.toUpperCase();
inclDirs = includeDirectories;
}

/* (non-Javadoc)
* @see java.io.FileFilter#accept(java.io.File)
*/
public boolean accept(File pathname)
{
if(!inclDirs && pathname.isDirectory())
{
return false;
}
else return pathname.getName().toUpperCase().startsWith(startsWith);
}
}


If you've got a real keen eye, you might have noticed that the original rollOver() method declares that it throws an IOException (and so likewise does our cleanupAndRollover()), but that this isn't necessary - the rollOver() method already explicitly handles the IOException and there are no conditions that would throw another, so feel free to clean this up if you like - you'll have to remove the throws declarations and the try...catch block in the subAppend() method. However, if you are planning on implementing the .zip functionality I discussed earlier, the fact that cleanupAndRollover() can throw an IOException will come in handy shortly.

Next, we need to modify the subAppend() method to have it call our cleanupAndRollover() method instead of the original rollOver() method:
protected void subAppend(LoggingEvent event) 
{
long n = System.currentTimeMillis();
if (n >= nextCheck) 
{
now.setTime(n);
nextCheck = rc.getNextCheckMillis(now);
try 
{
cleanupAndRollover();
}
catch(IOException ioe) 
{
LogLog.error("cleanupAndRollover() failed.", ioe);
}
}
super.subAppend(event);
}


We're making real progress here - we now have a class that will take an appender that will create a new log each day and will keep a restricted number of file back ups.

The other thing we wanted to do was to augment the code so that it would optionally .zip up the backed-up log files to save space in our log filesystem. Fortunately, all of the classes required to compress files using .zip are built right into Java, so we don't need any additional libraries.

We can add the method below directly to the class:

/**
* Compresses the passed file to a .zip file, stores the .zip in the
* same directory as the passed file, and then deletes the original,
* leaving only the .zipped archive.
* @param file
*/
private void zipAndDelete(File file) throws IOException
{
if(!file.getName().endsWith(".zip"))
{
File zipFile = new File(file.getParent(), file.getName() + ".zip");
FileInputStream fis = new FileInputStream(file);
FileOutputStream fos = new FileOutputStream(zipFile);
ZipOutputStream zos = new ZipOutputStream(fos);
ZipEntry zipEntry = new ZipEntry(file.getName());
zos.putNextEntry(zipEntry);

byte[] buffer = new byte[4096];
while(true)
{
int bytesRead = fis.read(buffer);
if(bytesRead == -1) break;
else
{
zos.write(buffer, 0, bytesRead);
}
}
zos.closeEntry();
fis.close();
zos.close();
file.delete();
}
}


Great! We're almost done - we make a small addition to our cleanupAndRollover() method, so that it will make use of our new .zip functionality:
protected void cleanupAndRollOver()
{
//Check to see if there are already 5 files
File file = new File(fileName);
Calendar cal = Calendar.getInstance();
int maxDays = 7;
try
{
maxDays = Integer.parseInt(getMaxNumberOfDays());
} 
catch(Exception e)
{
//just leave it at 7.
}
cal.add(Calendar.DATE, -maxDays);
Date cutoffDate = cal.getTime();
if (file.getParentFile().exists())
{
File[] files = file.getParentFile().listFiles(
new StartsWithFileFilter(file.getName(), false));
int nameLength = file.getName().length();
for (int i = 0; i < files.length; i++)
{
String datePart = null;
try
{
datePart = files[i].getName().substring(nameLength);
Date date = sdf.parse(datePart);
if (date.before(cutoffDate))
{
files[i].delete();
}
//If we're supposed to zip files and this isn't already a zip
else if(getCompressBackups().equalsIgnoreCase("YES") || getCompressBackups().equalsIgnoreCase("TRUE"))
{
zipAndDelete(files[i]);
}
}
catch (Exception pe)
{
//This isn't a file we should touch (it isn't named correctly) 
}
}
}

rollOver();
}


...and we're done coding. Make a few changes changes to your log4j.properties file (or .xml) to add the new properties, like in the example below:
log4j.rootLogger=INFO, FILE

log4j.appender.FILE=ca.justtechnologies.utils.logging.CustodianDailyRollingFileAppender
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d{MMM dd yyyy HH:mm:ss,SSS} [%t] %-5p %l - %m%n
log4j.appender.FILE.File=/var/log/web-apps/Dashboard.log
log4j.appender.FILE.DatePattern='.'yyyy-MM-dd
log4j.appender.FILE.MaxNumberOfDays=14
log4j.appender.FILE.CompressBackups=true


Happy Logging!!!

14 comments:

Mike said...

Wow, that is a really nice extension to the DailyRollingFileAppender. Thanks for sharing that with us and making it so easy to use.

Russell said...

Wow... this class has all the enhancements we've been searching for! Well done. There is a broken link though for the java file ... could you please re-upload it? Cheers

Ryan Kimber said...

I've fixed the broken link - you can download the completed file again.

Jason said...

Good stuff! There is one problem if you try and use a different date format though. When getting the datePart in cleanupAndRollOver, the length of the substring should be based on the length of the datePattern, like: (datePattern.length() - 2)

myT said...

Thanks a lot for the CustodianDailyRollingFileAppender!! It was exactly what we needed... we made some minor changes, I posted our version of it on http://mytselection.blogspot.com/2009/11/extra-features-for-log4j.html

Yellen said...

Just the Appender I have been looking for.. Thank god!! I was just about to write my own when I stumbled upon this.. :)

Ryan said...

Thank you for your suggestions. I've incorporated most of the and fixed the issue that was pointed out with the date pattern.

CR9 said...

Is there a plan to include this logger in the official log4j distribution ?
Version 1.2.16 is already... It may take some time before the next release... That should leave enough time to do the integration.

Anonymous said...

10x I'll give it a try

Tilman Hausherr said...

Thanks man! Just what I needed today.

Anonymous said...

Amazing... but the link broken again.. http://patientordersets.comtechblogfiles/CustodianDailyRollingFileAppender.java

Btw, I got it from my friend..

Anonymous said...

Thank you! Excellent contribution! It was exactly what I was looking for.

Arun Ponnaiah said...

This custom class works well. It saved our time and effort. Thanks for sharing.

Arun Ponnaiah said...

very helpful!