log4net 檔名使用「大寫」字母造成檔案被覆寫問題

事情是這樣子的…我們有個專案裡面有使用 log4net v 1.2.11.0 ，在案子裡面是使用 RollingFileAppender ， rollingStyle 是 Composite ，依日期時間及檔案大小來切檔，設定檔如下，

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
<log4net debug="true">
	<appender name="DBRollingFileAppender" type="log4net.Appender.RollingFileAppender">
	  <file type="log4net.Util.PatternString" value="[你的路徑]\temp\%date{yyyy}\%date{MM}\%date{dd}\" />
	  <staticLogFileName value="false"/>
	  <appendToFile value="true"/>
	  <!--設定檔案分割依據Date和Size-->
	  <rollingStyle value="Composite"/>
	  <!--設定每個檔案的大小-->
	  <MaximumFileSize value="250KB" />
	  <!--設定分割檔案的最大數量-->
	  <maxSizeRollBackups value="2000" />
	  <CountDirection value="1" />
	  <!--log檔案的命名-->
	  <datePattern value="yyyy-MM-dd-HH-DB2.lo\g"/>
	  <layout type="log4net.Layout.PatternLayout">
		<conversionPattern value="[%date] [%-5level] From %logger%newline  %file:%line [%property{NDC}]%newline  %message%newline%newline" />
	  </layout>
	  <filter type="log4net.Filter.LevelRangeFilter">
		<param name="LevelMin" value="INFO"/>
		<param name="LevelMax" value="INFO"/>
	  </filter>
	</appender>
	<appender name="SystemRollingFileAppender" type="log4net.Appender.RollingFileAppender">
	  <!--存放log檔案的路徑(%property{LogPath}屬性請勿任意修改)-->
	  <file type="log4net.Util.PatternString" value="[你的路徑]\temp\%date{yyyy}\%date{MM}\%date{dd}\" />
	  <staticLogFileName value="false"/>
	  <appendToFile value="true"/>
	  <!--設定檔案分割依據Date和Size-->
	  <rollingStyle value="Composite"/>
	  <!--設定每個檔案的大小-->
	  <MaximumFileSize value="20KB" />
	  <!--設定分割檔案的最大數量-->
	  <maxSizeRollBackups value="2000" />
	  <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
	  <CountDirection value="1" />
	  <!--log檔案的命名-->
	  <datePattern value="yyyy-MM-dd-HH-DB.lo\g"/>
	  <layout type="log4net.Layout.PatternLayout">
		<conversionPattern value="%d{yyyy-MM-dd HH:mm} %level %logger %ndc - %message%newline" />
	  </layout>
	  <filter type="log4net.Filter.LevelRangeFilter">
		<param name="LevelMin" value="DEBUG"/>
		<param name="LevelMax" value="DEBUG"/>
	  </filter>
	</appender>
	<!--紀錄錯誤訊息-->
	<appender name="ErrorRollingFileAppender" type="log4net.Appender.RollingFileAppender">
	  <!--存放log檔案的路徑-->
	  <file type="log4net.Util.PatternString" value="[你的路徑]\temp\%date{yyyy}\%date{MM}\%date{dd}\" />
	  <staticLogFileName value="false"/>
	  <appendToFile value="true"/>
	  <!--設定檔案分割依據Date和Size-->
	  <rollingStyle value="Composite"/>
	  <!--設定每個檔案的大小-->
	  <MaximumFileSize value="250KB" />
	  <!--設定分割檔案的最大數量-->
	  <maxSizeRollBackups value="2000" />
	  <!--log檔案的命名-->
	  <datePattern value="yyyy-MM-dd-HH-DB3.lo\g"/>
	  <layout type="log4net.Layout.PatternLayout">
		<conversionPattern value="[%date] [%-5level] From %logger%newline  %file:%line [%property{NDC}]%newline  %message%newline%newline" />
	  </layout>
	  <filter type="log4net.Filter.LevelRangeFilter">
		<param name="LevelMin" value="WARN"/>
	  </filter>
	</appender>
	<root>
	  <level value="ALL"/>
	  <appender-ref ref="DBRollingFileAppender"/>
	  <appender-ref ref="SystemRollingFileAppender"/>
	  <appender-ref ref="ErrorRollingFileAppender"/>
	</root>
