Skip to content

Commit

Permalink
Fix two bugs in DiagnosticsEventListener (#1107)
Browse files Browse the repository at this point in the history 
* Fix NRE in DiagnosticsEventListener.OnEventWritten
Fixes #1106

* Save EventSources enabled during DiagnosticsEventListener construction
Fixes #1108

* Fix net45 tests

* Fix netcoreapp20 unit test failure
  • Loading branch information
@pharring @cijothomas
pharring authored and cijothomas committed Apr 9, 2019
1 parent 34b5e10 commit a2d70ef
Show file tree
Hide file tree
Showing 3 changed files with 174 additions and 62 deletions.
58 changes: 57 additions & 1 deletion ...ationInsights.Test/Shared/Extensibility/Implementation/Tracing/DiagnosticsListenerTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,20 @@ public void TestEventSending()
[TestMethod]
public void TestListenerWithDifferentSeverity()
{
// Ensure there are no left-over DiagnosticTelemetryModules
// from previous tests that will mess up this one.
TelemetryConfiguration.Active.Dispose();
var modules = TelemetryModules.Instance.Modules;
if (modules != null)
{
foreach (var module in modules)
{
(module as IDisposable)?.Dispose();
}

modules.Clear();
}

var senderMock = new DiagnosticsSenderMock();
var senders = new List<IDiagnosticsSender> { senderMock };
using (var listener = new DiagnosticsListener(senders))
Expand All @@ -70,11 +84,53 @@ public void TestListenerWithDifferentSeverity()
Assert.AreEqual(1, senderMock.Messages.Count);

senderMock.Messages.Clear();

listener.LogLevel = EventLevel.Error;
CoreEventSource.Log.LogError("Logging an error");

// If you see the following assert fail, it's because another test has
// leaked a DiagnosticsTelemetryModule (via TelemetryConfiguration.Active
// for example). There will be a DiagnosticEventListener which forwards
// error messages to a PortalDiagnosticsSender. That listener is still
// getting events from EventSources. We send an Error event, which goes
// not only to our listener here, but also to the leaked one. The event
// gets forwarded to the PortalDiagnosticsSender. That turns the event
// into TraceTelemetry and tries to transmit it. Since we set the event
// level to verbose earlier, RichPayloadEventSource is is enabled and
// it writes the TraceTelemetry to all listeners (including us).
// Unfortuantely, the TraceTelemetry contains a nullable field which
// triggers a known .NET Core 2.0 bug inside WriteEvent. The internal
// exception gets reported as an error from WriteEvent resulting in another
// event with EventLevel.Error being reported here.
Assert.AreEqual(1, senderMock.Messages.Count);
}
}

[TestMethod]
public void TestEventSourceLogLevelWhenEventSourceIsAlreadyCreated()
{
using (var testEventSource = new TestEventSource())
{
var senderMock = new DiagnosticsSenderMock();
var senders = new List<IDiagnosticsSender> { senderMock };
using (var listener = new DiagnosticsListener(senders))
{
const EventKeywords AllKeyword = (EventKeywords)(-1);
// The default level is EventLevel.Error
Assert.IsTrue(testEventSource.IsEnabled(EventLevel.Error, AllKeyword));

// So Verbose should not be enabled
Assert.IsFalse(testEventSource.IsEnabled(EventLevel.Verbose, AllKeyword));

listener.LogLevel = EventLevel.Verbose;
Assert.IsTrue(testEventSource.IsEnabled(EventLevel.Verbose, AllKeyword));
}
}
}

[EventSource(Name = "Microsoft-ApplicationInsights-" + nameof(TestEventSource))]
private class TestEventSource : EventSource
{
}
}
}
146 changes: 86 additions & 60 deletions ...rosoft.ApplicationInsights.Test/Shared/Extensibility/TelemetryConfigurationFactoryTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -78,10 +78,13 @@ public void InitializesInstanceWithInformationFromConfigurationFileWhenItExists(
string configFileContents = Configuration("<InstrumentationKey>F8474271-D231-45B6-8DD4-D344C309AE69</InstrumentationKey>");

TelemetryConfiguration configuration = new TelemetryConfiguration();
new TestableTelemetryConfigurationFactory().Initialize(configuration, new TestableTelemetryModules(), configFileContents);
using (var testableTelemetryModules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(configuration, testableTelemetryModules, configFileContents);

// Assume that LoadFromXml method is called, tested separately
Assert.IsFalse(string.IsNullOrEmpty(configuration.InstrumentationKey));
// Assume that LoadFromXml method is called, tested separately
Assert.IsFalse(string.IsNullOrEmpty(configuration.InstrumentationKey));
}
}

[TestMethod]
Expand Down Expand Up @@ -422,24 +425,27 @@ public void InitializeTelemetryProcessorsFromConfigurationFile()
"</TelemetryProcessors>");

TelemetryConfiguration configuration = new TelemetryConfiguration();
new TestableTelemetryConfigurationFactory().Initialize(configuration, new TestableTelemetryModules(), configFileContents);

