log4net LogicalThreadContext не работает

Question

У меня есть ошибка в log4net или недоразумение с моей стороны.

Я пытаюсь использовать LogicalThreadContext, чтобы связать некоторые данные с контекстом вызова и распространить их на любой журналзаявления, сделанные любым потоком в этом контексте.Это предполагаемое преимущество LogicalThreadContext над ThreadContext.

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

[Fact]
public void log4net_logical_thread_context_test()
{
    XmlConfigurator.Configure();
    var log = LogManager.GetLogger(GetType());
    var waitHandle = new ManualResetEvent(false);

    using (LogicalThreadContext.Stacks["foo"].Push("Some contextual info"))
    {
        log.Debug("START");

        ThreadPool.QueueUserWorkItem(delegate
        {
            log.Debug("A DIFFERENT THREAD");
            waitHandle.Set();
        });

        waitHandle.WaitOne();
        log.Debug("STOP");
    }
}

Моя конфигурация log4net выглядит следующим образом:

<?xml version="1.0" encoding="utf-8" ?>

<configuration>
    <configSections>
        <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
    </configSections>

    <log4net>
        <appender name="FileAppender" type="log4net.Appender.FileAppender">
            <file value="log.txt" />
            <appendToFile value="true" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="[%thread]|[%property{foo}]|%message%newline"/>
            </layout>
        </appender>

        <root>
            <level value="DEBUG" />
            <appender-ref ref="FileAppender" />
        </root>
    </log4net>
</configuration>

И мой вывод выглядит так:

[xUnit.net STA Test Execution Thread]|[Some contextual info]|START
[32]|[(null)]|A DIFFERENT THREAD
[xUnit.net STA Test Execution Thread]|[Some contextual info]|STOP

Как видите,данные, которые я помещаю в стек LTC, присутствуют только в операторах регистрации, сделанных в том же потоке .В операторе журнала, выполненном фоновым потоком, отсутствуют контекстные данные.Отладывая тест, я увидел, что на самом деле LogicalThreadContext.Stacks.Count равен нулю в фоновом потоке.

Копаясь в источник log4net, я обнаружил, что он использует класс CallContext.Этот класс делает то, что говорит на жестяной коробке - он позволяет контексту для текущего «вызова» быть сохраненным и извлеченным.Как это происходит на низком уровне, я понятия не имею.

CallContext имеет два набора методов, с помощью которых можно сохранять и извлекать контекстную информацию: GetData / SetData и LogicalGetData /LogicalSetData.В документации очень мало информации о разнице между этими двумя наборами методов, но в примерах используется GetData / SetData.Так же, как и в log4net LogicalThreadContext.

. Быстрый тест показал, что GetData / SetData демонстрирует ту же проблему - данные не распространяются по потокам.Я подумал, что вместо этого пошлю LogicalGetData / LogicalSetData:

[Fact]
public void call_context_test()
{
    XmlConfigurator.Configure();
    var log = LogManager.GetLogger(GetType());

    var count = 5;
    var waitHandles = new ManualResetEvent[count];

    for (var i = 0; i < count; ++i)
    {
        waitHandles[i] = new ManualResetEvent(false);
        var localI = i;

        // on a bg thread, set some call context data
        ThreadPool.QueueUserWorkItem(delegate
        {
            CallContext.LogicalSetData("name", "value " + localI);
            log.DebugFormat("Set call context data to '{0}'", CallContext.LogicalGetData("name"));
            var localWaitHandle = new ManualResetEvent(false);

            // then on another bg thread, make sure the logical call context value is correct with respect to the "owning" bg thread
            ThreadPool.QueueUserWorkItem(delegate
            {
                var value = CallContext.LogicalGetData("name");
                log.DebugFormat("Retrieved call context data '{0}'", value);
                Assert.Equal("value " + localI, value);
                localWaitHandle.Set();
            });

            localWaitHandle.WaitOne();
            waitHandles[localI].Set();
        });
    }

    foreach (var waitHandle in waitHandles)
    {
        waitHandle.WaitOne();
    }
}

Этот тест пройден - контекстная информация успешно распространяется по потокам при использовании LogicalGetData / LogicalSetData.

Итак, мой вопрос таков: не так ли в log4net?Или я что-то упускаю?

ОБНОВЛЕНИЕ: Я также попытался выполнить пользовательскую сборку log4net с ее классом LogicalThreadContextProperties, измененным согласно моим выводам выше.Я перезапустил свой первоначальный тест, и он сработал.Это кажется мне слишком очевидной проблемой для продукта, который используют многие люди, поэтому я должен предположить, что что-то упустил.

