¿Cuándo usar 'contexto de diagnóstico anidado' (NDC)?

Question

Jugando con log4net, he visto la posibilidad de usar una pila de etiquetas de contexto por subproceso llamada NDC.

Las etiquetas insertadas en esta pila se muestran en un PatternLayout especificando el parámetro de código % x o % ndc .

El uso es algo así como:

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

El resultado es algo así como:

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

En su experiencia de programación con log4net, ¿cuándo encontró útil esta característica?

Answer 1

En una aplicación de servidor como ASP.NET.

Por ejemplo, puede enviar información sobre la solicitud actual al NDC.

Answer 2

¿Quieres un ejemplo?

Tome la siguiente API web escrita con 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";
}

Cuando se realizan solicitudes HTTP concurrentes del servidor, el registro se puede intercalar. Por ejemplo,

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

En este ejemplo simple, podría usar la identificación del hilo para distinguir las solicitudes, pero eso puede ser complicado a medida que el archivo de registro crece en complejidad.

Una mejor alternativa es proporcionar identificadores únicos que agrupen los mensajes de registro para la misma solicitud. Podemos actualizar el código de la siguiente manera:

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

Esto produce un registro que puede seleccionar para ver los problemas asociados con una solicitud específica. P.ej.

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 3

Estas funciones son útiles cuando tiene muchos registros por recorrer. ¿Cuándo tendrías muchos registros? Diagnóstico de errores extraños en un sistema de producción con salidas entrelazadas. Tener más contextos le permite filtrar la salida o no generar registros innecesarios.

Otro contexto anidado de casos podría ser útil si un método o alguna característica se llama varias veces en diferentes contextos y necesita una forma de distinguirlos.

Answer 4

NDC.Push ha quedado en desuso. La forma preferida ahora ( ThreadContext.Stacks [" NDC "] ) es esta:

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

Recuerde verificar su patrón de conversión para que incluya % property {NDC} :

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