public void FlushingMultipleTimesSimultaneous()
{
var asyncTarget = new AsyncTargetWrapper
{
TimeToSleepBetweenBatches = 2000,
WrappedTarget = new DebugTarget(),
};
asyncTarget.Initialize(null);
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();
});
firstContinuationResetEvent.WaitOne();
secondContinuationResetEvent.WaitOne();
Assert.True(firstContinuationCalled);
Assert.True(secondContinuationCalled);
}
public void FallbackGroupTargetAsyncTest()
{
using (new NoThrowNLogExceptions())
{
var myTarget1 = new MyTarget {
FailCounter = int.MaxValue
}; // Always failing.
var myTarget1Async = new AsyncTargetWrapper(myTarget1)
{
TimeToSleepBetweenBatches = 0
}; // Always failing.
var myTarget2 = new MyTarget()
{
Layout = "${ndlc}"
};
var wrapper = CreateAndInitializeFallbackGroupTarget(true, myTarget1Async, myTarget2);
var exceptions = new List <Exception>();
// no exceptions
for (var i = 0; i < 10; ++i)
{
using (NestedDiagnosticsLogicalContext.Push("Hello World"))
{
wrapper.WriteAsyncLogEvent(LogEventInfo.CreateNullEvent().WithContinuation(exceptions.Add));
}
}
ManualResetEvent resetEvent = new ManualResetEvent(false);
myTarget1Async.Flush((ex) => { Assert.Null(ex); resetEvent.Set(); });
resetEvent.WaitOne(1000);
Assert.Equal(10, exceptions.Count);
for (var i = 0; i < 10; ++i)
{
Assert.Null(exceptions[i]);
}
Assert.Equal(10, myTarget2.WriteCount);
AssertNoFlushException(wrapper);
}
}
public async Task MultipleLogEntriesAsync()
{
var logs = Enumerable.Range(1, 5).Select(i => $"Message{i}");
var uploadedEntries = await RunTestWorkingServer(
googleTarget =>
{
AsyncTargetWrapper asyncWrapper = new AsyncTargetWrapper(googleTarget)
{
TimeToSleepBetweenBatches = 500
};
LogManager.Configuration.LoggingRules.Clear();
LogManager.Configuration.AddRuleForAllLevels(asyncWrapper, "*");
LogManager.ReconfigExistingLoggers();
LogInfo(logs.Take(2));
asyncWrapper.Flush((ex) => { });
LogInfo(logs.Skip(2));
return(Task.FromResult(0));
});
Assert.Equal(5, uploadedEntries.Count);
Assert.Equal(logs, uploadedEntries.Select(x => x.TextPayload.Trim()));
}
static void Main(string[] args)
{
FileTarget target = new FileTarget();
target.Layout = "${longdate} ${logger} ${message}";
target.FileName = "${basedir}/logs/logfile.txt";
target.KeepFileOpen = false;
target.Encoding = "iso-8859-2";
AsyncTargetWrapper wrapper = new AsyncTargetWrapper();
wrapper.WrappedTarget = target;
wrapper.QueueLimit = 5000;
wrapper.OverflowAction = AsyncTargetWrapperOverflowAction.Discard;
NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(wrapper, LogLevel.Debug);
Logger logger = LogManager.GetLogger("Example");
logger.Debug("log message");
wrapper.Flush();
}
/// <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();
}
}
