「ネストされた診断コンテキスト」(NDC)を使用する場合
質問
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でのプログラミングの経験で、この機能が便利だと感じたのはいつですか?
解決
ASP.NETなどのサーバーアプリケーション。
たとえば、現在のリクエストに関する情報をNDCにプッシュできます。
他のヒント
例が必要ですか
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
これらの機能は、通過するログがたくさんある場合に便利です。いつログがたくさんありますか?出力をインターリーブする実稼働システムでの奇妙なバグの診断。コンテキストを増やすと、出力をフィルタリングしたり、不要なログを出力しないようにすることができます。
別のケースのネストされたコンテキストは、メソッドまたは機能が異なるコンテキストで複数回呼び出され、それらを区別する方法が必要な場合に役立ちます。
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>