月別: 2020年7月

福岡の香月です。

log4netのRollingFileAppenderを使って日付で出力ファイルが切り替わる設定をしていたところ、日付が変わって新しいファイルへの出力が始まると先頭に出力されるであろうログがなぜか出力されない現象に遭遇しました。
設定はこうです。
複数のプロセスで同じ設定を用いて、同じファイルに対してログ出力します。

<appender name="SystemLogAppender" type="log4net.Appender.RollingFileAppender">
  <file value="log/system.log" />
  <appendToFile value="true" />
  <datePattern value="_yyyyMMdd" />
  <preserveLogFileNameExtension value="true" />
  <staticLogFileName value="false" />
  <lockingModel type="log4net.Appender.FileAppender+InterProcessLock" />
  <encoding value="Shift_JIS"/>
  <maxSizeRollBackups value="-1" />
  <maximumFileSize value="2GB" />
  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.fff} %-5p %m%n"/>
  </layout>
</appender>

AppenderはRollingFileAppenderを指定しています。複数プロセスで使用するため、lockingModelはInterProcessLockを指定します。これによりファイルストリームを開きっぱなしにして、mutexで排他制御しながら末端にシークし書き込みを行うことで、複数プロセスから効率的にログ出力を行ってくれます。
複数プロセスから使う場合はこれ以外にもMinimalLockを指定できますが、書き込むたびにファイルのオープンクローズを実施するため速度が求められる場合は不向きでしょう。さらに複数プロセスからの出力が同時に走った場合、片方はオープンできないためログが出力されません。

この設定でビルドし、業務終わりにアプリを起動して一晩中実行させ、翌朝出社して確認しても日付が変わった後のログの内容が足りませんでした。
最初はlog4netの使い方が悪いのか、自分のプログラムにバグがあるのかさんざん悩んだんですがさっぱりわからない。トレース用に埋め込んだログも当然のように出ていないのでどうしたものかと思いました。

しかし、プロセスが1つの場合はちゃんと期待通りのログが出ていました。問題があるのは複数プロセスの場合だけだったのです。

そこでlog4netのロジックを確認することにしました。 幸いなことにソースはこちらから取得できます。
https://github.com/apache/logging-log4net
すると、ファイルが切り替わったあとは最後に書き込んだプロセスのログが先頭に来て、それ以前のログが破棄される作りになっていたのです。

少しずつソースを見てみましょう。今回使っているのはRollingFileAppenderです。日付が変わるときにファイルを切り替える部分は、RollOverTime()という関数であることがわかりました。こうなっています。
https://github.com/apache/logging-log4net/blob/master/src/Appender/RollingFileAppender.cs

protected void RollOverTime(bool fileIsOpen) 
{
    ：
    ：
    if (fileIsOpen)
    {
        // This will also close the file. This is OK since multiple close operations are safe.
        SafeOpenFile(m_baseFileName, false);
    }
}

ふむふむ、SafeOpenFile()で新しいファイルをオープンしに行くわけね。そして第二引数がfalseと。そしてSaveOpenFile()の実態はベースクラスFileAppenderにありました。
https://github.com/apache/logging-log4net/blob/master/src/Appender/FileAppender.cs
ここから次の順番で呼び出されていきます。

• RollingFileAppender.OpenFile()
• FileAppender.OpenFile()
• FileAppender.InterProcessLock.OpenFile()
• FileAppender.LockingModelBase.CreateStream()

protected Stream CreateStream(string filename, bool append, FileShare fileShare)
{
	using (CurrentAppender.SecurityContext.Impersonate(this))
	{
		// Ensure that the directory structure exists
		string directoryFullName = Path.GetDirectoryName(filename);

		// Only create the directory if it does not exist
		// doing this check here resolves some permissions failures
		if (!Directory.Exists(directoryFullName))
		{
			Directory.CreateDirectory(directoryFullName);
		}

		FileMode fileOpenMode = append ? FileMode.Append : FileMode.Create;
		return new FileStream(filename, fileOpenMode, FileAccess.Write, fileShare);
	}
}

ここでSafeOpenFile()の第二引数で指定されたfalseは、CreateStreamのappendに代入されていることがわかりました。この場合FileMode.Createが指定され、FileStreamインスタンスが作成されます。
ではこのFileMode.Createはどのような動きをするかというと、

オペレーティング システムが新しいファイルを作成することを指定します。ファイルが既に存在する場合は上書きされます。これには Write 許可が必要です。
FileMode.Create は、ファイルが存在しない場合は CreateNew を使用した要求、ファイルが存在する場合は Truncate を使用した要求と等価です。

https://docs.microsoft.com/ja-jp/dotnet/api/system.io.filemode?view=netcore-3.1

複数のプロセスでログ出力を行う場合、FileStreamを最後に作成するプロセスによりそれまでのプロセスが作成したログファイルの中身がTruncateされて、つまり削除されてしまうわけです。
発生している現象とも合致するのでこれが問題であることを確信しました。

対応するためにはRollingFileAppender.RollOverTime()から呼んでるSafeOpenFile()の第二引数をtrueに知ればよいわけです。実際に修正して確認してみると、見事欠損することなく必要なログが出力されていました。
めでたしめでたし。

なお、SafeOpenFile()はRollingFileAppender.RollOverSize()内からも呼び出しているのでここも忘れずにtrueに変更しましょう。