C# NLog Asyncメソッドでの callsite の取得 #C#

NLog における呼び出し元情報の取得の仕組み

NLog には呼び出し元情報をログに出力する機能があります。既定の動作ではスタックトレースを利用しますので、ロガークラスのログ出力メソッドを呼び出した一つ前のスタックフレームの情報が出力されます。

なお、NLog のバージョンは 4.5.10 です。

既定の動作では呼び出し元が正しく取得されない例

アプリケーションコードとログ出力メソッドの間に拡張メソッドやラッパークラスを挟むと、（実装としては正しい動作ですが、）プログラマが期待している呼び出し元情報は出力されません。

ログ出力コード

private async void BtnNLog_Click(object sender, EventArgs e)
{
    NLog.ILogger logger = NLog.LogManager.GetCurrentClassLogger();
    logger.Info("Info メソッドでログを出力しました。");
    logger.InfoEx("InfoEx メソッドでログを出力しました。");
}

private async void BtnNLogAsync_Click(object sender, EventArgs e)
{
    NLog.ILogger logger = NLog.LogManager.GetCurrentClassLogger();
    logger.Info("Info メソッドでログを出力しました。");
    logger.InfoEx("InfoEx メソッドでログを出力しました。");
    await logger.InfoAsync("InfoAsync メソッドでログを出力しました。");
}

public static class NLoggerExtensions
{
    public static void InfoEx(this NLog.ILogger logger, string message)
    {
        logger.Info(message);
    }
    public static async Task InfoAsync(this NLog.ILogger logger, string message)
    {
        await Task.Yield();
        logger.Info(message);
    }
}

NLog.configのレイアウト定義

<layout xsi:type="CSVLayout" delimiter="Tab">
    <withHeader>false</withHeader>
    <quoting>Nothing</quoting>
    <column layout="${uppercase:${level}}" />
    <column layout="${message}" />
    <!-- 型名 -->
    <column layout="${callsite:className=true:methodName=false:fileName=false:includeSourcePath=false}" />
    <!-- メソッド名 -->
    <column layout="${callsite:className=false:methodName=true:fileName=false:includeSourcePath=false}" />
    <!-- ソースファイル名 -->
    <column layout="${callsite:className=false:methodName=false:fileName=true:includeSourcePath=false}" />
    <!-- ソースファイルパス -->
    <column layout="${callsite:className=false:methodName=false:fileName=true:includeSourcePath=true}" />
</layout>

InfoEx メソッドから出力されたログの呼び出し元は NLoggerExtensions になります。
BtnNLogAsync_Click メソッドは async メソッドですのでコンパイル時に匿名クラスが生成されます。呼び出し元はその匿名クラスになります。

出力結果

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1  BtnNLog_Click   (Form1.cs:148)  (E:\sources\WindowsFormsApp2\Form1.cs:148)  
INFO    InfoEx メソッドでログを出力しました。    NLoggerExtensions   InfoEx  (Form1.cs:160)  (E:\sources\WindowsFormsApp2\Form1.cs:160)  

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext    (Form1.cs:137)  (E:\sources\WindowsFormsApp2\Form1.cs:137)  
INFO    InfoEx メソッドでログを出力しました。    NLoggerExtensions   InfoEx  (Form1.cs:160)  (E:\sources\WindowsFormsApp2\Form1.cs:160)  
INFO    InfoAsync メソッドでログを出力しました。 NLoggerExtensions+<InfoAsync>d__1   MoveNext    (Form1.cs:165)  (E:\sources\WindowsFormsApp2\Form1.cs:165)

ロガーの型を指定する

ログ出力時にロガーの型を指定することによって、呼び出し元情報の取得動作を変えることができます。スタックトレースを遡る過程で、指定されたロガーの型が現れるフレームの次のフレームが呼び出し元であると見なされます。

【A certain engineer "COMPLEX"】開発メモその30 LoggerServiceを実装する

public static class NLoggerExtensions
{
    public static void InfoEx(this NLog.ILogger logger, string message)
    {
        // ログ情報を生成します。
        NLog.LogEventInfo info = new NLog.LogEventInfo(NLog.LogLevel.Info, logger.Name, message);
        // ロガーの型に NLoggerExtensions を指定します。
        logger.Log(typeof(NLoggerExtensions), info);
    }
    public static async Task InfoAsync(this NLog.ILogger logger, string message)
    {
        await Task.Yield();
        // ログ情報を生成します。
        NLog.LogEventInfo info = new NLog.LogEventInfo(NLog.LogLevel.Info, logger.Name, message);
        // ロガーの型に NLoggerExtensions を指定します。
        logger.Log(typeof(NLoggerExtensions), info);
    }
}

