Skip to content

Deadlock on ConcurrentRequestQueue.WaitForBelowRequestLimit() #3414

@yyjdelete

Description

@yyjdelete

Hi! Thanks for reporting this feature/bug/question!

Please keep / fill in the relevant info from this template so that we can help you as best as possible.

QUESTIONS are preferred on StackOverflow. You could expect a faster response there (but do include all the info below). Use the tag "nlog" https://stackoverflow.com/questions/ask

For .NET Core users, please check the platform support: https://github.com/NLog/NLog/wiki/platform-support

NLog version: 4.6.3

Platform: .Net 4.7.2/ .NET Core 2

Current NLog config (xml or C#, if relevant)
It happen when set <default-wrapper xsi:type="AsyncWrapper" overflowAction="Block" forceLockingQueue="false" />(or netcore2.0 without forceLockingQueue). And can be reproducted with the below code.

            var queue = new NLog.Targets.Wrappers.ConcurrentRequestQueue(10, NLog.Targets.Wrappers.AsyncTargetWrapperOverflowAction.Block);

            for (var j = 0; j < 3; ++j)
            {
                int cur = j;
                _ = Task.Run(() =>
                {
                    for (int i = 0; i < 20; ++i)
                    {
                        queue.Enqueue(default(NLog.Common.AsyncLogEventInfo));
                        Console.WriteLine($"Thread {cur}: PostEnqueue {i + 1}");
                    }
                });
            }
            Task.Run(() =>
            {
                Thread.Sleep(1000);
                int left = 20 * 3;
                while (left > 0)
                {
                    var tmp = queue.DequeueBatch(3);
                    left -= tmp.Length;
                    if (tmp.Length != 0)
                        Console.WriteLine($"DequeueBatch left={left}");
                }
                Console.WriteLine("Finished");
            }).Wait();

You can see some threads are block on line133(Monitor.Enter(_logEventInfoQueue);), but the queue is empty at that time. Seems Monitor.Wait() should not change the value of lockTaken at line141.

private long WaitForBelowRequestLimit()
{
long currentCount;
bool lockTaken = false;
try
{
// Attempt to yield using SpinWait
currentCount = TrySpinWaitForLowerCount();
// If yield did not help, then wait on a lock
while (currentCount > RequestLimit)
{
if (!lockTaken)
{
InternalLogger.Debug("Blocking because the overflow action is Block...");
Monitor.Enter(_logEventInfoQueue);
lockTaken = true;
InternalLogger.Trace("Entered critical section.");
}
else
{
InternalLogger.Debug("Blocking because the overflow action is Block...");
if (!Monitor.Wait(_logEventInfoQueue, 100))
lockTaken = false;
else
InternalLogger.Trace("Entered critical section.");
}
currentCount = Interlocked.Read(ref _count);
}
if (lockTaken)
{
Monitor.PulseAll(_logEventInfoQueue);
}
}
finally
{
if (lockTaken)
Monitor.Exit(_logEventInfoQueue);
}
return currentCount;
}

  • What is the current result?
    Still block even if the queue is empty at that time.
  • What is the expected result?
    No block after the queue be empty.
  • Did you checked the Internal log?
  • Please post full exception details (message, stacktrace, inner exceptions)
  • Are there any workarounds? yes/no
  • Is there a version in which it did work?
  • Can you help us by writing an unit test?

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugBug report / Bug fix

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions