public void ForwardedPipProcessErrorTest()
{
var eventName = "PipProcessError";
var text = "Pip process error message";
var pipSemiStableHash = (long)24;
m_eventListener.RegisterEventSource(global::BuildXL.Engine.ETWLogger.Log);
m_eventListener.NestedLoggerHandler += eventData =>
{
m_eventFields = new PipProcessErrorEventFields(eventData.Payload, true);
};
using (var testElements = PipProcessErrorTestElement.Create(this))
using (AzureDevOpsListener listener = new AzureDevOpsListener(Events.Log, testElements.Console, DateTime.Now, testElements.ViewModel, false, null))
{
listener.RegisterEventSource(global::BuildXL.Engine.ETWLogger.Log);
global::BuildXL.Engine.Tracing.Logger.Log.DistributionWorkerForwardedError(LoggingContext, new WorkerForwardedEvent()
{
EventId = (int)LogEventId.PipProcessError,
EventName = eventName,
EventKeywords = 0,
Text = text,
PipProcessErrorEvent = testElements.PipProcessError,
});
testElements.Console.ValidateCall(MessageLevel.Info, testElements.ExpectingConsoleLog);
XAssert.IsTrue(testElements.ViewModel.BuildSummary.PipErrors.Any(e => e.SemiStablePipId == $"Pip{(pipSemiStableHash):X16}"));
XAssert.AreEqual(m_eventFields, testElements.PipProcessError, "You may edit the PipProcessError and/or WorkerForwardedEvent fields, and/or struct PipProcessErrorEventFields.");
AssertErrorEventLogged(SharedLogEventId.DistributionWorkerForwardedError);
}
}
public static PipProcessErrorTestElement Create(BuildXLTestBase testBase)
{
var result = new PipProcessErrorTestElement();
var pipProcessError = new PipProcessErrorEventFields(
(long)24,
"my cool pip",
@"specs\mypip.dsc",
@"specs\workingDir",
"coolpip.exe",
"Failure message Line1\r\nFailure message Line2\rFailure message Line3\n",
"Find output file in following path:",
@"specs\workingDir\out.txt",
-1,
"what does this do?",
"my pip");
var processedOutputToLog = "Failure message Line1%0D%0A##[error]Failure message Line2%0D##[error]Failure message Line3%0A##[error]";
result.ExpectingConsoleLog = @$ "##vso[task.logIssue type=error;]DX0064 [Pip0000000000000018, {pipProcessError.ShortPipDescription}, {pipProcessError.PipSpecPath}] - failed with exit code {pipProcessError.ExitCode}, {pipProcessError.OptionalMessage}%0D%0A##[error]{processedOutputToLog}%0D%0A##[error]{pipProcessError.MessageAboutPathsToLog}%0D%0A##[error]{pipProcessError.PathsToLog}";
result.PipProcessError = pipProcessError;
result.Console = new MockConsole();
result.ViewModel = new BuildViewModel();
var buildSummaryFilePath = Path.Combine(testBase.TestOutputDirectory, "test.md");
result.ViewModel.BuildSummary = new BuildSummary(buildSummaryFilePath);
result.m_loggingContext = testBase.LoggingContext;
return(result);
}
public void ValidateErrorCap()
{
m_eventListener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
m_eventListener.NestedLoggerHandler += eventData =>
{
m_eventFields = new PipProcessErrorEventFields(eventData.Payload, false);
};
using (var testElements = PipProcessErrorTestElement.Create(this))
using (AzureDevOpsListener listener = new AzureDevOpsListener(Events.Log, testElements.Console, DateTime.Now, testElements.ViewModel, false, null, maxIssuesToLog: 1))
{
listener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
// First log should go through as normal
testElements.LogPipProcessError();
testElements.Console.ValidateCall(MessageLevel.Info, testElements.ExpectingConsoleLog);
// Second will log the message about being truncated
testElements.LogPipProcessError();
testElements.Console.ValidateCall(MessageLevel.Info, "truncated");
// Third should result in no more messages logged
testElements.LogPipProcessError();
testElements.Console.ValidateNoCall();
}
// The TestEventListener is watching all errors, not the AzureDevOpsListener processed ones. Make sure it's cool with seeing 3 errors
AssertErrorEventLogged(LogEventId.PipProcessError, 3);
}
private (PipProcessErrorEventFields pipProcessError, string expectingConsoleLog, MockConsole console, BuildViewModel viewModel) CreatePipProcessErrorTestElement()
{
var pipProcessError = new PipProcessErrorEventFields(
(long)24,
"my cool pip",
@"specs\mypip.dsc",
@"specs\workingDir",
"coolpip.exe",
"Failure message Line1\r\nFailure message Line2\rFailure message Line3\n",
"Find output file in following path:",
@"specs\workingDir\out.txt",
-1,
"what does this do?",
"my pip");
var processedOutputToLog = "Failure message Line1%0D%0A##[error]Failure message Line2%0D##[error]Failure message Line3%0A##[error]";
var expectingConsoleLog = @$ "##vso[task.logIssue type=error;][Pip0000000000000018, {pipProcessError.ShortPipDescription}, {pipProcessError.PipSpecPath}] - failed with exit code {pipProcessError.ExitCode}, {pipProcessError.OptionalMessage}%0D%0A##[error]{processedOutputToLog}%0D%0A##[error]{pipProcessError.MessageAboutPathsToLog}%0D%0A##[error]{pipProcessError.PathsToLog}";
var console = new MockConsole();
var viewModel = new BuildViewModel();
var buildSummaryFilePath = Path.Combine(TestOutputDirectory, "test.md");
viewModel.BuildSummary = new BuildSummary(buildSummaryFilePath);
return(pipProcessError, expectingConsoleLog, console, viewModel);
}
public void LogAzureDevOpsIssueTest()
{
m_eventListener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
m_eventListener.NestedLoggerHandler += eventData =>
{
m_eventFields = new PipProcessErrorEventFields(eventData.Payload, false);
};
var testElements = CreatePipProcessErrorTestElement();
using (AzureDevOpsListener listener = new AzureDevOpsListener(Events.Log, testElements.console, DateTime.Now, testElements.viewModel, false, null))
{
listener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
global::BuildXL.Processes.Tracing.Logger.Log.PipProcessError(LoggingContext,
testElements.pipProcessError.PipSemiStableHash,
testElements.pipProcessError.PipDescription,
testElements.pipProcessError.PipSpecPath,
testElements.pipProcessError.PipWorkingDirectory,
testElements.pipProcessError.PipExe,
testElements.pipProcessError.OutputToLog,
testElements.pipProcessError.MessageAboutPathsToLog,
testElements.pipProcessError.PathsToLog,
testElements.pipProcessError.ExitCode,
testElements.pipProcessError.OptionalMessage,
testElements.pipProcessError.ShortPipDescription);
testElements.console.ValidateCall(MessageLevel.Info, testElements.expectingConsoleLog);
XAssert.AreEqual(m_eventFields, testElements.pipProcessError, "You may edit the PipProcessError event fields, update the test and/or struct PipProcessErrorEventFields.");
AssertErrorEventLogged(LogEventId.PipProcessError);
}
}
protected override async void Output(EventLevel level, EventWrittenEventArgs eventData, string text, bool doNotTranslatePaths = false)
{
if ((level != EventLevel.Error) && (level != EventLevel.Warning))
{
return;
}
if (((long)eventData.Keywords & (long)Keywords.NotForwardedToMaster) > 0)
{
return;
}
try
{
PipProcessErrorEvent pipProcessErrorEvent = null;
if (eventData.EventId == (int)LogEventId.PipProcessError)
{
var pipProcessErrorEventFields = new PipProcessErrorEventFields(eventData.Payload, false);
pipProcessErrorEvent = new PipProcessErrorEvent()
{
PipSemiStableHash = pipProcessErrorEventFields.PipSemiStableHash,
PipDescription = pipProcessErrorEventFields.PipDescription,
PipSpecPath = pipProcessErrorEventFields.PipSpecPath,
PipWorkingDirectory = pipProcessErrorEventFields.PipWorkingDirectory,
PipExe = pipProcessErrorEventFields.PipExe,
OutputToLog = pipProcessErrorEventFields.OutputToLog,
MessageAboutPathsToLog = pipProcessErrorEventFields.MessageAboutPathsToLog,
PathsToLog = pipProcessErrorEventFields.PathsToLog,
ExitCode = pipProcessErrorEventFields.ExitCode,
OptionalMessage = pipProcessErrorEventFields.OptionalMessage,
ShortPipDescription = pipProcessErrorEventFields.ShortPipDescription,
};
}
await m_workerService.SendEventMessagesAsync(
forwardedEvents : new List <EventMessage>(1)
{
new EventMessage()
{
Id = Interlocked.Increment(ref m_nextEventId),
Level = (int)level,
EventKeywords = (long)eventData.Keywords,
EventId = eventData.EventId,
EventName = eventData.EventName,
Text = text,
PipProcessErrorEvent = pipProcessErrorEvent,
},
});
}
catch (Exception ex) when(ExceptionUtilities.HandleUnexpectedException(ex))
{
// Do nothing. Exception filter handles the logic.
}
}
private void LogAzureDevOpsIssue(EventWrittenEventArgs eventData, string eventType)
{
using (var pooledInstance = Pools.StringBuilderPool.GetInstance())
{
var builder = pooledInstance.Instance;
builder.Append("##vso[task.logIssue type=");
builder.Append(eventType);
int dxCode = eventData.EventId;
var message = eventData.Message;
var args = eventData.Payload == null?CollectionUtilities.EmptyArray <object>() : eventData.Payload.ToArray();
string body;
var newArgs = args;
// construct a short message for ADO console
if ((eventData.EventId == (int)LogEventId.PipProcessError) ||
(eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedError && (int)args[1] == (int)LogEventId.PipProcessError))
{
dxCode = (int)LogEventId.PipProcessError;
var pipProcessError = new PipProcessErrorEventFields(eventData.Payload, eventData.EventId != (int)LogEventId.PipProcessError);
args[0] = Pip.FormatSemiStableHash(pipProcessError.PipSemiStableHash);
args[1] = pipProcessError.ShortPipDescription;
args[2] = pipProcessError.PipSpecPath;
args[3] = pipProcessError.ExitCode;
args[4] = pipProcessError.OptionalMessage;
args[5] = pipProcessError.OutputToLog;
args[6] = pipProcessError.MessageAboutPathsToLog;
args[7] = pipProcessError.PathsToLog;
message = "[{0}, {1}, {2}] - failed with exit code {3}, {4}\r\n{5}\r\n{6}\r\n{7}";
}
else if (eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedError || eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedWarning)
{
message = "{0}";
}
body = string.Format(CultureInfo.CurrentCulture, message, args);
builder.Append(";]");
// DX code
builder.Append("DX");
builder.Append(dxCode.ToString("D4"));
builder.Append(' ');
// substitute newlines in the message
var encodedBody = body.Replace("\r\n", $"%0D%0A##[{eventType}]")
.Replace("\r", $"%0D##[{eventType}]")
.Replace("\n", $"%0A##[{eventType}]");
builder.Append(encodedBody);
m_console.WriteOutputLine(MessageLevel.Info, builder.ToString());
}
}
public void LogAzureDevOpsIssueTest()
{
m_eventListener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
m_eventListener.NestedLoggerHandler += eventData =>
{
m_eventFields = new PipProcessErrorEventFields(eventData.Payload, false);
};
using (var testElements = PipProcessErrorTestElement.Create(this))
using (AzureDevOpsListener listener = new AzureDevOpsListener(Events.Log, testElements.Console, DateTime.Now, testElements.ViewModel, false, null))
{
listener.RegisterEventSource(global::BuildXL.Processes.ETWLogger.Log);
testElements.LogPipProcessError();
testElements.Console.ValidateCall(MessageLevel.Info, testElements.ExpectingConsoleLog);
XAssert.AreEqual(m_eventFields, testElements.PipProcessError, "You may edit the PipProcessError event fields, update the test and/or struct PipProcessErrorEventFields.");
AssertErrorEventLogged(LogEventId.PipProcessError);
}
}
public async Task ReceivedWorkerNotificationAsync(WorkerNotificationArgs notification)
{
var worker = GetWorkerById(notification.WorkerId);
if (notification.ExecutionLogData.Count != 0)
{
// The channel is unblocked and ACK is sent after we put the execution blob to the queue in 'LogExecutionBlobAsync' method.
await worker.LogExecutionBlobAsync(notification);
}
// Return immediately to unblock the channel so that worker can receive the ACK for the sent message
await Task.Yield();
foreach (var forwardedEvent in notification.ForwardedEvents)
{
EventLevel eventLevel = (EventLevel)forwardedEvent.Level;
// For some errors, we need to exit the worker.
// Those errors should not make the master fail,
// so we override the level with Warning.
if (await worker.NotifyInfrastructureErrorAsync(forwardedEvent))
{
eventLevel = EventLevel.Warning;
}
switch (eventLevel)
{
case EventLevel.Error:
var status = worker.Status;
// If we receive new failures from an already stopped worker (we're not talking to it anymore), we log them as verbose events instead.
// This prevents logging errors for failed work that we retried elsewhere after abandoning that worker: in those cases,
// the build will succeed but we will complain about the logged errors and crash.
var shouldLogForwardedErrorAsVerbose = status == WorkerNodeStatus.Stopped;
Action <LoggingContext, WorkerForwardedEvent> logForwardedError =
shouldLogForwardedErrorAsVerbose ? Logger.Log.StoppedDistributionWorkerForwardedError : Logger.Log.DistributionWorkerForwardedError;
if (forwardedEvent.EventId == (int)BuildXL.Processes.Tracing.LogEventId.PipProcessError)
{
var pipProcessErrorEvent = new PipProcessErrorEventFields(
forwardedEvent.PipProcessErrorEvent.PipSemiStableHash,
forwardedEvent.PipProcessErrorEvent.PipDescription,
forwardedEvent.PipProcessErrorEvent.PipSpecPath,
forwardedEvent.PipProcessErrorEvent.PipWorkingDirectory,
forwardedEvent.PipProcessErrorEvent.PipExe,
forwardedEvent.PipProcessErrorEvent.OutputToLog,
forwardedEvent.PipProcessErrorEvent.MessageAboutPathsToLog,
forwardedEvent.PipProcessErrorEvent.PathsToLog,
forwardedEvent.PipProcessErrorEvent.ExitCode,
forwardedEvent.PipProcessErrorEvent.OptionalMessage,
forwardedEvent.PipProcessErrorEvent.ShortPipDescription);
logForwardedError(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
PipProcessErrorEvent = pipProcessErrorEvent,
});
}
else
{
logForwardedError(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
});
}
if (!shouldLogForwardedErrorAsVerbose)
{
m_loggingContext.SpecifyErrorWasLogged((ushort)forwardedEvent.EventId);
}
break;
case EventLevel.Warning:
Logger.Log.DistributionWorkerForwardedWarning(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
});
break;
default:
break;
}
}
foreach (PipCompletionData completedPip in notification.CompletedPips)
{
worker.NotifyPipCompletion(completedPip);
}
}
private void LogAzureDevOpsIssue(EventWrittenEventArgs eventData, string eventType)
{
using (var pooledInstance = Pools.StringBuilderPool.GetInstance())
{
var builder = pooledInstance.Instance;
builder.Append("##vso[task.logIssue type=");
builder.Append(eventType);
var message = eventData.Message;
var args = eventData.Payload == null?CollectionUtilities.EmptyArray <object>() : eventData.Payload.ToArray();
string body;
// see if this event provides provenance info
if (message.StartsWith(EventConstants.ProvenancePrefix, StringComparison.Ordinal))
{
Contract.Assume(args.Length >= 3, "Provenance prefix contains 3 formatting tokens.");
// file
builder.Append(";sourcepath=");
builder.Append(args[0]);
//line
builder.Append(";linenumber=");
builder.Append(args[1]);
//column
builder.Append(";columnnumber=");
builder.Append(args[2]);
//code
builder.Append(";code=DX");
builder.Append(eventData.EventId.ToString("D4"));
}
var newArgs = args;
// construct a short message for ADO console
if ((eventData.EventId == (int)LogEventId.PipProcessError) ||
(eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedError && (int)args[1] == (int)LogEventId.PipProcessError))
{
var pipProcessError = new PipProcessErrorEventFields(eventData.Payload, eventData.EventId != (int)LogEventId.PipProcessError);
args[0] = Pip.FormatSemiStableHash(pipProcessError.PipSemiStableHash);
args[1] = pipProcessError.ShortPipDescription;
args[2] = pipProcessError.PipSpecPath;
args[3] = pipProcessError.ExitCode;
args[4] = pipProcessError.OptionalMessage;
args[5] = pipProcessError.OutputToLog;
args[6] = pipProcessError.MessageAboutPathsToLog;
args[7] = pipProcessError.PathsToLog;
message = "[{0}, {1}, {2}] - failed with exit code {3}, {4}\r\n{5}\r\n{6}\r\n{7}";
}
else if (eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedError || eventData.EventId == (int)SharedLogEventId.DistributionWorkerForwardedWarning)
{
message = "{0}";
}
body = string.Format(CultureInfo.CurrentCulture, message, args);
builder.Append(";]");
// substitute newlines in the message
var encodedBody = body.Replace("\r\n", $"%0D%0A##[{eventType}]")
.Replace("\r", $"%0D##[{eventType}]")
.Replace("\n", $"%0A##[{eventType}]");
builder.Append(encodedBody);
m_console.WriteOutputLine(MessageLevel.Info, builder.ToString());
}
}
public async Task ReceivedWorkerNotificationAsync(WorkerNotificationArgs notification)
{
var worker = GetWorkerById(notification.WorkerId);
if (notification.ExecutionLogData.Count != 0)
{
// The channel is unblocked and ACK is sent after we put the execution blob to the queue in 'LogExecutionBlobAsync' method.
await worker.LogExecutionBlobAsync(notification);
}
// Return immediately to unblock the channel so that worker can receive the ACK for the sent message
await Task.Yield();
foreach (var forwardedEvent in notification.ForwardedEvents)
{
EventLevel eventLevel = (EventLevel)forwardedEvent.Level;
// For some errors, we need to exit the worker.
// Those errors should not make the master fail,
// so we override the level with Warning.
if (await worker.NotifyInfrastructureErrorAsync(forwardedEvent))
{
eventLevel = EventLevel.Warning;
}
switch (eventLevel)
{
case EventLevel.Error:
if (forwardedEvent.EventId == (int)BuildXL.Processes.Tracing.LogEventId.PipProcessError)
{
var pipProcessErrorEvent = new PipProcessErrorEventFields(
forwardedEvent.PipProcessErrorEvent.PipSemiStableHash,
forwardedEvent.PipProcessErrorEvent.PipDescription,
forwardedEvent.PipProcessErrorEvent.PipSpecPath,
forwardedEvent.PipProcessErrorEvent.PipWorkingDirectory,
forwardedEvent.PipProcessErrorEvent.PipExe,
forwardedEvent.PipProcessErrorEvent.OutputToLog,
forwardedEvent.PipProcessErrorEvent.MessageAboutPathsToLog,
forwardedEvent.PipProcessErrorEvent.PathsToLog,
forwardedEvent.PipProcessErrorEvent.ExitCode,
forwardedEvent.PipProcessErrorEvent.OptionalMessage,
forwardedEvent.PipProcessErrorEvent.ShortPipDescription);
Logger.Log.DistributionWorkerForwardedError(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
PipProcessErrorEvent = pipProcessErrorEvent,
});
}
else
{
Logger.Log.DistributionWorkerForwardedError(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
});
}
m_loggingContext.SpecifyErrorWasLogged((ushort)forwardedEvent.EventId);
break;
case EventLevel.Warning:
Logger.Log.DistributionWorkerForwardedWarning(
m_loggingContext,
new WorkerForwardedEvent()
{
Text = forwardedEvent.Text,
WorkerName = worker.Name,
EventId = forwardedEvent.EventId,
EventName = forwardedEvent.EventName,
EventKeywords = forwardedEvent.EventKeywords,
});
break;
default:
break;
}
}
foreach (PipCompletionData completedPip in notification.CompletedPips)
{
worker.NotifyPipCompletion(completedPip);
}
}
