Quand utiliser le 'contexte de diagnostic imbriqué' (NDC)?

Question

En jouant avec log4net, j'ai vu la possibilité d'utiliser une pile d'étiquettes de contexte par thread appelée NDC.

Les étiquettes insérées dans cette pile sont affichées dans un PatternLayout en spécifiant le paramètre de format %x ou %ndc.

L'utilisation est quelque chose comme:

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"); 

La sortie est quelque chose comme:

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

votre expérience de programmation avec log4net, quand avez-vous trouvé cette fonctionnalité utile?

Answer 1

Dans une application serveur telle qu'ASP.NET.

Par exemple, vous pouvez transférer des informations sur la demande en cours vers le NDC.

Answer 2

Ces fonctionnalités sont pratiques lorsque vous avez beaucoup de journaux à parcourir. Quand auriez-vous beaucoup de journaux? Diagnostiquer un bug bizarre sur un système de production avec des sorties d'entrelacement. Avoir plus de contextes vous donne le moyen de filtrer la sortie ou de ne pas sortir les journaux inutiles. Un autre cas de contextes imbriqués pourrait être utile si une méthode ou une fonctionnalité est appelée plusieurs fois dans des contextes différents et que vous avez besoin d'un moyen de les distinguer.

Answer 3

Vous voulez un exemple?

Prenez l'API Web suivant écrit en utilisant ASP.NET MVC4:

// 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"; 
} 

Lorsque requêtes HTTP simultanées du serveur sont faites, l'enregistrement peut se entrelacée. Par exemple.

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 

Dans cet exemple simple, vous pouvez utiliser l'identifiant de fil pour distinguer les demandes, mais qui peut se compliquer que le fichier journal augmente en complexité.

Une meilleure alternative consiste à fournir des identificateurs uniques qui regroupent les messages de journal pour la même requête. Nous pouvons mettre à jour le code à ce qui suit:

// 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"; 
    } 
} 

Cela produit un journal que vous pouvez voir grep les problèmes liés à une demande spécifique. Par exemple.

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 

Answer 4

NDC.Push a été déprécié. La manière préférée maintenant (ThreadContext.Stacks["NDC"]) est la suivante:

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

Rappelez-vous de vérifier votre modèle de conversion afin qu'il comprend %property{NDC}:

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