</log4net>

這樣子的設定 log4net 會在 temp 目錄再依 年、月、日 建立目錄，然後產生 .0, .1 …的檔案如下圖，

這樣子的 log 在測試機都正常運作，唯獨在正式機卻會發生第 1 個檔案 .0 的 log 檔有正常產生，但 .1 的檔案卻一直被重覆的寫，導致要看 log 都常常看不到 (SystemRollingFileAppender)。雖然 maxSizeRollBackups 設定了 2000 ，但使終都只有 2 個檔案。 在我的 Local 測試也都沒什麼問題，用測試程式看它的 m_curSizeRollBackups 屬性也都正常，如下，

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
// 如果不是透過 class access ，記得要在 Application_Start 呼叫 log4net.Config.XmlConfigurator.Configure(); 哦!
var logType = System.Reflection.MethodBase.GetCurrentMethod().DeclaringType;
//Assembly assem = logType.Assembly;
var logger = LogManager.GetLogger(logType);
var appenders = logger.Logger.Repository.GetAppenders();
var rollingAppenders = appenders.OfType<RollingFileAppender>();
foreach (var appender in rollingAppenders)
{
	Response.Write($"<h3>*** Name:{appender.Name} *** </h3>");
	Response.Write($"File : {appender.File}<br/>");
	Response.Write($"CountDirection : {appender.CountDirection}<br/>");
	Response.Write($"MaxSizeRollBackups : {appender.MaxSizeRollBackups}<br/>");
	Response.Write($"MaxFileSize : {appender.MaxFileSize}<br/>");
	Response.Write($"StaticLogFileName : {appender.StaticLogFileName}<br/>");
	var propInfo = appender.GetType().BaseType.BaseType
		.GetProperty("QuietWriter", BindingFlags.NonPublic | BindingFlags.Instance);

	var quiteWriter = propInfo?.GetValue(appender) as CountingQuietTextWriter;
	Response.Write($"FileSize : {quiteWriter?.Count}<br/>");

	var scheduleFieldInfo = appender.GetType().GetField("m_scheduledFilename", BindingFlags.NonPublic | BindingFlags.Instance);
	var scheduleField = scheduleFieldInfo.GetValue(appender) ;
	Response.Write($"m_scheduledFilename : {scheduleField}<br/>");

	var m_curSizeRollBackupsFieldInfo = appender.GetType().GetField("m_curSizeRollBackups", BindingFlags.NonPublic | BindingFlags.Instance);
	var m_curSizeRollBackupsField = m_curSizeRollBackupsFieldInfo.GetValue(appender);
	Response.Write($"m_curSizeRollBackups : {m_curSizeRollBackupsField}<br/>");
}

如下， log4net 寫到了 2017-10-27-14-DB.log.6 這個檔案，

後來我將 IIS Express 的站台關掉再重新執行，結果 m_curSizeRollBackups 的值居然變成了 0 。如下，

1
2
3
4
5
6
7
8
9
10
*** Name:SystemRollingFileAppender ***

File : C:\Users\rainm\Documents\Visual Studio 2017\Projects\log4netTest\log4netTest\temp\2017\10\27\2017-10-27-14-DB.log.0
CountDirection : 1
MaxSizeRollBackups : 2000
MaxFileSize : 20480
StaticLogFileName : False
FileSize : 20540
m_scheduledFilename : C:\Users\rainm\Documents\Visual Studio 2017\Projects\log4netTest\log4netTest\temp\2017\10\27\2017-10-27-14-DB.log.0
m_curSizeRollBackups : 0