BtnNLog_Click から呼び出した InfoEx メソッドの呼び出し元は Form1 に変わりましたが、BtnNLogAsync_Click から呼び出した InfoAsync メソッドの呼び出し元は NLoggerExtensions のままです。InfoAsync メソッドの冒頭の Task.Yield によって分割され、以降の処理が NLoggerExtensions の内部に生成された匿名クラスで行われるためです。
BtnNLogAsync_Click から出力されたログの呼び出し元メソッドは MoveNext になっています。これも匿名クラスの MoveNext メソッドからログ出力が行われていることが原因です。

出力結果

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1  BtnNLog_Click   (Form1.cs:146)  (E:\sources\WindowsFormsApp2\Form1.cs:146)  
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1  BtnNLog_Click   (Form1.cs:147)  (E:\sources\WindowsFormsApp2\Form1.cs:147)  

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext    (Form1.cs:137)  (E:\sources\WindowsFormsApp2\Form1.cs:137)  
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext    (Form1.cs:138)  (E:\sources\WindowsFormsApp2\Form1.cs:138)  
INFO    InfoAsync メソッドでログを出力しました。 NLoggerExtensions+<InfoAsync>d__1   MoveNext    (Form1.cs:165)  (E:\sources\WindowsFormsApp2\Form1.cs:165)

そもそも pdb ファイルが必要

スタックトレースを使用する以上、実行ディレクトリに pdb ファイルが必要です。pdb ファイルがない場合は呼び出し元情報は取得されません。

出力結果

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1  BtnNLog_Click           
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1  BtnNLog_Click           

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext            
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext            
INFO    InfoAsync メソッドでログを出力しました。 NLoggerExtensions+<InfoAsync>d__1   MoveNext

明示的に呼び出し元情報を指定する

NLog では、明示的に呼び出し元情報が指定されている場合にはスタックトレースからの情報を使用しないように実装されています。

.NET Framework 4.5 で追加された CallerInfo 属性を使用します。これらの属性を使用すると、呼び出し時に引数が省略された場合にコンパイラによってリテラル値が埋め込まれます。実行時のコストがなくなるのが特徴です。ただ、残念ながら提供されているのは CallerMemberName CallerFilePath CallerLineNumber の三つのみです。クラス名に対応した属性は提供されていません。今後のバージョンアップで追加されることを期待します。

public static class NLoggerExtensions
{
    public static void InfoEx(this NLog.ILogger logger, string message
        , string callerClassName = ""
        , [CallerMemberName] string callerMemberName = ""
        , [CallerFilePath] string callerFilePath = ""
        , [CallerLineNumber] int callerLineNumber = 0)
    {
        if (string.IsNullOrEmpty(callerClassName)) { callerClassName = GetCallerClassName(2); }
        NLog.LogEventInfo info = new NLog.LogEventInfo(NLog.LogLevel.Info, logger.Name, message);
        // 呼び出し元情報を設定します。
        info.SetCallerInfo(callerClassName, callerMemberName, callerFilePath, callerLineNumber);
        logger.Log(typeof(NLoggerExtensions), info);
    }
    public static async Task InfoAsync(this NLog.ILogger logger, string message
        , string callerClassName = ""
        , [CallerMemberName] string callerMemberName = ""
        , [CallerFilePath] string callerFilePath = ""
        , [CallerLineNumber] int callerLineNumber = 0)
    {
        if (string.IsNullOrEmpty(callerClassName)) { callerClassName = GetCallerClassName(4); }
        NLog.LogEventInfo info = new NLog.LogEventInfo(NLog.LogLevel.Info, logger.Name, message);
        // 呼び出し元情報を設定します。
        info.SetCallerInfo(callerClassName, callerMemberName, callerFilePath, callerLineNumber);
        await Task.Yield();
        logger.Log(typeof(NLoggerExtensions), info);
    }
    private static string GetCallerClassName(int skipFlames)
    {
        return new StackFrame(skipFlames).GetMethod().DeclaringType.FullName;
    }
}

呼び出し元クラス名を取得できる属性はないため、仕方なくスタックトレースから取得しています。コンパイラや JIT の動作によって変わる可能性があり、実用的にはこのままの実装では問題があると思います。

InfoExメソッドから呼び出されたときのスタックトレース

