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

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

<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 …的檔案如下圖,

001.png

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

// 如果不是透過 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 這個檔案,

002.png

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

*** 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

 

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,如下,

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))

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

  • 修改程式然後更新 log4net

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

 

  • 請注意哦~~ 目前 github 上的版本還沒有修正哦 !!! 如果您有類似的問題,可以參考看看哦 ~~~

 

作者: 亂馬客

亂馬客 @叡揚資訊 rainmaker_ho@gss.com.tw https://rainmakerho.github.io/ https://www.slideshare.net/rainmakerho

log4net 檔名使用「大寫字母」造成檔案被「覆寫」問題 有 “ 2 則迴響 ”

發表迴響

你的電子郵件位址並不會被公開。 必要欄位標記為 *