Aug 09 2007

Log4j DailyRollingFileAppender 개선 - Failed to rename 에러 최소화하기

분류: Open.Library 태그: ,, , , , Heart @ 11:04 오후

Trackback : http://dev.heartsavior.net/archives/88/trackback/

Log4j 의 Appender로 DailyRollingFileAppender를 사용할 경우에 파일 교체 시기에 ‘Failed to rename’ 이라는 에러를 만나게 되는 경우가 있습니다.
이 에러가 발생하면 새로운 내용은 기존 파일에 그대로 쓰여지지만 기존 로그 파일의 내용이 전부 날아가는 심각한 상황이 발생하죠. 물론 기존 내용이 날아가므로 파일 교체 기능도 제대로 수행하지 못하구요.

저도 이 문제로 약간 고민하다가, 문제를 바로 해결할 수 있을까 해서 구글링을 시도했었는데…
관련 페이지가 엄청나게 많더군요. 많은 사람들이 이 문제로 고민을 했다는 반증이라고 생각됩니다.
아무튼 관련 페이지는 엄청나게 많은 반면 깔끔하게 해결이 되는 것은 찾을 수가 없었습니다. 대신, 에러가 발생하는 원인을 지적하는 내용은 많았기 때문에 계속 찾아보는 것보다 원인에 대한 해결책을 구현해 보는 것이 낫겠다는 생각을 하고 구현으로 방향을 선회했습니다.

원인은 바로, 같은 파일을 여러 로그 인스턴스에서 참조하는 경우에 각 로그 인스턴스에서 로그 파일을 인스턴스가 정리되거나 파일 교체가 일어날 때까지 놓지 않기 때문이었습니다.
(저는 설정 파일에 여러 카테고리를 설정하고 모든 카테고리에서 하나의 로그 파일을 사용하도록 하니까 이런 문제가 생기더군요. 물론 각 카테고리마다 인스턴스를 하나씩 생성했죠.)

아래는 Log4j 1.2.14의 DailyRollingFileAppender.java 의 rollOver() 에서 주석을 제거한 내용입니다.

void rollOver() throws IOException {

if (datePattern == null) {
errorHandler.error(”Missing DatePattern option in rollOver().”);
return;
}

String datedFilename = fileName+sdf.format(now);
if (scheduledFilename.equals(datedFilename)) {
return;
}

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

DailyRollingFileAppender에서는 파일을 바꿔야 할 시기가 되면 파일을 닫고 파일 이름 변경을 시도합니다.(즉, 파일을 계속 잡고 있는다는 이야기…)
그렇기 때문에, 다른 로그 인스턴스 중에 같은 파일을 계속 잡고 있다면 자신만 closeFile()로 파일을 닫는다고 해도 File.renameTo()가 정상적으로 동작할 수가 없는 것이죠.

가장 간단하게 생각할 수 있는 방법은 rollOver() 에서 파일을 닫을 때, 같은 파일을 사용하는 모든 로그 인스턴스에서 파일을 닫는 것입니다. (물론 새로운 파일을 연결해 주는 것도 잊지 말아야 하겠죠?)

이 방법을 나름대로 간단하게 구현하기 위해, DailyRollingFileAppender의 내용을 붙여서 새로운 클래스를 만들었습니다.
(rollOver() 메소드의 한정자가 패키지이기 때문에, 새로운 클래스를 Log4j 라이브러리에 포함하고 상속받아서 구현할 수도 있겠지만 새로운 클래스를 정의하여 내용을 그대로 Copy & Paste 하고 필요한 부분만 수정하였습니다. Log4j의 jar 파일에 포함하는 것은 Ant 사용법을 안다면 껌이기 때문에 여러분의 몫입니다…^^;;)

구현 방법을 살펴봅시다.

우선 모든 로그 인스턴스를 제가 필요로 할 때 찾을 수 있어야 하기 때문에 아래와 같은 static attribute를 추가합니다.

private static ArrayList<FixedDailyRollingFileAppender> arrAppender = new ArrayList<FixedDailyRollingFileAppender>();

다음으로, 모든 생성자에서 아까 만든 ArrayList로 객체를 포함시킵니다.

FixedDailyRollingFileAppender.arrAppender.add(this);

마지막으로 rollOver()를 수정합니다.

synchronized // For multiple instance
void rollOver() throws IOException {
if (datePattern == null) {
errorHandler.error(”Missing DatePattern option in rollOver().”);
return;
}

String datedFilename = fileName+sdf.format(now);
if (scheduledFilename.equals(datedFilename)) {
return;
}

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();
}
}

// 위에서 이미 닫음
//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 {
appender.setFile(fileName, true, this.bufferedIO, this.bufferSize);
}
catch(IOException e) {
errorHandler.error(”setFile(”+fileName+”, true) call failed.”);
}

appender.scheduledFilename = datedFilename;
}
}
}

구현한 내용을 요약하면…
1. 파일을 닫을 때 같은 파일을 사용하는 로그 인스턴스를 발견해서 모두 파일을 닫아 줌
2. 파일을 변경
3. 닫아준 인스턴스를 다시 찾아서 파일을 다시 설정해 줌

이 되는 것이죠.

멀티쓰레드의 경우 파일을 닫고 변경하고 설정하는 과정 중에 같은 파일을 사용하는 로그 인스턴스 두 개 이상이 rollOver()로 진입하면 소위 꼬일 수가 있으므로 rollOver()에 synchronized 키워드를 넣어 주었습니다.

구현된 전체 내용입니다.

전체 구현 보기..

깔끔하지는 못한 구현이지만 이런 문제로 고생하고 있는 분들에게 도움이 되었으면 합니다. ^^