public void QueueHangfire_Logging()
{
var hangFireLogger = new HangfireLogProvider(TestLoggerFactory);
var sourceContext = "QueueHangfireUnitTests";
var logger = hangFireLogger.GetLogger(sourceContext);
var testString = "Test: QueueHangfire_Logging";
using (TestCorrelator.CreateContext())
{
logger.Log(LogLevel.Debug, () => testString);
TestCorrelator.GetLogEventsFromCurrentContext()
.Should().ContainSingle()
.Which.Properties["State"].ToString()
.Should().Be(testString.ToDoubleQuoted());
TestCorrelator.GetLogEventsFromCurrentContext()
.Should().ContainSingle()
.Which.Properties["SourceContext"].ToString()
.Should().Be(sourceContext.ToDoubleQuoted());
}
}
public async Task Should_create_log_scope()
{
using (TestCorrelator.CreateContext())
{
_logger.LogInformation("Start message without correlation id.");
// Act
await _sut.CorrelateAsync(() =>
{
_logger.LogInformation("Message with correlation id.");
return(Task.CompletedTask);
});
_logger.LogInformation("End message without correlation id.");
// Assert
List <LogEvent> logEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
logEvents.Should()
.HaveCount(3)
.And.ContainSingle(ev => ev.MessageTemplate.Text == "Message with correlation id." && ev.Properties.ContainsKey("CorrelationId"));
}
}
public void XunitSink_Create_TestCorrelator()
{
var fileSystem = new FileSystem(typeof(XunitSinkUnitTests));
var loggerSettings =
new SerilogLoggerSettings(fileSystem, LogEventLevel.Debug, LoggingOutputFlags.TestCorrelator);
var loggerConfiguration = XunitLoggingSink.CreateXUnitLoggerConfiguration(_testOutputHelper, loggerSettings,
XUnitSerilogFormatter.RenderedCompactJsonFormatter);
var loggerFactory = XunitLoggingSink.CreateXUnitSerilogFactory(loggerSettings, loggerConfiguration);
var logger = loggerFactory.CreatePureLogger <XunitSinkUnitTests>();
logger.Should().NotBeNull("CreatePureLogger should always succeed");
using (TestCorrelator.CreateContext())
{
logger.LogInformation("Test: XunitSink_Create_TestCorrelator");
TestCorrelator.GetLogEventsFromCurrentContext()
.Should().ContainSingle()
.Which.MessageTemplate.Text
.Should().Be("Test: XunitSink_Create_TestCorrelator");
}
}
public async Task Run_ThrowsOnReportingRepositoryException()
{
// Arrange
SetupRepositoryMethods();
var expectedException = new ApplicationException("Connection was unsuccessful");
// Override migration with an exception
_externalStoredProcedureRepository
.Setup(r => r.ExecuteReportingGenerateStoredProcedure())
.Throws(expectedException);
Log.Logger = new LoggerConfiguration().WriteTo.TestCorrelator().CreateLogger();
using (TestCorrelator.CreateContext())
{
// Act
var actualException = await Assert.ThrowsAsync<ApplicationException>(async () =>
await _reportingDataRefreshJob.Run(null));
// Assert
Assert.Equal(expectedException, actualException);
AssertRepositoryMethodsCalled();
var logEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
AssertContainsInfoMessages(logEvents, new[]
{
"Starting specimen-matching uspGenerate", "Starting migration uspGenerate", "Starting reporting uspGenerate"
});
Assert.Contains(logEvents,
logEvent => logEvent.Level == LogEventLevel.Error
&& logEvent.RenderMessage() == "Error occured during reporting data refresh job"
&& logEvent.Exception == expectedException);
AssertDoesNotContainInfoMessages(logEvents, new[]
{
"Finishing reporting data refresh job"
});
}
}
public void Getting_LogEvents_preserves_the_order_in_which_they_were_emitted()
{
var logEvents =
Enumerable.Range(0, 100)
.Select(_ =>
new LogEvent(
DateTimeOffset.MinValue,
LogEventLevel.Information,
null,
new MessageTemplate(Enumerable.Empty <MessageTemplateToken>()),
Enumerable.Empty <LogEventProperty>()))
.ToList();
using (var context = TestCorrelator.CreateContext())
{
foreach (var logEvent in logEvents)
{
Log.Write(logEvent);
}
TestCorrelator.GetLogEventsFromCurrentContext().Should().Equal(logEvents);
}
}
public async Task Invoke_logs_as_expected()
{
var logger = new LoggerConfiguration()
.WriteTo.TestCorrelator()
.CreateLogger();
var mw = new RequestLoggingMiddleware((innerHttpContext) => Task.FromResult(0), Helpers.MockIAppSettings(), logger);
var context = TestContext();
using (TestCorrelator.CreateContext())
{
await mw.InvokeAsync(context);
var logEvent = TestCorrelator.GetLogEventsFromCurrentContext().FirstOrDefault();
using var scope = new AssertionScope();
logEvent.Should().NotBeNull();
Assert.AreEqual(RequestLoggingMiddleware.DBG_LOG_TEMPLATE, logEvent.MessageTemplate.Text);
logEvent.Level.Should().Be(LogEventLevel.Information);
}
}
public async Task Run_LogsInfo_WhenFieldReducedByVerySmallAmount(int currentCount, int previousCount)
{
// Arrange
var tableCounts = new[] { CreateBasicTableCounts(currentCount), CreateBasicTableCounts(previousCount) };
_tableCountsRepository
.Setup(r => r.GetRecentTableCounts())
.Returns(Task.FromResult(tableCounts.AsEnumerable()));
Log.Logger = new LoggerConfiguration().WriteTo.TestCorrelator().CreateLogger();
using (TestCorrelator.CreateContext())
{
// Act
await _updateTableCountsJob.Run(null);
// Assert
var logEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
Assert.DoesNotContain(logEvents, logEvent => logEvent.Level > LogEventLevel.Information);
Assert.Contains(logEvents, logEvent => logEvent.Level == LogEventLevel.Information &&
logEvent.RenderMessage() == "Table counts look normal");
}
}
public void When_A_Request_Logger_Is_In_The_Pipeline()
{
Log.Logger = new LoggerConfiguration().MinimumLevel.Information().WriteTo.TestCorrelator().CreateLogger();
using (var context = TestCorrelator.CreateContext())
{
var myCommand = new MyCommand();
var registry = new SubscriberRegistry();
registry.Register <MyCommand, IHandleRequests <MyCommand> >();
var container = new ServiceCollection();
var requestLogger = new RequestLoggingHandler <MyCommand>();
container.AddTransient <IHandleRequests <MyCommand>, MyLoggedHandler>();
container.AddTransient(typeof(RequestLoggingHandler <MyCommand>), provider => requestLogger);
var handlerFactory = new ServiceProviderHandlerFactory(container.BuildServiceProvider());
var commandProcessor = new CommandProcessor(registry, handlerFactory, handlerFactory,
new InMemoryRequestContextFactory(), new PolicyRegistry());
commandProcessor.Send(myCommand);
//_should_log_the_request_handler_call
//_should_log_the_type_of_handler_in_the_call
//TestCorrelator.GetLogEventsFromCurrentContext().Should().HaveCount(3);
TestCorrelator.GetLogEventsFromContextGuid(context.Guid)
.Should().Contain(x => x.MessageTemplate.Text.StartsWith("Logging handler pipeline call"))
.Which.Properties["1"].ToString().Should().Be($"\"{typeof(MyCommand)}\"");
commandProcessor?.Dispose();
}
}
public async Task Run_ThrowsOnSpecimenMatchingStoredProcedureMessage()
{
// Arrange
List<dynamic> sqlResult = new List<object> { new { ErrorMessage = "Divide by zero error encountered." } };
const string serialisedResult = "[{\"ErrorMessage\":\"Divide by zero error encountered.\"}]";
SetupRepositoryMethods(specimenMatchingReturnResult: sqlResult.AsEnumerable());
Log.Logger = new LoggerConfiguration().WriteTo.TestCorrelator().CreateLogger();
using (TestCorrelator.CreateContext())
{
// Act
var exception = await Assert.ThrowsAsync<ApplicationException>(async () =>
await _reportingDataRefreshJob.Run(null));
// Assert
Assert.Equal("Stored procedure did not execute successfully as result has messages, check the logs",
exception.Message);
AssertRepositoryMethodsCalled(reportingCalled: false);
var logEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
AssertContainsInfoMessages(logEvents, new[]
{
"Starting migration uspGenerate",
"Starting specimen-matching uspGenerate",
$"Result: {serialisedResult}"
});
Assert.Contains(logEvents,
logEvent => logEvent.Level == LogEventLevel.Error
&& logEvent.RenderMessage() == "Error occured during reporting data refresh job");
AssertDoesNotContainInfoMessages(logEvents, new[]
{
"Starting reporting uspGenerate", "Finishing reporting data refresh job"
});
}
}
static int Main(string[] args)
{
InitLogger();
Test.Module("Nancy.Serilog.Core Tests");
Test.CaseAsync("Serilog emits correlated log events when with same logger being passed down to dependencies", async() =>
{
using (TestCorrelator.CreateContext())
{
var browser = new Browser(new Bootstrapper());
var result = await browser.Get("/");
var eventLogs = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
Test.Equal(5, eventLogs.Count());
Test.Equal(true, eventLogs.All(log => log.Level == LogEventLevel.Information));
var firstRequestId = eventLogs.First().Properties.AsEnumerable().First(log => log.Key == "RequestId").Value.ToString();
Test.Equal(false, String.IsNullOrWhiteSpace(firstRequestId));
var allRequestIds = eventLogs.Select(log =>
{
return(log.Properties
.ToList()
.First(prop => prop.Key == "RequestId")
.Value
.ToString());
});
Test.Equal(true, allRequestIds.All(requestId => requestId == firstRequestId));
}
});
return(Test.Report());
}
public void Log_each_incoming_request_and_each_outgoing_response()
{
using (TestCorrelator.CreateContext())
{
AppFunc pipelineFunc(AppFunc next) => RequestLogging.Middleware(next, m_Logger);
var ctx = SetupOwinTestEnvironment("/test");
var pipeline = pipelineFunc(m_NoOp);
var env = ctx.Environment;
pipeline(env);
var msgs = TestCorrelator.GetLogEventsFromCurrentContext();
msgs.Should().NotBeEmpty().And.HaveCount(2);
var reqLogMsg = msgs.First();
reqLogMsg.Level.Should().Be(LogEventLevel.Information);
reqLogMsg.RenderMessage().Should().Be("Incoming request: \"GET\", PathString { Value: \"/test\", HasValue: True }, []");
var resLogMsg = msgs.Last();
resLogMsg.Level.Should().Be(LogEventLevel.Information);
resLogMsg.RenderMessage().Should().Be("Outgoing response: 200, []");
}
}
public void PureSeriLogger_PushLogProperties_LogPropertyList_Include_False()
{
const string testProperty = "Property";
const string testValue = "Value";
const string testLogMsg = "Test Message";
var logPropertyList = new List <IPureLogPropertyLevel>()
{
new PureLogPropertyLevel(new KeyValuePair <string, object>(testProperty, testValue), LogLevel.Debug)
};
using (TestCorrelator.CreateContext())
using (_pureSeriLogger.PushLogProperties(logPropertyList, IncludeLogPropertyFalse))
{
_pureSeriLogger.LogDebug(testLogMsg);
var currentTestContext = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
currentTestContext.Should().ContainSingle().Which.Properties.ContainsKey(testProperty).Should().BeFalse();
currentTestContext.Should().ContainSingle().Which.MessageTemplate.Text.Should().Be(testLogMsg);
}
}
public void PureSeriLogger_PushLogProperties_KeyValue_LogPropertyList()
{
const string testProperty = "Property";
const string testValue = "Value";
const string testLogMsg = "Test Message";
var logPropertyList = new List <KeyValuePair <string, object> >()
{
new KeyValuePair <string, object>(testProperty, testValue)
};
using (TestCorrelator.CreateContext())
using (_pureSeriLogger.PushLogProperties(logPropertyList))
{
_pureSeriLogger.LogDebug(testLogMsg);
var currentTestContext = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
currentTestContext.Should().ContainSingle().Which.Properties.ContainsKey(testProperty).Should().BeTrue();
currentTestContext.Should().ContainSingle().Which.Properties[testProperty].ToString().Should().Be(testValue.ToDoubleQuoted());
currentTestContext.Should().ContainSingle().Which.MessageTemplate.Text.Should().Be(testLogMsg);
}
}
public async Task Run_LogsInfo_WhenNotEnoughRecords(int numberOfRecords)
{
// Arrange
_tableCountsRepository
.Setup(r => r.GetRecentTableCounts())
.Returns(Task.FromResult(Enumerable.Repeat(CreateBasicTableCounts(), numberOfRecords)));
Log.Logger = new LoggerConfiguration().WriteTo.TestCorrelator().CreateLogger();
using (TestCorrelator.CreateContext())
{
// Act
await _updateTableCountsJob.Run(null);
const string expectedMessage =
"Not enough table counts available. Try re-running the update-table-counts job.";
// Assert
var logEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
Assert.DoesNotContain(logEvents, logEvent => logEvent.Level > LogEventLevel.Information);
Assert.Contains(logEvents, logEvent => logEvent.Level == LogEventLevel.Information &&
logEvent.RenderMessage() == expectedMessage);
}
}
private void RoundTripTest <T>(T obj)
{
using (TestCorrelator.CreateContext())
{
Log.Information("This is a test message {@Obj}", obj);
var loggedEvents = TestCorrelator.GetLogEventsFromCurrentContext().ToList();
loggedEvents.Should().ContainSingle();
var writer = new StringWriter();
new CompactJsonFormatter().Format(loggedEvents.Single(), writer);
var reader = new StringReader(writer.ToString());
using var jsonReader = new LogEventReader(reader);
jsonReader.TryRead(out var deserialisedEvent);
string objJson = deserialisedEvent.Properties["Obj"].ToString();
var deserialisedObj = JsonConvert.DeserializeObject <T>(objJson, _jsonSerializerSettings !);
deserialisedObj.Should().BeEquivalentTo(obj, "of round trip");
}
}
private void ResetContext()
{
_context.Dispose();
_context = TestCorrelator.CreateContext();
}