[0]NLoggerExtensions.GetCallerClassName
[1]NLoggerExtensions.InfoEx
[2]WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13.MoveNext　←　2つスキップしてここを取得
[3]System.Runtime.CompilerServices.AsyncVoidMethodBuilder.Start
[4]WindowsFormsApp2.Form1.BtnNLogAsync_Click
[5]System.Windows.Forms.Control.OnClick
[6]System.Windows.Forms.Button.OnClick
[7]System.Windows.Forms.Button.OnMouseUp
[8]System.Windows.Forms.Control.WmMouseUp
[9]System.Windows.Forms.Control.WndProc
[10]System.Windows.Forms.ButtonBase.WndProc
[11]System.Windows.Forms.Button.WndProc
[12]System.Windows.Forms.Control+ControlNativeWindow.OnMessage
[13]System.Windows.Forms.Control+ControlNativeWindow.WndProc
[14]System.Windows.Forms.NativeWindow.DebuggableCallback
[15]System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW
[16]System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop
[17]System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner
[18]System.Windows.Forms.Application+ThreadContext.RunMessageLoop
[19]System.Windows.Forms.Application.Run
[20]WindowsFormsApp2.Program.Main

InfoAsyncメソッドから呼び出されたときのスタックトレース

[0]NLoggerExtensions.GetCallerClassName
[1]NLoggerExtensions+<InfoAsync>d__1.MoveNext
[2]System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start
[3]NLoggerExtensions.InfoAsync
[4]WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13.MoveNext　←　4つスキップしてここを取得
[5]System.Runtime.CompilerServices.AsyncVoidMethodBuilder.Start
[6]WindowsFormsApp2.Form1.BtnNLogAsync_Click
[7]System.Windows.Forms.Control.OnClick
[8]System.Windows.Forms.Button.OnClick
[9]System.Windows.Forms.Button.OnMouseUp
[10]System.Windows.Forms.Control.WmMouseUp
[11]System.Windows.Forms.Control.WndProc
[12]System.Windows.Forms.ButtonBase.WndProc
[13]System.Windows.Forms.Button.WndProc
[14]System.Windows.Forms.Control+ControlNativeWindow.OnMessage
[15]System.Windows.Forms.Control+ControlNativeWindow.WndProc
[16]System.Windows.Forms.NativeWindow.DebuggableCallback
[17]System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW
[18]System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop
[19]System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner
[20]System.Windows.Forms.Application+ThreadContext.RunMessageLoop
[21]System.Windows.Forms.Application.Run
[22]WindowsFormsApp2.Program.Main

指定した呼び出し元が出力されています。BtnNLogAsync_Click メソッドからの Info メソッドは NLog の既定の動作によって呼び出し元が取得されていますので、呼び出し元メソッド名は MoveNext になっています。

出力結果

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1  BtnNLog_Click   (Form1.cs:146)  (E:\sources\WindowsFormsApp2\Form1.cs:146)  
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1  BtnNLog_Click   (Form1.cs:147)  (E:\sources\WindowsFormsApp2\Form1.cs:147)  

INFO    Info メソッドでログを出力しました。  WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    MoveNext    (Form1.cs:137)  (E:\sources\WindowsFormsApp2\Form1.cs:137)  
INFO    InfoEx メソッドでログを出力しました。    WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    BtnNLogAsync_Click  (Form1.cs:138)  (E:\sources\WindowsFormsApp2\Form1.cs:138)  
INFO    InfoAsync メソッドでログを出力しました。 WindowsFormsApp2.Form1+<BtnNLogAsync_Click>d__13    BtnNLogAsync_Click  (Form1.cs:139)  (E:\sources\WindowsFormsApp2\Form1.cs:139)

log4net の場合

log4net もスタックトレースを使用して呼び出し元情報を取得します。ロガーの型を与えることによって取得するフレームを制御することはできますが、呼び出し元情報を直接指定する方法を見つけることはできませんでした。

まとめ

CallerInfo 属性に呼び出し元クラス名を取得できる属性が追加されれば、「明示的に呼び出し元情報を指定する」方法がよいのではないかと思います。
多くのログライブラリには呼び出し元情報を出力する機能がありますが、できれば特定のログライブラリの実装に依存したくはありません。NLog の callsite や log4net の %class のようなライブラリ固有の機能ではなく、CallerInfo 属性を用いてリテラル値で取得し、ログメッセージ文字列やペイロードとして出力するのがよいのではないかと思います・