public void ScopePropertyFormatTests()
{
// Arrange
ScopeContext.Clear();
var logFactory = new LogFactory();
logFactory.Setup().LoadConfigurationFromXml(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${scopeproperty:item=myitem:format=@} ${message}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
var logger = logFactory.GetCurrentClassLogger();
var target = logFactory.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
// Act
using (logger.PushScopeProperty("myitem", new { RequestId = 123 }))
{
logger.Debug("a");
}
// Assert
Assert.Equal("{\"RequestId\":123} a", target.LastMessage);
}
public void ScopeNestedTopTwoTest()
{
// Arrange
ScopeContext.Clear();
var logFactory = new LogFactory();
logFactory.Setup().LoadConfigurationFromXml(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${scopenested:topframes=2} ${message}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
var logger = logFactory.GetCurrentClassLogger();
var target = logFactory.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
// Act
using (logger.PushScopeState("ala"))
{
using (logger.PushScopeState("ma"))
{
using (logger.PushScopeState("kota"))
{
logger.Debug("c");
}
}
}
// Assert
Assert.Equal("ma kota c", target.LastMessage);
}
public void LegacyMdlcSetShouldNotAffectStackValues3()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "Bob";
var expectedNestedState = "First Push";
object propertyValue1;
object propertyValue2;
object[] allNestedStates = null;
var success1 = false;
var success2 = false;
// Act
using (ScopeContext.PushNestedState(expectedNestedState))
{
using (ScopeContext.PushProperty("Hello", "World"))
{
MappedDiagnosticsLogicalContext.Set("Hello", expectedValue); // Enter legacy mode (need to overwrite)
success1 = ScopeContext.TryGetProperty("Hello", out propertyValue1);
allNestedStates = ScopeContext.GetAllNestedStates();
}
success2 = ScopeContext.TryGetProperty("Hello", out propertyValue2);
}
// Assert
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
Assert.True(success1);
Assert.Equal(expectedValue, propertyValue1);
Assert.False(success2);
Assert.Null(propertyValue2);
}
public void ScopeNestedTwoPropertiesNewlineTest()
{
// Arrange
ScopeContext.Clear();
var logFactory = new LogFactory();
logFactory.Setup().LoadConfigurationFromXml(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${scopenested:format=@:separator=${newline}}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
var logger = logFactory.GetCurrentClassLogger();
var target = logFactory.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
// Act
using (logger.PushScopeState(new Dictionary <string, object>()
{
{ "Hello", 42 }, { "Unlucky", 13 }
}))
{
logger.Debug("c");
}
// Assert
Assert.Equal(string.Format("[{0}{{{0}\"Hello\": 42,{0}\"Unlucky\": 13{0}}}{0}]", System.Environment.NewLine), target.LastMessage);
}
public void TargetWithContextConfigTest()
{
Target.Register("contexttarget", typeof(CustomTargetWithContext));
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog throwExceptions='true'>
<targets>
<target name='debug' type='contexttarget' includeCallSite='true'>
<contextproperty name='threadid' layout='${threadid}' hello='world' />
</target>
</targets>
<rules>
<logger name='*' levels='Error' writeTo='debug' />
</rules>
</nlog>");
ILogger logger = LogManager.GetLogger("A");
ScopeContext.Clear();
logger.Error("log message");
var target = LogManager.Configuration.FindTargetByName("debug") as CustomTargetWithContext;
Assert.NotEqual(0, target.LastMessage.Length);
var lastCombinedProperties = target.LastCombinedProperties;
Assert.NotEmpty(lastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("threadid", System.Environment.CurrentManagedThreadId.ToString()), lastCombinedProperties);
}
public void DoublePushNestedStateTest()
{
// Arrange
ScopeContext.Clear();
var expectedNestedState1 = "First Push";
var expectedNestedState2 = System.Guid.NewGuid();
object topNestedState1 = null;
object topNestedState2 = null;
object[] allNestedStates = null;
// Act
using (ScopeContext.PushNestedState(expectedNestedState1))
{
topNestedState1 = ScopeContext.PeekNestedState();
using (ScopeContext.PushNestedState(expectedNestedState2))
{
topNestedState2 = ScopeContext.PeekNestedState();
allNestedStates = ScopeContext.GetAllNestedStates();
}
}
var failed = ScopeContext.PeekNestedState() != null;
// Assert
Assert.Equal(expectedNestedState1, topNestedState1);
Assert.Equal(expectedNestedState2, topNestedState2);
Assert.Equal(2, allNestedStates.Length);
Assert.Equal(expectedNestedState2, allNestedStates[0]);
Assert.Equal(expectedNestedState1, allNestedStates[1]);
Assert.False(failed);
}
public void LoggerPushPropertyTest()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
Dictionary <string, object> allProperties = null;
var success = false;
object value;
var logger = new LogFactory().GetCurrentClassLogger();
// Act
using (logger.PushScopeProperty("HELLO", expectedValue))
{
success = ScopeContext.TryGetProperty("hello", out value);
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
var failed = ScopeContext.TryGetProperty("hello", out var _);
// Assert
Assert.True(success);
Assert.Equal(expectedValue, value);
Assert.Single(allProperties);
Assert.Equal(expectedValue, allProperties["HELLO"]);
Assert.False(failed);
}
public void LoggerPushScopePropertiesCovarianceTest(bool convertDictionary)
{
// Arrange
ScopeContext.Clear();
var expectedString = "World";
var expectedId = 42;
IReadOnlyCollection <KeyValuePair <string, IConvertible> > expectedProperties = new[] { new KeyValuePair <string, IConvertible>("Hello", expectedString), new KeyValuePair <string, IConvertible>("RequestId", expectedId) };
if (convertDictionary)
{
expectedProperties = expectedProperties.ToDictionary(i => i.Key, i => i.Value);
}
Dictionary <string, object> allProperties = null;
object stringValueLookup = null;
var logger = new LogFactory().GetCurrentClassLogger();
// Act
using (logger.PushScopeProperty("Hello", "People"))
{
using (logger.PushScopeProperties(expectedProperties))
{
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
ScopeContext.TryGetProperty("Hello", out stringValueLookup);
}
// Assert
Assert.Equal(2, allProperties.Count);
Assert.Equal(expectedString, allProperties["Hello"]);
Assert.Equal(expectedId, allProperties["RequestId"]);
Assert.Equal(expectedProperties.Select(p => new KeyValuePair <string, object>(p.Key, p.Value)), allProperties);
Assert.Equal("People", stringValueLookup);
}
public void ScopeNestedSinglePropertyTest()
{
// Arrange
ScopeContext.Clear();
var logFactory = new LogFactory();
logFactory.Setup().LoadConfigurationFromXml(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${scopenested:format=@}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
var logger = logFactory.GetCurrentClassLogger();
var target = logFactory.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
// Act
using (logger.PushScopeState(new[] { new KeyValuePair <string, object>("Hello", "World") }))
{
logger.Debug("c");
}
// Assert
Assert.Equal("[ { \"Hello\": \"World\" } ]", target.LastMessage);
}
public void LoggerPushScopePropertiesTest()
{
// Arrange
ScopeContext.Clear();
var expectedString = "World";
var expectedGuid = System.Guid.NewGuid();
var expectedProperties = new[] { new KeyValuePair <string, object>("Hello", expectedString), new KeyValuePair <string, object>("RequestId", expectedGuid) };
IEnumerable <KeyValuePair <string, object> > allPropertiesState = null;
Dictionary <string, object> allProperties = null;
var logger = new LogFactory().GetCurrentClassLogger();
object stringValueLookup = null;
// Act
using (logger.PushScopeProperties(expectedProperties))
{
allPropertiesState = ScopeContext.GetAllProperties();
allProperties = allPropertiesState.ToDictionary(x => x.Key, x => x.Value);
}
ScopeContext.TryGetProperty("Hello", out stringValueLookup);
// Assert
#if !NET35 && !NET40 && !NET45
Assert.Same(expectedProperties, allPropertiesState);
#endif
Assert.Equal(2, allProperties.Count);
Assert.Equal(expectedString, allProperties["Hello"]);
Assert.Equal(expectedGuid, allProperties["RequestId"]);
Assert.Equal(expectedProperties.Select(p => new KeyValuePair <string, object>(p.Key, p.Value)), allProperties);
Assert.Null(stringValueLookup);
}
public void LoggerPushScopePropertiesOverwriteTest()
{
// Arrange
ScopeContext.Clear();
var expectedString = "World";
var expectedGuid = System.Guid.NewGuid();
var expectedProperties = new[] { new KeyValuePair <string, object>("Hello", expectedString), new KeyValuePair <string, object>("RequestId", expectedGuid) };
Dictionary <string, object> allProperties = null;
object stringValueLookup = null;
var logger = new LogFactory().GetCurrentClassLogger();
// Act
using (logger.PushScopeProperty("Hello", "People"))
{
using (logger.PushScopeProperties(expectedProperties))
{
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
ScopeContext.TryGetProperty("Hello", out stringValueLookup);
}
// Assert
Assert.Equal(2, allProperties.Count);
Assert.Equal(expectedString, allProperties["Hello"]);
Assert.Equal(expectedGuid, allProperties["RequestId"]);
Assert.Equal(expectedProperties.Select(p => new KeyValuePair <string, object>(p.Key, p.Value)), allProperties);
Assert.Equal("People", stringValueLookup);
}
public void PushNestedStatePropertiesTest()
{
// Arrange
ScopeContext.Clear();
var expectedString = "World";
var expectedGuid = System.Guid.NewGuid();
var expectedProperties = new[] { new KeyValuePair <string, object>("Hello", expectedString), new KeyValuePair <string, object>("RequestId", expectedGuid) };
var expectedNestedState = "First Push";
Dictionary <string, object> allProperties = null;
object[] allNestedStates = null;
object stringValueLookup = null;
// Act
using (ScopeContext.PushProperty("Hello", "People"))
{
using (ScopeContext.PushNestedStateProperties(expectedNestedState, expectedProperties))
{
allNestedStates = ScopeContext.GetAllNestedStates();
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
ScopeContext.TryGetProperty("Hello", out stringValueLookup);
}
// Assert
Assert.Equal(2, allProperties.Count);
Assert.Equal(expectedString, allProperties["Hello"]);
Assert.Equal(expectedGuid, allProperties["RequestId"]);
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
Assert.Equal("People", stringValueLookup);
}
public void LegacyMdlcSetShouldNotAffectStackValues2()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
var expectedNestedState = "First Push";
object propertyValue;
object[] allNestedStates = null;
var success = false;
// Act
using (ScopeContext.PushNestedState(expectedNestedState))
{
using (ScopeContext.PushProperty("Hello", expectedValue))
{
MappedDiagnosticsLogicalContext.Set("Hello", expectedValue); // Skip legacy mode (ignore when same value)
success = ScopeContext.TryGetProperty("Hello", out propertyValue);
allNestedStates = ScopeContext.GetAllNestedStates();
}
}
// Assert
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
Assert.True(success);
Assert.Equal(expectedValue, propertyValue);
}
public void TargetWithContextPropertyTypeTest()
{
Target.Register("contexttarget", typeof(CustomTargetWithContext));
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog throwExceptions='true'>
<targets>
<default-wrapper type='AsyncWrapper' timeToSleepBetweenBatches='0' overflowAction='Block' />
<target name='debug' type='contexttarget' includeCallSite='true'>
<contextproperty name='threadid' layout='${threadid}' propertyType='System.Int32' />
<contextproperty name='processid' layout='${processid}' propertyType='System.Int32' />
<contextproperty name='timestamp' layout='${date}' propertyType='System.DateTime' />
<contextproperty name='int-non-existing' layout='${event-properties:non-existing}' propertyType='System.Int32' includeEmptyValue='true' />
<contextproperty name='int-non-existing-empty' layout='${event-properties:non-existing}' propertyType='System.Int32' includeEmptyValue='false' />
<contextproperty name='object-non-existing' layout='${event-properties:non-existing}' propertyType='System.Object' includeEmptyValue='true' />
<contextproperty name='object-non-existing-empty' layout='${event-properties:non-existing}' propertyType='System.Object' includeEmptyValue='false' />
</target>
</targets>
<rules>
<logger name='*' levels='Error' writeTo='debug' />
</rules>
</nlog>");
ILogger logger = LogManager.GetLogger("A");
ScopeContext.Clear();
var logEvent = new LogEventInfo()
{
Message = "log message"
};
logger.Error(logEvent);
LogManager.Flush();
var target = LogManager.Configuration.AllTargets.OfType <CustomTargetWithContext>().FirstOrDefault();
Assert.NotEqual(0, target.LastMessage.Length);
var lastCombinedProperties = target.LastCombinedProperties;
Assert.NotEmpty(lastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("threadid", System.Environment.CurrentManagedThreadId), lastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("processid", System.Diagnostics.Process.GetCurrentProcess().Id), lastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("int-non-existing", 0), lastCombinedProperties);
Assert.DoesNotContain("int-non-existing-empty", lastCombinedProperties.Keys);
Assert.Contains(new KeyValuePair <string, object>("object-non-existing", ""), lastCombinedProperties);
Assert.DoesNotContain("object-non-existing-empty", lastCombinedProperties.Keys);
}
public void TargetWithContextJsonTest()
{
Target.Register("contexttarget", typeof(CustomTargetWithContext));
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog throwExceptions='true'>
<targets>
<default-wrapper type='AsyncWrapper' timeToSleepBetweenBatches='0' overflowAction='Block' />
<target name='debug' type='contexttarget' includeCallSite='true'>
<layout type='JsonLayout' includeScopeProperties='true'>
<attribute name='level' layout='${level:upperCase=true}'/>
<attribute name='message' layout='${message}' />
<attribute name='exception' layout='${exception}' />
<attribute name='threadid' layout='${threadid}' />
</layout>
</target>
</targets>
<rules>
<logger name='*' levels='Error' writeTo='debug' />
</rules>
</nlog>");
ILogger logger = LogManager.GetLogger("A");
ScopeContext.Clear();
ScopeContext.PushProperty("TestKey", "Hello Thread World");
logger.Error("log message");
var target = LogManager.Configuration.AllTargets.OfType <CustomTargetWithContext>().FirstOrDefault();
System.Threading.Thread.Sleep(1);
for (int i = 0; i < 1000; ++i)
{
if (target.LastMessage != null)
{
break;
}
System.Threading.Thread.Sleep(1);
}
Assert.NotEqual(0, target.LastMessage.Length);
Assert.Contains(System.Environment.CurrentManagedThreadId.ToString(), target.LastMessage);
var lastCombinedProperties = target.LastCombinedProperties;
Assert.Empty(lastCombinedProperties);
}
public void LegacyNdlcClearShouldNotAffectProperties1()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
var success = false;
object propertyValue;
// Act
using (ScopeContext.PushProperty("Hello", expectedValue))
{
NestedDiagnosticsLogicalContext.Clear(); // Should not clear anything (skip legacy mode)
success = ScopeContext.TryGetProperty("Hello", out propertyValue);
}
// Assert
Assert.True(success);
Assert.Equal(expectedValue, propertyValue);
}
public void LegacyMdlcRemoveShouldNotAffectStackValues1()
{
// Arrange
ScopeContext.Clear();
var expectedNestedState = "First Push";
object[] allNestedStates = null;
// Act
using (ScopeContext.PushNestedState(expectedNestedState))
{
MappedDiagnosticsLogicalContext.Remove("Hello"); // Should not remove anything (skip legacy mode)
allNestedStates = ScopeContext.GetAllNestedStates();
}
// Assert
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
}
public void PushPropertyNestedTest()
{
// Arrange
ScopeContext.Clear();
var expectedString = "World";
var expectedGuid = System.Guid.NewGuid();
Dictionary <string, object> allProperties = null;
object stringValueLookup1 = null;
object stringValueLookup2 = null;
bool stringValueLookup3 = false;
object guidValueLookup1 = null;
bool guidValueLookup2 = false;
bool guidValueLookup3 = false;
// Act
using (ScopeContext.PushProperty("Hello", expectedString))
{
using (ScopeContext.PushProperty("RequestId", expectedGuid))
{
ScopeContext.TryGetProperty("Hello", out stringValueLookup1);
ScopeContext.TryGetProperty("RequestId", out guidValueLookup1);
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
ScopeContext.TryGetProperty("Hello", out stringValueLookup2);
guidValueLookup2 = ScopeContext.TryGetProperty("RequestId", out var _);
}
guidValueLookup3 = ScopeContext.TryGetProperty("RequestId", out var _);
stringValueLookup3 = ScopeContext.TryGetProperty("Hello", out var _);
// Assert
Assert.Equal(2, allProperties.Count);
Assert.Equal(expectedString, allProperties["Hello"]);
Assert.Equal(expectedGuid, allProperties["RequestId"]);
Assert.Equal(expectedString, stringValueLookup1);
Assert.Equal(expectedString, stringValueLookup2);
Assert.Equal(expectedGuid, guidValueLookup1);
Assert.False(guidValueLookup2);
Assert.False(guidValueLookup3);
Assert.False(guidValueLookup3);
Assert.False(stringValueLookup3);
}
public void LegacyMdlcRemoveShouldNotAffectStackValues2()
{
// Arrange
ScopeContext.Clear();
var expectedValue1 = "World";
var expectedValue2 = System.Guid.NewGuid();
var expectedNestedState1 = "First Push";
var expectedNestedState2 = System.Guid.NewGuid();
object propertyValue1;
object propertyValue2;
object[] allNestedStates = null;
var success1 = false;
var success2 = false;
// Act
using (ScopeContext.PushNestedState(expectedNestedState1))
{
using (ScopeContext.PushProperty("Hello", expectedValue1))
{
using (ScopeContext.PushNestedState(expectedNestedState2))
{
ScopeContext.PushProperty("RequestId", expectedValue2);
MappedDiagnosticsLogicalContext.Remove("RequestId"); // Should not change stack (Legacy mode)
allNestedStates = ScopeContext.GetAllNestedStates();
success1 = ScopeContext.TryGetProperty("Hello", out propertyValue1);
success2 = ScopeContext.TryGetProperty("RequestId", out propertyValue2);
}
}
}
// Assert
Assert.Equal(2, allNestedStates.Length);
Assert.Equal(expectedNestedState2, allNestedStates[0]);
Assert.Equal(expectedNestedState1, allNestedStates[1]);
Assert.True(success1);
Assert.False(success2);
Assert.Equal(expectedValue1, propertyValue1);
Assert.Null(propertyValue2);
}
public void LegacyMdlcClearShouldNotAffectStackValues2()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
var expectedNestedState = "First Push";
object[] allNestedStates = null;
// Act
using (ScopeContext.PushNestedState(expectedNestedState))
{
ScopeContext.PushProperty("Hello", expectedValue);
MappedDiagnosticsLogicalContext.Clear(); // Should not clear stack (Legacy mode)
allNestedStates = ScopeContext.GetAllNestedStates();
}
// Assert
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
}
public void LayoutParserEscapeCodesForRegExTestV2()
{
ScopeContext.Clear();
var configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog throwExceptions='true'>
<variable name=""searchExp""
value=""(?<!\\d[ -]*)(?\:(?<digits>\\d)[ -]*)\{8,16\}(?=(\\d[ -]*)\{3\}(\\d)(?![ -]\\d))""
/>
<variable name=""message1"" value=""${replace:inner=${message}:searchFor=${searchExp}:replaceWith=\u003a\u003a:regex=true:ignorecase=true}"" />
<targets>
<target name=""d1"" type=""Debug"" layout=""${message1}"" />
</targets>
<rules>
<logger name=""*"" minlevel=""Trace"" writeTo=""d1"" />
</rules>
</nlog>");
var d1 = configuration.FindTargetByName("d1") as DebugTarget;
Assert.NotNull(d1);
var layout = d1.Layout as SimpleLayout;
Assert.NotNull(layout);
var c = layout.Renderers.Count;
Assert.Equal(1, c);
var l1 = layout.Renderers[0] as ReplaceLayoutRendererWrapper;
Assert.NotNull(l1);
Assert.True(l1.Regex);
Assert.True(l1.IgnoreCase);
Assert.Equal(@"::", l1.ReplaceWith);
Assert.Equal(@"(?<!\d[ -]*)(?:(?<digits>\d)[ -]*){8,16}(?=(\d[ -]*){3}(\d)(?![ -]\d))", l1.SearchFor);
}
public void XmlLayoutLog4j()
{
LogManager.Configuration = XmlLoggingConfiguration.CreateFromXmlString(@"
<nlog throwExceptions='true'>
<targets>
<target name='debug' type='debug'>
<layout type='xmllayout' elementName='log4j:event' propertiesElementName='log4j:data' propertiesElementKeyAttribute='name' propertiesElementValueAttribute='value' includeAllProperties='true' includeMdc='true' includeMdlc='true' >
<attribute name='logger' layout='${logger}' includeEmptyValue='true' />
<attribute name='level' layout='${uppercase:${level}}' includeEmptyValue='true' />
<element name='log4j:message' value='${message}' />
<element name='log4j:throwable' value='${exception:format=tostring}' />
<element name='log4j:locationInfo'>
<attribute name='class' layout='${callsite:methodName=false}' includeEmptyValue='true' />
</element>
</layout>
</target>
</targets>
<rules>
<logger name='*' minlevel='debug' appendto='debug' />
</rules>
</nlog>");
ScopeContext.Clear();
ScopeContext.PushProperty("foo1", "bar1");
ScopeContext.PushProperty("foo2", "bar2");
ScopeContext.PushProperty("foo3", "bar3");
var logger = LogManager.GetLogger("hello");
var logEventInfo = LogEventInfo.Create(LogLevel.Debug, "A", null, null, "some message");
logEventInfo.Properties["nlogPropertyKey"] = "<nlog\r\nPropertyValue>";
logger.Log(logEventInfo);
var target = LogManager.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
Assert.Equal(@"<log4j:event logger=""A"" level=""DEBUG""><log4j:message>some message</log4j:message><log4j:locationInfo class=""NLog.UnitTests.Layouts.XmlLayoutTests""/><log4j:data name=""foo1"" value=""bar1""/><log4j:data name=""foo2"" value=""bar2""/><log4j:data name=""foo3"" value=""bar3""/><log4j:data name=""nlogPropertyKey"" value=""<nlog PropertyValue>""/></log4j:event>", target.LastMessage);
}
public void TargetWithContextAsyncTest()
{
CustomTargetWithContext target = new CustomTargetWithContext();
target.ContextProperties.Add(new TargetPropertyWithContext("threadid", "${threadid}"));
target.IncludeScopeProperties = true;
target.IncludeGdc = true;
target.IncludeScopeNestedStates = true;
target.IncludeCallSite = true;
AsyncTargetWrapper wrapper = new AsyncTargetWrapper();
wrapper.WrappedTarget = target;
wrapper.TimeToSleepBetweenBatches = 0;
NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(wrapper, LogLevel.Debug);
Logger logger = LogManager.GetLogger("Example");
GlobalDiagnosticsContext.Clear();
ScopeContext.Clear();
GlobalDiagnosticsContext.Set("TestKey", "Hello Global World");
GlobalDiagnosticsContext.Set("GlobalKey", "Hello Global World");
ScopeContext.PushProperty("TestKey", "Hello Async World");
ScopeContext.PushProperty("AsyncKey", "Hello Async World");
logger.Debug("log message");
Assert.True(WaitForLastMessage(target));
Assert.NotEqual(0, target.LastMessage.Length);
Assert.NotNull(target.LastCombinedProperties);
Assert.NotEmpty(target.LastCombinedProperties);
Assert.Equal(5, target.LastCombinedProperties.Count);
Assert.Contains(new KeyValuePair <string, object>("GlobalKey", "Hello Global World"), target.LastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("AsyncKey", "Hello Async World"), target.LastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("TestKey", "Hello Async World"), target.LastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("TestKey_1", "Hello Global World"), target.LastCombinedProperties);
Assert.Contains(new KeyValuePair <string, object>("threadid", System.Environment.CurrentManagedThreadId.ToString()), target.LastCombinedProperties);
}
public void LegacyNdlcPopShouldNotAffectProperties3()
{
// Arrange
ScopeContext.Clear();
var expectedValue1 = "World";
var expectedValue2 = System.Guid.NewGuid();
var expectedNestedState1 = "First Push";
var expectedNestedState2 = System.Guid.NewGuid();
var success1 = false;
var success2 = false;
object propertyValue1;
object propertyValue2;
object nestedState1;
object nestedState2;
// Act
using (ScopeContext.PushProperty("Hello", expectedValue1))
{
ScopeContext.PushNestedState(expectedNestedState1);
ScopeContext.PushNestedState(expectedNestedState2);
using (ScopeContext.PushProperty("RequestId", expectedValue2))
{
nestedState2 = NestedDiagnosticsLogicalContext.PopObject(); // Evil pop where it should leave properties alone (Legacy mode)
nestedState1 = NestedDiagnosticsLogicalContext.PopObject(); // Evil pop where it should leave properties alone (Legacy mode)
success1 = ScopeContext.TryGetProperty("Hello", out propertyValue1);
success2 = ScopeContext.TryGetProperty("RequestId", out propertyValue2);
}
}
// Assert
Assert.True(success1);
Assert.True(success2);
Assert.Equal(expectedValue1, propertyValue1);
Assert.Equal(expectedValue2, propertyValue2);
Assert.Equal(expectedNestedState1, nestedState1);
Assert.Equal(expectedNestedState2, nestedState2);
}
public void PushNestedStateTest()
{
// Arrange
ScopeContext.Clear();
var expectedNestedState = "First Push";
object topNestedState = null;
object[] allNestedStates = null;
// Act
using (ScopeContext.PushNestedState(expectedNestedState))
{
topNestedState = ScopeContext.PeekNestedState();
allNestedStates = ScopeContext.GetAllNestedStates();
}
var failed = ScopeContext.PeekNestedState() != null;
// Assert
Assert.Equal(expectedNestedState, topNestedState);
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
Assert.False(failed);
}
public void LegacyNdlcPopShouldNotAffectProperties2()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
var expectedNestedState = "First Push";
var success = false;
object propertyValue;
object nestedState;
// Act
using (ScopeContext.PushProperty("Hello", expectedValue))
{
ScopeContext.PushNestedState(expectedNestedState);
nestedState = NestedDiagnosticsLogicalContext.PopObject(); // Should only pop active scope (skip legacy mode)
success = ScopeContext.TryGetProperty("Hello", out propertyValue);
}
// Assert
Assert.True(success);
Assert.Equal(expectedValue, propertyValue);
Assert.Equal(expectedNestedState, nestedState);
}
public void ClearScopeContextTest()
{
// Arrange
ScopeContext.Clear();
var expectedNestedState = "First Push";
var expectedString = "World";
var expectedGuid = System.Guid.NewGuid();
object[] allNestedStates1 = null;
object[] allNestedStates2 = null;
object stringValueLookup1 = null;
object stringValueLookup2 = null;
// Act
using (ScopeContext.PushProperty("Hello", expectedString))
{
using (ScopeContext.PushProperty("RequestId", expectedGuid))
{
using (ScopeContext.PushNestedState(expectedNestedState))
{
ScopeContext.Clear();
allNestedStates1 = ScopeContext.GetAllNestedStates();
ScopeContext.TryGetProperty("Hello", out stringValueLookup1);
}
}
// Original scope was restored on dispose, verify expected behavior
allNestedStates2 = ScopeContext.GetAllNestedStates();
ScopeContext.TryGetProperty("Hello", out stringValueLookup2);
}
// Assert
Assert.Null(stringValueLookup1);
Assert.Equal(expectedString, stringValueLookup2);
Assert.Empty(allNestedStates1);
Assert.Empty(allNestedStates2);
}
public void LoggerPushNestedStatePrimitiveTest()
{
// Arrange
ScopeContext.Clear();
var expectedNestedState = 42;
object topNestedState = null;
object[] allNestedStates = null;
var logger = new LogFactory().GetCurrentClassLogger();
// Act
using (logger.PushScopeState(expectedNestedState))
{
topNestedState = ScopeContext.PeekNestedState();
allNestedStates = ScopeContext.GetAllNestedStates();
}
var failed = ScopeContext.PeekNestedState() != null;
// Assert
Assert.Equal(expectedNestedState, topNestedState);
Assert.Single(allNestedStates);
Assert.Equal(expectedNestedState, allNestedStates[0]);
Assert.False(failed);
}
public void PushPropertyCaseInsensitiveTest()
{
// Arrange
ScopeContext.Clear();
var expectedValue = "World";
Dictionary <string, object> allProperties = null;
var success = false;
object value;
// Act
using (ScopeContext.PushProperty("HELLO", expectedValue))
{
success = ScopeContext.TryGetProperty("hello", out value);
allProperties = ScopeContext.GetAllProperties().ToDictionary(x => x.Key, x => x.Value);
}
var failed = ScopeContext.TryGetProperty("hello", out var _);
// Assert
Assert.True(success);
Assert.Equal(expectedValue, value);
Assert.Single(allProperties);
Assert.Equal(expectedValue, allProperties["HELLO"]);
Assert.False(failed);
}
public void ScopeNestedTimingTest()
{
// Arrange
ScopeContext.Clear();
var logFactory = new LogFactory();
logFactory.Setup().LoadConfigurationFromXml(@"
<nlog>
<targets><target name='debug' type='Debug' layout='${ndlc}|${scopetiming:CurrentScope=false:StartTime=true:Format=yyyy-MM-dd HH\:mm\:ss}|${scopetiming:CurrentScope=false:StartTime=false:Format=fff}|${scopetiming:CurrentScope=true:StartTime=true:Format=HH\:mm\:ss.fff}|${scopetiming:CurrentScope=true:StartTime=false:Format=fffffff}|${message}' /></targets>
<rules>
<logger name='*' minlevel='Debug' writeTo='debug' />
</rules>
</nlog>");
var logger = logFactory.GetCurrentClassLogger();
var target = logFactory.Configuration.FindTargetByName <NLog.Targets.DebugTarget>("debug");
logger.Debug("0");
string messageNoScope = target.LastMessage;
string messageFirstScope;
string messageFirstScopeSleep;
string messageFirstScopeExit;
string messageSecondScope;
string messageSecondScopeSleep;
Assert.Equal("|||||0", messageNoScope);
using (logger.PushScopeState("ala"))
{
logger.Debug("a");
messageFirstScope = target.LastMessage;
System.Threading.Thread.Sleep(10);
logger.Debug("b");
messageFirstScopeSleep = target.LastMessage;
using (logger.PushScopeState("ma"))
{
logger.Debug("a");
messageSecondScope = target.LastMessage;
System.Threading.Thread.Sleep(10);
logger.Debug("b");
messageSecondScopeSleep = target.LastMessage;
}
logger.Debug("c");
messageFirstScopeExit = target.LastMessage;
}
// Assert
var measurements = messageFirstScope.Split(new[] { '|' }, System.StringSplitOptions.RemoveEmptyEntries);
Assert.Equal(6, measurements.Length);
Assert.Equal("ala", measurements[0]);
Assert.InRange(int.Parse(measurements[2]), 0, 999);
Assert.InRange(int.Parse(measurements[4]), 0, 9999999);
Assert.Equal("a", measurements[measurements.Length - 1]);
measurements = messageFirstScopeSleep.Split(new[] { '|' }, System.StringSplitOptions.RemoveEmptyEntries);
Assert.Equal("ala", measurements[0]);
Assert.InRange(int.Parse(measurements[2]), 10, 999);
Assert.InRange(int.Parse(measurements[4]), 100000, 9999999);
Assert.Equal("b", measurements[measurements.Length - 1]);
measurements = messageSecondScope.Split(new[] { '|' }, System.StringSplitOptions.RemoveEmptyEntries);
Assert.Equal(6, measurements.Length);
Assert.Equal("ala ma", measurements[0]);
Assert.InRange(int.Parse(measurements[2]), 10, 999);
Assert.InRange(int.Parse(measurements[4]), 0, 9999999);
Assert.Equal("a", measurements[measurements.Length - 1]);
measurements = messageSecondScopeSleep.Split(new[] { '|' }, System.StringSplitOptions.RemoveEmptyEntries);
Assert.Equal(6, measurements.Length);
Assert.Equal("ala ma", measurements[0]);
Assert.InRange(int.Parse(measurements[2]), 20, 999);
Assert.InRange(int.Parse(measurements[4]), 100000, 9999999);
Assert.Equal("b", measurements[measurements.Length - 1]);
measurements = messageFirstScopeExit.Split(new[] { '|' }, System.StringSplitOptions.RemoveEmptyEntries);
Assert.Equal("ala", measurements[0]);
Assert.InRange(int.Parse(measurements[2]), 20, 999);
Assert.InRange(int.Parse(measurements[4]), 200000, 9999999);
Assert.Equal("c", measurements[measurements.Length - 1]);
}
