понедельник, 31 августа 2009 г.

Write compressing rolling file appender for log4j

UPD: One good man leave a good comment :)

I think this is now supported in the standard;

http://logging.apache.org/log4j/companions/extras/apidocs/org/apache/log4j/rolling/TimeBasedRollingPolicy.html


Good day!

On the last week, we gave our software to support specialists. They installed the program to production servers. And over three thousand users began to work with it. At the on of that week, I didn't hear nothing about our product. This is good the good sign! :) But, we have one little problem, log file that wrote program had size little more 1Gb!!! This is not very good result :) Server's administrator sent me this log file. I analyzed it. Unfortunately, all information in it was very useful and didn't find anything that I can remove from log.

For logging, we use log4j. If you never use log4j, I recommend to read official document. Log4j have interface Appender. When you want log something, you call some code, looks like this:

...
import org.apache.log4j.Logger;

public class YourClass {
  private static final Logger log = Logger.getLogger(YourClass.class)
  ...
  public void someMethod() {
    log.info("Call someMethod()");
  }
  ...
}

Log4j pass all logging events through appenders, that you configure. By default, you have many appenders, that can send log over SMTP, JMS and do other interesting things. But, this list has no appenders that can periodically compress log file. To solve this problem, I write my own appender, that can periodically compress current log file. Because, I need compress only files, I inherit my appender from FileAppender and override subAppend() method. I don't speak more and simple show you result code:)

import org.apache.log4j.FileAppender;
import org.apache.log4j.helpers.LogLog;
import org.apache.log4j.spi.LoggingEvent;

import java.io.File;
import java.io.FileInputStream;
import java.io.IOException;
import java.io.FileOutputStream;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.GregorianCalendar;
import java.util.zip.GZIPOutputStream;

/**
 * Appender that periodically compress current log.
 * You need only pass one setting - period after that log should compress.
 * Available periods are MINUTLY, HOURLY, DAILY, WEEKLY, MONTHLY.
 *
 * @author Pokidov.Dmitry
 *         Date: 27.08.2009
 */
public class CompressingRollingFileAppender extends FileAppender {
 enum Period {MINUTLY, HOURLY, DAILY, WEEKLY, MONTHLY}

 private GregorianCalendar rollDate;
 private Period period = Period.HOURLY;
 private SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm");

 @Override
 public void activateOptions() {
  super.activateOptions();
  setAppend(false);
 }

 /**
  * Period for rolling. By default - {@code HOURLY}
  * @param period new period. Available values: MINUTLY, HOURLY, DAILY, WEEKLY, MONTHLY.
  */
 public void setPeriod(String period) {
  try {
   this.period = Period.valueOf(period);
  } catch (IllegalArgumentException e) {
   LogLog.warn("No period with name [" + period + "]", e);
  }

  LogLog.debug("Set roll period to [" + this.period + "]");
 }

 @Override
 public void setAppend(boolean flag) {
  LogLog.warn("Compression rolling appender doesn't support append option(always set to false)");
 }

 protected void rollOver() {
  String currentFileName = getFile();
  File currentFile = new File(currentFileName);
  File zipFile = new File(currentFileName + "." + dateFormat.format(new Date()) + ".gz");
  try {
   /*
     actually, I use helper that read all bytes, using NIO.
     see http://jajatips.blogspot.com/2008/11/reading-from-inputstream.html
   */
   FileInputStream stream = new FileInputStream(currentFile);
   byte[] content = new byte[](stream.available());
   stream.read(content);

   GZIPOutputStream gzipOutputStream = new GZIPOutputStream(new FileOutputStream(zipFile));
   gzipOutputStream.write(content, 0, content.length);
   gzipOutputStream.finish();
   gzipOutputStream.flush();
   gzipOutputStream.close();

   setFile(currentFileName, false, getBufferedIO(), getBufferSize());
   rollDate.add(getDateFieldByPeriod(), 1);
  } catch (IOException e) {
   LogLog.error("Error compress current log file [" + currentFile + "] to zip file [" + zipFile + "]", e);
  }
 }

