in Public/Src/Engine/Processes/SandboxedProcessPipExecutor.cs [1632:2055]
private async Task<SandboxedProcessPipExecutionResult> ProcessSandboxedProcessResultAsync(
LoggingContext loggingContext,
SandboxedProcessResult result,
long sandboxPrepMs,
CancellationToken cancellationToken,
HashSet<AbsolutePath> allInputPathsUnderSharedOpaques,
ISandboxedProcess process)
{
var sw = System.Diagnostics.Stopwatch.StartNew();
bool canceled = result.Killed && cancellationToken.IsCancellationRequested;
bool hasMessageParsingError = result?.MessageProcessingFailure != null;
bool exitedWithSuccessExitCode = m_pip.SuccessExitCodes.Length == 0
? result.ExitCode == 0
: m_pip.SuccessExitCodes.Contains(result.ExitCode);
bool exitedSuccessfullyAndGracefully = !canceled && exitedWithSuccessExitCode;
bool exitedWithRetryAbleUserError = m_pip.RetryExitCodes.Contains(result.ExitCode) && m_remainingUserRetryCount > 0;
long maxDetoursHeapSize = process.GetDetoursMaxHeapSize() + result.DetoursMaxHeapSize;
Dictionary<string, int> pipProperties = null;
bool allOutputsPresent = false;
bool loggingSuccess = true;
ProcessTimes primaryProcessTimes = result.PrimaryProcessTimes;
JobObject.AccountingInformation? jobAccounting = result.JobAccountingInformation;
var start = DateTime.UtcNow;
// If this operation fails, error was logged already
bool sharedOpaqueProcessingSuccess = TryGetObservedFileAccesses(
result,
allInputPathsUnderSharedOpaques,
out var unobservedOutputs,
out var sharedDynamicDirectoryWriteAccesses,
out SortedReadOnlyArray<ObservedFileAccess, ObservedFileAccessExpandedPathComparer> observed,
out IReadOnlySet<AbsolutePath> createdDirectories);
LogSubPhaseDuration(m_loggingContext, m_pip, SandboxedProcessCounters.SandboxedPipExecutorPhaseGettingObservedFileAccesses, DateTime.UtcNow.Subtract(start), $"(count: {observed.Length})");
TimeSpan time = primaryProcessTimes.TotalWallClockTime;
if (result.TimedOut)
{
LogTookTooLongError(result, m_timeout, time);
if (result.DumpCreationException != null)
{
Tracing.Logger.Log.PipFailedToCreateDumpFile(
loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
result.DumpCreationException.GetLogEventMessage());
}
}
else
{
TimeSpan warningTimeout = GetEffectiveTimeout(
m_pip.WarningTimeout,
m_sandboxConfig.DefaultWarningTimeout,
m_sandboxConfig.WarningTimeoutMultiplier);
if (time > warningTimeout)
{
LogTookTooLongWarning(m_timeout, time, warningTimeout);
}
// There are cases where the process exit code is not successful and the injection has failed.
// (ExitCode code is set by Windows - TerminateProcess, kill(), process crash).
// The build needs to fail in this case(s) as well and log that we had injection failure.
if (result.HasDetoursInjectionFailures)
{
Tracing.Logger.Log.PipProcessFinishedDetourFailures(loggingContext, m_pip.SemiStableHash, m_pipDescription);
}
if (exitedSuccessfullyAndGracefully)
{
Tracing.Logger.Log.PipProcessFinished(loggingContext, m_pip.SemiStableHash, m_pipDescription, result.ExitCode);
allOutputsPresent = CheckExpectedOutputs();
}
else
{
if (!canceled)
{
LogFinishedFailed(result);
var propertiesResult = await TrySetPipPropertiesAsync(result);
pipProperties = propertiesResult.PipProperties;
if (!propertiesResult.Success)
{
Contract.Assert(loggingContext.ErrorWasLogged, "Error should be logged upon TrySetPipPropertiesAsync failure.");
// There was an error logged when extracting properties from the pip. The pip needs to fail and not retry
loggingSuccess = false;
}
else
{
if (exitedWithRetryAbleUserError)
{
Tuple<AbsolutePath, Encoding> encodedStandardError = null;
Tuple<AbsolutePath, Encoding> encodedStandardOutput = null;
if (await TrySaveAndLogStandardOutputAsync(result) && await TrySaveAndLogStandardErrorAsync(result))
{
encodedStandardOutput = GetEncodedStandardConsoleStream(result.StandardOutput);
encodedStandardError = GetEncodedStandardConsoleStream(result.StandardError);
return SandboxedProcessPipExecutionResult.RetryProcessDueToUserSpecifiedExitCode(
result.ExitCode,
primaryProcessTimes,
jobAccounting,
result.DetouringStatuses,
sandboxPrepMs,
sw.ElapsedMilliseconds,
result.ProcessStartTime,
maxDetoursHeapSize,
m_containerConfiguration,
encodedStandardError,
encodedStandardOutput,
pipProperties,
sharedDynamicDirectoryWriteAccesses);
}
Contract.Assert(loggingContext.ErrorWasLogged, "Error should be logged upon TrySaveAndLogStandardOutput/Error failure.");
// There was an error logged when saving stdout or stderror.
loggingSuccess = false;
}
else if (m_sandboxConfig.RetryOnAzureWatsonExitCode && result.Processes.Any(p => p.ExitCode == AzureWatsonExitCode))
{
// Retry if the exit code is 0xDEAD.
var deadProcess = result.Processes.Where(p => p.ExitCode == AzureWatsonExitCode).First();
Tracing.Logger.Log.PipRetryDueToExitedWithAzureWatsonExitCode(
m_loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
deadProcess.Path,
deadProcess.ProcessId);
return SandboxedProcessPipExecutionResult.RetryProcessDueToAzureWatsonExitCode(
result.ExitCode,
primaryProcessTimes,
jobAccounting,
result.DetouringStatuses,
sandboxPrepMs,
sw.ElapsedMilliseconds,
result.ProcessStartTime,
maxDetoursHeapSize,
m_containerConfiguration,
pipProperties);
}
}
}
}
}
int numSurvivingChildErrors = 0;
if (!canceled && result.SurvivingChildProcesses?.Any() == true)
{
numSurvivingChildErrors = ReportSurvivingChildProcesses(result);
}
start = DateTime.UtcNow;
var fileAccessReportingContext = new FileAccessReportingContext(
loggingContext,
m_context,
m_sandboxConfig,
m_pip,
m_validateDistribution,
m_fileAccessAllowlist);
// Note that when MonitorFileAccesses == false, we should not assume the various reported-access sets are non-null.
if (m_sandboxConfig.UnsafeSandboxConfiguration.MonitorFileAccesses)
{
// First remove all the paths that are Injectable from in the process.
RemoveInjectableFileAccesses(result.AllUnexpectedFileAccesses);
foreach (ReportedFileAccess unexpectedFileAccess in result.AllUnexpectedFileAccesses)
{
Contract.Assume(
unexpectedFileAccess.Status == FileAccessStatus.Denied ||
unexpectedFileAccess.Status == FileAccessStatus.CannotDeterminePolicy);
fileAccessReportingContext.ReportFileAccessDeniedByManifest(unexpectedFileAccess);
}
}
if (result.Killed && numSurvivingChildErrors > 0)
{
LogChildrenSurvivedKilled();
}
bool mainProcessExitedCleanly =
(!result.Killed || numSurvivingChildErrors == 0) &&
exitedSuccessfullyAndGracefully;
if (!mainProcessExitedCleanly)
{
Tracing.Logger.Log.PipExitedUncleanly(
loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
canceled,
result.ExitCode,
result.Killed,
numSurvivingChildErrors);
}
// Observe that in some cases stderr reports to have length, but it is zero. Make sure that length > 0 to conclude stderr was written.
bool failedDueToWritingToStdErr = m_pip.WritingToStandardErrorFailsExecution && result.StandardError.HasLength && result.StandardError.Length > 0;
if (failedDueToWritingToStdErr)
{
Tracing.Logger.Log.PipProcessWroteToStandardErrorOnCleanExit(
m_loggingContext,
pipSemiStableHash: m_pip.SemiStableHash,
pipDescription: m_pipDescription,
pipSpecPath: m_pip.Provenance.Token.Path.ToString(m_context.PathTable),
pipWorkingDirectory: m_pip.WorkingDirectory.ToString(m_context.PathTable));
}
// This is the overall success of the process. At a high level, these are the things that can cause a process pip to fail:
// 1. The process being killed (built into mainProcessExitedCleanly)
// 2. The process not exiting with the appropriate exit code (mainProcessExitedCleanly)
// 3. The process not creating all outputs (allOutputsPresent)
// 4. The process running in a container, and even though succeeding, its outputs couldn't be moved to their expected locations
// 5. The process wrote to standard error, and even though it may have exited with a succesfull exit code, WritingToStandardErrorFailsPip
// is set (failedDueToWritingToStdErr)
bool mainProcessSuccess = mainProcessExitedCleanly && allOutputsPresent && !failedDueToWritingToStdErr;
bool standardOutHasBeenWrittenToLog = false;
bool errorOrWarnings = !mainProcessSuccess || m_numWarnings > 0;
bool shouldPersistStandardOutput = errorOrWarnings || m_pip.StandardOutput.IsValid;
if (shouldPersistStandardOutput)
{
if (!await TrySaveStandardOutputAsync(result))
{
loggingSuccess = false;
}
}
bool shouldPersistStandardError = !canceled && (errorOrWarnings || m_pip.StandardError.IsValid);
if (shouldPersistStandardError)
{
if (!await TrySaveStandardErrorAsync(result))
{
loggingSuccess = false;
}
}
LogSubPhaseDuration(m_loggingContext, m_pip, SandboxedProcessCounters.SandboxedPipExecutorPhaseProcessingStandardOutputs, DateTime.UtcNow.Subtract(start));
start = DateTime.UtcNow;
// After standard output and error may been saved, and shared dynamic write accesses were identified, we can merge
// outputs back to their original locations
if (!await m_processInContainerManager.MergeOutputsIfNeededAsync(m_pip, m_containerConfiguration, m_context, sharedDynamicDirectoryWriteAccesses))
{
// If the merge failed, update the status flags
mainProcessSuccess = false;
errorOrWarnings = true;
}
bool errorWasTruncated = false;
// if some outputs are missing or the process wrote to stderr, we are logging this process as a failed one (even if it finished with a success exit code).
if ((!mainProcessExitedCleanly || !allOutputsPresent || failedDueToWritingToStdErr) && !canceled && loggingSuccess)
{
standardOutHasBeenWrittenToLog = true;
// We only checked if all outputs are present if exitedSuccessfullyAndGracefully is true. So if exitedSuccessfullyAndGracefully is false,
// we don't log anything at this respect.
LogErrorResult logErrorResult = await TryLogErrorAsync(result, (!exitedSuccessfullyAndGracefully || allOutputsPresent), failedDueToWritingToStdErr);
errorWasTruncated = logErrorResult.ErrorWasTruncated;
loggingSuccess = logErrorResult.Success;
}
if (m_numWarnings > 0 && loggingSuccess && !canceled)
{
if (!await TryLogWarningAsync(result.StandardOutput, result.StandardError))
{
loggingSuccess = false;
}
}
// The full output may be requested based on the result of the pip. If the pip failed, the output may have been reported
// in TryLogErrorAsync above. Only replicate the output if the error was truncated due to an error regex
if ((!standardOutHasBeenWrittenToLog || errorWasTruncated) && loggingSuccess && !canceled)
{
// If the pip succeeded, we must check if one of the non-error output modes have been chosen
if ((m_sandboxConfig.OutputReportingMode == OutputReportingMode.FullOutputAlways) ||
(m_sandboxConfig.OutputReportingMode == OutputReportingMode.FullOutputOnWarningOrError && errorOrWarnings) ||
(m_sandboxConfig.OutputReportingMode == OutputReportingMode.FullOutputOnError && !mainProcessSuccess))
{
if (!await TryLogOutputAsync(result))
{
loggingSuccess = false;
}
}
}
LogSubPhaseDuration(m_loggingContext, m_pip, SandboxedProcessCounters.SandboxedPipExecutorPhaseLoggingOutputs, DateTime.UtcNow.Subtract(start));
// N.B. here 'observed' means 'all', not observed in the terminology of SandboxedProcessPipExecutor.
List<ReportedFileAccess> allFileAccesses = null;
if (m_sandboxConfig.UnsafeSandboxConfiguration.MonitorFileAccesses && m_sandboxConfig.LogObservedFileAccesses)
{
allFileAccesses = new List<ReportedFileAccess>(result.FileAccesses);
allFileAccesses.AddRange(result.AllUnexpectedFileAccesses);
}
m_logger.LogProcessObservation(
processes: m_sandboxConfig.LogProcesses ? result.Processes : null,
fileAccesses: allFileAccesses,
detouringStatuses: result.DetouringStatuses);
if (mainProcessSuccess && loggingSuccess)
{
Contract.Assert(!shouldPersistStandardOutput || result.StandardOutput.IsSaved);
Contract.Assert(!shouldPersistStandardError || result.StandardError.IsSaved);
}
// Log a warning for having converted ReadWrite file access request to Read file access request and the pip was not canceled and failed.
if (!mainProcessSuccess && !canceled && result.HasReadWriteToReadFileAccessRequest)
{
Tracing.Logger.Log.ReadWriteFileAccessConvertedToReadWarning(loggingContext, m_pip.SemiStableHash, m_pipDescription);
}
var finalStatus = canceled
? SandboxedProcessPipExecutionStatus.Canceled
: (mainProcessSuccess && loggingSuccess
? SandboxedProcessPipExecutionStatus.Succeeded
: SandboxedProcessPipExecutionStatus.ExecutionFailed);
if (result.StandardInputException != null && finalStatus == SandboxedProcessPipExecutionStatus.Succeeded)
{
// When process execution succeeded, standard input exception should not occur.
// Log error to correlate the pip with the standard input exception.
Tracing.Logger.Log.PipProcessStandardInputException(
loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
m_pip.Provenance.Token.Path.ToString(m_pathTable),
m_workingDirectory,
result.StandardInputException.Message + Environment.NewLine + result.StandardInputException.StackTrace);
}
if (hasMessageParsingError)
{
Tracing.Logger.Log.PipProcessMessageParsingError(
loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
result.MessageProcessingFailure.Content);
}
SandboxedProcessPipExecutionStatus status = SandboxedProcessPipExecutionStatus.ExecutionFailed;
RetryInfo retryInfo = null;
if (result.HasDetoursInjectionFailures)
{
status = SandboxedProcessPipExecutionStatus.PreparationFailed;
}
else if (canceled)
{
status = SandboxedProcessPipExecutionStatus.Canceled;
}
else if (!sharedOpaqueProcessingSuccess)
{
status = SandboxedProcessPipExecutionStatus.SharedOpaquePostProcessingFailed;
}
else if (mainProcessSuccess && loggingSuccess && !hasMessageParsingError)
{
status = SandboxedProcessPipExecutionStatus.Succeeded;
}
if (m_sandboxConfig.UnsafeSandboxConfiguration.MonitorFileAccesses &&
m_sandboxConfig.UnsafeSandboxConfiguration.SandboxKind != SandboxKind.MacOsKextIgnoreFileAccesses &&
status == SandboxedProcessPipExecutionStatus.Succeeded &&
m_pip.PipType == PipType.Process &&
unobservedOutputs != null)
{
foreach (var outputPath in unobservedOutputs)
{
// Report non observed access only if the output exists.
// If the output was not produced, missing declared output logic
// will report another error.
string expandedOutputPath = outputPath.ToString(m_pathTable);
bool isFile;
if ((isFile = FileUtilities.FileExistsNoFollow(expandedOutputPath)) ||
FileUtilities.DirectoryExistsNoFollow(expandedOutputPath))
{
Tracing.Logger.Log.PipOutputNotAccessed(
m_loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
"'" + expandedOutputPath + "'. " + (isFile ? "Found path is a file" : "Found path is a directory"));
status = SandboxedProcessPipExecutionStatus.FileAccessMonitoringFailed;
retryInfo = RetryInfo.GetDefault(RetryReason.OutputWithNoFileAccessFailed);
}
}
}
// If a PipProcessError was logged, the pip cannot be marked as succeeded
Contract.Assert(!standardOutHasBeenWrittenToLog || status != SandboxedProcessPipExecutionStatus.Succeeded);
return new SandboxedProcessPipExecutionResult(
status: status,
observedFileAccesses: observed,
sharedDynamicDirectoryWriteAccesses: sharedDynamicDirectoryWriteAccesses,
unexpectedFileAccesses: fileAccessReportingContext,
encodedStandardOutput: loggingSuccess && shouldPersistStandardOutput ? GetEncodedStandardConsoleStream(result.StandardOutput) : null,
encodedStandardError: loggingSuccess && shouldPersistStandardError ? GetEncodedStandardConsoleStream(result.StandardError) : null,
numberOfWarnings: m_numWarnings,
primaryProcessTimes: primaryProcessTimes,
jobAccountingInformation: jobAccounting,
exitCode: result.ExitCode,
sandboxPrepMs: sandboxPrepMs,
processSandboxedProcessResultMs: sw.ElapsedMilliseconds,
processStartTime: result.ProcessStartTime,
allReportedFileAccesses: allFileAccesses,
detouringStatuses: result.DetouringStatuses,
maxDetoursHeapSize: maxDetoursHeapSize,
containerConfiguration: m_containerConfiguration,
pipProperties: pipProperties,
timedOut: result.TimedOut,
retryInfo: retryInfo,
createdDirectories: createdDirectories);
}