[LOG4NET-298] Loggers are not fully re-entrant and can deadlock

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Won't Fix
• Affects Version/s: 1.2.10
• Component/s: Appenders
• Assignee: Unassigned
• Reporter: Tanguy Fautre
• Created: 28/Jul/11 16:51
• Updated: 06/Jun/13 07:06
• Resolved: 06/Jun/13 07:06

Description

Log4net internal locking seems to be too aggressive and coarse. It can deadlock in cases where a logging thread waits on another thread that also logs. While this is a similar issue to LOG4NET-225, there is no custom appender needed to reproduce it.

For example, the following program will deadlock in .\log4net-1.2.10\src\Appender\AppenderSkeleton.cs (AppenderSkeleton.DoAppend(), line 296)

using System.Threading.Tasks;
using log4net;
using log4net.Appender;
using log4net.Core;
using log4net.Layout;
using log4net.Repository.Hierarchy;

namespace HelloWorldCSharp
{
public class Program
{
private static readonly ILog Log = LogManager.GetLogger("My.Logger");

private static void InitLogger()
{
var appender = new ConsoleAppender

{ Name = "Unit Testing Console Appender", Layout = new PatternLayout("%message%n"), Threshold = Level.All }

;
appender.ActivateOptions();

var root = ((Hierarchy)LogManager.GetRepository()).Root;
root.Level = Level.Debug;
root.AddAppender(appender);
root.Repository.Configured = true;
}

public static void Main()
{
InitLogger();

Log.WarnFormat("Nasty thing

{0}

", new NastyThing());
}

private class NastyThing
{
public override string ToString()

{ Log.Warn("This message goes missing"); var t = Task.Factory.StartNew(DoLoggingInOtherThread); t.Wait(); // this deadlock deep in log4net return "NastyThing.ToString()"; }

}

public static void DoLoggingInOtherThread()

{ Log.Warn("This message deadlocks"); }

}
}

Current behaviour:

• prints nothing
• deadlocks

Expected behaviour:

• prints "This message goes missing"
• prints "This message deadlocks"
• prints "Nasty thing NastyThing.ToString()"
• exits cleanly

Having looked at the code from SkeletonAppender, I understand this may not be a trivial issue to fix. I feel however that this is a reasonable user expectation (especially given the fact that the use case above is read-only and makes no attempt to modify the log tree).

Cheers,
Tanguy