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

這樣子的 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 這個檔案，

後來我將 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 上的版本還沒有修正哦 !!! 如果您有類似的問題，可以參考看看哦 ~~~