 @Override
 protected void subAppend(LoggingEvent event) {
  if (rollDate == null) {
   rollDate = new GregorianCalendar();
   rollDate.add(getDateFieldByPeriod(), 1);
  }

  GregorianCalendar now = new GregorianCalendar();
  if (rollDate.before(now)) {
   rollOver();
  }

  super.subAppend(event);
 }

 private int getDateFieldByPeriod() {
  switch (period) {
   case MINUTLY:   return GregorianCalendar.MINUTE;
   case HOURLY:    return GregorianCalendar.HOUR;
   case DAILY:     return GregorianCalendar.DAY_OF_MONTH;
   case WEEKLY:    return GregorianCalendar.WEEK_OF_MONTH;
   case MONTHLY:   return GregorianCalendar.MONTH;
   default: return GregorianCalendar.MINUTE;
  }
 }
}

Also, I wrote test, because I don't want situation when error in logging subsystem cause crash in the application :)

import junit.framework.Assert;
import junit.framework.TestCase;
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

import java.io.File;
import java.io.StringReader;
import java.io.IOException;
import java.util.Properties;

/**
 * @author Pokidov.Dmitry
 *         Date: 28.08.2009
 */
public class CompressingRollingFileAppenderTest extends TestCase {
 private static final String LOG_DIR="log";

 private static class LogRun implements Runnable {
  private Logger log = Logger.getLogger(LogRun.class);

  @Override
  public void run() {
   for (int i = 0; i < 150; i++) {
    log.info("Log " + i);
    try {
     Thread.sleep(1000);
    } catch (InterruptedException e) {
     log.error("Interrupt", e);
    }
   }
  }
 }

 /**
  * Create 2 threads and create some log in it.
  */
 public void testAppender() {
  File dirLog = new File(LOG_DIR);
  try {
   for (File f : dirLog.listFiles()) {
    if (!f.delete()) {
     System.err.println("Cann't delete old log file [" + f.getName() + "]");
     Assert.fail("Cann't delete old log file [" + f.getName() + "]");
    }
   }

   PropertyConfigurator.configure(getLogProperties());

   Thread logThread1 = new Thread(new LogRun());
   Thread logThread2 = new Thread(new LogRun());

   logThread1.start();
   logThread2.start();

   logThread1.join();
   logThread2.join();
  } catch (Exception e) {
   e.printStackTrace();
   Assert.fail("Error while execute test: " + e.getMessage());
  }

  Assert.assertEquals(3, dirLog.list().length);
 }

 private Properties getLogProperties() throws IOException {
  Properties result = new Properties();
  String cfg = "log4j.debug=TRUE\n" +
               "log4j.rootLogger=INFO, main\n" +
               "\n" +
               "log4j.appender.main=com.otr.security.server.utils.CompressingRollingFileAppender\n" +
               "log4j.appender.main.Period=MINUTLY\n" +
               "log4j.appender.main.Append=true\n" +
               "log4j.appender.main.layout=org.apache.log4j.PatternLayout\n" +
               "log4j.appender.main.layout.ConversionPattern=[%d] %5p [%t] (%F:%L) - %m%n\n" +
               "log4j.appender.main.File=" + LOG_DIR + "/test.log";

  result.load(new StringReader(cfg));

  return result;
 }
}
And the production log4j.properties:
log4j.debug=TRUE
log4j.rootLogger=INFO, main

log4j.logger.com.mchange=ERROR
log4j.logger.org.springframework=ERROR

log4j.appender.main=server.utils.CompressingRollingFileAppender
log4j.appender.main.Period=DAILY
log4j.appender.main.File=log/server.log
log4j.appender.main.layout=org.apache.log4j.PatternLayout
log4j.appender.main.layout.ConversionPattern=[%d] %5p [%t] (%F:%L) - %m%n

3 комментария:

dimka комментирует...

Thank you! You are welcome!

Анонимный комментирует...

I think this is now supported in the standard;

http://logging.apache.org/log4j/companions/extras/apidocs/org/apache/log4j/rolling/TimeBasedRollingPolicy.html

dimka комментирует...

Thanks! I don't hear about companions early

Most popular

Authors