Skip to content

Commit 738668e

Browse files
committed
Fix MetricsEventSource tests
Last week I added a change to the error handling behavior when MetricEventSource is enabled by multiple listeners and didn't properly update the tests. 1. The major issue was timout failures which were being caused because there is a bug in EventListener where it doesn't notify EventSources that the source has been disabled when the listener is disposed. This in turn caused every tests after the first to reject the new EventListener because the EventSource believed it was still in use by the first EventListener. (EventListener bug is tracked #56378) 2. A secondary issue is that I didn't update the test which was explicitly verifying the behavior where the EventSource emits an error in response to having two listeners and I had changed the product behavior there. Fixes: 1. I worked around the EventListener bug by explicitly calling DisableEvents(). I also updated OnEventWritten to log the MultipleSessionsNotSupportedError so that any future error that is similar has more obvious diagnostic logging. 2. I updated the test with new expectation that the 1st listener continues normal operation and the 2nd listener is the one that gets rejected. I also did a little refactoring and added a 2nd tests of multiple listeners to confirm it works if the first one is disabled before the 2nd one starts.
1 parent 34094b3 commit 738668e

1 file changed

Lines changed: 89 additions & 70 deletions

File tree

src/libraries/System.Diagnostics.DiagnosticSource/tests/MetricEventSourceTests.cs

Lines changed: 89 additions & 70 deletions
Original file line numberDiff line numberDiff line change
@@ -376,7 +376,7 @@ public void EventSourcePublishesMissingDataPoints()
376376

377377
[ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNotBrowser))]
378378
[OuterLoop("Slow and has lots of console spew")]
379-
public void EventSourcePublishesEndEventsOnNewListener()
379+
public void EventSourceRejectsNewListener()
380380
{
381381
using Meter meter = new Meter("TestMeter7");
382382
Counter<int> c = meter.CreateCounter<int>("counter1", "hat", "Fooz!!");
@@ -395,11 +395,13 @@ public void EventSourcePublishesEndEventsOnNewListener()
395395
listener.WaitForCollectionStop(s_waitForEventTimeout, 2);
396396
c.Add(12);
397397
h.Record(26);
398-
listener.WaitForCollectionStop(s_waitForEventTimeout, 3);
399398

400-
// some alternate listener starts listening
399+
// some alternate listener attempts to listen in the middle
401400
using MetricsEventListener listener2 = new MetricsEventListener(_output, MetricsEventListener.TimeSeriesValues, IntervalSecs, "ADifferentMeter");
402-
listener.WaitForEndInstrumentReporting(s_waitForEventTimeout, 4);
401+
listener2.WaitForMultipleSessionsNotSupportedError(s_waitForEventTimeout);
402+
403+
404+
listener.WaitForCollectionStop(s_waitForEventTimeout, 3);
403405
events = listener.Events.ToArray();
404406
}
405407

@@ -409,7 +411,6 @@ public void EventSourcePublishesEndEventsOnNewListener()
409411
AssertGaugeEventsPresent(events, meter.Name, og.Name, "", og.Unit, "9", "18", "27");
410412
AssertHistogramEventsPresent(events, meter.Name, h.Name, "", h.Unit, "0.5=19;0.95=19;0.99=19", "0.5=26;0.95=26;0.99=26");
411413
AssertCollectStartStopEventsPresent(events, IntervalSecs, 3);
412-
AssertEndInstrumentReportingEventsPresent(events, c, oc, og, h);
413414
}
414415

415416
[ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNotBrowser))]
@@ -646,6 +647,63 @@ public void EventSourceHandlesObservableCallbackException()
646647
AssertCollectStartStopEventsPresent(events, IntervalSecs, 3);
647648
}
648649

