Ken*_*art 9 .net log4net multithreading
我有什么是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类根据我上面的发现进行了更改.我重新进行了初步测试并且运行正常.对于很多人使用的产品来说,这个问题太明显了,所以我不得不认为我错过了一些东西.
这是一个问题,我回想一下ThreadContext和LogicalThreadContext之间的区别:
log4net.ThreadContext和log4net.LogicalThreadContext有什么区别？
其中有一个链接是由log4net作者之一Nicko Cadell发布的关于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;
}
}
}
祝好运!