跳到主要內容

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，跟著就死翹翹啦!

Reference

標籤：

留言

張貼留言

這個網誌中的熱門文章

解決RobotFramework從3.1.2升級到3.2.2之後，Choose File突然會整個Hand住的問題

考慮到自動測試環境的維護，我們很久以前就使用java去執行robot framework。前陣子開始處理從3.1.2升級到3.2.2的事情，主要先把明確的runtime語法錯誤與deprecate item處理好，這部分內容可以參考: link 。 直到最近才發現，透過SeleniumLibrary執行Choose File去上傳檔案的動作，會導致測試案例timeout。本篇文章主要分享心路歷程與解決方法，我也送了一條issue給robot framework: link 。 我的環境如下: RobotFramework: 3.2.2 Selenium: 3.141.0 SeleniumLibrary: 3.3.1 Remote Selenium Version: selenium-server-standalone-3.141.59 首先並非所有Choose File的動作都會hang住，有些測試案例是可以執行的，但是上傳一個作業系統ISO檔案一定會發生問題。後來我透過wireshark去比對新舊版本的上傳動作，因為我使用 Remote Selenium ，所以Selenium會先把檔案透過REST API發送到Remote Selenium Server上。從下圖我們可以發現，在3.2.2的最後一個TCP封包，比3.1.2大概少了500個bytes。 於是就開始了我trace code之路。包含SeleniumLibrary產生要送給Remote Selenium Server的request內容，還有HTTP Content-Length的計算，我都確認過沒有問題。 最後發現問題是出在socket API的使用上，就是下圖的這支code: 最後發現可能因為開始使用nio的方式送資料，但沒處理到尚未送完的資料內容，而導致發生問題。加一個loop去做計算就可以解決了。 最後我有把解法提供給robot framework官方，在他們出新的版本之前，我是將改完的_socket.py放在我們自己的Lib底下，好讓我們測試可以正常進行。(shutil.py應該也是為了解某個bug而產生的樣子..)
張貼留言
閱讀完整內容

Show NIC selection when setting the network command with the device option

 Problem  在answer file中設定網卡名稱後，安裝時會停在以下畫面: 所使用的command參數如下: network --onboot = yes --bootproto =dhcp --ipv6 =auto --device =eth1 Diagnostic Result 這樣的參數，以前試驗過是可以安裝完成的。因此在發生這個問題後，我檢查了它的debug console: 從console得知，eth1可能是沒有連接網路線或者是網路太慢而導致的問題。後來和Ivy再三確認，有問題的是有接網路線的網卡，且問題是發生在activate階段: Solution 我想既然有retry應該就有次數或者timeout限制，因此發現在Anaconda的說明文件中( link )，有提到dhcptimeout這個boot參數。看了一些人的使用範例，應該是可以直接串在isolinux.cfg中，如下: default linux ksdevice = link ip =dhcp ks =cdrom: / ks.cfg dhcptimeout = 90 然而我在RHEL/CentOS 6.7與6.8試驗後都無效。 因此我就拿了顯示的錯誤字串，問問Google大師，想找一下Anaconda source code來看一下。最後找到別人根據Anaconda code修改的版本: link ，關鍵在於setupIfaceStruct函式中的setupIfaceStruct與readNetConfig: setupIfaceStruct: 會在dhcp時設定dhcptimeout。 readNetConfig: 在writeEnabledNetInfo將timeout寫入dhclient config中；在wait_for_iface_activation內會根據timeout做retry。 再來從log與code可以得知，它讀取的檔案是answer file而不是boot command line。因此我接下來的測試，就是在answer file的network command上加入dhcptimeout: network --onboot = yes --bootproto =dhcp --ipv6 =auto --device =eth1 --...
張貼留言
閱讀完整內容

Robot Framework - Evaluate該怎麼用?

Evaluate該怎麼用? 前言 Builtin的RobotFramework Library提供了Evaluate Keyword。它所提供的功能是「執行Python描述句」。但實際上到底有什麼用途呢?原本我僅僅拿來將string轉為int的功用，經過一些查詢與試驗，我將心得整理給大家。 Builtin Builtin的function可以參考Library Doc for Evaluate。我以有使用過的function做說明。 數字轉換 Python提供了int、long、float與complex等function讓你可以將字串轉為數字，也可以透過它們做四則運算。首先以字串轉數字為例，我將8設於${num_str}中，再透過Evaluate+int轉為數字。這裡必須注意的是: 「int()中放變數必須以單引號'括起」。否則，假如你設定的數字為08，在轉換int時會出現Syntax Error。 ${num_str} | Set Variable | 8 ${num} | Evaluate | int('${num_str}') 其中int與long的第二個參數為base，這是根據你的input所決定: Comment | num = 9 ${num} | Evaluate | int('11', 8) Comment | num = 11 ${num} | Evaluate | int('11', 10) Comment | num = 17 ${num} | Evaluate | int('11', 16) 其它還有像bin、oct、hex，可以將整數轉為2、8、16進位。 運算 四則運算: 直接將運算子加上即可: ${num} | Evaluate | int('${hour}')*60 + int('${min}') 指數: 可以用pow。以下面兩個例子來說，第一個是2的3次方為8，第二個是2的3次方再mod 7為1。需注意的是: 「傳入值必須是數字不可為字串」。 ${num} | Evaluate | pow(2,3) ${num} | Evaluate | pow(2,3,7) 取最大最小值: 使用max/min，可以選擇丟一個array的方式...
張貼留言
閱讀完整內容