650+
[ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNotBrowser))]
651+
[OuterLoop("Slow and has lots of console spew")]
652+
public void EventSourceWorksWithSequentialListeners()
653+
{
654+
using Meter meter = new Meter("TestMeter16");
655+
Counter<int> c = meter.CreateCounter<int>("counter1");
656+
int counterState = 3;
657+
ObservableCounter<int> oc = meter.CreateObservableCounter<int>("observableCounter1", () => { counterState += 7; return counterState; });
658+
int gaugeState = 0;
659+
ObservableGauge<int> og = meter.CreateObservableGauge<int>("observableGauge1", () => { gaugeState += 9; return gaugeState; });
660+
Histogram<int> h = meter.CreateHistogram<int>("histogram1");
661+
662+
EventWrittenEventArgs[] events;
663+
using (MetricsEventListener listener = new MetricsEventListener(_output, MetricsEventListener.TimeSeriesValues, IntervalSecs, "TestMeter16"))
664+
{
665+
listener.WaitForCollectionStop(s_waitForEventTimeout, 1);
666+
c.Add(5);
667+
h.Record(19);
668+
listener.WaitForCollectionStop(s_waitForEventTimeout, 2);
669+
c.Add(12);
670+
h.Record(26);
671+
listener.WaitForCollectionStop(s_waitForEventTimeout, 3);
672+
events = listener.Events.ToArray();
673+
}
674+
675+
AssertBeginInstrumentReportingEventsPresent(events, c, oc, og, h);
676+
AssertInitialEnumerationCompleteEventPresent(events);
677+
AssertCounterEventsPresent(events, meter.Name, c.Name, "", "", "5", "12");
678+
AssertCounterEventsPresent(events, meter.Name, oc.Name, "", "", "", "7");
679+
AssertGaugeEventsPresent(events, meter.Name, og.Name, "", "", "9", "18");
680+
AssertHistogramEventsPresent(events, meter.Name, h.Name, "", "", "0.5=19;0.95=19;0.99=19", "0.5=26;0.95=26;0.99=26");
681+
AssertCollectStartStopEventsPresent(events, IntervalSecs, 3);
682+
683+
// Now create a new listener and do everything a 2nd time. Because the listener above has been disposed the source should be
684+
// free to accept a new connection.
685+
events = null;
686+
using (MetricsEventListener listener = new MetricsEventListener(_output, MetricsEventListener.TimeSeriesValues, IntervalSecs, "TestMeter16"))
687+
{
688+
listener.WaitForCollectionStop(s_waitForEventTimeout, 1);
689+
c.Add(5);
690+
h.Record(19);
691+
listener.WaitForCollectionStop(s_waitForEventTimeout, 2);
692+
c.Add(12);
693+
h.Record(26);
694+
listener.WaitForCollectionStop(s_waitForEventTimeout, 3);
695+
events = listener.Events.ToArray();
696+
}
697+
698+
AssertBeginInstrumentReportingEventsPresent(events, c, oc, og, h);
699+
AssertInitialEnumerationCompleteEventPresent(events);
700+
AssertCounterEventsPresent(events, meter.Name, c.Name, "", "", "5", "12");
701+
AssertCounterEventsPresent(events, meter.Name, oc.Name, "", "", "", "7");
702+
AssertGaugeEventsPresent(events, meter.Name, og.Name, "", "", "36", "45");
703+
AssertHistogramEventsPresent(events, meter.Name, h.Name, "", "", "0.5=19;0.95=19;0.99=19", "0.5=26;0.95=26;0.99=26");
704+
AssertCollectStartStopEventsPresent(events, IntervalSecs, 3);
705+
}
706+
649707
private void AssertBeginInstrumentReportingEventsPresent(EventWrittenEventArgs[] events, params Instrument[] expectedInstruments)
650708
{
651709
var beginReportEvents = events.Where(e => e.EventName == "BeginInstrumentReporting").Select(e =>
@@ -961,10 +1019,20 @@ protected override void OnEventSourceCreated(EventSource eventSource)
9611019
}
9621020
}
9631021

1022+
public override void Dispose()
1023+
{
1024+
if (_source != null)
1025+
{
1026+
// workaround for https://github.com/dotnet/runtime/issues/56378
1027+
DisableEvents(_source);
1028+
}
1029+
base.Dispose();
1030+
}
1031+
9641032
protected override void OnEventWritten(EventWrittenEventArgs eventData)
9651033
{
9661034
string sessionId = eventData.Payload[0].ToString();
967-
if(sessionId != "" && sessionId != _sessionId)
1035+
if (eventData.EventName != "MultipleSessionsNotSupportedError" && sessionId != "" && sessionId != _sessionId)
9681036
{
9691037
return;
9701038
}
@@ -988,68 +1056,36 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData)
9881056
_autoResetEvent.Set();
9891057
}
9901058