天呀! 我重現了問題了，當 系統重啟後， log4net 的 m_curSizeRollBackups 就會被重置成 0 。maybe 是 log4net 的 bug ，從 github 下載最新的 log4net v 2.0.9 來試，居然也是一樣的狀況 。

查看github logging-log4net的 source ，開啟 RollingFileAppender.cs 來看，從 DetermineCurSizeRollBackups 這個 Method

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
private void DetermineCurSizeRollBackups()
{
	m_curSizeRollBackups = 0;

	string fullPath = null;
	string fileName = null;

	using(SecurityContext.Impersonate(this))
	{
		fullPath = System.IO.Path.GetFullPath(m_baseFileName);
		fileName = System.IO.Path.GetFileName(fullPath);
	}

	ArrayList arrayFiles = GetExistingFiles(fullPath);
	InitializeRollBackups(fileName, arrayFiles);

	LogLog.Debug(declaringType, "curSizeRollBackups starts at ["+m_curSizeRollBackups+"]");
}

它會把 Log 目錄中的檔案傳給 InitializeRollBackups 這個 Method，如下，

1
2
3
4
5
6
7
8
9
10
11
12
private void InitializeRollBackups(string baseFile, ArrayList arrayFiles)
{
	if (null != arrayFiles)
	{
		string baseFileLower = baseFile.ToLower(System.Globalization.CultureInfo.InvariantCulture);

		foreach(string curFileName in arrayFiles)
		{
			InitializeFromOneFile(baseFileLower, curFileName.ToLower(System.Globalization.CultureInfo.InvariantCulture));
		}
	}
}

而 InitializeRollBackups 中會將 baseFile 轉成小寫 再傳入 InitializeFromOneFile 這個 Method 去比較，而在 InitializeFromOneFile 有一行是比較 baseFile 與 prefix 及 suffix 比較(if (!curFileName.StartsWith(prefix) || !curFileName.EndsWith(suffix)))。

prefix 就是 config 中 datePattern 的設定值 (yyyy-MM-dd-HH-DB3.lo\g)，眼尖的朋友有發現了嗎? 我們的檔名裡面的 DB 是大寫，但程式中 log4net 已將目前的 log 檔轉成了小寫，當然比不到。所以在系統重啟時， m_curSizeRollBackups 的值就會是 0 。

應該要將 if (!curFileName.StartsWith(prefix) || !curFileName.EndsWith(suffix)) 改成不分大小寫的比較才對，_if (!curFileName.StartsWith(prefix, StringComparison.CurrentCultureIgnoreCase) || !curFileName.EndsWith(suffix, StringComparison.CurrentCultureIgnoreCase))_。

  • 請注意哦~~ 目前 github 上的版本還沒有修正哦 !!!

所以目前有以下 2 項解法，

  • 改程式然後更新 log4net

  • 將檔名 datePattern 從大寫改成小寫，例如 yyyy-MM-dd-HH-\db.lo\g (d 前面要有 \ 哦!)

tag:

    缺失模块。
    1、请确保node版本大于6.2
    2、在博客根目录（注意不是yilia根目录）执行以下命令：
    npm i hexo-generator-json-content --save

    3、在根目录_config.yml里添加配置： 

      jsonContent:
    meta: false
    pages: false
    posts:
      title: true
      date: true
      path: true
      text: false
      raw: false
      content: false
      slug: false
      updated: false
      comments: false
      link: false
      permalink: false
      excerpt: false
      categories: false
      tags: true

大家好，我是亂馬客 Rainmaker，目前任職於叡揚資訊，大家也都叫我 RM 。 平常負責開發公司各產品線的加值、共用的軟體，例如 Azure, OpenAI, Chatbot, Database ... 同時 Support 公司各種技術及資安修改問題。 Blog中的內容也是個人的看法， 如果有需要討論的地方， 可以留言，或是 mail 給我 :) rainmaker_ho@gss.com.tw