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 키워드를 넣어 주었습니다.

구현된 전체 내용입니다.

전체 구현 보기..

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


Jul 27 2007

[JAVA]Apache Logging(Log4j) - 편리한 로깅 기록을 도우는 라이브러리

분류: Open.Library 태그: ,, , Heart @ 12:49 오전

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

Log4j는 Java 관련한 로깅 라이브러리에서 가장 많이 사용되고 있는 라이브러리입니다.
아파치 재단의 명성에 걸맞게 상당히 강력하며, JDK 1.4부터 기본 포함되어 있습니다.

관련 자료들을 읽어 보시면 ‘정말 간단하게 강력한 로깅을 수행할 수 있구나’ 라고 생각하실 것입니다.

먼저, 영어 자료입니다.

@ Don’t Use System.out.println! Use Log4j

영어 문서를 자유롭게 읽으실 수 있으시다면 이 문서 하나만 보셔도 되지 않을까 싶네요. 사실 전 아래의 사이트로 공부했는데, 위의 문서를 대충 훓어보니 내용이 거의 다 있습니다.

영어 울렁증이 있으신 분은 (약간의 귀차니즘이 있지만) 아래 사이트를 참조하세요.

@ loveLazur 오픈소스 && 아키텍쳐 - 오픈소스를 이용한 SI

phpBB로 만들어져 있고, 가입을 해야 볼 수 있지만, 주인장님의 Log4j 관련한 포스트들은 그만한 가치가 있네요.
딱딱하지도 않고, 예제 중심으로 설명이 되어 초심자 입장에서 친숙하게 익힐 수가 있습니다.
출력해서 보려고 워드 파일에 정리하니까 40페이지 정도 되고, 한 페이지에 두장씩 찍으니 20페이지… 쭉 훓어보는 데 30분도 안 걸린 것 같네요. 이렇게 깔끔하게 정리해 주신 데 감사드려야겠습니다. ^^

간단한 설정 파일만으로도 강력한 로깅이 가능하다는 게 Log4j의 강력함이라고 할 수 있겠습니다.
아래는 제가 loveLazur 님의 포스트들을 읽고 테스트 용도로 만든 것입니다.

[log4jconf.xml]
<?xml version=”1.0″ encoding=”UTF-8″ ?>
<!DOCTYPE log4j:configuration SYSTEM “log4j.dtd”>
<log4j:configuration xmlns:log4j=’http://jakarta.apache.org/log4j/’>

<!– Standard output –>
<appender name=”STDOUT” class=”org.apache.log4j.ConsoleAppender”>
<layout class=”org.apache.log4j.PatternLayout”>
<param name=”ConversionPattern”
value=”%d %-5p [%t] %C{2} (%F:%L) - %m%n”/>
</layout>
</appender>

<!– Daily Rolling File Appender output –>
<appender name=”DAILY” class=”org.apache.log4j.DailyRollingFileAppender”>
<param name=”datePattern” value=”yyyy-MM-dd” />
<param name=”file” value=”log/SyncService.log” />
<param name=”append” value=”true” />
<layout class=”org.apache.log4j.PatternLayout”>
<param name=”ConversionPattern”
value=”%d %-5p [%t] %C{2} (%F:%L) - %m%n”/>
</layout>
</appender>

<!– Category logger–>
<category name=”CONSOLELOG” additivity=”false”>
<priority value=”debug” />
<appender-ref ref=”STDOUT” />
</category>

<!– package logger –>
<category name=”FILELOG” additivity=”false”>
<priority value=”debug” />
<appender-ref ref=”DAILY” />
</category>

<!– root category –>
<root>
<priority value =”debug” />
<appender-ref ref=”STDOUT” />
</root>
</log4j:configuration>

[test.java]

{
Logger logger = Logger.getLogger(”FILELOG”);

Logger logger2 = Logger.getLogger(”CONSOLELOG”);

String conf = “log4jconf.xml”;
DOMConfigurator.configure(conf);

logger.debug(”Here is some DEBUG”);
logger.info(”Here is some INFO”);
logger.warn(”Here is some WARN”);
logger.error(”Here is some ERROR”);
logger.fatal(”Here is some FATAL”);

logger2.debug(”Here is some DEBUG!!”);
}

이렇게 하면 콘솔 화면에는

2007-07-27 00:49:37,687 DEBUG [main] test.SyncFeatureTest (SyncFeatureTest.java:362) - Here is some DEBUG!!

log/SyncService.log 파일은

