public void AsyncTargetWrapperExceptionTest()
{
var targetWrapper = new AsyncTargetWrapper
{
OverflowAction = AsyncTargetWrapperOverflowAction.Grow,
TimeToSleepBetweenBatches = 500,
WrappedTarget = new DebugTarget(),
};
targetWrapper.Initialize(null);
// null out wrapped target - will cause exception on the timer thread
targetWrapper.WrappedTarget = null;
string internalLog = RunAndCaptureInternalLog(
() =>
{
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(ex => { }));
Thread.Sleep(1000);
},
LogLevel.Trace);
targetWrapper.Close();
Assert.True(internalLog.StartsWith("Error Error in lazy writer timer procedure: System.NullReferenceException", StringComparison.Ordinal), internalLog);
}
public void AsyncTargetWrapperExceptionTest()
{
var targetWrapper = new AsyncTargetWrapper
{
OverflowAction = AsyncTargetWrapperOverflowAction.Grow,
TimeToSleepBetweenBatches = 500,
WrappedTarget = new DebugTarget(),
Name = "AsyncTargetWrapperExceptionTest_Wrapper"
};
using (new NoThrowNLogExceptions())
{
targetWrapper.Initialize(null);
// null out wrapped target - will cause exception on the timer thread
targetWrapper.WrappedTarget = null;
string internalLog = RunAndCaptureInternalLog(
() =>
{
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(ex => { }));
targetWrapper.Close();
},
LogLevel.Trace);
Assert.True(internalLog.Contains("WrappedTarget is NULL"), internalLog);
}
}
public void NoEmptyEventLists()
{
var configuration = new LoggingConfiguration();
var target = new MyLogReceiverWebServiceTarget();
target.EndpointAddress = "http://notimportant:9999/";
target.Initialize(configuration);
var asyncTarget = new AsyncTargetWrapper(target)
{
Name = "NoEmptyEventLists_wrapper"
};
try
{
asyncTarget.Initialize(configuration);
asyncTarget.WriteAsyncLogEvents(new[] { LogEventInfo.Create(LogLevel.Info, "logger1", "message1").WithContinuation(ex => { }) });
Thread.Sleep(1000);
Assert.Equal(1, target.SendCount);
}
finally
{
asyncTarget.Close();
target.Close();
}
}
public void AsyncTargetWrapperCloseTest()
{
var myTarget = new MyAsyncTarget
{
ThrowExceptions = true,
};
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
OverflowAction = AsyncTargetWrapperOverflowAction.Grow,
TimeToSleepBetweenBatches = 1000,
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
bool continuationHit = false;
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(ex => { continuationHit = true; }));
// quickly close the target before the timer elapses
targetWrapper.Close();
// continuation will not be hit because the thread is down.
Thread.Sleep(1000);
Assert.IsFalse(continuationHit);
}
public void AsyncTargetWrapperAsyncWithExceptionTest1()
{
var myTarget = new MyAsyncTarget
{
ThrowExceptions = true,
};
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
Name = "AsyncTargetWrapperAsyncWithExceptionTest1_Wrapper"
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
var logEvent = new LogEventInfo();
Exception lastException = null;
var continuationHit = new ManualResetEvent(false);
AsyncContinuation continuation =
ex =>
{
lastException = ex;
continuationHit.Set();
};
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
Assert.True(continuationHit.WaitOne(5000));
Assert.NotNull(lastException);
Assert.IsType <InvalidOperationException>(lastException);
// no flush on exception
Assert.Equal(0, myTarget.FlushCount);
Assert.Equal(1, myTarget.WriteCount);
continuationHit.Reset();
lastException = null;
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
Assert.True(continuationHit.WaitOne(5000));
Assert.NotNull(lastException);
Assert.IsType <InvalidOperationException>(lastException);
Assert.Equal(0, myTarget.FlushCount);
Assert.Equal(2, myTarget.WriteCount);
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
public void RetryingTargetWrapperBlockingCloseTest()
{
RetryingIntegrationTest(3, () =>
{
var target = new MyTarget()
{
ThrowExceptions = 5,
};
var wrapper = new RetryingTargetWrapper()
{
WrappedTarget = target,
RetryCount = 10,
RetryDelayMilliseconds = 5000,
};
var asyncWrapper = new AsyncTargetWrapper(wrapper)
{
TimeToSleepBetweenBatches = 1
};
asyncWrapper.Initialize(null);
wrapper.Initialize(null);
target.Initialize(null);
var exceptions = new List <Exception>();
var events = new[]
{
new LogEventInfo(LogLevel.Debug, "Logger1", "Hello").WithContinuation(exceptions.Add),
new LogEventInfo(LogLevel.Info, "Logger1", "Hello").WithContinuation(exceptions.Add),
new LogEventInfo(LogLevel.Info, "Logger2", "Hello").WithContinuation(exceptions.Add),
};
// Attempt to write LogEvents that will take forever to retry
asyncWrapper.WriteAsyncLogEvents(events);
// Wait a little for the AsyncWrapper to start writing
System.Threading.Thread.Sleep(50);
// Close down the AsyncWrapper while busy writing
asyncWrapper.Close();
// Close down the RetryingWrapper while busy retrying
wrapper.Close();
// Close down the actual target while busy writing
target.Close();
// Wait a little for the RetryingWrapper to detect that it has been closed down
System.Threading.Thread.Sleep(200);
// The premature abort, causes the exception to be logged
Assert.NotNull(exceptions[0]);
});
}
public void AsyncTargetWrapperSyncTest1()
{
var myTarget = new MyTarget();
var targetWrapper = new AsyncTargetWrapper
{
WrappedTarget = myTarget,
Name = "AsyncTargetWrapperSyncTest1_Wrapper",
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
var logEvent = new LogEventInfo();
Exception lastException = null;
ManualResetEvent continuationHit = new ManualResetEvent(false);
Thread continuationThread = null;
AsyncContinuation continuation =
ex =>
{
lastException = ex;
continuationThread = Thread.CurrentThread;
continuationHit.Set();
};
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
// continuation was not hit
Assert.True(continuationHit.WaitOne(5000));
Assert.NotSame(continuationThread, Thread.CurrentThread);
Assert.Null(lastException);
Assert.Equal(1, myTarget.WriteCount);
continuationHit.Reset();
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
Assert.True(continuationHit.WaitOne(5000));
Assert.NotSame(continuationThread, Thread.CurrentThread);
Assert.Null(lastException);
Assert.Equal(2, myTarget.WriteCount);
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
private void EnqueuQueueBlock_OnClose_ReleasesWriters(bool forceLockingQueue)
{
// Setup
var slowTarget = new MethodCallTarget("slowTarget", (logEvent, parms) => System.Threading.Thread.Sleep(300));
var targetWrapper = new AsyncTargetWrapper("asynSlowTarget", slowTarget)
{
OverflowAction = AsyncTargetWrapperOverflowAction.Block,
QueueLimit = 3,
ForceLockingQueue = forceLockingQueue,
};
var logFactory = new LogFactory();
var loggingConfig = new NLog.Config.LoggingConfiguration(logFactory);
loggingConfig.AddRuleForAllLevels(targetWrapper);
logFactory.Configuration = loggingConfig;
var logger = logFactory.GetLogger("Test");
// Act
long allTasksCompleted = 0;
AsyncHelpers.ForEachItemInParallel(System.Linq.Enumerable.Range(1, 6), (ex) => Interlocked.Exchange(ref allTasksCompleted, 1), (value, cont) => { for (int i = 0; i < 100; ++i)
{
logger.Info("Hello {0}", value);
}
cont(null); });
Thread.Sleep(150); // Let them get stuck
Assert.Equal(0, Interlocked.Read(ref allTasksCompleted));
targetWrapper.Close(); // Release those who are stuck, and discard the rest
// Assert
for (int i = 0; i < 100; i++)
{
if (Interlocked.Read(ref allTasksCompleted) == 1)
{
break;
}
Thread.Sleep(10);
}
Assert.Equal(1, Interlocked.Read(ref allTasksCompleted));
}
public void AsyncTargetWrapperCloseTest()
{
var myTarget = new MyAsyncTarget
{
ThrowExceptions = true,
};
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
OverflowAction = AsyncTargetWrapperOverflowAction.Grow,
TimeToSleepBetweenBatches = 1000,
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(ex => { }));
// quickly close the target before the timer elapses
targetWrapper.Close();
}
public void FlushingMultipleTimesSimultaneous()
{
var asyncTarget = new AsyncTargetWrapper
{
TimeToSleepBetweenBatches = 1000,
WrappedTarget = new DebugTarget(),
Name = "FlushingMultipleTimesSimultaneous_Wrapper"
};
asyncTarget.Initialize(null);
try
{
asyncTarget.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(ex => { }));
var firstContinuationCalled = false;
var secondContinuationCalled = false;
var firstContinuationResetEvent = new ManualResetEvent(false);
var secondContinuationResetEvent = new ManualResetEvent(false);
asyncTarget.Flush(ex =>
{
firstContinuationCalled = true;
firstContinuationResetEvent.Set();
});
asyncTarget.Flush(ex =>
{
secondContinuationCalled = true;
secondContinuationResetEvent.Set();
});
Assert.True(firstContinuationResetEvent.WaitOne(5000), nameof(firstContinuationResetEvent));
Assert.True(secondContinuationResetEvent.WaitOne(5000), nameof(secondContinuationResetEvent));
Assert.True(firstContinuationCalled);
Assert.True(secondContinuationCalled);
}
finally
{
asyncTarget.Close();
}
}
public void AsyncTargetWrapperAsyncTest1()
{
var myTarget = new MyAsyncTarget();
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
Name = "AsyncTargetWrapperAsyncTest1_Wrapper"
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
var logEvent = new LogEventInfo();
Exception lastException = null;
var continuationHit = new ManualResetEvent(false);
AsyncContinuation continuation =
ex =>
{
lastException = ex;
continuationHit.Set();
};
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
Assert.True(continuationHit.WaitOne(5000));
Assert.Null(lastException);
Assert.Equal(1, myTarget.WriteCount);
continuationHit.Reset();
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(continuation));
Assert.True(continuationHit.WaitOne(5000));
Assert.Null(lastException);
Assert.Equal(2, myTarget.WriteCount);
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
/// <summary>
/// Test Fix for https://github.com/NLog/NLog/issues/1069
/// </summary>
private void AsyncTargetWrapperSyncTest_WhenTimeToSleepBetweenBatchesIsEqualToZero(bool forceLockingQueue)
{
LogManager.ThrowConfigExceptions = true;
var myTarget = new MyTarget();
var targetWrapper = new AsyncTargetWrapper()
{
WrappedTarget = myTarget,
TimeToSleepBetweenBatches = 0,
#if NET4_5
ForceLockingQueue = forceLockingQueue,
OptimizeBufferReuse = !forceLockingQueue,
#endif
BatchSize = 3,
QueueLimit = 5, // Will make it "sleep" between every second write
FullBatchSizeWriteLimit = 1,
OverflowAction = AsyncTargetWrapperOverflowAction.Block
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
int flushCounter = 0;
AsyncContinuation flushHandler = (ex) => { ++flushCounter; };
var itemPrepareList = new List <AsyncLogEventInfo>(500);
var itemWrittenList = new List <int>(itemPrepareList.Capacity);
for (int i = 0; i < itemPrepareList.Capacity; ++i)
{
var logEvent = new LogEventInfo();
int sequenceID = logEvent.SequenceID;
bool blockConsumer = (itemPrepareList.Capacity / 2) == i; // Force producers to get into blocking-mode
itemPrepareList.Add(logEvent.WithContinuation((ex) => { if (blockConsumer)
{
Thread.Sleep(125);
}
itemWrittenList.Add(sequenceID); }));
}
var eventProducer0 = new ManualResetEvent(false);
var eventProducer1 = new ManualResetEvent(false);
ParameterizedThreadStart producerMethod = (s) =>
{
var eventProducer = (ManualResetEvent)s;
if (eventProducer != null)
{
eventProducer.Set(); // Signal we are ready
}
int partitionNo = ReferenceEquals(eventProducer, eventProducer1) ? 1 : 0;
for (int i = 0; i < itemPrepareList.Count; ++i)
{
if (i % 2 == partitionNo)
{
targetWrapper.WriteAsyncLogEvent(itemPrepareList[i]);
}
}
};
Thread producer0 = new Thread(producerMethod);
producer0.IsBackground = true;
Thread producer1 = new Thread(producerMethod);
producer1.IsBackground = true;
producer1.Start(eventProducer0);
producer0.Start(eventProducer1);
Assert.True(eventProducer0.WaitOne(5000), "Producer0 Start Timeout");
Assert.True(eventProducer1.WaitOne(5000), "Producer1 Start Timeout");
long startTicks = Environment.TickCount;
Assert.True(producer0.Join(5000), "Producer0 Complete Timeout"); // Wait for producer0 to complete
Assert.True(producer1.Join(5000), "Producer1 Complete Timeout"); // Wait for producer1 to complete
long elapsedMilliseconds = Environment.TickCount - startTicks;
targetWrapper.Flush(flushHandler);
for (int i = 0; i < itemPrepareList.Count * 2 && itemWrittenList.Count != itemPrepareList.Count; ++i)
{
Thread.Sleep(1);
}
Assert.Equal(itemPrepareList.Count, itemWrittenList.Count);
int producer0sequenceID = 0;
int producer1sequenceID = 0;
for (int i = 1; i < itemWrittenList.Count; ++i)
{
if (itemWrittenList[i] % 2 == 0)
{
Assert.True(producer0sequenceID < itemWrittenList[i], "Producer0 invalid sequence");
producer0sequenceID = itemWrittenList[i];
}
else
{
Assert.True(producer1sequenceID < itemWrittenList[i], "Producer1 invalid sequence");
producer1sequenceID = itemWrittenList[i];
}
}
#if NET4_5
if (!IsAppVeyor()) // Skip timing test when running within OpenCover.Console.exe
#endif
Assert.InRange(elapsedMilliseconds, 0, 950);
targetWrapper.Flush(flushHandler);
for (int i = 0; i < 2000 && flushCounter != 2; ++i)
{
Thread.Sleep(1);
}
Assert.Equal(2, flushCounter);
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
public void AsyncTargetWrapperFlushTest()
{
var myTarget = new MyAsyncTarget
{
ThrowExceptions = true
};
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
Name = "AsyncTargetWrapperFlushTest_Wrapper",
OverflowAction = AsyncTargetWrapperOverflowAction.Grow
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
List <Exception> exceptions = new List <Exception>();
int eventCount = 5000;
for (int i = 0; i < eventCount; ++i)
{
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(
ex =>
{
lock (exceptions)
{
exceptions.Add(ex);
}
}));
}
Exception lastException = null;
ManualResetEvent mre = new ManualResetEvent(false);
string internalLog = RunAndCaptureInternalLog(
() =>
{
targetWrapper.Flush(
cont =>
{
try
{
// by this time all continuations should be completed
Assert.Equal(eventCount, exceptions.Count);
// with just 1 flush of the target
Assert.Equal(1, myTarget.FlushCount);
// and all writes should be accounted for
Assert.Equal(eventCount, myTarget.WriteCount);
}
catch (Exception ex)
{
lastException = ex;
}
finally
{
mre.Set();
}
});
Assert.True(mre.WaitOne(5000), InternalLogger.LogWriter?.ToString() ?? string.Empty);
},
LogLevel.Trace);
if (lastException != null)
{
Assert.True(false, lastException.ToString() + "\r\n" + internalLog);
}
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
public void AsyncTargetWrapperSyncTest_WhenTimeToSleepBetweenBatchesIsEqualToZero()
{
LogManager.ThrowConfigExceptions = true;
var myTarget = new MyTarget();
var targetWrapper = new AsyncTargetWrapper()
{
WrappedTarget = myTarget,
TimeToSleepBetweenBatches = 0,
BatchSize = 4,
QueueLimit = 2, // Will make it "sleep" between every second write
OverflowAction = AsyncTargetWrapperOverflowAction.Block
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
int flushCounter = 0;
AsyncContinuation flushHandler = (ex) => { ++flushCounter; };
List <KeyValuePair <LogEventInfo, AsyncContinuation> > itemPrepareList = new List <KeyValuePair <LogEventInfo, AsyncContinuation> >(500);
List <int> itemWrittenList = new List <int>(itemPrepareList.Capacity);
for (int i = 0; i < itemPrepareList.Capacity; ++i)
{
var logEvent = new LogEventInfo();
int sequenceID = logEvent.SequenceID;
itemPrepareList.Add(new KeyValuePair <LogEventInfo, AsyncContinuation>(logEvent, (ex) => itemWrittenList.Add(sequenceID)));
}
long startTicks = Environment.TickCount;
for (int i = 0; i < itemPrepareList.Count; ++i)
{
var logEvent = itemPrepareList[i].Key;
targetWrapper.WriteAsyncLogEvent(logEvent.WithContinuation(itemPrepareList[i].Value));
}
targetWrapper.Flush(flushHandler);
for (int i = 0; i < itemPrepareList.Count * 2 && itemWrittenList.Count != itemPrepareList.Count; ++i)
{
System.Threading.Thread.Sleep(1);
}
long elapsedMilliseconds = Environment.TickCount - startTicks;
Assert.Equal(itemPrepareList.Count, itemWrittenList.Count);
int prevSequenceID = 0;
for (int i = 0; i < itemWrittenList.Count; ++i)
{
Assert.True(prevSequenceID < itemWrittenList[i]);
prevSequenceID = itemWrittenList[i];
}
if (!IsAppVeyor())
{
Assert.True(elapsedMilliseconds < 750); // Skip timing test when running within OpenCover.Console.exe
}
targetWrapper.Flush(flushHandler);
for (int i = 0; i < 2000 && flushCounter != 2; ++i)
{
System.Threading.Thread.Sleep(1);
}
Assert.Equal(2, flushCounter);
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}
public void AsyncTargetWrapperFlushTest()
{
InternalLogger.LogToConsole = true;
InternalLogger.IncludeTimestamp = true;
InternalLogger.LogLevel = LogLevel.Trace;
var myTarget = new MyAsyncTarget
{
ThrowExceptions = true
};
var targetWrapper = new AsyncTargetWrapper(myTarget)
{
Name = "AsyncTargetWrapperFlushTest_Wrapper",
OverflowAction = AsyncTargetWrapperOverflowAction.Grow,
TimeToSleepBetweenBatches = 3
};
targetWrapper.Initialize(null);
myTarget.Initialize(null);
try
{
List <Exception> exceptions = new List <Exception>();
#if !SILVERLIGHT
int eventCount = Environment.Is64BitProcess ? 5000 : 500;
long missingEvents = Environment.Is64BitProcess ? 5000 : 500;
#else
int eventCount = 500;
long missingEvents = 500;
#endif
for (int i = 0; i < eventCount; ++i)
{
targetWrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(
ex =>
{
try
{
lock (exceptions)
{
exceptions.Add(ex);
}
Interlocked.Decrement(ref missingEvents);
}
catch (Exception e)
{
InternalLogger.Trace("Error in callback", e);
}
}));
}
Exception lastException = null;
ManualResetEvent mre = new ManualResetEvent(false);
string internalLog = RunAndCaptureInternalLog(
() =>
{
targetWrapper.Flush(
cont =>
{
try
{
DateTime start = DateTime.Now;
// We have to spin until all events are done being written by the above code, otherwise on
// slow computers the flush will be called before all events has been pushed to the event queue.
// causing the below assertions to fail.
if (missingEvents > 0)
{
InternalLogger.Trace("Still missing {0} events, exceptions captured:{1}", missingEvents, exceptions.Count);
}
while (missingEvents > 0)
{
InternalLogger.Trace("Still missing {0} events, exceptions captured:{1}", missingEvents, exceptions.Count);
Thread.Sleep(50);
if (DateTime.Now - start > TimeSpan.FromSeconds(20))
{
Assert.False(true, string.Format("threads did not manage to enqueue their messages within time limit, still missing:{0}events, exceptions captured:{1}", missingEvents, exceptions.Count));
}
}
// by this time all continuations should be completed
Assert.Equal(eventCount, exceptions.Count);
// We have to use interlocked, otherwise there are no guarantee that we get the correct value
// with just 1 flush of the target
int flushCount = Interlocked.CompareExchange(ref myTarget.FlushCount, 0, 1);
Assert.Equal(1, flushCount);
int writeCount = Interlocked.CompareExchange(ref myTarget.WriteCount, 0, eventCount);
// and all writes should be accounted for
Assert.Equal(eventCount, writeCount);
}
catch (Exception ex)
{
lastException = ex;
}
finally
{
mre.Set();
}
});
Assert.True(mre.WaitOne());
},
LogLevel.Trace);
if (lastException != null)
{
Assert.True(false, lastException.ToString() + "\r\n" + internalLog);
}
}
finally
{
myTarget.Close();
targetWrapper.Close();
}
}