InvalidOperationException when accessing the configuration from multiple threads

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

InvalidOperationException when accessing the configuration from multiple threads

Gregor
Hi,

I am having some trouble on creating and using loggers from multiple threads. I am currently not able to give the exact source of the problem but it occurs on using LogManager.GetLogger() and/or LogManager.ReconfigExistingLoggers().

See the following code snippet that reproduces the problem in a comparable scenario:

using System.Threading;
using System.Windows;
using NLog;

namespace nlog_test
{
        public partial class MainWindow : Window
        {
                private const int NUM_THREADS = 20;

                public MainWindow()
                {
                        InitializeComponent();
                        InitLogging();
                }

                private void InitLogging()
                {
                        for (int i = 0; i < NUM_THREADS; i++)
                                ThreadPool.QueueUserWorkItem(InitLogger, i);
                }

                private static void InitLogger(object id)
                {
                        Logger logger = LogManager.GetLogger("threadlogger" + id);

                        LogManager.ReconfigExistingLoggers();

                        logger.Info("Initialized logger {0}", id);
                }
        }
}

Cheers,
Gregor
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

Gregor
Maybe the stack trace is of any help here:

   bei System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
   bei System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   bei System.Collections.Generic.List`1.Enumerator.MoveNext()
   bei NLog.Internal.EnumerableHelpers.<OfType>d__0`1.MoveNext() in c:\NLogBuild\src\NLog\Internal\EnumerableHelpers.cs:Zeile 60.
   bei System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   bei NLog.Internal.EnumerableHelpers.ToList[T](IEnumerable`1 enumerable) in c:\NLogBuild\src\NLog\Internal\EnumerableHelpers.cs:Zeile 118.
   bei NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects) in c:\NLogBuild\src\NLog\Internal\ObjectGraphScanner.cs:Zeile 118.
   bei NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects) in c:\NLogBuild\src\NLog\Internal\ObjectGraphScanner.cs:Zeile 125.
   bei NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects) in c:\NLogBuild\src\NLog\Internal\ObjectGraphScanner.cs:Zeile 125.
   bei NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects) in c:\NLogBuild\src\NLog\Internal\ObjectGraphScanner.cs:Zeile 125.
   bei NLog.Internal.ObjectGraphScanner.FindReachableObjects[T](Object[] rootObjects) in c:\NLogBuild\src\NLog\Internal\ObjectGraphScanner.cs:Zeile 65.
   bei NLog.Internal.TargetWithFilterChain.PrecalculateStackTraceUsage() in c:\NLogBuild\src\NLog\Internal\TargetWithFilterChain.cs:Zeile 95.
   bei NLog.LogFactory.GetTargetsByLevelForLogger(String name, IList`1 rules, TargetWithFilterChain[] targetsByLevel, TargetWithFilterChain[] lastTargetsByLevel) in c:\NLogBuild\src\NLog\LogFactory.cs:Zeile 587.
   bei NLog.LogFactory.GetConfigurationForLogger(String name, LoggingConfiguration configuration) in c:\NLogBuild\src\NLog\LogFactory.cs:Zeile 599.
   bei NLog.LogFactory.GetLogger(LoggerCacheKey cacheKey) in c:\NLogBuild\src\NLog\LogFactory.cs:Zeile 717.
   bei NLog.LogFactory.GetLogger(String name) in c:\NLogBuild\src\NLog\LogFactory.cs:Zeile 330.
   bei NLog.LogManager.GetLogger(String name) in c:\NLogBuild\src\NLog\LogManager.cs:Zeile 181.
   ...
   ...
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

Gregor
The problem seems to be caused by the AsyncTargetWrapper - this code snippet should match the problem better:

using System.Threading;
using System.Windows;
using NLog;
using NLog.Config;
using NLog.Targets;
using NLog.Targets.Wrappers;

namespace nlog_test
{
        public partial class MainWindow : Window
        {
                private const int Iterations = 2000;
                private static Logger _log = LogManager.GetLogger("foo");

                public MainWindow()
                {
                        InitializeComponent();
                        InitLogging();
                }

                private void InitLogging()
                {
                        var async = new AsyncTargetWrapper(new MemoryTarget());

                        LogManager.Configuration.AddTarget("foo", async);
                        LogManager.Configuration.LoggingRules.Add(new LoggingRule("*", LogLevel.Trace, async));
                        LogManager.ReconfigExistingLoggers();

                        ThreadPool.QueueUserWorkItem(DoLogging);

                        for (int i = 0; i < Iterations; i++)
                        {
                                _log.Info("some logging action");
                                Thread.Sleep(3);
                        }
                }

                private static void DoLogging(object state)
                {
                        int i = 0;
                        while (true)
                        {
                                Logger logger = LogManager.GetLogger("foo" + i++);

                                logger.Info("do some logging action");
                                Thread.Sleep(10);
                        }
                }
        }
}
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

codyzu
Bump!

