Когда использовать «вложенный диагностический контекст» (NDC)?

Question

Играя с log4net, я видел возможность использовать для каждого потока стек контекстных меток, называемых NDC.

Метки, помещенные в этот стек, отображаются в PatternLayout с указанием параметра формата % x или % ndc .

Использование выглядит примерно так:

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?

Answer 1

В серверном приложении, таком как ASP.NET.

Например, вы можете отправить информацию о текущем запросе в НДЦ.

Answer 2

Хотите пример?

Возьмем следующий веб-API, написанный с использованием 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";
}

При выполнении одновременных 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

В этом простом примере вы могли бы использовать идентификатор потока, чтобы различать запросы, но это может оказаться непростым делом по мере усложнения файла журнала.

Лучшей альтернативой является предоставление уникальных идентификаторов, которые группируют сообщения журнала для одного и того же запроса. Мы можем обновить код следующим образом:

// 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

Answer 3

Эта функция пригодится, когда вам нужно просмотреть много журналов. Когда у вас будет много журналов? Диагностика странной ошибки в производственной системе с чередованием выходных данных. Наличие большего количества контекстов дает вам возможность фильтровать вывод или не выводить ненужные журналы.

В другом случае вложенные контексты могут быть полезны, если метод или некоторая функция вызывается несколько раз в разных контекстах, и вам нужен способ различать их.

Answer 4

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>