Quando usar o 'contexto de diagnóstico aninhado' (NDC)?

Question

Jogando com log4net, eu vi a possibilidade de usar uma pilha por thread de etiquetas de contexto chamado o NDC.

As etiquetas empurradas sobre esta pilha são exibidos em uma PatternLayout especificando o %x ou o parâmetro formato %ndc.

O uso é algo 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"); 

A saída é algo como:

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

Na sua experiência de programação com log4net, quando você encontrar esse recurso para ser útil?

Answer 1

Em um aplicativo de servidor, como ASP.NET.

Por exemplo, você pode enviar informações sobre a solicitação atual para o NDC.

Answer 2

Quer um exemplo?

Tome o seguinte API Web escrita utilizando 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";
}

Quando o servidor solicitações HTTP simultâneas são feitas, o registo pode ficar intercalados. Por exemplo.

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

Neste exemplo simples, você pode usar o identificador do tópico para distinguir os pedidos, mas isso pode ficar complicado como o arquivo de log cresce em complexidade.

A melhor alternativa é fornecer identificadores exclusivos desse grupo mensagens juntas de log para o mesmo pedido. Podemos atualizar o código como o seguinte:

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

Isso produz um log que você pode grep para ver as questões associadas a um pedido específico. Por exemplo.

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

Estes recurso vir a calhar quando você tem um monte de toras de passar. Quando você tem um monte de registros? Diagnosticar bug estranho em um sistema de produção com saídas de intercalação. Ter mais contextos dá-lhe forma de filtrar a saída ou não a saída de registros desnecessários.

Outro caso contextos aninhados poderia ser útil é se um método ou algum recurso é chamado várias vezes em contextos diferentes e você precisa de uma forma de distinguir entre eles.

Answer 4

NDC.Push foi preterido. A maneira preferida agora (ThreadContext.Stacks["NDC"]) é o seguinte:

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

Lembre-se de verificar o seu padrão de conversão para que ele inclui %property{NDC}:

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