I just hit this issue too. In my application, I have a form that configures logging using the configuration API. Then in some thread pool threads I am logging a bunch of stuff. I hit this InvalidOperationException when class attempted to create a Logger instance using LogManager.GetCurrentClassLogger(). A note, the Logger instance is a static variable, so I don't really have control over when it gets instantiated.

Have you found a solution to this issue?

Any thoughts from the dev?

The line of code throwing the exception:

protected static readonly Logger LOGGER = LogManager.GetCurrentClassLogger();


My stack trace:

at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at NLog.Internal.EnumerableHelpers.<OfType>d__0`1.MoveNext()
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at NLog.Internal.EnumerableHelpers.ToList[T](IEnumerable`1 enumerable)
   at NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects)
   at NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects)
   at NLog.Internal.ObjectGraphScanner.ScanProperties[T](List`1 result, Object o, Int32 level, Dictionary`2 visitedObjects)
   at NLog.Internal.ObjectGraphScanner.FindReachableObjects[T](Object[] rootObjects)
   at NLog.Internal.TargetWithFilterChain.PrecalculateStackTraceUsage()
   at NLog.LogFactory.GetTargetsByLevelForLogger(String name, IList`1 rules, TargetWithFilterChain[] targetsByLevel, TargetWithFilterChain[] lastTargetsByLevel)
   at NLog.LogFactory.GetConfigurationForLogger(String name, LoggingConfiguration configuration)
   at NLog.LogFactory.GetLogger(LoggerCacheKey cacheKey)
   at NLog.LogFactory.GetLogger(String name)
   at NLog.LogManager.GetCurrentClassLogger()
...
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

codyzu
I'm still encountering this issue...

Any info about this? Any help?
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

codyzu
I can also add that I am not using the AsyncTargetWrapper, but I am using a ThreadPool and calling ThreadPool.QueueUserWorkItem(...). That thread in turn is constructing a class that has a static Logger instance. When that class gets instantiated (presumably for the first time since it is initializing the static variables), I get this exception.

I would really like to get this issue resolved, I have been advocating the use of NLog in our dev department, but now I am concerned about it's thread safety. What can I provide to help resolve this issue?
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

codyzu
I have resolved this issue.

The short answer:

My project includes a custom target. My custom target has a pubic property of type list (actually BindingList). Apparently, this is a no-no, because at any time, NLog may do some reflection magic on my target that includes a foreach loop that iterates my list. If by a rare chance, I add something to that list (in another thread obviously), the foreach loop throws an exception because the list has been modified while the loop is iterating through the list.

I would say this should either be improved in the NLog source, or at least a big warning in the documentation page about custom targets.


Now the long answer:

I discovered the cause of the problem by turning on the NLog Internal Logging and seeing that the last line in the generated log was: "Scanning NLogTarget 'DataAccess.Tester Target[(unnamed)]'". The NLogTarget is my custom target.

In parallel I was digging through the NLog source using the stack trace from the exception. I knew the issue had something to do with foreach loops and iterators based on the exception being thrown from MoveNextRare(). Then I made the connection between my public BindingList property and the foreach loop...

The culprit exists in the NLog source in Internal/ObjectGraphScanner.cs, line 118. Here I can see my public property that is an IEnumerable (in my case a BindingList), is iterated using a foreach loop. Since NLog only knows that it is an IEnumerable, I can't think of any better looping logic to remove the dependency on the iterators. Furthermore, I still don't quite understand why NLog is iterating through all of the public properties... Could this be improved by only iterating through public properties that have a custom attribute?

Maybe there is not an elegant solution... if that is the case, I think it would be worth adding a warning to the custom target documentation. Something about how NLog will iterate through any public properties that are of type IEnumerable, so they should be avoided or very special threading considerations must be made.

I think this is why the other poster only had issues when using the AsyncTargetWrapper. The MemoryTarget also has a public List property (Logs) and I'm guessing the AsyncTargetWrapper causes the same threading issue that I had... one thread adds items to the list while NLog is iterating the list in another thread. I think is a larger issue that truly needs to be resolved.

Uggg, is the best solution really to add some thread synchronization logic? I would say in the case of the MemoryTarget, the list needs to be locked whenever a message is added. Instead of returning the internal list in a public property, the internal list should be locked and then a copy should be made (and returned).

I resolved my issue by simply moving my BindingList to another class and passing it to my target in the constructor. This allowed me to keep it as a private field for the target so that NLog never iterates through it.

Any thoughts Jarek?
Ben
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: InvalidOperationException when accessing the configuration from multiple threads

Ben
In reply to this post by Gregor
Just as emphasis that this is really a common pitfall: We are experiencing exactly  the same issue.

We wrote a custom NLog target which is temporarily added and removed via the API on top of our static NLog XML configuration target, to allow a live log view during a special phase of our program. I was absolute puzzled and would feel doomed if codyzu did not post an excellent analysis of the problem and how it might be workarounded.

So Jarek, please do tackle this inside the NLog framework itself. This is just too sporadic and unexpected to be avoided for most users.
Loading...