public void FinalizerCausesQueuedLogsToFlush()
{
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 10ms each.
const int opDelayMs = 5;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(SetupLog, opDelayMs, false);
const int expectedEntryCount = 25;
// Run the test code in a delegate so that local variable references can be GCed
Action logTestMessages = () =>
{
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
ExampleHelper.LogTestMessages(queueEntryWriter, expectedEntryCount);
// Key point: The BackgroundMultiLogWriter is never disposed, and it has a number of queued
// entries that haven't been written
};
logTestMessages();
Assert.True(slowLogWriter.Count < expectedEntryCount);
// Force a GC cyle, and wait for finalizers to complete.
GC.Collect();
GC.WaitForPendingFinalizers();
Assert.Equal(expectedEntryCount, slowLogWriter.Count);
// When the finalizer is called, an error is logged to the SetupLog.
Assert.True(SetupLog.Any(traceEntry => (traceEntry.TraceLevel == TraceLevel.Error) && (traceEntry.Message.StartsWith("In finalizer "))));
}
public void ExceedingQueueSizeBlocksLogging()
{
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 10ms each.
const int opDelayMs = 50;
const int maxQueueLength = 10;
const int countBlockingWrites = 4;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(SetupLog, opDelayMs, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter, maxQueueLength);
var stopwatch = Stopwatch.StartNew();
using (backgroundMultiLogWriter)
{
// First 10 messages log fast, then the queue is exactly full
ExampleHelper.LogTestMessages(queueEntryWriter, maxQueueLength);
stopwatch.Stop();
_testOutputHelper.WriteLine("First {0} writes took: {1}ms", maxQueueLength, stopwatch.ElapsedMilliseconds);
Assert.True(_inDebugger || (stopwatch.ElapsedMilliseconds <= opDelayMs), "Log writing should be fast, until the queue is filled.");
// Next writes block, since we've filled the queue
for (int i = 0; i < countBlockingWrites; ++i)
{
stopwatch.Restart();
ExampleHelper.LogTestMessages(queueEntryWriter, 1);
stopwatch.Stop();
long elapsedMilliseconds = stopwatch.ElapsedMilliseconds;
_testOutputHelper.WriteLine("Blocking write #{0}: {1}ms", i, elapsedMilliseconds);
Assert.True((elapsedMilliseconds >= (opDelayMs * 0.5)) || (i == 0) || _inDebugger,
"Expect blocking until 1 element is written - elapsed: " + elapsedMilliseconds);
// This assert is not passing on hqs01 - re-check another time.
// Timing-sensitive tests are always a bit delicate
//Assert.True((i == 0) || (elapsedMilliseconds < 2 * opDelayMs) || _inDebugger, "First write may be delayed; after that blocking should only occur for the duration of writing 1 entry. i=" + i + " Elapsed: " + elapsedMilliseconds);
}
stopwatch.Restart();
}
stopwatch.Stop();
_testOutputHelper.WriteLine("Stop + dispose took {0}", stopwatch.Elapsed);
// At this point, everything should have been logged
Assert.Equal(maxQueueLength + countBlockingWrites, slowLogWriter.Count);
Assert.True(stopwatch.ElapsedMilliseconds > maxQueueLength * opDelayMs, "Dispose writes all queued entries");
// maxQueueLength+2 is the number of sleeps to wait for - the queue is full, +2 is for Stop() + Dispose() sleeps
// 2.0 is just a tolerance for thread-related delays
Assert.True((stopwatch.ElapsedMilliseconds < (maxQueueLength + 2) * opDelayMs * 2.0) || _inDebugger, "Took longer than expected: " + stopwatch.ElapsedMilliseconds);
}
public void InnerWriterExceptionsAreHandled()
{
var innerLogWriter = new ExceptionThrowingLogWriter <MessageEntry>(SetupLog);
var backgroundMultiLogWriter = new BackgroundMultiLogWriter(SetupLog);
ILogWriter logWriter = backgroundMultiLogWriter.CreateProxyFor(innerLogWriter);
IEntryWriter <MessageEntry> entryWriter;
Assert.True(logWriter.TryGetEntryWriter(out entryWriter));
using (backgroundMultiLogWriter)
{
backgroundMultiLogWriter.Start();
ExampleHelper.LogTestMessages(entryWriter, 6);
}
_testOutputHelper.WriteLine("Setup messages:");
_testOutputHelper.WriteEntries(SetupLog);
Assert.Equal(7, SetupLog.Where((traceEntry, index) => traceEntry.TraceLevel >= TraceLevel.Error).Count());
}