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()); }