Log4j - FileWatchDog for Configuration

Problem

在軟體開發與debug的時候，為了幫助了解程式做到什麼地方、發生問題在哪或狀態如何，會使用log去記錄重要的執行過程。但每次修改完log4j property file為了讓它生效，會重新啟動應用程式讓它reload，但這樣不是很煩嗎?為了解決這樣問題，我們可以透過Log4J提供的PropertyWatchdog去polling property file是否有做過修改。如以下程式碼，透過PropertyConfigurator的configureAndWatch就可以了，預設是60秒check一次。

org.apache.log4j.PropertyConfigurator.configureAndWatch(aLogPropertyFilePath);

但如果你是使用1.2版本或之前的，可能會遇到和我一樣的情況。在我將package名稱如以下更動後(增加.internal)，就收到了log4j:ERROR Attempted to append to closed appender named的訊息，還狂跳不停。這是怎麼一回事?

log4j.additivity.org.tonylin.facebook=false
log4j.logger.org.tonylin.facebook=INFO, CONSOLE, LOGFILE
->
log4j.additivity.org.tonylin.facebook.internal=false
log4j.logger.org.tonylin.facebook.internal=INFO, CONSOLE, LOGFILE

How to resolve?

我先告訴大家我最後的解法，細部內容待我最後說明，有興趣的再繼續看。一看訊息就可以猜應該是狀態不正常造成的，在trace code後發現原先在每次檔案有改變後，也僅做了下面的動作。

new PropertyConfigurator().doConfigure(filename, LogManager.getLoggerRepository())

於是我直接寫了一個class去繼承Log4j既有的FileWatchdog，並於發生改變時，重新reset configuration，這個問題就這樣解決了。

public class Log4jPropertyWatcher extends FileWatchdog {
 
	private static Logger mLogger = LoggerFactory.getLogger(Log4jPropertyWatcher.class);
	private static long mDefaultInterval = 1000l;
 
	Log4jPropertyWatcher(String filename){
		super(filename);
	}
 
	@Override
	protected void doOnChange() {
		mLogger.debug("Log4j config is changed.");
		LogManager.getLoggerRepository().resetConfiguration();
		new PropertyConfigurator().doConfigure(filename, LogManager.getLoggerRepository());
	}
 
	public static void configureAndWatch(String filename){
		Log4jPropertyWatcher fileWatcher = new Log4jPropertyWatcher(filename);
		fileWatcher.setDelay(mDefaultInterval);
		fileWatcher.start();
	}
 
	public static void setWatchInterval(long aInterval){
		mDefaultInterval = aInterval;
	}
}

那Root Cuase呢? 錯誤訊息是由AppenderSkeleton丟出的，原因是它發現Appender已經被close了。close也許是關閉檔案或串流等等動作，這由根據Append實做決定，但重點是的確被某人給關閉了。

public synchronized void doAppend(LoggingEvent event)
{
     if (this.closed) {
       LogLog.error("Attempted to append to closed appender named [" + this.name + "].");
       return;
     }

於是重頭開始trace PropertyConfigurator，在parseCategory中發現它會透過logger的removeAllAppenders，將可能原有的Appender都close掉，且它每一個Appender都是相同的instance。這會造成什麼問題? 因為Log4j在做config的時候，會根據你所設定的package去加入Appender。如果你移除了某些package，又或者像是Problem中增加package的child而不保留原本的。原先的package並沒有被Log4j回收或清除，它在執行log時，會使用原本設定在它身上的Appender，跟著就死翹翹啦!

阿兩的筆記本 Ryoutsu's Notebook

搜尋此網誌