Process output streaming fixes

This commit is contained in:
Jordan Brown
2020-07-26 13:31:39 -04:00
parent d460330cab
commit 6399c4cbf1
14 changed files with 180 additions and 171 deletions
+2 -2
View File
@@ -1,4 +1,4 @@
using Microsoft.AspNetCore.Http.Headers;
using Microsoft.AspNetCore.Http.Headers;
using Microsoft.Extensions.Primitives;
using Microsoft.Net.Http.Headers;
using System;
@@ -138,7 +138,7 @@ namespace Tgstation.Server.Api
void AddError(HeaderTypes headerType, string message)
{
if (badHeaders != HeaderTypes.None)
errorBuilder.Append(Environment.NewLine);
errorBuilder.AppendLine();
badHeaders |= headerType;
errorBuilder.Append(message);
}
@@ -292,7 +292,8 @@ namespace Tgstation.Server.Host.Components.Deployment
cancellationToken.ThrowIfCancellationRequested();
logger.LogDebug("DreamMaker exit code: {0}", exitCode);
currentDreamMakerOutput = job.Output = dm.GetCombinedOutput();
job.Output = await dm.GetCombinedOutput(cancellationToken).ConfigureAwait(false);
currentDreamMakerOutput = job.Output;
logger.LogDebug("DreamMaker output: {0}{1}", Environment.NewLine, job.Output);
return exitCode;
}
@@ -257,21 +257,21 @@ namespace Tgstation.Server.Host.Components.Session
if (disposed)
return;
disposed = true;
logger.LogTrace("Disposing...");
if (!released)
{
process.Terminate();
byondLock.Dispose();
}
process.Dispose();
bridgeRegistration?.Dispose();
reattachInformation.Dmb?.Dispose(); // will be null when released
chatTrackingContext.Dispose();
reattachTopicCts.Dispose();
}
logger.LogTrace("Disposing...");
if (!released)
{
process.Terminate();
byondLock.Dispose();
}
process.Dispose();
bridgeRegistration?.Dispose();
reattachInformation.Dmb?.Dispose(); // will be null when released
chatTrackingContext.Dispose();
reattachTopicCts.Dispose();
if (!released)
{
// finish the async callback
@@ -267,8 +267,9 @@ namespace Tgstation.Server.Host.Components.Session
async Task<string> GetDDOutput()
{
// DCT x2: None available
if (!platformIdentifier.IsWindows)
return process.GetCombinedOutput();
return await process.GetCombinedOutput(default).ConfigureAwait(false);
var logFilePath = ioManager.ConcatPath(dmbProvider.Directory, logFileGuid.ToString());
try
@@ -347,9 +348,12 @@ namespace Tgstation.Server.Host.Components.Session
}
catch
{
process.Terminate();
process.Dispose();
throw;
using (process)
{
process.Terminate();
await process.Lifetime.ConfigureAwait(false);
throw;
}
}
}
catch
@@ -133,6 +133,7 @@ namespace Tgstation.Server.Host.Components.Session
{
using var process = processExecutor.GetProcess(reattachInfo.ProcessId);
process.Terminate();
await process.Lifetime.ConfigureAwait(false);
}
catch (Exception ex)
{
@@ -488,7 +488,7 @@ namespace Tgstation.Server.Host.Components.StaticFiles
{
var exitCode = await script.Lifetime.ConfigureAwait(false);
cancellationToken.ThrowIfCancellationRequested();
var scriptOutput = script.GetCombinedOutput();
var scriptOutput = await script.GetCombinedOutput(cancellationToken).ConfigureAwait(false);
if (exitCode != 0)
throw new JobException($"Script {I} exited with code {exitCode}:{Environment.NewLine}{scriptOutput}");
else
+13 -9
View File
@@ -1,4 +1,4 @@
using System;
using System;
using System.Threading;
using System.Threading.Tasks;
@@ -22,24 +22,28 @@ namespace Tgstation.Server.Host.System
/// <summary>
/// Get the stderr output of the <see cref="IProcess"/>
/// </summary>
/// <returns>The stderr output of the <see cref="IProcess"/></returns>
string GetErrorOutput();
/// <param name="cancellationToken">The <see cref="CancellationToken"/> for the operation.</param>
/// <returns>A <see cref="Task{TResult}"/> resulting in the stderr output of the <see cref="IProcess"/></returns>
Task<string> GetErrorOutput(CancellationToken cancellationToken);
/// <summary>
/// Get the stdout output of the <see cref="IProcess"/>
/// </summary>
/// <returns>The stdout output of the <see cref="IProcess"/></returns>
string GetStandardOutput();
/// <param name="cancellationToken">The <see cref="CancellationToken"/> for the operation.</param>
/// <returns>A <see cref="Task{TResult}"/> resulting in the stdout output of the <see cref="IProcess"/></returns>
Task<string> GetStandardOutput(CancellationToken cancellationToken);
/// <summary>
/// Get the stderr and stdout output of the <see cref="IProcess"/>
/// </summary>
/// <returns>The stderr and stdout output of the <see cref="IProcess"/></returns>
string GetCombinedOutput();
/// <param name="cancellationToken">The <see cref="CancellationToken"/> for the operation.</param>
/// <returns>A <see cref="Task{TResult}"/> resulting in the stderr and stdout output of the <see cref="IProcess"/></returns>
Task<string> GetCombinedOutput(CancellationToken cancellationToken);
/// <summary>
/// Terminates the process
/// Asycnhronously terminates the process.
/// </summary>
/// <remarks>To ensure the <see cref="IProcess"/> has ended, use the <see cref="IProcessBase.Lifetime"/> <see cref="Task{TResult}"/>.</remarks>
void Terminate();
/// <summary>
@@ -49,4 +53,4 @@ namespace Tgstation.Server.Host.System
/// <returns>A <see cref="Task{TResult}"/> resulting in the name of the account executing the <see cref="IProcess"/>.</returns>
Task<string> GetExecutingUsername(CancellationToken cancellationToken);
}
}
}
@@ -1,4 +1,4 @@
namespace Tgstation.Server.Host.System
namespace Tgstation.Server.Host.System
{
/// <summary>
/// For launching <see cref="IProcess"/>'
@@ -15,7 +15,13 @@
/// <param name="readError">If standard error should be read</param>
/// <param name="noShellExecute">If shell execute should not be used. Must be set if <paramref name="readError"/> or <paramref name="readOutput"/> are set.</param>
/// <returns>A new <see cref="IProcess"/></returns>
IProcess LaunchProcess(string fileName, string workingDirectory, string arguments = null, bool readOutput = false, bool readError = false, bool noShellExecute = false);
IProcess LaunchProcess(
string fileName,
string workingDirectory,
string arguments = null,
bool readOutput = false,
bool readError = false,
bool noShellExecute = false);
/// <summary>
/// Get a <see cref="IProcess"/> representing the running executable.
@@ -73,6 +73,9 @@ namespace Tgstation.Server.Host.System
if (!await ioManager.FileExists(GCorePath, cancellationToken).ConfigureAwait(false))
throw new JobException(ErrorCode.MissingGCore);
if(process.HasExited)
throw new JobException(ErrorCode.DreamDaemonOffline);
var pid = process.Id;
string output;
int exitCode;
@@ -87,7 +90,7 @@ namespace Tgstation.Server.Host.System
using (cancellationToken.Register(() => gcoreProc.Terminate()))
exitCode = await gcoreProc.Lifetime.ConfigureAwait(false);
output = gcoreProc.GetCombinedOutput();
output = await gcoreProc.GetCombinedOutput(cancellationToken).ConfigureAwait(false);
logger.LogDebug("gcore output:{0}{1}", Environment.NewLine, output);
}
+45 -58
View File
@@ -4,17 +4,13 @@ using System.Diagnostics;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Tgstation.Server.Host.Extensions;
namespace Tgstation.Server.Host.System
{
/// <inheritdoc />
sealed class Process : IProcess
{
/// <summary>
/// Maximum time to wait in a call to <see cref="global::System.Diagnostics.Process.WaitForExit(int)"/>.
/// </summary>
const int MaximumWaitMilliseconds = 30000;
/// <inheritdoc />
public int Id { get; }
@@ -36,13 +32,8 @@ namespace Tgstation.Server.Host.System
readonly global::System.Diagnostics.Process handle;
/// <summary>
/// A <see cref="TaskCompletionSource{TResult}"/> so that we can complete <see cref="Lifetime"/> if the <see cref="handle"/> becomes unresponsive.
/// </summary>
readonly TaskCompletionSource<object> emergencyLifetimeTcs;
readonly StringBuilder outputStringBuilder;
readonly StringBuilder errorStringBuilder;
readonly Task<string> standardOutputTask;
readonly Task<string> standardErrorTask;
readonly StringBuilder combinedStringBuilder;
/// <summary>
@@ -51,8 +42,8 @@ namespace Tgstation.Server.Host.System
/// <param name="processFeatures">The value of <see cref="processFeatures"/></param>
/// <param name="handle">The value of <see cref="handle"/></param>
/// <param name="lifetime">The value of <see cref="Lifetime"/></param>
/// <param name="outputStringBuilder">The value of <see cref="outputStringBuilder"/></param>
/// <param name="errorStringBuilder">The value of <see cref="errorStringBuilder"/></param>
/// <param name="standardOutputTask">The value of <see cref="standardOutputTask"/></param>
/// <param name="standardErrorTask">The value of <see cref="standardErrorTask"/></param>
/// <param name="combinedStringBuilder">The value of <see cref="combinedStringBuilder"/></param>
/// <param name="logger">The value of <see cref="logger"/></param>
/// <param name="preExisting">If <paramref name="handle"/> was NOT just created</param>
@@ -60,40 +51,48 @@ namespace Tgstation.Server.Host.System
IProcessFeatures processFeatures,
global::System.Diagnostics.Process handle,
Task<int> lifetime,
StringBuilder outputStringBuilder,
StringBuilder errorStringBuilder,
Task<string> standardOutputTask,
Task<string> standardErrorTask,
StringBuilder combinedStringBuilder,
ILogger<Process> logger,
bool preExisting)
{
this.processFeatures = processFeatures ?? throw new ArgumentNullException(nameof(processFeatures));
this.handle = handle ?? throw new ArgumentNullException(nameof(handle));
this.outputStringBuilder = outputStringBuilder;
this.errorStringBuilder = errorStringBuilder;
// Do this fast because the runtime will bitch if we try to access it after it ends
Id = handle.Id;
this.processFeatures = processFeatures ?? throw new ArgumentNullException(nameof(processFeatures));
this.standardOutputTask = standardOutputTask;
this.standardErrorTask = standardErrorTask;
this.combinedStringBuilder = combinedStringBuilder;
this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
emergencyLifetimeTcs = new TaskCompletionSource<object>();
Lifetime = WrapLifetimeTask(lifetime ?? throw new ArgumentNullException(nameof(lifetime)));
Id = handle.Id;
if (preExisting)
{
Startup = Task.CompletedTask;
return;
}
Startup = Task.Factory.StartNew(() =>
{
try
Startup = Task.Factory.StartNew(
() =>
{
handle.WaitForInputIdle();
}
catch (InvalidOperationException) { }
}, default, TaskCreationOptions.LongRunning, TaskScheduler.Current);
try
{
handle.WaitForInputIdle();
}
catch (InvalidOperationException ex)
{
logger.LogDebug(ex, "Error on WaitForInputIdle()!");
}
},
default, // DCT: None available
TaskCreationOptions.LongRunning,
TaskScheduler.Current);
logger.LogTrace("Created process ID: {0}", Id);
}
@@ -103,60 +102,48 @@ namespace Tgstation.Server.Host.System
async Task<int> WrapLifetimeTask(Task<int> lifetimeTask)
{
await Task.WhenAny(lifetimeTask, emergencyLifetimeTcs.Task).ConfigureAwait(false);
if (lifetimeTask.IsCompleted)
{
var exitCode = await lifetimeTask.ConfigureAwait(false);
logger.LogTrace("PID {0} exited with code {1}", Id, exitCode);
return exitCode;
}
logger.LogTrace("Using exit code -1 for hung PID {0}.", Id);
return -1;
// relevant: https://stackoverflow.com/a/26722542
var exitCode = await lifetimeTask.ConfigureAwait(false);
logger.LogTrace("PID {0} exited with code {1}", Id, exitCode);
return exitCode;
}
/// <inheritdoc />
public string GetCombinedOutput()
public async Task<string> GetCombinedOutput(CancellationToken cancellationToken)
{
if (combinedStringBuilder == null)
throw new InvalidOperationException("Output/Error reading was not enabled!");
throw new InvalidOperationException("Output/Error stream reading was not enabled!");
await Task.WhenAll(standardOutputTask, standardErrorTask).WithToken(cancellationToken).ConfigureAwait(false);
return combinedStringBuilder.ToString().TrimStart(Environment.NewLine.ToCharArray());
}
/// <inheritdoc />
public string GetErrorOutput()
public Task<string> GetErrorOutput(CancellationToken cancellationToken)
{
if (errorStringBuilder == null)
throw new InvalidOperationException("Error reading was not enabled!");
return errorStringBuilder.ToString().TrimStart(Environment.NewLine.ToCharArray());
if (standardErrorTask == null)
throw new InvalidOperationException("Error stream reading was not enabled!");
return standardErrorTask.WithToken(cancellationToken);
}
/// <inheritdoc />
public string GetStandardOutput()
public Task<string> GetStandardOutput(CancellationToken cancellationToken)
{
if (outputStringBuilder == null)
throw new InvalidOperationException("Output reading was not enabled!");
return outputStringBuilder.ToString().TrimStart(Environment.NewLine.ToCharArray());
if (standardOutputTask == null)
throw new InvalidOperationException("Output stream reading was not enabled!");
return standardOutputTask.WithToken(cancellationToken);
}
/// <inheritdoc />
public void Terminate()
{
if (handle.HasExited)
if (Lifetime.IsCompleted)
return;
try
{
logger.LogTrace("Terminating PID {0}...", Id);
handle.Kill();
if (!handle.WaitForExit(MaximumWaitMilliseconds))
{
logger.LogError(
"PID {0} hasn't exited in {1} seconds! This may cause issues with port reuse.",
Id,
TimeSpan.FromMilliseconds(MaximumWaitMilliseconds).TotalSeconds);
emergencyLifetimeTcs.TrySetResult(null);
}
// DO NOT USE WaitForExit! https://stackoverflow.com/a/26722542
}
catch (Exception e)
{
@@ -1,5 +1,6 @@
using Microsoft.Extensions.Logging;
using System;
using System.IO;
using System.Text;
using System.Threading.Tasks;
@@ -34,19 +35,36 @@ namespace Tgstation.Server.Host.System
var tcs = new TaskCompletionSource<int>();
handle.Exited += (a, b) =>
{
int exitCode;
try
{
exitCode = handle.ExitCode;
}
catch (InvalidOperationException)
{
return;
}
if (tcs.Task.IsCompleted)
{
logger.LogTrace("Skipping process exit handler as the TaskCompletionSource is already set");
return;
}
// Try because this can be invoked twice for weird reasons
if (tcs.TrySetResult(exitCode))
logger.LogTrace("Process exit event completed");
try
{
var exitCode = handle.ExitCode;
// Try because this can be invoked twice for weird reasons
if (tcs.TrySetResult(exitCode))
logger.LogTrace("Process termination event completed");
else
logger.LogTrace("Ignoring duplicate process termination event");
}
catch (InvalidOperationException ex)
{
if (!tcs.Task.IsCompleted)
throw;
logger.LogTrace(ex, "Ignoring expected exception!");
}
}
catch(Exception ex)
{
logger.LogError(ex, "Process exit handler exception!");
}
};
return tcs.Task;
@@ -128,92 +146,72 @@ namespace Tgstation.Server.Host.System
handle.StartInfo.UseShellExecute = !noShellExecute;
StringBuilder outputStringBuilder = null, errorStringBuilder = null, combinedStringBuilder = null;
StringBuilder combinedStringBuilder = null;
TaskCompletionSource<object> outputReadTcs = null;
TaskCompletionSource<object> errorReadTcs = null;
Task<string> outputTask = null;
Task<string> errorTask = null;
TaskCompletionSource<object> processStartTcs = null;
if (readOutput || readError)
{
combinedStringBuilder = new StringBuilder();
processStartTcs = new TaskCompletionSource<object>();
async Task<string> ConsumeReader(Func<TextReader> readerFunc)
{
var stringBuilder = new StringBuilder();
string text;
await processStartTcs.Task.ConfigureAwait(false);
var reader = readerFunc();
while ((text = await reader.ReadLineAsync().ConfigureAwait(false)) != null)
{
combinedStringBuilder.AppendLine();
combinedStringBuilder.Append(text);
stringBuilder.AppendLine();
stringBuilder.Append(text);
}
return stringBuilder.ToString();
}
if (readOutput)
{
outputStringBuilder = new StringBuilder();
outputTask = ConsumeReader(() => handle.StandardOutput);
handle.StartInfo.RedirectStandardOutput = true;
outputReadTcs = new TaskCompletionSource<object>();
handle.OutputDataReceived += (sender, e) =>
{
if (e.Data == null)
{
outputReadTcs.SetResult(null);
return;
}
combinedStringBuilder.Append(Environment.NewLine);
combinedStringBuilder.Append(e.Data);
outputStringBuilder.Append(Environment.NewLine);
outputStringBuilder.Append(e.Data);
};
}
if (readError)
{
errorStringBuilder = new StringBuilder();
errorTask = ConsumeReader(() => handle.StandardError);
handle.StartInfo.RedirectStandardError = true;
errorReadTcs = new TaskCompletionSource<object>();
handle.ErrorDataReceived += (sender, e) =>
{
if (e.Data == null)
{
errorReadTcs.SetResult(null);
return;
}
combinedStringBuilder.Append(Environment.NewLine);
combinedStringBuilder.Append(e.Data);
errorStringBuilder.Append(Environment.NewLine);
errorStringBuilder.Append(e.Data);
};
}
}
var lifetimeTask = AttachExitHandler(handle);
handle.Start();
static async Task<int> AddToLifetimeTask(Task<int> originalTask, TaskCompletionSource<object> tcs)
{
var exitCode = await originalTask.ConfigureAwait(false);
await tcs.Task.ConfigureAwait(false);
return exitCode;
}
try
{
if (readOutput)
{
handle.BeginOutputReadLine();
lifetimeTask = AddToLifetimeTask(lifetimeTask, outputReadTcs);
}
}
catch (InvalidOperationException) { }
try
{
if (readError)
{
handle.BeginErrorReadLine();
lifetimeTask = AddToLifetimeTask(lifetimeTask, errorReadTcs);
}
}
catch (InvalidOperationException) { }
handle.Start();
return new Process(
processFeatures,
handle,
lifetimeTask,
outputStringBuilder,
errorStringBuilder,
combinedStringBuilder,
loggerFactory.CreateLogger<Process>(), false);
var process = new Process(
processFeatures,
handle,
lifetimeTask,
outputTask,
errorTask,
combinedStringBuilder,
loggerFactory.CreateLogger<Process>(), false);
processStartTcs?.SetResult(null);
return process;
}
catch (Exception ex)
{
processStartTcs?.SetException(ex);
throw;
}
}
catch
{
@@ -6,6 +6,8 @@ using System.Linq;
using System.Management;
using System.Threading;
using System.Threading.Tasks;
using Tgstation.Server.Api.Models;
using Tgstation.Server.Host.Jobs;
namespace Tgstation.Server.Host.System
{
@@ -91,6 +93,9 @@ namespace Tgstation.Server.Host.System
=> Task.Factory.StartNew(
() =>
{
if (process.HasExited)
throw new JobException(ErrorCode.DreamDaemonOffline);
using var fileStream = new FileStream(outputFile, FileMode.CreateNew);
if (!NativeMethods.MiniDumpWriteDump(
process.Handle,
@@ -87,7 +87,7 @@ namespace Tgstation.Server.Tests.Instance
while (!dumpTask.IsCompleted)
KillDD(false);
var job = await WaitForJob(await dumpTask, 10, true, null, cancellationToken);
Assert.IsTrue(job.ErrorCode == ErrorCode.DreamDaemonOffline || job.ErrorCode == ErrorCode.GCoreFailure);
Assert.IsTrue(job.ErrorCode == ErrorCode.DreamDaemonOffline || job.ErrorCode == ErrorCode.GCoreFailure, $"{job.ErrorCode}: {job.ExceptionDetails}");
await Task.Delay(TimeSpan.FromSeconds(20), cancellationToken);
var ddStatus = await instanceClient.DreamDaemon.Read(cancellationToken);
@@ -209,7 +209,7 @@ namespace Tgstation.Server.Tests.Instance
ourProcessHandler.Suspend();
await Task.WhenAny(ourProcessHandler.Lifetime, Task.Delay(TimeSpan.FromSeconds(20)));
await Task.WhenAny(ourProcessHandler.Lifetime, Task.Delay(TimeSpan.FromMinutes(1)));
var timeout = 20;
do
@@ -434,8 +434,8 @@ namespace Tgstation.Server.Tests
var exitCode = await process.Lifetime.WithToken(cts.Token);
Assert.AreEqual(0, exitCode);
Assert.AreEqual(String.Empty, process.GetErrorOutput().Trim());
Assert.AreEqual("Hello World!", process.GetStandardOutput().Trim());
Assert.AreEqual(String.Empty, (await process.GetErrorOutput(default)).Trim());
Assert.AreEqual("Hello World!", (await process.GetStandardOutput(default)).Trim());
}
}
}