public void GetLinkingMetadata_IsHandled_MetadataPropertyAdded()
{
// Arrange
var wasRun = false;
var testDict = new Dictionary <string, string>
{
{ "trace.id", "trace-id" },
{ "span.id", "span-id" },
{ "entity.name", "entity-name" },
{ "entity.type", "entity-type" },
{ "entity.guid", "entity-guid" },
{ "hostname", "host-name" }
};
Mock.Arrange(() => _testAgent.GetLinkingMetadata())
.DoInstead(() => { wasRun = true; })
.Returns(testDict);
var testEnricher = new NewRelicEnricher(() => _testAgent);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(WarningLogMessage);
// Assert
Assert.That(wasRun, Is.True);
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(WarningLogMessage));
Assert.That(_outputSink.LogEvents[0].Properties, Does.ContainKey(LinkingMetadataKey));
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
}
public void GetLinkingMetadata_IsHandled_DuplicateKeyInMessageTemplate()
{
// Arrange
const string TestValue = "TEST VALUE";
const string TestTemplate = "TEMPLATE {newrelic.linkingmetadata}"; // matches our metadata property name
var wasRun = false;
var testDict = new Dictionary <string, string> {
{ "message", "duplicate" }
}; // must not be empty
Mock.Arrange(() => _testAgent.GetLinkingMetadata())
.DoInstead(() => { wasRun = true; })
.Returns(testDict);
var testEnricher = new NewRelicEnricher(() => _testAgent);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(TestTemplate, TestValue);
// Assert
Assert.That(wasRun, Is.True);
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(TestTemplate));
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
Assert.That(_outputSink.LogEvents[0].Properties, Does.ContainKey(LinkingMetadataKey));
Assert.That(_outputSink.LogEvents[0].Properties[LinkingMetadataKey].ToString(), Does.Not.Contain(TestValue));
}
public void Enricher_IsHandled_Exception()
{
// Arrange
var wasRun = false;
Mock.Arrange(() => _testAgent.GetLinkingMetadata())
.DoInstead(() =>
{
wasRun = true;
throw new Exception("Exception - GetLinkingMetadata");
});
var testEnricher = new NewRelicEnricher(() => _testAgent);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(ExceptionLogMessage);
// Assert
Assert.That(wasRun, Is.True);
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(ExceptionLogMessage));
Assert.That(_outputSink.LogEvents[0].Properties, Does.Not.ContainKey(LinkingMetadataKey));
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(1));
Assert.That(_testRunDebugLogs[0], Does.Contain("System.Exception"));
}
public void Output_Intrinsics_ThreadId()
{
const string ThreadIDKey = "ThreadID";
var testThreadIDValue = _random.Next(0, int.MaxValue);
// Arrange
var testEnricher = new TestEnricher();
var threadIdEnricher = new TestEnricher()
.WithUserPropValue(ThreadIDKey, testThreadIDValue);
var formatter = new NewRelicFormatter()
.WithPropertyMapping(ThreadIDKey, NewRelicLoggingProperty.ThreadId);
var testOutputSink = new TestSinkWithFormatter(formatter);
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher, threadIdEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
//additional 1 for threadid
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties + 1, resultDic);
Assert.That(resultDic, Contains.Key("thread.id"));
Assert.That(testOutputSink.InputsAndOutputs[0].LogEvent.Properties[ThreadIDKey].ToString(), Is.EqualTo(resultDic["thread.id"].GetString()));
}
public void IsHandled_NullValue_InNewRelicDictionary()
{
// Arrange
var testNRProperties = new Dictionary <string, string>()
{
{ StringATestKey, StringTestValue },
{ NullTestKey, null }
};
var testEnricher = new TestEnricher()
.WithUserPropValue(IntegerTestKey, IntegerTestValue)
.WithNewRelicMetadataValue(testNRProperties);
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties, resultDic);
Asserts.KeyAndValueMatch(resultDic, UserPropertyKeyPrefix + IntegerTestKey, IntegerTestValue);
Assert.That(resultDic, Does.Not.ContainKey(UserPropertyKeyPrefix + LinkingMetadataKey));
Asserts.KeyAndValueMatch(resultDic, StringATestKey, StringTestValue);
Asserts.KeyAndValueMatch(resultDic, NullTestKey, JsonValueKind.Null);
}
public void Output_ExceptionProperties_NoMessage()
{
// Arrange
var testEnricher = new TestEnricher();
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
var testException = new Exception(string.Empty);
// Act
try
{
TestHelpers.CreateStackTracedError(0, testException, 3);
}
catch (Exception ex)
{
testLogger.Error(ex, LogMessage);
}
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties + 2, resultDic);
Assert.That(resultDic, Does.Not.ContainKey("error.message"));
Asserts.KeyAndValueMatch(resultDic, "error.class", testException.GetType().FullName);
Asserts.KeyAndValueMatch(resultDic, "error.stack", testException.StackTrace);
}
public void Mapping_NonReservedProperty_MapsProperly()
{
var testNRProperties = new Dictionary <string, string>()
{
{ StringATestKey, "TestValue1" },
{ StringBTestKey, "TestValue2" }
};
var testEnricher = new TestEnricher()
.WithNewRelicMetadataValue(testNRProperties);
// Build test data and configure formatter
var expectedOutputs = new Dictionary <string, string>();
var inputValues = new Dictionary <string, int>();
var testFormatter = new NewRelicFormatter();
foreach (var prop in _newRelicPropertiesNotReserved)
{
var propName = Guid.NewGuid().ToString();
var propValue = _random.Next(int.MaxValue);
inputValues.Add(propName, propValue);
expectedOutputs.Add(LoggingExtensions.GetOutputName(prop), propValue.ToString());
testEnricher.WithUserPropValue(propName, propValue);
testFormatter.WithPropertyMapping(propName, prop);
}
var testOutputSink = new TestSinkWithFormatter(testFormatter);
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
foreach (var expectedOutput in expectedOutputs)
{
Asserts.KeyAndValueMatch(resultDic, expectedOutput.Key, expectedOutput.Value);
}
foreach (var inputVal in inputValues)
{
Assert.That(resultDic, Does.Not.ContainKey(inputVal.Key));
Assert.That(resultDic, Does.Not.ContainKey(UserPropertyKeyPrefix + inputVal.Key));
}
}
public void GetLinkingMetadata_IsHandled_NotAttachedAgent()
{
// Arrange
var testEnricher = new NewRelicEnricher();
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(WarningLogMessage);
// Assert
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(WarningLogMessage));
Assert.That(_outputSink.LogEvents[0].Properties, Does.Not.ContainKey(LinkingMetadataKey), "The agent was running and instrumented the test process.");
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
}
public void GetLinkingMetadata_IsHandled_NullAgent()
{
// Arrange
var testEnricher = new NewRelicEnricher(() => null);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(WarningLogMessage);
// Assert
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(WarningLogMessage));
Assert.That(_outputSink.LogEvents[0].Properties, Does.Not.ContainKey(LinkingMetadataKey));
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
}
public void Output_Intrinsics_LogLevel(LogEventLevel level)
{
// Arrange
var testEnricher = new TestEnricher();
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Write(level, LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties, resultDic);
Assert.That(resultDic, Contains.Key("log.level"));
Assert.That(testOutputSink.InputsAndOutputs[0].LogEvent.Level.ToString(), Is.EqualTo(resultDic["log.level"].GetString()));
}
public void Output_Intrinsics_Timestamp_AsUnixTimestamp()
{
// Arrange
var testEnricher = new TestEnricher();
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties, resultDic);
Assert.That(resultDic, Contains.Key("timestamp"));
Assert.That(testOutputSink.InputsAndOutputs[0].LogEvent.Timestamp.ToUnixTimeMilliseconds(),
Is.EqualTo(resultDic["timestamp"].GetInt64()));
}
public void Output_Intrinsics_MessageAndTemplate()
{
// Arrange
var testEnricher = new TestEnricher();
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
const string template = "We have {value1}, {value2}, and {value3}.";
testLogger.Warning(template, 1, "two", false);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, template);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties + 3, resultDic);
Asserts.KeyAndValueMatch(resultDic, "message", "We have 1, \"two\", and False.");
}
public void GetLinkingMetadata_IsHandled_EmptyDictionaryResult()
{
// Arrange
var wasRun = false;
Mock.Arrange(() => _testAgent.GetLinkingMetadata())
.DoInstead(() => { wasRun = true; })
.Returns(new Dictionary <string, string>());
var testEnricher = new NewRelicEnricher(() => _testAgent);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
// Act
testLogger.Warning(WarningLogMessage);
// Assert
Assert.That(wasRun, Is.True);
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(1));
Assert.That(_outputSink.LogEvents[0].MessageTemplate.Text, Is.EqualTo(WarningLogMessage));
Assert.That(_outputSink.LogEvents[0].Properties, Does.Not.ContainKey(LinkingMetadataKey));
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
}
public void Output_UserProperties()
{
// Arrange
var testEnricher = new TestEnricher()
.WithUserPropValue(IntegerTestKey, IntegerTestValue)
.WithUserPropValue(BooleanTestKey, BooleanTestValue)
.WithUserPropValue(NullTestKey, NullTestValue)
.WithUserPropValue(StringATestKey, StringTestValue)
.WithUserPropValue(DictionaryTestKey, new Dictionary <string, object>()
{
{ "DKeyA", "DValueA" }, { "DKeyB", 42 }
})
.WithNewRelicMetadataValue(new Dictionary <string, string>());
var testOutputSink = new TestSinkWithFormatter(new NewRelicFormatter());
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
AssertNoSerilogErrorsAndCountOutputs(_testRunDebugLogs, testOutputSink.InputsAndOutputs, LogMessage);
var resultDic = SerilogTestHelpers.DeserializeOutputJSON(testOutputSink.InputsAndOutputs[0]);
AssertThatPropertyCountsMatch(testEnricher, CountIntrinsicProperties, resultDic);
Asserts.KeyAndValueMatch(resultDic, UserPropertyKeyPrefix + IntegerTestKey, IntegerTestValue);
Asserts.KeyAndValueMatch(resultDic, UserPropertyKeyPrefix + BooleanTestKey, BooleanTestValue);
Asserts.KeyAndValueMatch(resultDic, UserPropertyKeyPrefix + NullTestKey, JsonValueKind.Null);
Asserts.KeyAndValueMatch(resultDic, UserPropertyKeyPrefix + StringATestKey, StringTestValue);
Assert.That(resultDic, Contains.Key(UserPropertyKeyPrefix + DictionaryTestKey));
Assert.That(resultDic[UserPropertyKeyPrefix + DictionaryTestKey].ValueKind, Is.EqualTo(JsonValueKind.Object));
var innerDic = JsonSerializer.Deserialize <Dictionary <string, JsonElement> >(resultDic[UserPropertyKeyPrefix + DictionaryTestKey].ToString());
Assert.That(innerDic, Contains.Key("DKeyA"));
Assert.That(innerDic["DKeyA"].GetString(), Is.EqualTo("DValueA"));
Assert.That(innerDic, Contains.Key("DKeyB"));
Assert.That(innerDic["DKeyB"].GetUInt32(), Is.EqualTo(42));
Assert.That(resultDic, Does.Not.ContainKey(UserPropertyKeyPrefix + LinkingMetadataKey));
}
public void IsHandled_Exception()
{
// Arrange
// Setup formatter to fail part-way through emitting the JSON string.
// Want to verify that a partial JSON string is not written out.
var testEnricher = new TestEnricher()
.WithUserPropValue("StartTestKey", "This is the start")
.WithUserPropValue("ErrorTestKey", TestErrMsg)
.WithUserPropValue("EndTestKey", "This is the end");
var testFormatter = new TestFormatterThatThrowException();
var testOutputSink = new TestSinkWithFormatter(testFormatter);
var testLogger = SerilogTestHelpers.GetLogger(testOutputSink, testEnricher);
// Act
testLogger.Warning(LogMessage);
// Assert
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(1));
Assert.That(testOutputSink.InputsAndOutputs.Count, Is.EqualTo(1));
Assert.That(testOutputSink.InputsAndOutputs[0].LogEvent.MessageTemplate.Text, Is.EqualTo(LogMessage));
Assert.That(testOutputSink.InputsAndOutputs[0].FormattedOutput, Is.Null);
}
public void GetLinkingMetadata_CalledOnceForEachEvent()
{
// Arrange
const string warningCountLogMessageExpected = "This is warning #";
const string warningCountLogMessage = "This is warning #{Count}";
var testEnricher = new NewRelicEnricher(() => _testAgent);
var testLogger = SerilogTestHelpers.GetLogger(_outputSink, testEnricher);
var rnd = new Random();
var countLogAttempts = rnd.Next(2, 25);
var expectedMessages = new List <string>();
// Act
for (var i = 0; i < countLogAttempts; i++)
{
expectedMessages.Add(warningCountLogMessageExpected + i.ToString());
testLogger.Warning(warningCountLogMessage, i);
}
// Assert
Assert.That(_testRunDebugLogs.Count, Is.EqualTo(0));
Mock.Assert(() => _testAgent.GetLinkingMetadata(), Occurs.Exactly(countLogAttempts));
Assert.That(_outputSink.LogEvents.Count, Is.EqualTo(countLogAttempts));
Assert.That(_outputSink.LogEvents[0].Properties, Does.Not.ContainKey(LinkingMetadataKey));
//The actual messages are what we expected.
for (var i = 0; i < _outputSink.LogEvents.Count; i++)
{
var expectedMessage = expectedMessages[i];
var sw = new StringWriter();
var logEvent = _outputSink.LogEvents[i];
logEvent.RenderMessage(sw);
var actualMessage = sw.ToString();
Assert.That(actualMessage, Is.EqualTo(expectedMessage));
}
}
