public void LoggerCanRenderLogMessage()
{
var sink = new TestSink();
var serilogSink = new DirectSubmissionSerilogSink(sink, DirectSubmissionLogLevel.Debug);
var level = LogEventLevel.Error;
var rawText = "someValue";
GetSerilogMessageProcessor()
.Process("This is {SomeValue}", new object[] { "someValue" }, out var parsedTemplate, out var boundProperties);
var logEvent = new LogEvent(DateTimeOffset.Now, level, exception: null, parsedTemplate, boundProperties);
var proxy = logEvent.DuckCast <ILogEvent>();
serilogSink.Emit(proxy);
var log = sink.Events.Should().ContainSingle().Subject;
var sb = new StringBuilder();
var formatter = LogSettingsHelper.GetFormatter();
log.Format(sb, formatter);
var formatted = sb.ToString();
formatted.Should()
.NotBeNullOrWhiteSpace()
.And.Contain(rawText)
.And.Contain($@"This is \""{rawText}\""");
}
public async Task EmitBatchEchoesLogsApiReturnValue(bool logsApiResponse)
{
var mutex = new ManualResetEventSlim();
bool LogsSentCallback(int x)
{
mutex.Set();
return(logsApiResponse);
}
var logsApi = new TestLogsApi(LogsSentCallback);
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new TestSink(logsApi, LogSettingsHelper.GetFormatter(), options);
sink.Start();
var log = new TestLogEvent(DirectSubmissionLogLevel.Debug, "First message");
var queue = new Queue <DatadogLogEvent>();
queue.Enqueue(log);
var result = await sink.CallEmitBatch(queue);
result.Should().Be(logsApiResponse);
}
public void LoggerCanRenderLogMessage()
{
var sink = new TestSink();
var formatter = LogSettingsHelper.GetFormatter();
var logger = GetLogger(sink);
var level = (int)DirectSubmissionLogLevel.Error;
logger.IsEnabled(level).Should().BeTrue();
var state = "someValue";
var eventId = 123;
logger.Log(
logLevel: level,
eventId: eventId,
state: state,
exception: null,
(s, ex) => $"This is {s}");
var log = sink.Events.Should().ContainSingle().Subject;
var sb = new StringBuilder();
log.Format(sb, formatter);
var formatted = sb.ToString();
formatted.Should()
.NotBeNullOrWhiteSpace()
.And.Contain(state)
.And.Contain(eventId.ToString())
.And.Contain($"This is {state}");
}
public void IfCircuitBreakerBreaksThenNoApiRequestsAreSent()
{
var mutex = new ManualResetEventSlim();
int logsReceived = 0;
bool LogsSentCallback(int x)
{
Interlocked.Add(ref logsReceived, x);
mutex.Set();
return(false);
}
var logsApi = new TestLogsApi(LogsSentCallback);
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new DatadogSink(logsApi, LogSettingsHelper.GetFormatter(), options);
sink.Start();
for (var i = 0; i < BatchingSink.FailuresBeforeCircuitBreak; i++)
{
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, "A message"));
mutex.Wait(10_000).Should().BeTrue();
mutex.Reset();
}
// circuit should be broken
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, "A message"));
mutex.Wait(3_000).Should().BeFalse(); // don't expect it to be set
logsReceived.Should().Be(BatchingSink.FailuresBeforeCircuitBreak);
}
private static DirectSubmissionLogger GetLogger(TestSink sink)
{
var settings = LogSettingsHelper.GetValidSettings();
return(new DirectSubmissionLogger(
name: "TestLogger",
scopeProvider: new NullScopeProvider(),
sink: sink,
logFormatter: LogSettingsHelper.GetFormatter(),
minimumLogLevel: settings.MinimumLevel));
}
public void SerializesEventCorrectly()
{
var logEvent = GetLogEvent();
var log = logEvent.DuckCast <ILogEvent>();
var formatter = LogSettingsHelper.GetFormatter();
var sb = new StringBuilder();
SerilogLogFormatter.FormatLogEvent(formatter, sb, log);
var actual = sb.ToString();
var expected = @"{""@t"":""2021-09-13T10:40:57.0000000Z"",""@m"":""This is a test with a 123"",""@l"":""Debug"",""@x"":""System.InvalidOperationException: Oops, just a test!"",""Value"":123,""OtherProperty"":62,""@i"":""a9a87aee"",""ddsource"":""csharp"",""service"":""MyTestService"",""dd_env"":""integration_tests"",""dd_version"":""1.0.0"",""host"":""some_host""}";
actual.Should().Be(expected);
}
public void SerializesEventCorrectly()
{
var logEvent = GetLogEvent();
var formatter = LogSettingsHelper.GetFormatter();
var sb = new StringBuilder();
#if LOG4NET_2
var log = logEvent.DuckCast <ILoggingEventDuck>();
Log4NetLogFormatter.FormatLogEvent(formatter, sb, log, log.TimeStampUtc);
#else
var log = logEvent.DuckCast <ILoggingEventLegacyDuck>();
Log4NetLogFormatter.FormatLogEvent(formatter, sb, log, log.TimeStamp);
#endif
var actual = sb.ToString();
var expected = @"{""@t"":""2021-09-13T10:40:57.0000000Z"",""@m"":""This is a test with a 123"",""@l"":""Debug"",""@x"":""System.InvalidOperationException: Oops, just a test!"",""Value"":123,""@i"":""aad9c020"",""ddsource"":""csharp"",""service"":""MyTestService"",""dd_env"":""integration_tests"",""dd_version"":""1.0.0"",""host"":""some_host""}";
actual.Should().Be(expected);
}
public void SinkSendsMessageAsJsonBatch()
{
var mutex = new ManualResetEventSlim();
int logsReceived = 0;
const int expectedCount = 2;
bool LogsSentCallback(int x)
{
if (Interlocked.Add(ref logsReceived, x) == expectedCount)
{
mutex.Set();
}
return(true);
}
var logsApi = new TestLogsApi(LogsSentCallback);
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new DatadogSink(logsApi, LogSettingsHelper.GetFormatter(), options);
sink.Start();
var firstMessage = "First message";
var secondMessage = "Second message";
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, firstMessage));
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Information, secondMessage));
mutex.Wait(TimeSpan.FromSeconds(10)).Should().BeTrue();
logsApi.Logs.Should().NotBeEmpty();
var logs = logsApi.Logs
.Select(batch => Encoding.UTF8.GetString(batch.Logs.Array))
.SelectMany(batch => JsonConvert.DeserializeObject <List <TestLogEvent> >(batch))
.ToList();
logs.Should().NotBeNull();
logs.Count.Should().Be(2);
logs[0].Level.Should().Be(DirectSubmissionLogLevel.Debug);
logs[0].Message.Should().Be(firstMessage);
logs[1].Level.Should().Be(DirectSubmissionLogLevel.Information);
logs[1].Message.Should().Be(secondMessage);
}
public void CanDeserializeFormattedLogs()
{
var formatter = LogSettingsHelper.GetFormatter();
var log1 = GetLog(formatter, "This is a {Value}", DirectSubmissionLogLevel.Warning, new Dictionary <string, string> {
{ "Value", "SomeValue" }
});
var log2 = GetLog(formatter, "This is another template with some other value", DirectSubmissionLogLevel.Information, new Dictionary <string, string> {
{ "Value", "SomeOtherValue" }
});
var serialized = $"[{log1},{log2}]";
using var ms = new MemoryStream(Encoding.UTF8.GetBytes(serialized));
var logs = MockLogsIntake.Log.DeserializeFromStream(ms);
logs.Should().NotBeNull();
logs.Should().HaveCount(2);
}
public void SinkSendsMessagesToLogsApi()
{
var mutex = new ManualResetEventSlim();
var logsApi = new TestLogsApi(_ =>
{
mutex.Set();
return(true);
});
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new DatadogSink(logsApi, LogSettingsHelper.GetFormatter(), options);
sink.Start();
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, "First message"));
// Wait for the logs to be sent, should be done in 50ms
mutex.Wait(TimeSpan.FromSeconds(10)).Should().BeTrue();
logsApi.Logs.Should().ContainSingle();
}
public void SerializesEventCorrectly()
{
var formatter = LogSettingsHelper.GetFormatter();
var scopeProvider = new LoggerExternalScopeProvider();
var logger = new TestLogger(scopeProvider, formatter, new DateTime(2021, 09, 13, 10, 40, 57));
scopeProvider.Push(new Dictionary <string, object> {
{ "OtherProperty", 62 }
});
scopeProvider.Push("Some other value");
logger.Log(
LogLevel.Debug,
new InvalidOperationException("Oops, just a test!"),
"This is a test with a {Value}",
123);
var expected = @"{""@t"":""2021-09-13T10:40:57.0000000Z"",""@m"":""This is a test with a 123"",""@l"":""Debug"",""@x"":""System.InvalidOperationException: Oops, just a test!"",""Value"":123,""OtherProperty"":62,""Scopes"":[""Some other value""]""@i"":""a9a87aee"",""ddsource"":""csharp"",""service"":""MyTestService"",""host"":""some_host""}";
logger.Logs.Should().ContainSingle(expected);
}
public void LoggerIncludesPropertiesInLog()
{
var formatter = LogSettingsHelper.GetFormatter();
var memoryAppender = new MemoryAppender();
var sink = new Log4NetHelper.TestSink();
var appender = Log4NetHelper.GetAppender(sink, DirectSubmissionLogLevel.Debug);
var appenderProxy = (IAppender)appender.DuckImplement(typeof(IAppender));
var repository = log4net.LogManager.GetRepository();
BasicConfigurator.Configure(repository, memoryAppender, appenderProxy);
var logger = LogManager.GetLogger(typeof(DirectSubmissionLog4NetAppenderTests));
// Set an ambient property
var someKey = "some key";
var someValue = "some Value";
log4net.ThreadContext.Properties[someKey] = someValue;
// write the log
var message = "This is a value";
logger.Error(message);
// remove the context before rendering
log4net.ThreadContext.Properties.Remove(someKey);
var logEvent = sink.Events.Should().ContainSingle().Subject;
// get the rendered log
var sb = new StringBuilder();
logEvent.Format(sb, formatter);
var log = sb.ToString();
log.Should()
.Contain(message)
.And.Contain(someKey)
.And.Contain(someValue)
.And.Contain(DirectSubmissionLogLevelExtensions.Error);
}
public void DoesntAddPropertiesThatAreAlreadyAddedTwice()
{
var formatter = LogSettingsHelper.GetFormatter();
var scopeProvider = new LoggerExternalScopeProvider();
var logger = new TestLogger(scopeProvider, formatter, new DateTime(2021, 09, 13, 10, 40, 57));
var properties = new Dictionary <string, object>
{
{ "Host", nameof(DoesntAddPropertiesThatAreAlreadyAddedTwice) + "host" },
{ "dd_service", nameof(DoesntAddPropertiesThatAreAlreadyAddedTwice) + "service" },
{ "ddsource", nameof(DoesntAddPropertiesThatAreAlreadyAddedTwice) + "source" },
{ "ddtags", nameof(DoesntAddPropertiesThatAreAlreadyAddedTwice) + ":tag" },
};
using (scopeProvider.Push(properties))
using (scopeProvider.Push("Another value"))
{
logger.Log(
LogLevel.Debug,
new InvalidOperationException("Oops, just a test!"),
"This is a test with a {Value} and a {Host}",
123,
"some host");
}
var log = logger.Logs.Should().ContainSingle().Subject;
var json = JObject.Parse(log);
// should have all the added properties
foreach (var property in properties)
{
json.Properties()
.Where(x => string.Equals(property.Key, x.Name, StringComparison.OrdinalIgnoreCase))
.Should()
.ContainSingle()
.Which.Value.ToString()
.Should()
.Be(property.Value.ToString());
}
}
public void SinkSendsMultipleBatches()
{
var mutex = new ManualResetEventSlim();
int logsReceived = 0;
const int expectedCount = 5;
bool LogsSentCallback(int x)
{
if (Interlocked.Add(ref logsReceived, x) == expectedCount)
{
mutex.Set();
}
return(true);
}
var logsApi = new TestLogsApi(LogsSentCallback);
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new DatadogSink(logsApi, LogSettingsHelper.GetFormatter(), options);
sink.Start();
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, "First message"));
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Information, "Second message"));
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Information, "Third message"));
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Information, "Fourth message"));
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Information, "Fifth message"));
mutex.Wait(TimeSpan.FromSeconds(10)).Should().BeTrue();
logsApi.Logs.Should().HaveCountGreaterOrEqualTo(3); // batch size is 2, so at least 3 batches
var logs = logsApi.Logs
.Select(batch => Encoding.UTF8.GetString(batch.Logs.Array))
.SelectMany(batch => JsonConvert.DeserializeObject <List <TestLogEvent> >(batch))
.ToList();
logs.Count.Should().Be(5);
logs.Select(x => x.Message).Should().OnlyHaveUniqueItems();
}
public void ShouldNotEmitLogWhenNotEnabled()
{
var sink = new TestSink();
var formatter = LogSettingsHelper.GetFormatter();
var logger = new DirectSubmissionLogger(
name: "TestLogger",
scopeProvider: new NullScopeProvider(),
sink: sink,
logFormatter: formatter,
minimumLogLevel: DirectSubmissionLogLevel.Information);
var level = (int)DirectSubmissionLogLevel.Debug;
logger.IsEnabled(level).Should().BeFalse();
logger.Log(
logLevel: level,
eventId: 123,
state: "someValue",
exception: null,
(s, ex) => $"This is {s}");
sink.Events.Should().BeEmpty();
}
public void SerializesEventCorrectlyWhenUsingFallbackProperties()
{
var logEvent = GetLogEvent();
var log = NLogHelper.GetLogEventProxy(logEvent);
var fallback = new Dictionary <object, object>
{
{ "Value", 123 },
{ "OtherProperty", 62 },
};
var wrapper = new LogEntry(log, properties: null, fallback);
var formatter = LogSettingsHelper.GetFormatter();
var sb = new StringBuilder();
NLogLogFormatter.FormatLogEvent(formatter, sb, wrapper);
var actual = sb.ToString();
var expected = @"{""@t"":""2021-09-13T10:40:57.0000000Z"",""@m"":""This is a test with a 123"",""@l"":""Debug"",""@x"":""System.InvalidOperationException: Oops, just a test!"",""Value"":123,""OtherProperty"":62,""@i"":""e5450052"",""ddsource"":""csharp"",""service"":""MyTestService"",""dd_env"":""integration_tests"",""dd_version"":""1.0.0"",""host"":""some_host""}";
actual.Should().Be(expected);
}
public void SinkRejectsGiantMessages()
{
var mutex = new ManualResetEventSlim();
var logsApi = new TestLogsApi();
var options = new BatchingSinkOptions(batchSizeLimit: 2, queueLimit: DefaultQueueLimit, period: TinyWait);
var sink = new DatadogSink(
logsApi,
LogSettingsHelper.GetFormatter(),
options,
oversizeLogCallback: _ => mutex.Set(),
sinkDisabledCallback: () => { });
sink.Start();
var message = new StringBuilder().Append('x', repeatCount: 1024 * 1024).ToString();
sink.EnqueueLog(new TestLogEvent(DirectSubmissionLogLevel.Debug, message));
// Wait for the logs to be sent, should be done in 50ms
mutex.Wait(TimeSpan.FromSeconds(10)).Should().BeTrue();
logsApi.Logs.Should().BeEmpty();
}
public void LoggerIncludesPropertiesInLog()
{
var formatter = LogSettingsHelper.GetFormatter();
var sink = new NLogHelper.TestSink();
var target = NLogHelper.CreateTarget(sink, DirectSubmissionLogLevel.Debug);
var targetProxy = NLogCommon <LoggingConfiguration> .CreateNLogTargetProxy(target);
var config = new LoggingConfiguration();
NLogHelper.AddTargetToConfig(config, targetProxy);
var logFactory = new LogFactory(config);
var logger = logFactory.GetLogger(nameof(LoggerIncludesPropertiesInLog));
// We don't currently record NDC/NDLC
#if NLOG_45
var messageTemplate = "This is a message with {Value}";
#else
var messageTemplate = "This is a message with {0}";
#endif
var mdcKey = "some mdcKey";
var mdcValue = "some mdcValue";
#if !NLOG_2
var mdclKey = "some mdclKey";
var mdclValue = "some mdclValue";
#endif
// var nestedScope = "some nested name";
// var nestedDictionary = new Dictionary<string, object> { { "nlcKey", 657 } };
// var dictValues = nestedDictionary.First();
try
{
MappedDiagnosticsContext.Set(mdcKey, mdcValue);
#if !NLOG_2
MappedDiagnosticsLogicalContext.Set(mdclKey, mdclValue);
#endif
logger.Error(messageTemplate, 123);
}
finally
{
MappedDiagnosticsContext.Remove(mdcKey);
#if !NLOG_2
MappedDiagnosticsLogicalContext.Remove(mdclKey);
#endif
}
var logEvent = sink.Events.Should().ContainSingle().Subject;
// get the rendered log
var sb = new StringBuilder();
logEvent.Format(sb, formatter);
var log = sb.ToString();
log.Should()
.Contain("This is a message with 123")
.And.Contain(mdcKey)
.And.Contain(mdcValue)
#if !NLOG_2
.And.Contain(mdclKey)
.And.Contain(mdclValue)
#endif
// .And.Contain(nestedScope)
// .And.Contain(dictValues.Key)
// .And.Contain(dictValues.Value.ToString())
.And.Contain(DirectSubmissionLogLevelExtensions.Error);
}
public ILoggerDuckTypingTests()
{
_sink = new NullDatadogSink();
_formatter = LogSettingsHelper.GetFormatter();
_iloggerProviderType = LoggerFactoryIntegrationCommon <ILoggerProvider> .ProviderInterfaces;
}
public void CanSetProviderUsingHelper()
{
var factory = new LoggerFactory();
var loggerProvider = new DirectSubmissionLoggerProvider(new NullDatadogSink(), LogSettingsHelper.GetFormatter(), DirectSubmissionLogLevel.Debug);
LoggerFactoryIntegrationCommon <LoggerFactory> .AddDirectSubmissionLoggerProvider(factory, loggerProvider);
}
public void CanDuckTypeExternalScopeProviderAndUseWithProxyProvider()
{
var scopeProvider = new LoggerExternalScopeProvider();
var loggerProvider = new DirectSubmissionLoggerProvider(new NullDatadogSink(), LogSettingsHelper.GetFormatter(), DirectSubmissionLogLevel.Debug);
var proxyProvider = (ISupportExternalScope)loggerProvider.DuckImplement(_iloggerProviderType);
proxyProvider.SetScopeProvider(scopeProvider);
var logger = loggerProvider.CreateLogger("Test logger name");
using var scope = logger.BeginScope(123);
scope.Should().NotBeNull();
logger.IsEnabled(3).Should().BeTrue();
logger.Log(logLevel: 3, 12, state: 123, null, (state, ex) => $"This is my message with a {state}");
}
