Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

AutoFlushTargetWrapper - Fix race-condition that makes unit-tests unstable #5076

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
snakefoot merged 1 commit into from
Sep 29, 2022
Merged

AutoFlushTargetWrapper - Fix race-condition that makes unit-tests unstable #5076

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
44 changes: 27 additions & 17 deletions 44 src/NLog/Internal/AsyncOperationCounter.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ namespace NLog.Internal
{
using System;
using System.Collections.Generic;
using Common;
using NLog.Common;

/// <summary>
/// Keeps track of pending operation count, and can notify when pending operation count reaches zero
Expand All @@ -59,7 +59,12 @@ public void BeginOperation()
/// <param name="exception">Exception coming from the completed operation [optional]</param>
public void CompleteOperation(Exception exception)
{
System.Threading.Interlocked.Decrement(ref _pendingOperationCounter);
NotifyCompletion(exception);
}

private int NotifyCompletion(Exception exception)
{
int pendingOperations = System.Threading.Interlocked.Decrement(ref _pendingOperationCounter);

if (_pendingCompletionList.Count > 0)
{
Expand All @@ -74,6 +79,8 @@ public void CompleteOperation(Exception exception)
}
}
}

return pendingOperations;
}

/// <summary>
Expand All @@ -83,24 +90,32 @@ public void CompleteOperation(Exception exception)
/// <returns>AsyncContinuation operation</returns>
public AsyncContinuation RegisterCompletionNotification(AsyncContinuation asyncContinuation)
{
if (_pendingOperationCounter == 0)
// We only want to wait for the operations currently in progress (not the future operations)
int remainingCompletionCounter = System.Threading.Interlocked.Increment(ref _pendingOperationCounter);
if (remainingCompletionCounter <= 1)
{
// No active operations
if (NotifyCompletion(null) < 0)
{
System.Threading.Interlocked.Exchange(ref _pendingOperationCounter, 0);
}
return asyncContinuation;
}
else
{
lock (_pendingCompletionList)
{
if (NotifyCompletion(null) <= 0)
{
return asyncContinuation; // No active operations
}

var pendingCompletion = new LinkedListNode<AsyncContinuation>(null);
_pendingCompletionList.AddLast(pendingCompletion);

// We only want to wait for the operations currently in progress (not the future operations)
int remainingCompletionCounter = System.Threading.Interlocked.Increment(ref _pendingOperationCounter);
remainingCompletionCounter = System.Threading.Interlocked.Increment(ref _pendingOperationCounter);
if (remainingCompletionCounter <= 0)
{
System.Threading.Interlocked.Exchange(ref _pendingOperationCounter, 0);
_pendingCompletionList.Remove(pendingCompletion);
return asyncContinuation;
remainingCompletionCounter = 1;
}

pendingCompletion.Value = (ex) =>
Expand All @@ -109,16 +124,10 @@ public AsyncContinuation RegisterCompletionNotification(AsyncContinuation asyncC
{
lock (_pendingCompletionList)
{
System.Threading.Interlocked.Decrement(ref _pendingOperationCounter);
_pendingCompletionList.Remove(pendingCompletion);
var nodeNext = _pendingCompletionList.First;
while (nodeNext != null)
{
var nodeValue = nodeNext.Value;
nodeNext = nodeNext.Next;
nodeValue(ex); // Will modify _pendingCompletionList
}
NotifyCompletion(ex);
}

asyncContinuation(ex);
}
};
Expand All @@ -134,6 +143,7 @@ public AsyncContinuation RegisterCompletionNotification(AsyncContinuation asyncC
public void Clear()
{
_pendingCompletionList.Clear();
System.Threading.Interlocked.Exchange(ref _pendingOperationCounter, 0);
}
}
}
18 changes: 11 additions & 7 deletions 18 src/NLog/Targets/Wrappers/AutoFlushTargetWrapper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,9 +153,9 @@ protected override void Write(AsyncLogEventInfo logEvent)
AsyncContinuation currentContinuation = logEvent.Continuation;
AsyncContinuation wrappedContinuation = (ex) =>
{
_pendingManualFlushList.CompleteOperation(ex);
if (ex is null)
FlushOnCondition();
_pendingManualFlushList.CompleteOperation(ex);
currentContinuation(ex);
};
_pendingManualFlushList.BeginOperation();
Expand Down Expand Up @@ -187,16 +187,20 @@ protected override void FlushAsync(AsyncContinuation asyncContinuation)

private void FlushOnCondition()
{
if (FlushOnConditionOnly)
FlushWrappedTarget((e) => { });
else
FlushAsync((e) => { });
FlushWrappedTarget((e) => { });
}

private void FlushWrappedTarget(AsyncContinuation asyncContinuation)
{
var wrappedContinuation = _pendingManualFlushList.RegisterCompletionNotification(asyncContinuation);
WrappedTarget.Flush(wrappedContinuation);
if (AsyncFlush)
{
var wrappedContinuation = _pendingManualFlushList.RegisterCompletionNotification(asyncContinuation);
WrappedTarget.Flush(wrappedContinuation);
}
else
{
WrappedTarget.Flush(asyncContinuation);
}
}

/// <inheritdoc/>
Expand Down
55 changes: 54 additions & 1 deletion 55 tests/NLog.UnitTests/Targets/Wrappers/AutoFlushTargetWrapperTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,6 +120,54 @@ public void AutoFlushTargetWrapperAsyncTest2()
var logEvent = new LogEventInfo();
Exception lastException = null;

// Schedule 100 writes, where each write on completion schedules followup-flush (in random order)
const int expectedWriteCount = 100;
const int expectedFlushCount = expectedWriteCount + 3;
for (int i = 0; i < expectedWriteCount; ++i)
{
wrapper.WriteAsyncLogEvent(logEvent.WithContinuation(ex => lastException = ex));
}

var continuationHit = new ManualResetEvent(false);
AsyncContinuation continuation =
ex =>
{
continuationHit.Set();
};

// Schedule 1st flush (can complete before follow-flushes)
wrapper.Flush(ex => { });
Assert.Null(lastException);
// Schedule 2nd flush (can complete before follow-flushes)
wrapper.Flush(continuation);
Assert.Null(lastException);
Assert.True(continuationHit.WaitOne(5000));
Assert.Null(lastException);
// Schedule 3rd flush (can complete before follow-flushes)
wrapper.Flush(ex => { });
Assert.Null(lastException);

for (int i = 0; i < 500; ++i)
{
if (myTarget.WriteCount == expectedWriteCount && myTarget.FlushCount == expectedFlushCount)
break;
Thread.Sleep(10);
}

Assert.Equal(expectedWriteCount, myTarget.WriteCount);
Assert.Equal(expectedFlushCount, myTarget.FlushCount);
}

[Fact]
public void AutoFlushTargetWrapperAsyncTest3()
{
var myTarget = new MyAsyncTarget();
var wrapper = new AutoFlushTargetWrapper(myTarget) { AsyncFlush = false };
myTarget.Initialize(null);
wrapper.Initialize(null);
var logEvent = new LogEventInfo();
Exception lastException = null;

for (int i = 0; i < 100; ++i)
{
wrapper.WriteAsyncLogEvent(logEvent.WithContinuation(ex => lastException = ex));
Expand Down Expand Up @@ -334,9 +382,14 @@ protected override void Write(AsyncLogEventInfo logEvent)

protected override void FlushAsync(AsyncContinuation asyncContinuation)
{
InternalLogger.Trace("Flush Started");
FlushCount++;
ThreadPool.QueueUserWorkItem(
s => asyncContinuation(null));
s =>
{
asyncContinuation(null);
InternalLogger.Trace("Flush Completed");
});
}

public bool ThrowExceptions { get; set; }
Expand Down
Morty Proxy This is a proxified and sanitized view of the page, visit original site.