log4j筆記：升級2.X版本的日誌滾動問題

由於slf4j依賴的log4j在流量大的時候總遇到多線程引發的死鎖問題，升級到log4j2.x版本。原來的log4j.properties配置文件已經不被log4j2支持了，須要改寫爲log4j2.xml。在升級的過程當中，配置與原先相同，使用異步日誌，按小時滾動，卻發現配置後日志輸出正常，但滾動的功能不正常，查出如下兩個問題。

 

1. 日誌不按小時滾動

原來的配置以下：

 <RollingRandomAccessFile name="RollingFile" fileName="${backupFilePatch}${fileName}" filePattern="${backupFilePatch}${fileName}.%d{yyyy-MM-dd}.%i" immediateFlush="false">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %p %c{1}[%L]-%m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>            
            </Policies>
            <DefaultRolloverStrategy max="120"/>
 </RollingRandomAccessFile>

根據官網的介紹，我理解成了interval=1的時候固定按小時滾動，其實interval的單位是根據filePattern來的，即filePattern配置中的最小單位，因此在yyyy-MM-dd這樣的配置中，interval的單位是day，而%i則是interval的序號，日誌是按天滾動的。因此將配置改成${backupFilePatch}${fileName}.%d{yyyy-MM-dd.HH}就能按小時滾動了。

 

2. 每小時滾動後，日誌不寫入新文件，而是寫入舊的歸檔文件。

這個問題更詭異。tomcat啓動後，日誌是寫入log文件的，可是整點日誌滾動以後，log歸檔爲log-日期，產生一個新的log文件，但日誌仍是打入了歸檔以後的文件log-日期。放置了一天以後，發現更詭異的事情，日誌老是寫入上一個歸檔文件。例如，7點的時候，產生一個歸檔文件log-日期.6，7點到8點的日誌都打入了文件6，log文件始終是空的，而8點以後，log歸檔爲log-日期-7，以後的日誌都打入文件7，新產生的log文件仍是爲空。

該問題遍尋不着解法。在某一次整點時，正好刷新了一下，發現log文件有新內容，再刷新又成爲上面那種現象了。由此聯想到，有可能不僅是log4j2在對這個文件進行操做。

 

排查發現，改寫log4j2.xml以後，原來的log4j.properties還留在項目裏。因爲maven層層疊疊的依賴，有幾個包引用的是log4j1.x版本，在運行的時候，始終有一個包用的是log4j1.x在打日誌，所以加載的是log4j.properties的配置。log4j.properties和log4j2.xml的配置徹底相同，寫入的也是同一個日誌文件。整點的時候，這兩個類都對log文件進行歸檔操做，猜測是log4j2先執行歸檔，寫入新log文件，而這個文件又被log4j1歸檔，所以後面log4j2的日誌都寫入了上一個歸檔文件。

 

將log4j.properties中的日誌改成其餘名稱，問題解決。