991-
public void WaitForCollectionStop(TimeSpan timeout, int numStops)
992-
{
993-
DateTime startTime = DateTime.Now;
994-
DateTime stopTime = startTime + timeout;
995-
int initialStopCount = GetCountCollectionStops();
996-
while (true)
997-
{
998-
if (GetCountCollectionStops() >= numStops)
999-
{
1000-
return;
1001-
}
1002-
TimeSpan remainingTime = stopTime - DateTime.Now;
1003-
if (remainingTime.TotalMilliseconds < 0 || !_autoResetEvent.WaitOne(remainingTime))
1004-
{
1005-
int currentStopCount = GetCountCollectionStops();
1006-
throw new TimeoutException("Timed out waiting for a StopCollection event. " +
1007-
$"StartTime={startTime} stopTime={stopTime} initialStopCount={initialStopCount} currentStopCount={currentStopCount} targetStopCount={numStops}");
1008-
}
1009-
}
1010-
}
1059+
public void WaitForCollectionStop(TimeSpan timeout, int numEvents) => WaitForEvent(timeout, numEvents, "CollectionStop");
1060+
1061+
public void WaitForEndInstrumentReporting(TimeSpan timeout, int numEvents) => WaitForEvent(timeout, numEvents, "EndInstrumentReporting");
1062+
1063+
public void WaitForEnumerationComplete(TimeSpan timeout) => WaitForEvent(timeout, 1, "InitialInstrumentEnumerationComplete");
10111064

1012-
public void WaitForEndInstrumentReporting(TimeSpan timeout, int numEvents)
1065+
public void WaitForMultipleSessionsNotSupportedError(TimeSpan timeout) => WaitForEvent(timeout, 1, "MultipleSessionsNotSupportedError");
1066+
1067+
void WaitForEvent(TimeSpan timeout, int numEvents, string eventName)
10131068
{
10141069
DateTime startTime = DateTime.Now;
10151070
DateTime stopTime = startTime + timeout;
1016-
int initialEventCount = GetCountEndInstrumentReporting();
1071+
int initialEventCount = GetCountEvents(eventName);
10171072
while (true)
10181073
{
1019-
if (GetCountEndInstrumentReporting() >= numEvents)
1074+
if (GetCountEvents(eventName) >= numEvents)
10201075
{
10211076
return;
10221077
}
10231078
TimeSpan remainingTime = stopTime - DateTime.Now;
10241079
if (remainingTime.TotalMilliseconds < 0 || !_autoResetEvent.WaitOne(remainingTime))
10251080
{
1026-
int currentEventCount = GetCountEndInstrumentReporting();
1027-
throw new TimeoutException("Timed out waiting for a EndInstrumentReporting event. " +
1081+
int currentEventCount = GetCountEvents(eventName);
1082+
throw new TimeoutException($"Timed out waiting for a {eventName} event. " +
10281083
$"StartTime={startTime} stopTime={stopTime} initialEventCount={initialEventCount} currentEventCount={currentEventCount} targetEventCount={numEvents}");
10291084
}
10301085
}
10311086
}
10321087

1033-
public void WaitForEnumerationComplete(TimeSpan timeout)
1034-
{
1035-
DateTime startTime = DateTime.Now;
1036-
DateTime stopTime = startTime + timeout;
1037-
int initialEventCount = GetCountEnumerationComplete();
1038-
while (true)
1039-
{
1040-
if (GetCountEnumerationComplete() >= 1)
1041-
{
1042-
return;
1043-
}
1044-
TimeSpan remainingTime = stopTime - DateTime.Now;
1045-
if (remainingTime.TotalMilliseconds < 0 || !_autoResetEvent.WaitOne(remainingTime))
1046-
{
1047-
int currentEventCount = GetCountEnumerationComplete();
1048-
throw new TimeoutException("Timed out waiting for a EndInstrumentReporting event. " +
1049-
$"StartTime={startTime} stopTime={stopTime} initialEventCount={initialEventCount} currentEventCount={currentEventCount}");
1050-
}
1051-
}
1052-
}
1088+
10531089

10541090
private void AssertOnError()
10551091
{
@@ -1064,29 +1100,12 @@ private void AssertOnError()
10641100
}
10651101
}
10661102

1067-
private int GetCountCollectionStops()
1103+
private int GetCountEvents(string eventName)
10681104
{
10691105
lock (this)
10701106
{
10711107
AssertOnError();
1072-
return Events.Where(e => e.EventName == "CollectionStop").Count();
1073-
}
1074-
}
1075-
1076-
private int GetCountEndInstrumentReporting()
1077-
{
1078-
lock (this)
1079-
{
1080-
AssertOnError();
1081-
return Events.Where(e => e.EventName == "EndInstrumentReporting").Count();
1082-
}
1083-
}
1084-
1085-
private int GetCountEnumerationComplete()
1086-
{
1087-
lock (this)
1088-
{
1089-
return Events.Where(e => e.EventName == "InitialInstrumentEnumerationComplete").Count();
1108+
return Events.Where(e => e.EventName == eventName).Count();
10901109
}
10911110
}
10921111
}

0 commit comments

Comments
 (0)