2007-07-27 00:49:37,640 DEBUG [main] test.SyncFeatureTest (SyncFeatureTest.java:356) - Here is some DEBUG
2007-07-27 00:49:37,671 INFO  [main] test.SyncFeatureTest (SyncFeatureTest.java:357) - Here is some INFO
2007-07-27 00:49:37,671 WARN  [main] test.SyncFeatureTest (SyncFeatureTest.java:358) - Here is some WARN
2007-07-27 00:49:37,671 ERROR [main] test.SyncFeatureTest (SyncFeatureTest.java:359) - Here is some ERROR
2007-07-27 00:49:37,687 FATAL [main] test.SyncFeatureTest (SyncFeatureTest.java:360) - Here is some FATAL

로 기록됩니다. 특히, “FILELOG” 로거로 로깅되는 정보는 날짜가 지나면 파일이 자동으로 생성되어 나뉩니다.


Mar 26 2007

나를 위한 코딩을 해 보자.

분류: Dev.Think 태그: ,, , , Heart @ 11:44 오후

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

# Help yourself! programmer…

포스트 내용이 구구절절 공감이 된다.

프로그래머로 사회생활을 시작한 지 1년 반 정도 되었는데, 종종 코드들을 돌아보면 엄청난 양의 중복이 존재함을 깨닫는다.
하지만 그 놈의 ‘귀차니즘’이 뭔지, 퇴근이 뭔지…
최대한 시간을 줄이기 위해 소스를 통째로 찾아서 갖다 붙이는 작업을 하게 된다.
그 때 당시에는 라이브러리로 만드는 것보다 시간이 덜 걸린다. 하지만 그걸 여러 번 반복하게 되니 이 작업 자체가 만만하지 않음을 깨닫는다.
프로그램을 모두 뒤져가면서 소스 떼어내고, 컴파일 에러 나는지 확인하고, 컴파일 에러를 고치기 위해 또 소스를 뒤져서 붙이거나 필요없는 소스를 제거하고, 또 에러 확인하고…

입사때 부터 이걸 깨닫고 조금만 고생해 두었으면 지금쯤 라이브러리 조합만으로도 엄청난 코딩을 줄일 수 있었을텐데… 내일부터 시간 날때마다 정리를 해 둬야겠다.

라이브러리와는 조금 다른 이야기이지만, 비슷한 이야기를 하나 더…

대학교 연구실 교수님께서 자주 하시는 말씀이 있다.
“매크로 작업이 있으면, 손으로 할 때 걸리는 시간과 프로그램을 만드는 시간을 예상해 보고, 손으로 하는 게 빠르면 손으로 하고, 비슷하기라도 하면 프로그램을 만들어라.”

학생 때는 나도 매크로 작업이 필요할 때는 되도록이면 간단한 유틸리티라도 작성해서 사용했는데, 입사하고 나면서 점점 귀찮아지면서 ‘손으로 하고 말지’ 라는 생각이 앞서는 것 같다.
(물론 회사 입사 이후로도 몇 가지 만들긴 했는데, 엄청 귀찮아하면서 만들었다.)

그런데 작업을 하다 보면 매크로 작업은 한 번 하면 보통 나중에도 여러 번 하게 되는 것 같다.

그래서, 교수님 말씀에 개인적인 생각을 한 가지 더 추가해야 될 것 같다.
“두 번 이상 사용할 것 같다면 프로그램을 만들어라.”

정리하자면, 자신을 위해 이런 작업은 ‘귀차니즘’을 극복하고 긴 안목을 두고 해야 되지 않을까 싶다.
(생각해보니 역으로 생각하면 ‘귀차니즘’을 위하여 해야 되는 것일 수도 있네…)

1. 라이브러리화 할 수 있는 것들은 모두 라이브러리화 하고 API 스타일의 문서를 만들자. 그리고 추가되는 클래스를 잘 분류해서 라이브러리를 자주 업데이트하자.

2. 매크로 작업을 유틸리티로 작성하자.

라이브러리야 뭐 회사에서 사용하는 언어를 따라가면 되니…
리팩토링과 클래스 디자인, 디자인 패턴, 그리고 ‘귀차니즘’을 공부해야 할 것 같다.

매크로 작업은 C/C++로 코딩하기에는 좀 비효율적인 것 같고… 스크립트 언어를 하나 공부해보면 좋을 것 같다. 미뤄두고 있는 파이썬 언어를 시간날 때 마다 공부해보아야겠다.

공부할 게 무궁무진하구나…