問題與分析

在使用Log4j2時，雖然可以正確讀取配置檔案並生成log檔案，但偶然發現控制檯列印了異常資訊如下：

2018-12-31 17:28:14,282 Log4j2-TF-19-ConfiguratonFileWatcher-6 ERROR Unable to invoke factory method in class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: No factory method found for
 
 class org.apache.logging.log4j.core.appender.RollingFileAppender java.lang.IllegalStateException: No factory method found for class org.apache.logging.log4j.core.appender.RollingFileAppender
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.findFactoryMethod(PluginBuilder.java:
 
235)
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:135)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:959)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.
 
createConfiguration(AbstractConfiguration.java:899)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:891)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:514)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:238)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:250)
        at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:547)
        at org.apache.logging.log4j.core.LoggerContext.onChange(LoggerContext.java:670)
        at org.apache.logging.log4j.core.config.ConfiguratonFileWatcher$ReconfigurationRunnable.run(ConfiguratonFileWatcher.java:68)
        at java.lang.Thread.run(Thread.java:748)

將控制檯的所有資訊都複製出來，仔細查詢，又發現了相關的異常資訊：

2018-12-31 17:28:14,241 Log4j2-TF-19-ConfiguratonFileWatcher-6 ERROR Unable to create file logs/${ctx:domainId}/CNTCore.log java.io.IOException: The filename, directory name, or volume label syntax is incorrect
        at java.io.WinNTFileSystem.canonicalize0(Native Method)
        at java.io.WinNTFileSystem.canonicalize(WinNTFileSystem.java:428)
        at java.io.File.getCanonicalPath(File.java:618)
	at ....


2018-12-31 17:28:14,280 Log4j2-TF-19-ConfiguratonFileWatcher-6 ERROR Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: ManagerFactory [...] unable to create manager for [logs/${ctx:domainId}/CNTCore.log] with data [...] java.lang.IllegalStateException: ManagerFactory [...] unable to create manager for [logs/${ctx:domainId}/CNTCore.log] with data [...]
        at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:115)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:114)
        at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.getFileManager(RollingFileManager.java:188)
        at ....

看起來是因為配置檔案裡的RollingFile使用到了${ctx:domainId}導致了這個問題。百度了下，發現了log4j2的jira issue：Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile

該問題和我遇到的一樣，而在jira裡有comment如下：

Question: Does system property logfile have a value?

結合專案的配置檔案log4j2.xml:

<RollingFile name="logfile" immediateFlush="true" fileName="logs/${ctx:domainId}/CNTCore.log"
    filePattern="logs/${ctx:domainId}/CNTCore.log.%d{yyyy-MM-dd-a}.gz" append="true">
    <PatternLayout>
        <pattern>%d %t %p %X{TracingMsg} %c - %m%n</pattern>
    </PatternLayout>
    <Policies>
        <TimeBasedTriggeringPolicy modulate="true" interval="1" />
    </Policies>
</RollingFile>

可以看出，這個異常是由於RollingFile使用到了${ctx:domainId}，而該變數值是null，導致無法建立對應的RollingFile檔案到磁碟。但是這個domainId是通過ThreadContext把值put進去的，不可能是null，從最終的效果來看，這個變數其實也是拿到了值的，因為對應的日誌檔案以及存在於磁碟上了。

既然如此，為什麼還會出現這個異常呢？通過觀察控制檯可以發現，每過一段時間就會出現一次該異常。從異常中可以看到ConfiguratonFileWatcher，好像有些明白為什麼了。

ConfiguratonFileWatcher是用來掃描配置檔案是否被改動過的，在配置檔案中設定的掃描間隔是30s：

<configuration monitorInterval="30">
    ....
</configuration>

由於掃描檔案時另外起一個執行緒去掃描的，而${ctx:domainId}的值是存放於ThreadContext中的，ThreadContext是執行緒安全的，同一個key對應的value在不同執行緒中是不一定相同的。而對於新啟動的執行緒來說，並沒有將domainId的值存放進去，於是新執行緒在掃描配置檔案的RollingFile時，自然是無法獲取到${ctx:domainId}的值，故而每隔一段時間就會報上邊的異常。

解決方法

方案一

既然問題是因為掃描配置檔案是否改動造成的，那麼只要將動態載入的功能關閉就行了，如下：

<configuration monitorInterval="0">
    ....
</configuration>

方案二

如果希望不關閉動態載入配置檔案的功能，可以將domainId的值存放到System.properties裡：

System.setProperty("domainId", "xxx");

然後通過${sys:xxx}的方式來獲取該properties的值：

<RollingFile name="logfile" immediateFlush="true" fileName="logs/${sys:domainId}/CNTCore.log"
    filePattern="logs/${sys:domainId}/CNTCore.log.%d{yyyy-MM-dd-a}.gz" append="true">
    <PatternLayout>
        <pattern>%d %t %p %X{TracingMsg} %c - %m%n</pattern>
    </PatternLayout>
    <Policies>
        <TimeBasedTriggeringPolicy modulate="true" interval="1" />
    </Policies>
</RollingFile>

在log4j2中關於這些變數取值有以下這些種類：

參考連結

• Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile
• Property Substitution