Answer 1

Вот вопрос, который я задавал некоторое время назад о том, в чем разница между ThreadContext и LogicalThreadContext:

В чем разница между log4net.ThreadContext и log4net.LogicalThreadContext?

Там есть ссылка на сообщение Нико Каделла, одного из авторов log4net, о том, как работает LogicalThreadContext.Он говорит о том, что элементы, хранящиеся в CallContext, которые поддерживают ILogicalThreadAffinative, автоматически распространяются на дочерние потоки, но что log4net не использует ILogicalThreadAffinative.Он не упоминает ничего об использовании CallContext.LogicalSetData, который, как вы обнаружили, заставляет данные CallContext автоматически распространяться на дочерние потоки без необходимости реализации ILogicalThreadAffinative.

В заключение, я не думаю, что выничего не хватает.Я действительно думаю, что log4net ошибся.

Я понимаю, что вы не просили какой-либо код, но вот некоторая работа, которую я сделал несколько месяцев назад, когда я изучал log4net, CallContext, PatternLayoutConverter и т. Д..

Во-первых, объект «контекст логического потока», который я создал несколько месяцев назад.Я написал его, чтобы имитировать абстракции контекста ведения журнала, предоставляемые средством ведения журнала Castle.

  public static class LogicalThreadDiagnosticContext
  {
    const string slot = "Logging.Context.LogicalThreadDiagnosticContext";

    internal static IDictionary<string, object> LogicalThreadDictionary
    {
      get
      {
        IDictionary<string, object> dict = (IDictionary<string, object>)CallContext.LogicalGetData(slot);
        if (dict == null)
        {
          dict = new Dictionary<string, object>();
          CallContext.LogicalSetData(slot, dict);
        }

        return dict;
      }
    }

    public new static string ToString()
    {
      if (LogicalThreadDictionary.Count == 0) return "";

      IEnumerable<string> es = (from kvp in LogicalThreadDictionary select string.Format("{0} = {1}", kvp.Key, kvp.Value));

      string s = string.Join(";", es);

      return s;
    }

    public static IDictionary<string, object> CloneProperties()
    {
      return new Dictionary<string, object>(LogicalThreadDictionary);
    }

    public static void Set(string item, object value)
    {
      LogicalThreadDictionary[item] = value;
    }

    public static object Get(string item)
    {
      object s;

      if (!LogicalThreadDictionary.TryGetValue(item, out s))
      {
        s = string.Empty;
      }

      return s;
    }

    public static bool Contains(string item)
    {
      return LogicalThreadDictionary.ContainsKey(item);
    }

    public static void Remove(string item)
    {
      LogicalThreadDictionary.Remove(item);
    }

    public static void Clear()
    {
      LogicalThreadDictionary.Clear();
    }

    public static int Count
    {
      get { return LogicalThreadDictionary.Count; }
    }
  }

Вот шаблон log4net PatternLayoutConverter (который был написан в другое время, в основном в качестве эксперимента, помогающего узнать о log4net иCallContext).Ожидается, что свойство Option будет указывать конкретное именованное значение из контекста логического вызова.Не составит труда написать аналогичный PatternLayoutConverter, который получит словарь из логического контекста на основе приведенного выше имени, а затем использует параметр Option для индексации в словаре.

  class LogicalCallContextLayoutConverter : PatternLayoutConverter
  {
    private bool isDisabled = false;

    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      if (isDisabled || Option == null || Option.Length == 0) return;

      try
      {
        object data = CallContext.LogicalGetData(Option);
        if (data != null)
        {
          writer.Write(data.ToString());
        }
      }
      catch (SecurityException)
      {
        isDisabled = true;
      }
    }
  }

Для использования словаряСхема, как в первом примере кода, PatternLayoutConverter может выглядеть примерно так (не скомпилировано и не проверено):

  class LogicalCallContextLayoutConverter : PatternLayoutConverter
  {
    private bool isDisabled = false;

    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      if (isDisabled || Option == null || Option.Length == 0) return;

      try
      {
        object data = LogicalThreadDiagnosticContext[Option];
        if (data != null)
        {
          if (data != null)
          {
            writer.Write(data.ToString());
          }
        }
      }
      catch (SecurityException)
      {
        isDisabled = true;
      }
    }
  }

Удачи!