NullReferenceException in DiagnosticsEventListener.OnEventWritten

[pharring]

This is the same as #341 (I can't re-open that one, though). Now I have a root cause and a fix ready to go.

Repro Steps

Compile and run this console app on .NET Core referencing the latest ApplicationInsights (base) NuGet (actually it repros as far back as 2.4.0):

using System;
using System.Threading.Tasks;
using Microsoft.ApplicationInsights.Channel;
using Microsoft.ApplicationInsights.Extensibility;

namespace AINullListenerRepro
{
    class Program
    {
        static void Main(string[] args)
        {
            var t1 = Task.Run(Race1);
            var t2 = Task.Run(Race2);
            Console.WriteLine("Running...");
            Console.ReadKey();
        }

        static async Task Race1()
        {
            while (true)
            {
                using (var channel = new InMemoryChannel())
                {
                    await Task.Yield();
                }
            }
        }

        static async Task Race2()
        {
            while (true)
            {
                using (var telemetryConfiguration = TelemetryConfiguration.Active)
                {
                    await Task.Yield();
                }
            }
        }
    }
}

Actual Behavior

After a few seconds:
NullReferenceException in DiagnosticsEventListener.OnEventWritten.
The listener field is null.

Expected Behavior

No exception.

Version Info

SDK Version : 2.4.0 to 2.9.1
.NET Version : .NET Core 2.2 (although I think it repros on other platforms too)
How Application was onboarded with SDK: VisualStudio
OS : Windows 10
Hosting Info (IIS/Azure WebApps/ etc) : N/A

This issue has been plaguing my unit tests for Snapshot Debugger for that last week or so. It's timing dependent.

Explanation for the repro:

1. Race1 just creates and disposes an InMemoryChannel over and over. That has the effect of reporting "No Telemetry Items passed to Enqueue" to the CoreEventSource over and over.
2. Race2 creates and disposes the TelemetryConfiguration.Active. A lot happens there, but the important thing for the repro is that it adds the DiagnosticsTelemtryModule which establishes the DiagnosticsEventListener.

The two threads race with each other. At some point, the DiagnosticsEventListener constructor begins. It first calls the base class; note that the listener and logLevel fields are not yet set -- they're still null and zero. During the base class constructor, the OnEventSourceCreated virtual method is called. This is unusual; a quirk of EventListener. We detect that the event source is the CoreEventSource and enable it with AllKeyword and a logLevel of zero - LogAlways (that's a bug actually because it doesn't honor the logLevel that was passed in the constructor, but it's not this bug). Now that the event source is enabled, the other thread gets a chance to run -- to write an event. DiagnosticsEventListener's constructor still hasn't completed, but it gets a callback on OnEventWritten and gets all the way to the last line where listener is still null. NRE.

[pharring]

The call-back to OnEventSourceCreated from the base class, as I mentioned, is quirky, but expected. The logging package (EventSourceTelemetryModule) had to deal with it too. See https://github.com/Microsoft/ApplicationInsights-dotnet-logging/blob/develop/src/EventSourceListener/EventSourceTelemetryModule.cs#L182

Also see the test case for EventListener which does the same sort of thing:
https://github.com/dotnet/corefx/blob/master/src/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs#L40

I believe, to fix the mis-configured 'logLevel', you would need to do something like that: Remember the set of EventSources that you want to enable in a List, and then run through that list at the end of the derived constructor.