Log4j 의 Appender로 DailyRollingFileAppender를 사용할 경우에 파일 교체 시기에 ‘Failed to rename’ 이라는 에러를 만나게 되는 경우가 있습니다.
이 에러가 발생하면 새로운 내용은 기존 파일에 그대로 쓰여지지만 기존 로그 파일의 내용이 전부 날아가는 심각한 상황이 발생하죠. 물론 기존 내용이 날아가므로 파일 교체 기능도 제대로 수행하지 못하구요.
원인은 바로, 같은 파일을 여러 로그 인스턴스에서 참조하는 경우에 각 로그 인스턴스에서 로그 파일을 인스턴스가 정리되거나 파일 교체가 일어날 때까지 놓지 않기 때문이었습니다.
(저는 설정 파일에 여러 카테고리를 설정하고 모든 카테고리에서 하나의 로그 파일을 사용하도록 하니까 이런 문제가 생기더군요. 물론 각 카테고리마다 인스턴스를 하나씩 생성했죠.)
아래는 Log4j 1.2.14의 DailyRollingFileAppender.java 의 rollOver() 에서 주석을 제거한 내용입니다.
DailyRollingFileAppender에서는 파일을 바꿔야 할 시기가 되면 파일을 닫고 파일 이름 변경을 시도합니다.(즉, 파일을 계속 잡고 있는다는 이야기…)
그렇기 때문에, 다른 로그 인스턴스 중에 같은 파일을 계속 잡고 있다면 자신만 closeFile()로 파일을 닫는다고 해도 File.renameTo()가 정상적으로 동작할 수가 없는 것이죠.
이 방법을 나름대로 간단하게 구현하기 위해, DailyRollingFileAppender의 내용을 붙여서 새로운 클래스를 만들었습니다.
(rollOver() 메소드의 한정자가 패키지이기 때문에, 새로운 클래스를 Log4j 라이브러리에 포함하고 상속받아서 구현할 수도 있겠지만 새로운 클래스를 정의하여 내용을 그대로 Copy & Paste 하고 필요한 부분만 수정하였습니다. Log4j의 jar 파일에 포함하는 것은 Ant 사용법을 안다면 껌이기 때문에 여러분의 몫입니다…^^;;)
구현 방법을 살펴봅시다.
우선 모든 로그 인스턴스를 제가 필요로 할 때 찾을 수 있어야 하기 때문에 아래와 같은 static attribute를 추가합니다.
다음으로, 모든 생성자에서 아까 만든 ArrayList로 객체를 포함시킵니다.
마지막으로 rollOver()를 수정합니다.
이 되는 것이죠.
멀티쓰레드의 경우 파일을 닫고 변경하고 설정하는 과정 중에 같은 파일을 사용하는 로그 인스턴스 두 개 이상이 rollOver()로 진입하면 소위 꼬일 수가 있으므로 rollOver()에 synchronized 키워드를 넣어 주었습니다.
구현된 전체 내용입니다.
/**
*
*/
package net.heartsavior;
import org.apache.log4j.*;
import java.io.IOException;
import java.io.File;
import java.text.SimpleDateFormat;
import java.util.ArrayList;
import java.util.Date;
import java.util.GregorianCalendar;
import java.util.Calendar;
import java.util.HashMap;
import java.util.Iterator;
import java.util.TimeZone;
import java.util.Locale;
import org.apache.log4j.helpers.LogLog;
import org.apache.log4j.spi.LoggingEvent;
/**
FixedDailyRollingFileAppender extends {@link FileAppender} so that the
underlying file is rolled over at a user chosen frequency.
<p>The rolling schedule is specified by the <b>DatePattern</b>
option. This pattern should follow the {@link SimpleDateFormat}
conventions. In particular, you <em>must</em> escape literal text
within a pair of single quotes. A formatted version of the date
pattern is used as the suffix for the rolled file name.
<p>For example, if the <b>File</b> option is set to
<code>/foo/bar.log</code> and the <b>DatePattern</b> set to
<code>’.'yyyy-MM-dd</code>, on 2001-02-16 at midnight, the logging
file <code>/foo/bar.log</code> will be copied to
<code>/foo/bar.log.2001-02-16</code> and logging for 2001-02-17
will continue in <code>/foo/bar.log</code> until it rolls over
the next day.
<p>Is is possible to specify monthly, weekly, half-daily, daily,
hourly, or minutely rollover schedules.
<p><table border=”1″ cellpadding=”2″>
<tr>
<th>DatePattern</th>
<th>Rollover schedule</th>
<th>Example</th>
<tr>
<td><code>’.'yyyy-MM</code>
<td>Rollover at the beginning of each month</td>
<td>At midnight of May 31st, 2002 <code>/foo/bar.log</code> will be
copied to <code>/foo/bar.log.2002-05</code>. Logging for the month
of June will be output to <code>/foo/bar.log</code> until it is
also rolled over the next month.
<tr>
<td><code>’.'yyyy-ww</code>
<td>Rollover at the first day of each week. The first day of the
week depends on the locale.</td>
<td>Assuming the first day of the week is Sunday, on Saturday
midnight, June 9th 2002, the file <i>/foo/bar.log</i> will be
copied to <i>/foo/bar.log.2002-23</i>. Logging for the 24th week
of 2002 will be output to <code>/foo/bar.log</code> until it is
rolled over the next week.
<tr>
<td><code>’.'yyyy-MM-dd</code>
<td>Rollover at midnight each day.</td>
<td>At midnight, on March 8th, 2002, <code>/foo/bar.log</code> will
be copied to <code>/foo/bar.log.2002-03-08</code>. Logging for the
9th day of March will be output to <code>/foo/bar.log</code> until
it is rolled over the next day.
<tr>
<td><code>’.'yyyy-MM-dd-a</code>
<td>Rollover at midnight and midday of each day.</td>
<td>At noon, on March 9th, 2002, <code>/foo/bar.log</code> will be
copied to <code>/foo/bar.log.2002-03-09-AM</code>. Logging for the
afternoon of the 9th will be output to <code>/foo/bar.log</code>
until it is rolled over at midnight.
<tr>
<td><code>’.'yyyy-MM-dd-HH</code>
<td>Rollover at the top of every hour.</td>
<td>At approximately 11:00.000 o’clock on March 9th, 2002,
<code>/foo/bar.log</code> will be copied to
<code>/foo/bar.log.2002-03-09-10</code>. Logging for the 11th hour
of the 9th of March will be output to <code>/foo/bar.log</code>
until it is rolled over at the beginning of the next hour.
<tr>
<td><code>’.'yyyy-MM-dd-HH-mm</code>
<td>Rollover at the beginning of every minute.</td>
<td>At approximately 11:23,000, on March 9th, 2001,
<code>/foo/bar.log</code> will be copied to
<code>/foo/bar.log.2001-03-09-10-22</code>. Logging for the minute
of 11:23 (9th of March) will be output to
<code>/foo/bar.log</code> until it is rolled over the next minute.
</table>
<p>Do not use the colon “:” character in anywhere in the
<b>DatePattern</b> option. The text before the colon is interpeted
as the protocol specificaion of a URL which is probably not what
you want.
@author Eirik Lygre
@author Ceki Gülcü */
/**
Fixed ‘
*/
public class FixedDailyRollingFileAppender extends FileAppender {
private static ArrayList<FixedDailyRollingFileAppender> arrAppender =
new ArrayList<FixedDailyRollingFileAppender>();
// 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 FixedDailyRollingFileAppender() {
// Configuration 파일에서 로딩하면 이 생성자가 호출됨
FixedDailyRollingFileAppender.arrAppender.add(this);
}
/**
Instantiate a <code>FixedDailyRollingFileAppender</code> and open the
file designated by <code>filename</code>. The opened filename will
become the ouput destination for this appender.
*/
public FixedDailyRollingFileAppender (Layout layout, String filename,
String datePattern) throws IOException {
super(layout, filename, true);
this.datePattern = datePattern;
activateOptions();
FixedDailyRollingFileAppender.arrAppender.add(this);
}
/**
The <b>DatePattern</b> 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 <b>DatePattern</b> option. */
public String getDatePattern() {
return datePattern;
}
public synchronized 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()));
LogLog.debug(”Appender : ” + this.toString() + ” , FileName : ” + scheduledFilename);
} 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.
*/
synchronized // For multiple instance
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;
}
/**
* 같은 파일을 쓰고 있는 FixedDailyRollingAppender 객체들을 찾아서 파일을 닫아준다.
*/
Iterator<FixedDailyRollingFileAppender> iter =
FixedDailyRollingFileAppender.arrAppender.iterator();
while( iter.hasNext() ) {
FixedDailyRollingFileAppender appender = iter.next();
// Windows System에서는 대소문자 가리지 않음…
// Unix System에서는 compare()를 사용하면 됨
if( this.fileName.compareToIgnoreCase(appender.fileName) == 0 &&
appender.fileName.length() == this.fileName.length() ) {
appender.closeFile();
}
}
// 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+"].”);
}
iter = FixedDailyRollingFileAppender.arrAppender.iterator();
while( iter.hasNext() ) {
FixedDailyRollingFileAppender appender = iter.next();
// Windows System에서는 대소문자 가리지 않음…
// Unix System에서는 compare()를 사용하면 됨
if( this.fileName.compareToIgnoreCase(appender.fileName) == 0 &&
appender.fileName.length() == this.fileName.length() ) {
try {
// This will also close the file. This is OK since multiple
// close operations are safe.
appender.setFile(fileName, true, this.bufferedIO, this.bufferSize);
}
catch(IOException e) {
errorHandler.error(”setFile(”+fileName+”, true) call failed.”);
}
appender.scheduledFilename = datedFilename;
}
}
}
/**
* This method differentiates FixedDailyRollingFileAppender from its
* super class.
*
* <p>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 synchronized 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 FixedDailyRollingFileAppender.
* Given a periodicity type and the current time, it computes the
* start of the next interval.
* */
class RollingCalendar extends GregorianCalendar {
int type = FixedDailyRollingFileAppender.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 FixedDailyRollingFileAppender.TOP_OF_MINUTE:
this.set(Calendar.SECOND, 0);
this.set(Calendar.MILLISECOND, 0);
this.add(Calendar.MINUTE, 1);
break;
case FixedDailyRollingFileAppender.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 FixedDailyRollingFileAppender.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 FixedDailyRollingFileAppender.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 FixedDailyRollingFileAppender.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 FixedDailyRollingFileAppender.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();
}
}
깔끔하지는 못한 구현이지만 이런 문제로 고생하고 있는 분들에게 도움이 되었으면 합니다. ^^