public void TestMultiLogMessage()
{
NestedDiagnosticsContext.Push("TestNdc");
for (int i = 0; i < 20; ++i)
{
Log.DebugFormat("debug message {0}", i);
}
Log.Trace("Trace message");
Log.Debug("Debug message");
Log.Info("Info message");
Log.Info("Info message");
Log.Info("Info message");
Log.Info("This is a\nmultiline message\nthat should have\nhtml breaks");
Log.Info("A message with <html> elements that should be rendered as text");
Log.Warn(new Exception(), "Warning message (this should be a triggering message)");
Log.Info("Info message");
Log.Error("Error message 1 (a non-trigger error, due to holddown after last warning)");
Log.InfoFormat("Info message");
Log.Error("Error message 2");
Log.InfoFormat("Info message");
Log.Trace("Trace message");
Log.Debug("Debug message");
Log.Info("Info message");
Log.Warn("Warn message");
Log.Error("Error message");
Log.Fatal("Fatal message");
Log.Error(new Exception("Test"), "Error message 3 (second triggering due to appender being closed)");
}
public void NestedDiagnosticContextInformation_is_stored_in_the_same_sort_order_as_used_by_the_nested_diagnostic_layout_renderer()
{
var ndcSeparator = "::";
var ndlcSeparator = " ";
ConfigureLogManager(ndcSeparator, ndlcSeparator);
// Act
NestedDiagnosticsContext.Clear();
NestedDiagnosticsLogicalContext.Push("foo");
NestedDiagnosticsLogicalContext.Push("bar");
NestedDiagnosticsLogicalContext.Clear();
NestedDiagnosticsContext.Push("baz1");
NestedDiagnosticsContext.Push("baz2");
NestedDiagnosticsContext.Push("baz3");
var logEvent = Log("A", LogLevel.Debug, null, null, "some message");
// Assert
var expected = GetExpectedNdcValue(logEvent, ndcSeparator, ndlcSeparator);
var actual = GetXmlDocument().GetElementsByTagName("log4j:NDC")[0].InnerText;
Assert.Equal(expected, actual);
}
public LogContext(Logger logger, string context)
{
this.logger = logger;
this.ndc = NestedDiagnosticsContext.Push(context);
this.stopWatch = System.Diagnostics.Stopwatch.StartNew();
}
/// <summary>
/// Выполняет логирование N раз с имитацией обращения к внешней системе после каждого логирования
/// </summary>
/// <param name="index"></param>
/// <param name="total"></param>
static void Log4WithSleepNdc(int index, int total)
{
using (NestedDiagnosticsContext.Push("NDC" + index))
for (int i = 0; i < 4; i++)
{
LogFormattedStringLess();
Thread.Sleep(sleep);
}
}
/// <summary>
/// Begin a scope. Log in config with ${ndc}
/// TODO not working with async
/// </summary>
/// <param name="state">The state</param>
/// <returns></returns>
public IDisposable BeginScope <TState>(TState state)
{
if (state == null)
{
throw new ArgumentNullException(nameof(state));
}
return(NestedDiagnosticsContext.Push(state));
}
public IDisposable BeginScopeImpl(object state)
{
if (state == null)
{
throw new ArgumentNullException(nameof(state));
}
return(NestedDiagnosticsContext.Push(state.ToString()));
}
public void TargetWithContextNdcSerializeTest()
{
NestedDiagnosticsContext.Clear();
NestedDiagnosticsContext.Push(new { a = "b" });
CustomTargetWithContext target = new CustomTargetWithContext()
{
IncludeNdc = true, SkipAssert = true
};
WriteAndAssertSingleKey(target);
}
private void ProcessQueue()
{
try
{
do
{
using (NestedDiagnosticsContext.Push(Guid.NewGuid().ToString()))
{
try
{
JobQueueItem job = null;
lock (Queue)
{
if (Queue.Count != 0)
{
job = Queue.OrderBy(c => c.Source).First();
logger.Trace("Popping {0} from the queue.", job);
Queue.Remove(job);
}
}
if (job != null)
{
Execute(job);
}
}
catch (ThreadAbortException)
{
throw;
}
catch (Exception e)
{
logger.FatalException("An error has occurred while executing job.", e);
}
}
} while (Queue.Count != 0);
}
catch (ThreadAbortException e)
{
logger.Warn(e.Message);
}
catch (Exception e)
{
logger.ErrorException("Error has occurred in queue processor thread", e);
}
finally
{
StopWatch.Stop();
logger.Trace("Finished processing jobs in the queue.");
}
}
public void NDCTop1TestTest()
{
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${ndc:topframes=1} ${message}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
NestedDiagnosticsContext.Clear();
LogManager.GetLogger("A").Debug("0");
AssertDebugLastMessage("debug", " 0");
using (NestedDiagnosticsContext.Push("ala"))
{
LogManager.GetLogger("A").Debug("a");
AssertDebugLastMessage("debug", "ala a");
using (NestedDiagnosticsContext.Push("ma"))
{
LogManager.GetLogger("A").Debug("b");
AssertDebugLastMessage("debug", "ma b");
using (NestedDiagnosticsContext.Push("kota"))
{
LogManager.GetLogger("A").Debug("c");
AssertDebugLastMessage("debug", "kota c");
NestedDiagnosticsContext.Push("kopytko");
LogManager.GetLogger("A").Debug("d");
AssertDebugLastMessage("debug", "kopytko d");
Assert.Equal("kopytko", NestedDiagnosticsContext.Pop()); // manual pop
LogManager.GetLogger("A").Debug("c");
AssertDebugLastMessage("debug", "kota c");
}
LogManager.GetLogger("A").Debug("b");
AssertDebugLastMessage("debug", "ma b");
}
LogManager.GetLogger("A").Debug("a");
AssertDebugLastMessage("debug", "ala a");
}
LogManager.GetLogger("A").Debug("0");
AssertDebugLastMessage("debug", " 0");
Assert.Equal(string.Empty, NestedDiagnosticsContext.Pop());
Assert.Equal(string.Empty, NestedDiagnosticsContext.TopMessage);
NestedDiagnosticsContext.Push("zzz");
Assert.Equal("zzz", NestedDiagnosticsContext.TopMessage);
NestedDiagnosticsContext.Clear();
Assert.Equal(string.Empty, NestedDiagnosticsContext.Pop());
Assert.Equal(string.Empty, NestedDiagnosticsContext.TopMessage);
}
public void NDCTest()
{
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${ndc} ${message}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
NestedDiagnosticsContext.Clear();
LogManager.GetLogger("A").Debug("0");
AssertDebugLastMessage("debug", " 0");
using (NestedDiagnosticsContext.Push("ala"))
{
LogManager.GetLogger("A").Debug("a");
AssertDebugLastMessage("debug", "ala a");
using (NestedDiagnosticsContext.Push("ma"))
{
LogManager.GetLogger("A").Debug("b");
AssertDebugLastMessage("debug", "ala ma b");
using (NestedDiagnosticsContext.Push("kota"))
{
LogManager.GetLogger("A").Debug("c");
AssertDebugLastMessage("debug", "ala ma kota c");
using (NestedDiagnosticsContext.Push("kopytko"))
{
LogManager.GetLogger("A").Debug("d");
AssertDebugLastMessage("debug", "ala ma kota kopytko d");
}
LogManager.GetLogger("A").Debug("c");
AssertDebugLastMessage("debug", "ala ma kota c");
}
LogManager.GetLogger("A").Debug("b");
AssertDebugLastMessage("debug", "ala ma b");
}
LogManager.GetLogger("A").Debug("a");
AssertDebugLastMessage("debug", "ala a");
}
LogManager.GetLogger("A").Debug("0");
AssertDebugLastMessage("debug", " 0");
}
public void If_Ndc_And_Ndlc_is_present_they_are_combined_with_a_NdcSeparator()
{
// Arrange
var ndcSeparator = "::";
var ndlcSeparator = " ";
ConfigureLogManager(ndcSeparator, ndlcSeparator);
// Act
NestedDiagnosticsContext.Clear();
NestedDiagnosticsContext.Push("foo");
NestedDiagnosticsLogicalContext.Clear();
NestedDiagnosticsLogicalContext.Push("bar");
var logEvent = Log("A", LogLevel.Debug, null, null, "some message");
// Assert
var expected = GetExpectedNdcValue(logEvent, ndcSeparator, ndlcSeparator);
var actual = GetXmlDocument().GetElementsByTagName("log4j:NDC")[0].InnerText;
Assert.Equal(expected, actual);
}
public void NDCTest2_object()
{
List <Exception> exceptions = new List <Exception>();
ManualResetEvent mre = new ManualResetEvent(false);
int counter = 100;
int remaining = counter;
for (int i = 0; i < counter; ++i)
{
ThreadPool.QueueUserWorkItem(
s =>
{
try
{
NestedDiagnosticsContext.Clear();
Assert.Null(NestedDiagnosticsContext.TopObject);
Assert.Null(NestedDiagnosticsContext.PopObject());
AssertContents(NestedDiagnosticsContext.GetAllMessages());
using (NestedDiagnosticsContext.Push("foo"))
{
Assert.Equal("foo", NestedDiagnosticsContext.TopObject);
AssertContents(NestedDiagnosticsContext.GetAllObjects(), "foo");
using (NestedDiagnosticsContext.Push("bar"))
{
AssertContents(NestedDiagnosticsContext.GetAllObjects(), "bar", "foo");
Assert.Equal("bar", NestedDiagnosticsContext.TopObject);
NestedDiagnosticsContext.Push("baz");
AssertContents(NestedDiagnosticsContext.GetAllObjects(), "baz", "bar", "foo");
Assert.Equal("baz", NestedDiagnosticsContext.TopObject);
Assert.Equal("baz", NestedDiagnosticsContext.PopObject());
AssertContents(NestedDiagnosticsContext.GetAllObjects(), "bar", "foo");
Assert.Equal("bar", NestedDiagnosticsContext.TopObject);
}
AssertContents(NestedDiagnosticsContext.GetAllObjects(), "foo");
Assert.Equal("foo", NestedDiagnosticsContext.TopObject);
}
AssertContents(NestedDiagnosticsContext.GetAllMessages());
Assert.Null(NestedDiagnosticsContext.PopObject());
}
catch (Exception ex)
{
lock (exceptions)
{
exceptions.Add(ex);
}
}
finally
{
if (Interlocked.Decrement(ref remaining) == 0)
{
mre.Set();
}
}
});
}
mre.WaitOne();
StringBuilder exceptionsMessage = new StringBuilder();
foreach (var ex in exceptions)
{
if (exceptionsMessage.Length > 0)
{
exceptionsMessage.Append("\r\n");
}
exceptionsMessage.Append(ex.ToString());
}
Assert.True(exceptions.Count == 0, exceptionsMessage.ToString());
}
public void TestLogMessage()
{
NestedDiagnosticsContext.Push("TestNdc");
Log.Error("This is a test message");
}
public void Log4JXmlTest()
{
LogManager.Configuration = CreateConfigurationFromString(@"
<nlog throwExceptions='true'>
<targets>
<target name='debug' type='Debug' layout='${log4jxmlevent:includeCallSite=true:includeSourceInfo=true:includeMdc=true:includeMdlc=true:includeMdlc=true:IncludeAllProperties=true:ndcItemSeparator=\:\::includenlogdata=true}' />
</targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
MappedDiagnosticsContext.Clear();
NestedDiagnosticsContext.Clear();
MappedDiagnosticsContext.Set("foo1", "bar1");
MappedDiagnosticsContext.Set("foo2", "bar2");
MappedDiagnosticsLogicalContext.Clear();
MappedDiagnosticsLogicalContext.Set("foo3", "bar3");
NestedDiagnosticsContext.Push("baz1");
NestedDiagnosticsContext.Push("baz2");
NestedDiagnosticsContext.Push("baz3");
ILogger logger = LogManager.GetLogger("A");
var logEventInfo = LogEventInfo.Create(LogLevel.Debug, "A", new Exception("Hello Exception", new Exception("Goodbye Exception")), null, "some message");
logEventInfo.Properties["nlogPropertyKey"] = "nlogPropertyValue";
logger.Log(logEventInfo);
string result = GetDebugLastMessage("debug");
string wrappedResult = "<log4j:dummyRoot xmlns:log4j='http://log4j' xmlns:nlog='http://nlog'>" + result + "</log4j:dummyRoot>";
Assert.NotEqual("", result);
// make sure the XML can be read back and verify some fields
StringReader stringReader = new StringReader(wrappedResult);
using (XmlReader reader = XmlReader.Create(stringReader))
{
while (reader.Read())
{
if (reader.NodeType == XmlNodeType.Element && reader.Prefix == "log4j")
{
switch (reader.LocalName)
{
case "dummyRoot":
break;
case "event":
Assert.Equal("DEBUG", reader.GetAttribute("level"));
Assert.Equal("A", reader.GetAttribute("logger"));
var epochStart = new DateTime(1970, 1, 1, 0, 0, 0, DateTimeKind.Utc);
long timestamp = Convert.ToInt64(reader.GetAttribute("timestamp"));
var time = epochStart.AddMilliseconds(timestamp);
var now = DateTime.UtcNow;
Assert.True(now.Ticks - time.Ticks < TimeSpan.FromSeconds(3).Ticks);
Assert.Equal(Thread.CurrentThread.ManagedThreadId.ToString(), reader.GetAttribute("thread"));
break;
case "message":
reader.Read();
Assert.Equal("some message", reader.Value);
break;
case "NDC":
reader.Read();
Assert.Equal("baz3::baz2::baz1", reader.Value);
break;
case "locationInfo":
Assert.Equal(MethodBase.GetCurrentMethod().DeclaringType.FullName, reader.GetAttribute("class"));
Assert.Equal(MethodBase.GetCurrentMethod().ToString(), reader.GetAttribute("method"));
break;
case "properties":
break;
case "throwable":
reader.Read();
Assert.Contains("Hello Exception", reader.Value);
Assert.Contains("Goodbye Exception", reader.Value);
break;
case "data":
string name = reader.GetAttribute("name");
string value = reader.GetAttribute("value");
switch (name)
{
case "log4japp":
Assert.Equal(AppDomain.CurrentDomain.FriendlyName + "(" + Process.GetCurrentProcess().Id + ")", value);
break;
case "log4jmachinename":
Assert.Equal(Environment.MachineName, value);
break;
case "foo1":
Assert.Equal("bar1", value);
break;
case "foo2":
Assert.Equal("bar2", value);
break;
case "foo3":
Assert.Equal("bar3", value);
break;
case "nlogPropertyKey":
Assert.Equal("nlogPropertyValue", value);
break;
default:
Assert.True(false, "Unknown <log4j:data>: " + name);
break;
}
break;
default:
throw new NotSupportedException("Unknown element: " + reader.LocalName);
}
continue;
}
if (reader.NodeType == XmlNodeType.Element && reader.Prefix == "nlog")
{
switch (reader.LocalName)
{
case "eventSequenceNumber":
break;
case "locationInfo":
Assert.Equal(this.GetType().Assembly.FullName, reader.GetAttribute("assembly"));
break;
case "properties":
break;
case "data":
var name = reader.GetAttribute("name");
var value = reader.GetAttribute("value");
Assert.Equal("nlogPropertyKey", name);
Assert.Equal("nlogPropertyValue", value);
break;
default:
throw new NotSupportedException("Unknown element: " + reader.LocalName);
}
}
}
}
}
public IDisposable BeginScopeImpl([NotNull] object state)
{
return(NestedDiagnosticsContext.Push(state.ToString()));
}
/// <summary>
/// Pushes the specified text on current thread NDC.
/// </summary>
/// <param name = "message">The message to be pushed.</param>
/// <returns>An instance of the object that implements IDisposable that returns the stack to the previous level when IDisposable.Dispose() is called. To be used with C# using() statement.</returns>
public IDisposable Push(string message)
{
return(NestedDiagnosticsContext.Push(message));
}
public void NDCTest1()
{
List <Exception> exceptions = new List <Exception>();
ManualResetEvent mre = new ManualResetEvent(false);
int counter = 500;
int remaining = counter;
for (int i = 0; i < counter; ++i)
{
ThreadPool.QueueUserWorkItem(
s =>
{
try
{
NestedDiagnosticsContext.Clear();
Assert.AreEqual(string.Empty, NestedDiagnosticsContext.TopMessage);
Assert.AreEqual(string.Empty, NestedDiagnosticsContext.Pop());
AssertContents(NestedDiagnosticsContext.GetAllMessages());
using (NestedDiagnosticsContext.Push("foo"))
{
Assert.AreEqual("foo", NestedDiagnosticsContext.TopMessage);
AssertContents(NestedDiagnosticsContext.GetAllMessages(), "foo");
using (NestedDiagnosticsContext.Push("bar"))
{
AssertContents(NestedDiagnosticsContext.GetAllMessages(), "bar", "foo");
Assert.AreEqual("bar", NestedDiagnosticsContext.TopMessage);
NestedDiagnosticsContext.Push("baz");
AssertContents(NestedDiagnosticsContext.GetAllMessages(), "baz", "bar", "foo");
Assert.AreEqual("baz", NestedDiagnosticsContext.TopMessage);
Assert.AreEqual("baz", NestedDiagnosticsContext.Pop());
AssertContents(NestedDiagnosticsContext.GetAllMessages(), "bar", "foo");
Assert.AreEqual("bar", NestedDiagnosticsContext.TopMessage);
}
AssertContents(NestedDiagnosticsContext.GetAllMessages(), "foo");
Assert.AreEqual("foo", NestedDiagnosticsContext.TopMessage);
}
AssertContents(NestedDiagnosticsContext.GetAllMessages());
Assert.AreEqual(string.Empty, NestedDiagnosticsContext.Pop());
}
catch (Exception ex)
{
lock (exceptions)
{
exceptions.Add(ex);
}
}
finally
{
if (Interlocked.Decrement(ref remaining) == 0)
{
mre.Set();
}
}
});
}
mre.WaitOne();
Assert.AreEqual(0, exceptions.Count);
}
