[.net] 'ネスト診断コンテキスト'(NDC)を使用するタイミング



Answers

例がありますか?

ASP.NET MVC4を使用して記述された次のWeb APIを取得します。

// GET api/HypervResource
public string Get()
{
    logger.Debug("Start of service test");
    System.Threading.Thread.Sleep(5000); // simulate work
    logger.Debug("End of service test");
    return "HypervResource controller running, use POST to send JSON encoded RPCs";
}

サーバの同時HTTP要求が行われると、ロギングがインターリーブされる可能性があります。 例えば

2013-06-27 13:28:11,967 [10] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:12,976 [12] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:14,116 [13] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:16,971 [10] DEBUG HypervResource.WmiCalls [(null)] - End of service test
2013-06-27 13:28:17,979 [12] DEBUG HypervResource.WmiCalls [(null)] - End of service test
2013-06-27 13:28:19,119 [13] DEBUG HypervResource.WmiCalls [(null)] - End of service test

この単純な例では、スレッドIDを使用してリクエストを区別することができますが、ログファイルが複雑になるにつれて複雑になる可能性があります。

より良い代替案は、同じ要求に対するログメッセージをグループ化する一意の識別子を提供することです。 コードを次のように更新することができます。

// GET api/HypervResource
public string Get()
{
    using(log4net.NDC.Push(Guid.NewGuid().ToString()))
    {
        logger.Debug("Start of service test");
        System.Threading.Thread.Sleep(5000); // simulate work
        logger.Debug("End of service test");
        return "HypervResource controller running, use POST to send JSON encoded RPCs";
    }
}

これにより、特定の要求に関連する問題を表示するためにgrepできるログが生成されます。 例えば

2013-06-27 14:04:31,431 [11] DEBUG HypervResource.WmiCalls [525943cb-226a-43c2-8bd5-03c258d58a79] - Start of service test
2013-06-27 14:04:32,322 [12] DEBUG HypervResource.WmiCalls [5a8941ee-6e26-4c1d-a1dc-b4d9b776630d] - Start of service test
2013-06-27 14:04:34,450 [13] DEBUG HypervResource.WmiCalls [ff2246f1-04bc-4451-9e40-6aa1efb94073] - Start of service test
2013-06-27 14:04:36,434 [11] DEBUG HypervResource.WmiCalls [525943cb-226a-43c2-8bd5-03c258d58a79] - End of service test
2013-06-27 14:04:37,325 [12] DEBUG HypervResource.WmiCalls [5a8941ee-6e26-4c1d-a1dc-b4d9b776630d] - End of service test
2013-06-27 14:04:39,453 [13] DEBUG HypervResource.WmiCalls [ff2246f1-04bc-4451-9e40-6aa1efb94073] - End of service test
Question

log4netで遊んで、私はNDCと呼ばれるコンテキストラベルのスレッドごとのスタックを使用する可能性を見てきました。

このスタックにプッシュされたラベルは、 %xまたは%ndc形式のパラメータを指定することによってPatternLayoutに表示されます。

使い方は次のようなものです:

ILog log = log4net.LogManager.GetLogger(...) ;

//pattern layout format: "[%ndc] - %message%newline"

log.Info("message 1"); 
using(log4net.NDC.Push("context")
{
    using(log4net.NDC.Push("inner_context")
    {
      log.Info("message 2"); 
    }
    log.Info("message 3"); 
}
log.Info("message 4"); 

出力は次のようなものです。

null - message 1
context inner_context - message 2
context - message 3
null - message 4

log4netのプログラミング経験では、いつこの機能が役立つのが分かりましたか?




NDC.Pushは廃止されました。 現在の好ましい方法( ThreadContext.Stacks["NDC"] )は次のとおりです:

var disposable = ThreadContext.Stacks["NDC"].Push("context");
try
{
  Log.Info("begin"); // optional, but nice
  ...
}
finally
{
  Log.Info("end"); // optional, but nice
  disposable.Dispose();
}

%property{NDC}含まれるように変換パターンをチェックすることを忘れないでください:

<layout type="log4net.Layout.PatternLayout">
  <conversionPattern
    value="%date [%2thread] %-5level [%property{NDC}] - %.10240message%newline" />
</layout>