public static IDisposable SetupEventListener(EventLevel level)
{
var eventListener = new ConsoleEventListener(Events.Log, DateTime.UtcNow, true, true, true, false, level: level);
var primarySource = bxlScriptAnalyzer.ETWLogger.Log;
if (primarySource.ConstructionException != null)
{
throw primarySource.ConstructionException;
}
eventListener.RegisterEventSource(primarySource);
eventListener.EnableTaskDiagnostics(BuildXL.Tracing.ETWLogger.Tasks.CommonInfrastructure);
var eventSources = new EventSource[]
{
bxlScriptAnalyzer.ETWLogger.Log,
BuildXL.Engine.Cache.ETWLogger.Log,
BuildXL.Engine.ETWLogger.Log,
BuildXL.Scheduler.ETWLogger.Log,
BuildXL.Tracing.ETWLogger.Log,
BuildXL.Storage.ETWLogger.Log,
}.Concat(FrontEndControllerFactory.GeneratedEventSources);
using (var dummy = new TrackingEventListener(Events.Log))
{
foreach (var eventSource in eventSources)
{
Events.Log.RegisterMergedEventSource(eventSource);
}
}
return(eventListener);
}
public void TestErrorCategorization()
{
using (var listener = new TrackingEventListener(Events.Log))
{
string testMessage = "Message from test event";
Events.Log.UserErrorEvent(testMessage);
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(1, listener.UserErrorDetails.Count);
XAssert.AreEqual(0, listener.InfrastructureErrorDetails.Count);
XAssert.AreEqual(0, listener.InternalErrorDetails.Count);
XAssert.AreEqual("UserErrorEvent", listener.UserErrorDetails.FirstErrorName);
XAssert.IsTrue(listener.UserErrorDetails.FirstErrorMessage.Contains(testMessage));
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.InfrastructureErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(0, listener.UserErrorDetails.Count);
XAssert.AreEqual(1, listener.InfrastructureErrorDetails.Count);
XAssert.AreEqual(0, listener.InternalErrorDetails.Count);
XAssert.AreEqual("InfrastructureErrorEvent", listener.InfrastructureErrorDetails.FirstErrorName);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.ErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(0, listener.UserErrorDetails.Count);
XAssert.AreEqual(0, listener.InfrastructureErrorDetails.Count);
XAssert.AreEqual(1, listener.InternalErrorDetails.Count);
XAssert.AreEqual("ErrorEvent", listener.InternalErrorDetails.FirstErrorName);
}
}
public void TestErrorReplayedFromWorker(bool isUserError)
{
using (var listener = new TrackingEventListener(Events.Log))
{
listener.RegisterEventSource(global::BuildXL.Engine.ETWLogger.Log);
const string ErrorName = "MyTestEvent";
const string ErrorText = "Event logged from worker";
LoggingContext loggingContext = BuildXL.TestUtilities.Xunit.XunitBuildXLTest.CreateLoggingContextForTest();
global::BuildXL.Engine.Tracing.Logger.Log.DistributionWorkerForwardedError(loggingContext, new global::BuildXL.Engine.Tracing.WorkerForwardedEvent()
{
EventId = 100,
EventName = ErrorName,
EventKeywords = isUserError ? (int)global::BuildXL.Utilities.Instrumentation.Common.Keywords.UserError : 0,
Text = ErrorText,
});
XAssert.IsTrue(listener.HasFailures);
if (isUserError)
{
XAssert.AreEqual(1, listener.UserErrorDetails.Count);
XAssert.AreEqual(0, listener.InternalErrorDetails.Count);
XAssert.AreEqual(ErrorName, listener.UserErrorDetails.FirstErrorName);
XAssert.AreEqual(ErrorText, listener.UserErrorDetails.FirstErrorMessage);
}
else
{
XAssert.AreEqual(0, listener.UserErrorDetails.Count);
XAssert.AreEqual(1, listener.InternalErrorDetails.Count);
XAssert.AreEqual(ErrorName, listener.InternalErrorDetails.FirstErrorName);
XAssert.AreEqual(ErrorText, listener.InternalErrorDetails.FirstErrorMessage);
}
}
}
public void TrackingEventListenerHasFailuresOrWarnings()
{
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.VerboseEvent("1");
Events.Log.InfoEvent("1");
Events.Log.AlwaysEvent("1");
XAssert.IsFalse(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.WarningEvent("1");
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.ErrorEvent("1");
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.CriticalEvent("1");
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
}
public void TestErrorCategorization()
{
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.UserErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(1, listener.UserErrorCount);
XAssert.AreEqual(0, listener.InfrastructureErrorCount);
XAssert.AreEqual(0, listener.InternalErrorCount);
XAssert.AreEqual("UserErrorEvent", listener.FirstUserErrorName);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.InfrastructureErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(0, listener.UserErrorCount);
XAssert.AreEqual(1, listener.InfrastructureErrorCount);
XAssert.AreEqual(0, listener.InternalErrorCount);
XAssert.AreEqual("InfrastructureErrorEvent", listener.FirstInfrastructureErrorName);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.ErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.AreEqual(0, listener.UserErrorCount);
XAssert.AreEqual(0, listener.InfrastructureErrorCount);
XAssert.AreEqual(1, listener.InternalErrorCount);
XAssert.AreEqual("ErrorEvent", listener.FirstInternalErrorName);
}
}
public void WarningMapping()
{
TestEvents log = TestEvents.Log;
var wm = new WarningManager();
using (var listener = new TrackingEventListener(Events.Log, warningMapper: wm.GetState))
{
listener.RegisterEventSource(TestEvents.Log);
// should log as a warning
XAssert.AreEqual(0, listener.WarningCount);
log.WarningEvent("1");
XAssert.AreEqual(1, listener.WarningCount);
XAssert.AreEqual(0, listener.TotalErrorCount);
wm.SetState(WarningEventId, WarningState.AsError);
// should log as an error
log.WarningEvent("1");
XAssert.AreEqual(1, listener.TotalErrorCount);
XAssert.AreEqual(1, listener.WarningCount);
wm.SetState(WarningEventId, WarningState.Suppressed);
// should be suppressed
log.WarningEvent("1");
XAssert.AreEqual(1, listener.WarningCount);
XAssert.AreEqual(1, listener.TotalErrorCount);
}
using (var listener = new TrackingEventListener(Events.Log, warningMapper: wm.GetState))
{
listener.RegisterEventSource(TestEvents.Log);
// should log as a info
XAssert.AreEqual(0, listener.InformationalCount);
log.InfoEvent("1");
XAssert.AreEqual(1, listener.InformationalCount);
XAssert.AreEqual(0, listener.WarningCount);
XAssert.AreEqual(0, listener.TotalErrorCount);
wm.SetState(InfoEventId, WarningState.AsError);
// should not log as an error (only warnings are managed by warning mapper)
log.InfoEvent("1");
XAssert.AreEqual(2, listener.InformationalCount);
XAssert.AreEqual(0, listener.TotalErrorCount);
wm.SetState(InfoEventId, WarningState.Suppressed);
// should not be suppressed (only warnings are managed by warning mapper)
log.InfoEvent("1");
XAssert.AreEqual(3, listener.InformationalCount);
XAssert.AreEqual(0, listener.TotalErrorCount);
}
}
public void DistributedBuildConnectivityIssueTrumpsOtherErrors()
{
var loggingContext = XunitBuildXLTest.CreateLoggingContextForTest();
using (var listener = new TrackingEventListener(Events.Log))
{
listener.RegisterEventSource(global::BuildXL.Engine.ETWLogger.Log);
listener.RegisterEventSource(global::BuildXL.Scheduler.ETWLogger.Log);
global::BuildXL.Scheduler.Tracing.Logger.Log.PipMaterializeDependenciesFromCacheFailure(loggingContext, "ArbitraryPip", "ArbitraryMessage");
global::BuildXL.Engine.Tracing.Logger.Log.DistributionExecutePipFailedNetworkFailure(loggingContext, "ArbitraryPip", "ArbitraryWorker", "ArbitraryMessage", "ArbitraryStep", "ArbitraryCaller");
global::BuildXL.Scheduler.Tracing.Logger.Log.PipMaterializeDependenciesFromCacheFailure(loggingContext, "ArbitraryPip", "ArbitraryMessage");
var infrastructureErrorClassification = BuildXLApp.ClassifyFailureFromLoggedEvents(listener);
XAssert.AreEqual(ExitKind.InfrastructureError, infrastructureErrorClassification.ExitKind);
XAssert.AreEqual(global::BuildXL.Engine.Tracing.LogEventId.DistributionExecutePipFailedNetworkFailure.ToString(), infrastructureErrorClassification.ErrorBucket);
}
}
public void BaseEventListener()
{
// make sure this thing only deals with the BuildXL event source
using (var listener = new TrackingEventListener(Events.Log))
{
// this one should get through
Events log = Events.Log;
log.InfoEvent("Test 1");
XAssert.AreEqual(listener.InformationalCount, 1);
// this one should not
using (var log2 = new TestEventSource())
{
log2.InfoEvent("Test 1");
XAssert.AreEqual(listener.InformationalCount, 1);
}
}
}
public static IDisposable SetupLogging(EventLevel level, IEventWriter writer)
{
var eventListener = new TextWriterEventListener(eventSource: Events.Log, writer: writer, baseTime: DateTime.UtcNow, level: level);
var primarySource = bxl.ETWLogger.Log;
if (primarySource.ConstructionException != null)
{
// Rethrow an exception preserving the original stack trace.
var edi = ExceptionDispatchInfo.Capture(primarySource.ConstructionException);
edi.Throw();
// This code is unreachable, but compiler doesn't know about it.
throw null;
}
eventListener.RegisterEventSource(primarySource);
eventListener.EnableTaskDiagnostics(BuildXL.Tracing.ETWLogger.Tasks.CommonInfrastructure);
AriaV2StaticState.Enable(AriaTenantToken.Key);
var eventSources = new EventSource[]
{
bxl.ETWLogger.Log,
BuildXL.Engine.Cache.ETWLogger.Log,
BuildXL.Engine.ETWLogger.Log,
BuildXL.Scheduler.ETWLogger.Log,
BuildXL.Tracing.ETWLogger.Log,
bxlScriptAnalyzer.ETWLogger.Log,
BuildXL.Ide.LanguageServer.ETWLogger.Log,
BuildXL.FrontEnd.Core.ETWLogger.Log,
BuildXL.FrontEnd.Script.ETWLogger.Log,
BuildXL.FrontEnd.Nuget.ETWLogger.Log,
};
using (var listener = new TrackingEventListener(Events.Log))
{
foreach (var eventSource in eventSources)
{
Events.Log.RegisterMergedEventSource(eventSource);
}
}
return(eventListener);
}
public void ErrorPrecedence()
{
using (var listener = new TrackingEventListener(Events.Log))
{
Events.Log.UserErrorEvent("1");
var userErrorClassification = BuildXLApp.ClassifyFailureFromLoggedEvents(listener);
XAssert.AreEqual(ExitKind.UserError, userErrorClassification.ExitKind);
XAssert.AreEqual("UserErrorEvent", userErrorClassification.ErrorBucket);
// Now add an infrasctructure error. This should take prescedence
Events.Log.InfrastructureErrorEvent("1");
var infrastructureErrorClassification = BuildXLApp.ClassifyFailureFromLoggedEvents(listener);
XAssert.AreEqual(ExitKind.InfrastructureError, infrastructureErrorClassification.ExitKind);
XAssert.AreEqual("InfrastructureErrorEvent", infrastructureErrorClassification.ErrorBucket);
// Finally add an internal error. Again, this takes highest prescedence
Events.Log.ErrorEvent("1");
var internalErrorClassification = BuildXLApp.ClassifyFailureFromLoggedEvents(listener);
XAssert.AreEqual(ExitKind.InternalError, internalErrorClassification.ExitKind);
XAssert.AreEqual("ErrorEvent", internalErrorClassification.ErrorBucket);
}
}
public void UnexpectedConditionTelemetryCapTest()
{
using (var listener = new TrackingEventListener(Events.Log))
{
listener.RegisterEventSource(global::BuildXL.Tracing.ETWLogger.Log);
LoggingContext context = new LoggingContext("Test");
int maxTelemetryUnexpectedConditions = global::BuildXL.Tracing.Logger.MaxTelemetryUnexpectedConditions;
for (int i = 0; i < maxTelemetryUnexpectedConditions + 1; i++)
{
global::BuildXL.Tracing.Logger.Log.UnexpectedCondition(context, "UnexpectedConditionTest");
}
// Make sure only 5 of the 6 events went to telemetry. The 6th events should only go local
XAssert.AreEqual(maxTelemetryUnexpectedConditions, listener.CountsPerEventId(EventId.UnexpectedConditionTelemetry));
XAssert.AreEqual(1, listener.CountsPerEventId(EventId.UnexpectedConditionLocal));
// Now change the logging context for a new session and make sure the event goes to telemetry again
context = new LoggingContext("Test2");
global::BuildXL.Tracing.Logger.Log.UnexpectedCondition(context, "UnexpectedConditionTest");
XAssert.AreEqual(maxTelemetryUnexpectedConditions + 1, listener.CountsPerEventId(EventId.UnexpectedConditionTelemetry));
XAssert.AreEqual(1, listener.CountsPerEventId(EventId.UnexpectedConditionLocal));
}
}
public void TrackingEventListener()
{
const int NumVerbose = 9;
const int NumInfo = 8;
const int NumWarning = 7;
const int NumError = 6;
const int NumCritical = 5;
const int NumAlways = 4;
using (var listener = new TrackingEventListener(Events.Log))
{
Events log = Events.Log;
for (int i = 0; i < NumVerbose; i++)
{
log.VerboseEvent("1");
}
for (int i = 0; i < NumInfo; i++)
{
log.InfoEvent("1");
}
for (int i = 0; i < NumWarning; i++)
{
log.WarningEvent("1");
}
for (int i = 0; i < NumError; i++)
{
log.ErrorEvent("1");
}
for (int i = 0; i < NumCritical; i++)
{
log.CriticalEvent("1");
}
for (int i = 0; i < NumAlways; i++)
{
log.AlwaysEvent("1");
}
XAssert.AreEqual(listener.VerboseCount, NumVerbose);
XAssert.AreEqual(listener.InformationalCount, NumInfo);
XAssert.AreEqual(listener.WarningCount, NumWarning);
XAssert.AreEqual(listener.TotalErrorCount, NumError + NumCritical);
XAssert.AreEqual(listener.CriticalCount, NumCritical);
XAssert.AreEqual(listener.AlwaysCount, NumAlways);
XAssert.IsTrue(listener.HasFailures);
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events log = Events.Log;
XAssert.IsFalse(listener.HasFailures);
XAssert.IsFalse(listener.HasFailuresOrWarnings);
log.WarningEvent("1");
XAssert.IsFalse(listener.HasFailures);
XAssert.IsTrue(listener.HasFailuresOrWarnings);
log.ErrorEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log))
{
Events log = Events.Log;
log.CriticalEvent("1");
XAssert.IsTrue(listener.HasFailures);
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
using (var listener = new TrackingEventListener(Events.Log, warningMapper: _ => WarningState.AsError))
{
Events log = Events.Log;
log.WarningEvent("1");
XAssert.AreEqual(1, listener.TotalErrorCount);
XAssert.IsTrue(listener.HasFailures);
XAssert.IsTrue(listener.HasFailuresOrWarnings);
}
}
