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