// Assume that LoadFromXml method is called, tested separately
Assert.IsTrue(configuration.TelemetryProcessors != null);
AssertEx.IsType<StubTelemetryProcessor>(configuration.TelemetryProcessorChain.FirstTelemetryProcessor);

//validate the chain linking stub1->stub2->pass through->sink
var tp1 = (StubTelemetryProcessor)configuration.TelemetryProcessorChain.FirstTelemetryProcessor;
var tp2 = (StubTelemetryProcessor2)tp1.next;
var passThroughProcessor = tp2.next as PassThroughProcessor;
Assert.IsNotNull(passThroughProcessor);

// The sink has only a transmission processor and a default channel.
var sink = passThroughProcessor.Sink;
Assert.IsNotNull(sink);
Assert.AreEqual(1, sink.TelemetryProcessorChain.TelemetryProcessors.Count);
AssertEx.IsType<TransmissionProcessor>(sink.TelemetryProcessorChain.FirstTelemetryProcessor);
AssertEx.IsType<InMemoryChannel>(sink.TelemetryChannel);
using (var testableTelemetryModules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(configuration, testableTelemetryModules, configFileContents);

// Assume that LoadFromXml method is called, tested separately
Assert.IsTrue(configuration.TelemetryProcessors != null);
AssertEx.IsType<StubTelemetryProcessor>(configuration.TelemetryProcessorChain.FirstTelemetryProcessor);

//validate the chain linking stub1->stub2->pass through->sink
var tp1 = (StubTelemetryProcessor)configuration.TelemetryProcessorChain.FirstTelemetryProcessor;
var tp2 = (StubTelemetryProcessor2)tp1.next;
var passThroughProcessor = tp2.next as PassThroughProcessor;
Assert.IsNotNull(passThroughProcessor);

// The sink has only a transmission processor and a default channel.
var sink = passThroughProcessor.Sink;
Assert.IsNotNull(sink);
Assert.AreEqual(1, sink.TelemetryProcessorChain.TelemetryProcessors.Count);
AssertEx.IsType<TransmissionProcessor>(sink.TelemetryProcessorChain.FirstTelemetryProcessor);
AssertEx.IsType<InMemoryChannel>(sink.TelemetryChannel);
}
}

[TestMethod]
Expand All @@ -453,23 +459,26 @@ public void InitializeTelemetryProcessorsWithWrongProcessorInTheMiddle()
"</TelemetryProcessors>");

TelemetryConfiguration configuration = new TelemetryConfiguration();
new TestableTelemetryConfigurationFactory().Initialize(configuration, new TestableTelemetryModules(), configFileContents);

Assert.IsTrue(configuration.TelemetryProcessors != null);
AssertEx.IsType<StubTelemetryProcessor>(configuration.TelemetryProcessorChain.FirstTelemetryProcessor);

//validate the chain linking stub1->stub2->pass through->sink
var tp1 = (StubTelemetryProcessor)configuration.TelemetryProcessorChain.FirstTelemetryProcessor;
var tp2 = (StubTelemetryProcessor2)tp1.next;
var passThroughProcessor = tp2.next as PassThroughProcessor;
Assert.IsNotNull(passThroughProcessor);

// The sink has only a transmission processor and a default channel.
var sink = passThroughProcessor.Sink;
Assert.IsNotNull(sink);
Assert.AreEqual(1, sink.TelemetryProcessorChain.TelemetryProcessors.Count);
AssertEx.IsType<TransmissionProcessor>(sink.TelemetryProcessorChain.FirstTelemetryProcessor);
AssertEx.IsType<InMemoryChannel>(sink.TelemetryChannel);
using (var testableTelemetryModules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(configuration, testableTelemetryModules, configFileContents);

Assert.IsTrue(configuration.TelemetryProcessors != null);
AssertEx.IsType<StubTelemetryProcessor>(configuration.TelemetryProcessorChain.FirstTelemetryProcessor);

//validate the chain linking stub1->stub2->pass through->sink
var tp1 = (StubTelemetryProcessor)configuration.TelemetryProcessorChain.FirstTelemetryProcessor;
var tp2 = (StubTelemetryProcessor2)tp1.next;
var passThroughProcessor = tp2.next as PassThroughProcessor;
Assert.IsNotNull(passThroughProcessor);

// The sink has only a transmission processor and a default channel.
var sink = passThroughProcessor.Sink;
Assert.IsNotNull(sink);
Assert.AreEqual(1, sink.TelemetryProcessorChain.TelemetryProcessors.Count);
AssertEx.IsType<TransmissionProcessor>(sink.TelemetryProcessorChain.FirstTelemetryProcessor);
AssertEx.IsType<InMemoryChannel>(sink.TelemetryChannel);
}
}

[TestMethod]
Expand Down Expand Up @@ -647,10 +656,12 @@ public void InitializeTelemetryModulesFromConfigurationFile()
</TelemetryModules>"
);

var modules = new TestableTelemetryModules();
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);
using (var modules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);

Assert.AreEqual(2, modules.Modules.Count); // Diagnostics module is added by default
Assert.AreEqual(2, modules.Modules.Count); // Diagnostics module is added by default
}
}

