InvalidOperationException: ValueFactory attempted to access the Value property

[kirill-gerasimenko]

Hi,

I'm using Bootstrapper from nuget package elmah.bootstrapper.1.0.0-beta5 and from time to time I've got the following exception (couldn't find the stable way to reproduce though).

System.InvalidOperationException: ValueFactory attempted to access the Value property of this instance.
   at System.Lazy`1.CreateValue()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Lazy`1.get_Value()
   at Elmah.Bootstrapper.ErrorLogHandlerMappingModule.OnPostMapRequestHandler(HttpContextBase context)
   at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Usually it happens when I rebuild the project with IISExpress running, trying to F5 gives error, after another F5 in browser - all works fine. If site is running under IIS - i need to recycle the app pool.

If you need more details I can provide them, thanks!

[atifaziz]

I didn't ask for thread-safety for lazy initialization because I didn't need it. However, reading the Lazy<T> source, it seems to me that its recursion detection kicks in a thread-unsafe way, causing a false-negative. There is no recursive call in the Bootstrapper code to the same lazy-backed property. My guess is that more than one thread is running through the lazy value factory, with one setting ALREADY_INVOKED_SENTINEL and another seeing it before the initialization is over. The second thread then thinks it's seeing a recursive call & throws InvalidOperationException to guard against it. A bit too helpful if you ask me.

I've only run this through my head and writing out my theory loud to bounce it off you. Let me know if you think I've gone completely off a cliff. I'll try and test out my theory tomorrow with some code & then make a fix.

[kirill-gerasimenko]

I've taken a look at Lazy sources you pointed and it seems like you're right.

I've made small test program in linqpad and it shows the issue(if change LazyThreadSafetyMode from None - issue is gone):

void Main()
{
    var lazy = new Lazy<int>(() => { Thread.Sleep(1000 * 10); return 1; }, LazyThreadSafetyMode.None);

    var tasks = Enumerable
        .Range(0, 10)
        .Select(_ => { Thread.Sleep(100); return Task.Run(() => lazy.Value); })
        .Cast<Task>()
        .ToArray();

    Task.WaitAll(tasks);
}

[atifaziz]

@kirill-gerasimenko Thanks for sharing your results. I've also written a test to try out the theory and reaching the same conclusion and will share it shortly.

[atifaziz]

Following is a test console program I wrote to exercise LazyThreadSafetyMode. It's slightly involved but I wanted to do this only once and get it right.

namespace LazyTest
{
    #region Imports

    using System;
    using System.Collections.Generic;
    using System.Diagnostics;
    using System.Linq;
    using System.Reflection;
    using System.Text.RegularExpressions;
    using System.Threading;
    using static System.Console;

    #endregion

    static class ThreadStatics
    {
        [ThreadStatic] public static int Id;
    }

    class Program
    {
        public static LazyThreadSafetyMode LazyThreadSafetyMode = LazyThreadSafetyMode.None;

        static void Main(string[] args)
        {
            var debuggable = (DebuggableAttribute)
                Attribute.GetCustomAttribute(Assembly.GetExecutingAssembly(),
                                             typeof(DebuggableAttribute));

            WriteLine($"DebuggableAttribute.IsJITOptimizerDisabled = {debuggable?.IsJITOptimizerDisabled}");

            var options = new
            {
                Threads =
                    args.Where(s => Regex.IsMatch(s, "^([0-9]+)$"))
                        .Select(s => (int?)int.Parse(s))
                        .FirstOrDefault() ?? 20,

                LazyThreadSafetyMode =
                    args.Where(s => Enum.GetNames(typeof(LazyThreadSafetyMode))
                                        .Any(n => n.Equals(s, StringComparison.OrdinalIgnoreCase)))
                        .Select(s => (LazyThreadSafetyMode?)
                                     Enum.Parse(typeof(LazyThreadSafetyMode), s, ignoreCase: true))
                        .FirstOrDefault() ?? LazyThreadSafetyMode.None,
            };

            WriteLine($"Threads = {options.Threads}, LazyThreadSafetyMode = {options.LazyThreadSafetyMode}");
            WriteLine("* = Thread ran value factory");

            LazyThreadSafetyMode = options.LazyThreadSafetyMode;

            using (var ready = new ManualResetEvent(initialState: false))
            {
                var workerz =
                    from readee in new[] { ready }
                    from id in Enumerable.Range(1, options.Threads)
                    let bar = new int?[1]        // by-reference
                    let error = new Exception[1] // by-reference
                    select new
                    {
                        Id     = id,
                        Bar    = bar,
                        Error  = error,
                        Thread = new Thread(() =>
                        {
                            ThreadStatics.Id = id;
                            readee.WaitOne();
                            try { bar[0] = Foo.Bar; }
                            catch (Exception e) { error[0] = e; }
                        })
                    };

                var workers = workerz.ToArray();

                if (workers.Length < options.Threads)
                    WriteLine($"Warning! Using max threads of {workers.Length}.");

                Array.ForEach(workers, t => t.Thread.Start());
                ready.Set(); // go!
                Array.ForEach(workers, w => w.Thread.Join());
                foreach (var w in workers)
                {
                    var initialized = FooBarInitializers.Contains(w.Thread) ? '*' : ' ';
                    WriteLine($"{w.Id,3} {initialized} : Bar = {w.Bar[0],3}, Error = {w.Error[0]?.GetBaseException().Message}");
                }
            }
        }

        static readonly List<Thread> FooBarInitializers = new List<Thread>();

        public static void OnFooBarInitializing()
        {
            lock (FooBarInitializers)
                FooBarInitializers.Add(Thread.CurrentThread);
        }
    }

    static class Foo
    {
        public static int Bar => LazyBar.Value;
        static readonly Lazy<int> LazyBar = new Lazy<int>(CreateBar, Program.LazyThreadSafetyMode);

        static int CreateBar()
        {
            Program.OnFooBarInitializing();
            Thread.Yield(); // entropy
            return ThreadStatics.Id;
        }
    }
}

I used good old threads instead of tasks because I didn't want any pooling or task-inlining to come into effect & interfere with the observed results.

The program starts by printing whether or not JIT optimizations are in effect (debug vs. release build). It then parses the command line arguments, which are allowed to be specified in any order. If an argument is a number then it's taken as the number of threads to exercise with, with the default being 20. If it's one of the LazyThreadSafetyMode members then it's used for the Lazy<T> being exercised, with None being the default. Anything else is ignored silently.

The threads are created and wait until each one has had a chance to initialize a logical and stable thread ID (ThreadStatics.Id). They then go on to access the static class property Foo.Bar that is backed by a Lazy<T>. The property's lazy factory initializes it to the logical ID of the thread passing through it and also which threads have passed through it.

The results of each thread's observations, including any error, are printed at the end.

So with all that said and done, here are the results (using 10 threads):

DebuggableAttribute.IsJITOptimizerDisabled = False
Threads = 10, LazyThreadSafetyMode = None
* = Thread ran value factory
  1   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  2   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  3   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  4   : Bar =   0, Error = 
  5   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  6   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  7   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  8   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.
  9 * : Bar =   9, Error = 
 10   : Bar =    , Error = ValueFactory attempted to access the Value property of this instance.

Clearly, it's a mess. With PublicationOnly, you get (not surprise):

DebuggableAttribute.IsJITOptimizerDisabled = False
Threads = 10, LazyThreadSafetyMode = PublicationOnly
* = Thread ran value factory
  1 * : Bar =   9, Error = 
  2 * : Bar =   9, Error = 
  3 * : Bar =   9, Error = 
  4 * : Bar =   9, Error = 
  5 * : Bar =   9, Error = 
  6 * : Bar =   9, Error = 
  7 * : Bar =   9, Error = 
  8 * : Bar =   9, Error = 
  9 * : Bar =   9, Error = 
 10 * : Bar =   9, Error = 

And finally using ExecutionAndPublication (again, no surprises):

DebuggableAttribute.IsJITOptimizerDisabled = False
Threads = 10, LazyThreadSafetyMode = ExecutionAndPublication
* = Thread ran value factory
  1   : Bar =   9, Error = 
  2   : Bar =   9, Error = 
  3   : Bar =   9, Error = 
  4   : Bar =   9, Error = 
  5   : Bar =   9, Error = 
  6   : Bar =   9, Error = 
  7   : Bar =   9, Error = 
  8   : Bar =   9, Error = 
  9 * : Bar =   9, Error = 
 10   : Bar =   9, Error = 

[atifaziz]

This is now fixed by f8cca5e8ddb64b4a66fb5481ff324cb4814d7fca and published as beta 6. Thanks for reporting & testing.

[kirill-gerasimenko]

This is great! Thanks a lot for a quick fix!