マルチスレッドで扱うNlogで動的に出力先を変える際の注意

※7月1日追記　この記事で3通りの問題の対策を提起しましたが、実際にはどれも別の問題が発生するため使えませんでした…。

ASP.NETでNlogを使って、ログを出力していました。
userIdを見て動的に出力ファイルを変更していたのですが、マルチスレッドの影響で出力先が変わることがあったので、原因と対策を記します。

１．staticなLoggerで動的に出力先を変更する際の注意

私の実装はスレッド間で共通のstaticなloggerを作成していました。

LogManager.cs

public static class LogManager()
{
    // スレッド間で共通のLoggerを定義
    public static LogFactory factory = new LogFactory();
    public static Logger Logger = factory.GetLogger("API");

    public static void WriteLog(long userId, string message)
    {
        // Logの出力先を設定
        logger.Factory.Configuration.Variables["userId"] = userId.ToString();
        logger.Factory.Configuration.Variables["outputDateTime"] = DateTime.Now.ToString();

　　　　 // ☆

　　　　 // Logの出力
        logger.Info(message);
    }
}

問題は☆の位置で別スレッドからlogger.Factory.Configuration.Variablesの値が変更されると出力先も変わってしまいます。

原因はloggerがstaticであり、スレッド間で共通のオブジェクトだからです。

こちらの対策ですが、ロックすることで同期をとるのもいいと思いますが、私はスレッドごとにloggerのインスタンスを作ることにしました。

public static class LogManager()
{
    //外からLoggerを渡すようにする 
    public static void WriteLog(Logger logger, long userId, string message)
    {
        logger.Factory.Configuration.Variables["userId"] = userId.ToString();
        logger.Factory.Configuration.Variables["outputDateTime"] = DateTime.Now.ToString();
        logger.Info(message);
    }
}

public class BaseApiController()
{
    // スレッドが立ちあがる際にインスタンス生成
    public Logger apiLogger = NLog.LogManager.GetLogger("API");

    public void WriteApiLog(long userId, string message)
    {
        LogManager.WriteLog(apiLogger, userId, messsage);
    }
}

スレッドが立ちあがる際にインスタンス生成されるように記述しておくことで各スレッドごとにloggerが出来上がります。
私はControllerのBaseに置きました。

２.ReconfigExistingLoggersは別スレッドまで上書きしてしまう

私の勝手な認識でlogger.Factory.Configurationを更新したら、logger.Factory.ReconfigExistingLoggersで反映するものだと思っていたのですが、これをやってしまうと、別スレッドのLoggerまで書き換わってしまいます。

public static class LogManager()
{
    public static void WriteLog(Logger logger, long userId, string message)
    {
        logger.Factory.Configuration.Variables["userId"] = userId.ToString();
        logger.Factory.Configuration.Variables["outputDateTime"] = DateTime.Now.ToString();

        // 今生きているすべてのスレッドのloggerにuserIdとoutputDateTimeを反映してしまう
        logger.Factory.ReconfigExistingLoggers();

        // 結果、スレッド間のタイミングでここに来た際に書き変わっていることがある。
        logger.Info(message);
    }
}

Variablesの値は書き換えた時点でloggerのインスタンスに反映されています。
ReconfigExistingLoggersの利用は注意が必要でした。

３．logger.Factory.Configuration.Variablesは書き換えてはいけない

logger.Factory.Configuration.Variablesの値はスレッド間で共通の値だったため(内部的に同期を取っているよう)、コードから書き換えてはいけないようです。

代わりにスレッド単位で設定できるNLog.MappedDiagnosticsContextクラスの値を書き換えます。
以下はこのクラスのコメントです

Mapped Diagnostics Context - a thread-local structure that keeps a dictionary
of strings and provides methods to output them in layouts.

google翻訳
マップされた診断コンテキスト-辞書を保持するスレッドローカルな構造
文字列のレイアウトとそれらをレイアウトで出力するメソッドを提供します

つまりスレッドごとに固有のDictionaryですね。

次に使い方を記します。

public class BaseApiController()
{
    // スレッドが立ちあがる際にインスタンス生成
    public Logger apiLogger = NLog.LogManager.GetLogger("API");

    public void WriteApiLog(long userId, string message)
    {
        // static関数内でセットするとstaticのスレッドに適用されてしまうので、こちらに出しました。
        NLog.MappedDiagnosticsContext.Set("userId", userId.ToString());
        NLog.MappedDiagnosticsContext.Set("outputDateTime", DateTime.Now.ToString());
        LogManager.WriteLog(apiLogger, userId, messsage);
    }
}

Web.config側で${var:userId}のように指定しているところは${mdc:item=userId}に変更します。
filename="./Logs/${mdc:item=userId}/${mdc:item=outputDateTime}.csv

以上3つの設定でマルチスレッドでも出力先は正しく動的に変更されるようになりましたが、大量の同時書き込みがあるとサーバーの物理メモリがパンクしてしまうということが発生したので今のところこの対策ではだめでした…。
解決したら追加します…。