[TestMethod]
Expand All @@ -661,11 +672,13 @@ public void InitializeTelemetryModulesFromConfigurationFileWithNoModulesHasOneDi
</TelemetryModules>"
);

var modules = new TestableTelemetryModules();
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);
using (var modules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);

Assert.AreEqual(1, modules.Modules.Count);
AssertEx.IsType<DiagnosticsTelemetryModule>(modules.Modules[0]);
Assert.AreEqual(1, modules.Modules.Count);
AssertEx.IsType<DiagnosticsTelemetryModule>(modules.Modules[0]);
}
}


Expand All @@ -680,10 +693,12 @@ public void InitializeTelemetryModulesFromConfigurationFileWhenOneModuleCannotBe
</TelemetryModules>"
);

var modules = new TestableTelemetryModules();
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);
using (var modules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);

Assert.AreEqual(3, modules.Modules.Count); // Diagnostics module is added by default
Assert.AreEqual(3, modules.Modules.Count); // Diagnostics module is added by default
}
}

[TestMethod]
Expand All @@ -700,14 +715,16 @@ public void InitializeDoesNotThrowIsModuleInitializationFails()
OnInitialize = _ => { throw new ArgumentException(); }
};

var modules = new TestableTelemetryModules();
modules.Modules.Add(module);
using (var modules = new TestableTelemetryModules())
{
modules.Modules.Add(module);

//Assert.DoesNotThrow
new TestableTelemetryConfigurationFactory().Initialize(
new TelemetryConfiguration(),
modules,
configFileContents);
//Assert.DoesNotThrow
new TestableTelemetryConfigurationFactory().Initialize(
new TelemetryConfiguration(),
modules,
configFileContents);
}
}

#endregion
Expand Down Expand Up @@ -1519,11 +1536,13 @@ public void InitializeIsMarkesAsInternalSdkOperation()
</TelemetryModules>"
);

var modules = new TestableTelemetryModules();
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);
using (var modules = new TestableTelemetryModules())
{
new TestableTelemetryConfigurationFactory().Initialize(new TelemetryConfiguration(), modules, configFileContents);

Assert.AreEqual(true, isInternalOperation);
Assert.AreEqual(false, SdkInternalOperationsMonitor.IsEntered());
Assert.AreEqual(true, isInternalOperation);
Assert.AreEqual(false, SdkInternalOperationsMonitor.IsEntered());
}
}

private static TelemetryConfiguration CreateTelemetryConfigurationWithDeveloperModeValue(string developerModeValue)
Expand All @@ -1548,8 +1567,15 @@ private static string Configuration(string innerXml)
</ApplicationInsights>";
}

private class TestableTelemetryModules : TelemetryModules
private class TestableTelemetryModules : TelemetryModules, IDisposable
{
public void Dispose()
{
foreach (var module in this.Modules)
{
(module as IDisposable)?.Dispose();
}
}
}

private class TestableTelemetryConfigurationFactory : TelemetryConfigurationFactory
Expand Down
32 changes: 31 additions & 1 deletion ...soft.ApplicationInsights/Extensibility/Implementation/Tracing/DiagnosticsEventListener.cs
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
namespace Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing
{
using System;
using System.Collections.Generic;
using System.Diagnostics.Tracing;
using System.Linq;

Expand All @@ -9,16 +10,29 @@ internal class DiagnosticsEventListener : EventListener
private const long AllKeyword = -1;
private readonly EventLevel logLevel;
private readonly DiagnosticsListener listener;
private readonly List<EventSource> eventSourcesDuringConstruction = new List<EventSource>();

public DiagnosticsEventListener(DiagnosticsListener listener, EventLevel logLevel)
{
this.listener = listener;
this.logLevel = logLevel;

List<EventSource> eventSources;
lock (this.eventSourcesDuringConstruction)
{
eventSources = this.eventSourcesDuringConstruction;
this.eventSourcesDuringConstruction = null;
}

foreach (var eventSource in eventSources)
{
this.EnableEvents(eventSource, this.logLevel, (EventKeywords)AllKeyword);
}
}

protected override void OnEventWritten(EventWrittenEventArgs eventSourceEvent)
{
if (eventSourceEvent == null)
if (eventSourceEvent == null || this.listener == null)
{
return;
}
Expand Down Expand Up @@ -46,6 +60,22 @@ protected override void OnEventSourceCreated(EventSource eventSource)
if (eventSource.Name.StartsWith("Microsoft-ApplicationInsights-", StringComparison.Ordinal) ||
eventSource.Name.Equals("Microsoft-AspNet-Telemetry-Correlation", StringComparison.Ordinal))
{
// If our constructor hasn't run yet (we're in a callback from the base class
// constructor), just make a note of the event source. Otherwise logLevel is
// set to the default, which is "LogAlways".
var tmp = this.eventSourcesDuringConstruction;
if (tmp != null)
{
lock (tmp)
{
if (this.eventSourcesDuringConstruction != null)
{
this.eventSourcesDuringConstruction.Add(eventSource);
return;
}
}
}

this.EnableEvents(eventSource, this.logLevel, (EventKeywords)AllKeyword);
}

Expand Down

0 comments on commit a2d70ef

Please sign in to comment.