public async Task LogPluginHost_HandleProcessExceptions()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
hostContext.Variables["throw_process"] = "1";
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1(), new TestPluginException()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace);
var task = logPluginHost.Run();
for (int i = 0; i < 1000; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
// regular one still running
Assert.True(trace.Outputs.Contains("Test1: 0"));
Assert.True(trace.Outputs.Contains("Test1: 999"));
Assert.True(trace.Outputs.Contains("Test1: Done"));
Assert.True(!trace.Outputs.Contains("TestException: 0"));
Assert.True(!trace.Outputs.Contains("TestException: 999"));
Assert.True(trace.Outputs.Contains("TestException: Done"));
}
}
// potential bug in XUnit cause the test failure.
// [Fact]
// [Trait("Level", "L0")]
// [Trait("Category", "Plugin")]
// public async Task LogPluginHost_HandleFinalizeExceptions()
// {
// using (TestHostContext tc = new TestHostContext(this))
// {
// AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
// hostContext.Variables["throw_finalize"] = "1";
// List<IAgentLogPlugin> plugins = new List<IAgentLogPlugin>() { new TestPlugin1(), new TestPluginException() };
// TestTrace trace = new TestTrace(tc);
// AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace);
// var task = logPluginHost.Run();
// for (int i = 0; i < 1000; i++)
// {
// logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
// }
// await Task.Delay(1000);
// logPluginHost.Finish();
// await task;
// // regular one still running
// Assert.True(trace.Outputs.Contains("Test1: 0"));
// Assert.True(trace.Outputs.Contains("Test1: 999"));
// Assert.True(trace.Outputs.Contains("Test1: Done"));
// Assert.True(trace.Outputs.Contains("TestException: 0"));
// Assert.True(trace.Outputs.Contains("TestException: 999"));
// Assert.True(!trace.Outputs.Contains("TestException: Done"));
// }
// }
private AgentLogPluginHostContext CreateTestLogPluginHostContext()
{
AgentLogPluginHostContext hostContext = new AgentLogPluginHostContext()
{
Endpoints = new List <ServiceEndpoint>(),
PluginAssemblies = new List <string>(),
Repositories = new List <Pipelines.RepositoryResource>(),
Variables = new Dictionary <string, VariableValue>(),
Steps = new Dictionary <string, Pipelines.TaskStepDefinitionReference>()
};
hostContext.Steps[Guid.Empty.ToString("D")] = new Pipelines.TaskStepDefinitionReference()
{
Id = Guid.NewGuid(),
Name = "Test",
Version = "1.0.0."
};
var systemConnection = new ServiceEndpoint()
{
Name = WellKnownServiceEndpointNames.SystemVssConnection,
Id = Guid.NewGuid(),
Url = new Uri("https://dev.azure.com/test"),
Authorization = new EndpointAuthorization()
{
Scheme = EndpointAuthorizationSchemes.OAuth,
Parameters = { { EndpointAuthorizationParameters.AccessToken, "Test" } }
}
};
hostContext.Endpoints.Add(systemConnection);
return(hostContext);
}
public async Task LogPluginHost_SlowPluginRecover()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1(), new TestPluginSlowRecover()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace, 950, 100);
var task = logPluginHost.Run();
for (int i = 0; i < 1000; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
// regular one still running
Assert.True(trace.Outputs.Contains("Test1: 0"));
Assert.True(trace.Outputs.Contains("Test1: 999"));
Assert.True(trace.Outputs.Contains("Test1: Done"));
Assert.True(trace.Outputs.Contains("TestSlowRecover: Done"));
Assert.True(trace.Outputs.Exists(x => x.Contains("TestPluginSlowRecover' has too many buffered outputs.")));
Assert.True(trace.Outputs.Exists(x => x.Contains("TestPluginSlowRecover' has cleared out buffered outputs.")));
}
}
public async Task LogPluginHost_NotInitialized()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1(), new TestPluginNotInitialized()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace);
var task = logPluginHost.Run();
for (int i = 0; i < 1000; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
// regular one still running
Assert.True(trace.Outputs.Contains("Test1: 0"));
Assert.True(trace.Outputs.Contains("Test1: 999"));
Assert.True(trace.Outputs.Contains("Test1: Done"));
Assert.True(!trace.Outputs.Contains("TestNotInitialized: 0"));
Assert.True(!trace.Outputs.Contains("TestNotInitialized: Done"));
}
}
public async Task LogPluginHost_ShortCircuitSlowPlugin()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1(), new TestPluginSlow()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace, 100, 100);
var task = logPluginHost.Run();
for (int i = 0; i < 1000; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
// regular one still running
Assert.True(trace.Outputs.Contains("Test1: 0"));
Assert.True(trace.Outputs.Contains("Test1: 999"));
Assert.True(trace.Outputs.Contains("Test1: Done"));
// slow one got killed
Assert.False(trace.Outputs.Contains("TestSlow: Done"));
Assert.True(trace.Outputs.Exists(x => x.Contains("Plugin has been short circuited")));
}
}
public async Task LogPluginHost_RunMultiplePlugins()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1(), new TestPlugin2()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace);
var task = logPluginHost.Run();
for (int i = 0; i < 1000; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
foreach (var fragment in new string[] { "Test1: 0", "Test1: 999", "Test1: Done", "Test2: 0", "Test2: 999", "Test2: Done" })
{
Assert.True(trace.Outputs.Contains(fragment), $"Found '{fragment}' in: {trace.Outputs}");
}
}
}
public async Task LogPluginHost_RunSinglePluginWithEmptyLinesInput()
{
using (TestHostContext tc = new TestHostContext(this))
{
AgentLogPluginHostContext hostContext = CreateTestLogPluginHostContext();
List <IAgentLogPlugin> plugins = new List <IAgentLogPlugin>()
{
new TestPlugin1()
};
TestTrace trace = new TestTrace(tc);
AgentLogPluginHost logPluginHost = new AgentLogPluginHost(hostContext, plugins, trace);
var task = logPluginHost.Run();
for (int i = 0; i < 100; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
for (int i = 0; i < 100; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
for (int i = 0; i < 10; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:");
}
for (int i = 100; i < 200; i++)
{
logPluginHost.EnqueueOutput($"{Guid.Empty.ToString("D")}:{i}");
}
await Task.Delay(1000);
logPluginHost.Finish();
await task;
Assert.True(trace.Outputs.Contains("Test1: 0"));
Assert.True(trace.Outputs.Contains("Test1: 99"));
Assert.True(trace.Outputs.Contains("Test1: "));
Assert.True(trace.Outputs.Contains("Test1: 100"));
Assert.True(trace.Outputs.Contains("Test1: 199"));
Assert.Equal(10, trace.Outputs.FindAll(x => x == "Test1: ").Count);
}
}
public static int Main(string[] args)
{
if (PlatformUtil.UseLegacyHttpHandler)
{
AppContext.SetSwitch("System.Net.Http.UseSocketsHttpHandler", false);
}
Console.CancelKeyPress += Console_CancelKeyPress;
// Set encoding to UTF8, process invoker will use UTF8 write to STDIN
Console.InputEncoding = Encoding.UTF8;
Console.OutputEncoding = Encoding.UTF8;
try
{
ArgUtil.NotNull(args, nameof(args));
ArgUtil.Equal(2, args.Length, nameof(args.Length));
string pluginType = args[0];
if (string.Equals("task", pluginType, StringComparison.OrdinalIgnoreCase))
{
string assemblyQualifiedName = args[1];
ArgUtil.NotNullOrEmpty(assemblyQualifiedName, nameof(assemblyQualifiedName));
string serializedContext = Console.ReadLine();
ArgUtil.NotNullOrEmpty(serializedContext, nameof(serializedContext));
AgentTaskPluginExecutionContext executionContext = StringUtil.ConvertFromJson <AgentTaskPluginExecutionContext>(serializedContext);
ArgUtil.NotNull(executionContext, nameof(executionContext));
VariableValue culture;
ArgUtil.NotNull(executionContext.Variables, nameof(executionContext.Variables));
if (executionContext.Variables.TryGetValue("system.culture", out culture) &&
!string.IsNullOrEmpty(culture?.Value))
{
CultureInfo.DefaultThreadCurrentCulture = new CultureInfo(culture.Value);
CultureInfo.DefaultThreadCurrentUICulture = new CultureInfo(culture.Value);
}
AssemblyLoadContext.Default.Resolving += ResolveAssembly;
try
{
Type type = Type.GetType(assemblyQualifiedName, throwOnError: true);
var taskPlugin = Activator.CreateInstance(type) as IAgentTaskPlugin;
ArgUtil.NotNull(taskPlugin, nameof(taskPlugin));
taskPlugin.RunAsync(executionContext, tokenSource.Token).GetAwaiter().GetResult();
}
catch (Exception ex)
{
// any exception throw from plugin will fail the task.
executionContext.Error(ex.Message);
executionContext.Debug(ex.StackTrace);
}
finally
{
AssemblyLoadContext.Default.Resolving -= ResolveAssembly;
}
return(0);
}
else if (string.Equals("command", pluginType, StringComparison.OrdinalIgnoreCase))
{
string assemblyQualifiedName = args[1];
ArgUtil.NotNullOrEmpty(assemblyQualifiedName, nameof(assemblyQualifiedName));
string serializedContext = Console.ReadLine();
ArgUtil.NotNullOrEmpty(serializedContext, nameof(serializedContext));
AgentCommandPluginExecutionContext executionContext = StringUtil.ConvertFromJson <AgentCommandPluginExecutionContext>(serializedContext);
ArgUtil.NotNull(executionContext, nameof(executionContext));
AssemblyLoadContext.Default.Resolving += ResolveAssembly;
try
{
Type type = Type.GetType(assemblyQualifiedName, throwOnError: true);
var commandPlugin = Activator.CreateInstance(type) as IAgentCommandPlugin;
ArgUtil.NotNull(commandPlugin, nameof(commandPlugin));
commandPlugin.ProcessCommandAsync(executionContext, tokenSource.Token).GetAwaiter().GetResult();
}
catch (Exception ex)
{
// any exception throw from plugin will fail the command.
executionContext.Error(ex.ToString());
}
finally
{
AssemblyLoadContext.Default.Resolving -= ResolveAssembly;
}
return(0);
}
else if (string.Equals("log", pluginType, StringComparison.OrdinalIgnoreCase))
{
// read commandline arg to get the instance id
var instanceId = args[1];
ArgUtil.NotNullOrEmpty(instanceId, nameof(instanceId));
// read STDIN, the first line will be the HostContext for the log plugin host
string serializedContext = Console.ReadLine();
ArgUtil.NotNullOrEmpty(serializedContext, nameof(serializedContext));
AgentLogPluginHostContext hostContext = StringUtil.ConvertFromJson <AgentLogPluginHostContext>(serializedContext);
ArgUtil.NotNull(hostContext, nameof(hostContext));
// create plugin object base on plugin assembly names from the HostContext
List <IAgentLogPlugin> logPlugins = new List <IAgentLogPlugin>();
AssemblyLoadContext.Default.Resolving += ResolveAssembly;
try
{
foreach (var pluginAssembly in hostContext.PluginAssemblies)
{
try
{
Type type = Type.GetType(pluginAssembly, throwOnError: true);
var logPlugin = Activator.CreateInstance(type) as IAgentLogPlugin;
ArgUtil.NotNull(logPlugin, nameof(logPlugin));
logPlugins.Add(logPlugin);
}
catch (Exception ex)
{
// any exception throw from plugin will get trace and ignore, error from plugins will not fail the job.
Console.WriteLine($"Unable to load plugin '{pluginAssembly}': {ex}");
}
}
}
finally
{
AssemblyLoadContext.Default.Resolving -= ResolveAssembly;
}
// start the log plugin host
var logPluginHost = new AgentLogPluginHost(hostContext, logPlugins);
Task hostTask = logPluginHost.Run();
while (true)
{
var consoleInput = Console.ReadLine();
if (string.Equals(consoleInput, $"##vso[logplugin.finish]{instanceId}", StringComparison.OrdinalIgnoreCase))
{
// singal all plugins, the job has finished.
// plugin need to start their finalize process.
logPluginHost.Finish();
break;
}
else
{
// the format is TimelineRecordId(GUID):Output(String)
logPluginHost.EnqueueOutput(consoleInput);
}
}
// wait for the host to finish.
hostTask.GetAwaiter().GetResult();
return(0);
}
else
{
throw new ArgumentOutOfRangeException(pluginType);
}
}
catch (Exception ex)
{
// infrastructure failure.
Console.Error.WriteLine(ex.ToString());
return(1);
}
finally
{
Console.CancelKeyPress -= Console_CancelKeyPress;
}
}
public Task StartAsync(IExecutionContext context, List <IStep> steps, CancellationToken token)
{
Trace.Entering();
ArgUtil.NotNull(context, nameof(context));
List <PluginInfo> enabledPlugins = new List <PluginInfo>();
if (context.Variables.GetBoolean("agent.disablelogplugin") ?? false)
{
// all log plugs are disabled
context.Debug("All log plugins are disabled.");
}
else
{
foreach (var plugin in _logPlugins)
{
if (context.Variables.GetBoolean($"agent.disablelogplugin.{plugin.Key}") ?? false)
{
// skip plugin
context.Debug($"Log plugin '{plugin.Key}' is disabled.");
continue;
}
else
{
enabledPlugins.Add(plugin.Value);
}
}
}
if (enabledPlugins.Count > 0)
{
// Resolve the working directory.
string workingDirectory = HostContext.GetDirectory(WellKnownDirectory.Work);
ArgUtil.Directory(workingDirectory, nameof(workingDirectory));
// Agent.PluginHost
string file = Path.Combine(HostContext.GetDirectory(WellKnownDirectory.Bin), $"Agent.PluginHost{Util.IOUtil.ExeExtension}");
ArgUtil.File(file, $"Agent.PluginHost{Util.IOUtil.ExeExtension}");
// Agent.PluginHost's arguments
string arguments = $"log \"{_instanceId.ToString("D")}\"";
var processInvoker = HostContext.CreateService <IProcessInvoker>();
processInvoker.OutputDataReceived += (object sender, ProcessDataReceivedEventArgs e) =>
{
if (e.Data != null)
{
_outputs.Enqueue(e.Data);
}
};
processInvoker.ErrorDataReceived += (object sender, ProcessDataReceivedEventArgs e) =>
{
if (e.Data != null)
{
_outputs.Enqueue(e.Data);
}
};
_pluginHostProcess?.Dispose();
_pluginHostProcess = processInvoker.ExecuteAsync(workingDirectory: workingDirectory,
fileName: file,
arguments: arguments,
environment: null,
requireExitCodeZero: true,
outputEncoding: Encoding.UTF8,
killProcessOnCancel: true,
redirectStandardIn: _redirectedStdin,
inheritConsoleHandler: false,
keepStandardInOpen: true,
cancellationToken: token);
// construct plugin context
AgentLogPluginHostContext pluginContext = new AgentLogPluginHostContext
{
PluginAssemblies = new List <string>(),
Repositories = context.Repositories,
Endpoints = context.Endpoints,
Variables = new Dictionary <string, VariableValue>(),
Steps = new Dictionary <string, Pipelines.TaskStepDefinitionReference>()
};
// plugins
pluginContext.PluginAssemblies.AddRange(_logPlugins.Values.Select(x => x.AssemblyName));
var target = context.StepTarget();
Variables.TranslationMethod translateToHostPath = Variables.DefaultStringTranslator;
ContainerInfo containerInfo = target as ContainerInfo;
// Since plugins run on the host, but the inputs and variables have already been translated
// to the container path, we need to convert them back to the host path
// TODO: look to see if there is a better way to not have translate these back
if (containerInfo != null)
{
translateToHostPath = (string val) => { return(containerInfo.TranslateToHostPath(val)); };
}
// variables
context.Variables.CopyInto(pluginContext.Variables, translateToHostPath);
// steps
foreach (var step in steps)
{
var taskStep = step as ITaskRunner;
if (taskStep != null)
{
pluginContext.Steps[taskStep.ExecutionContext.Id.ToString("D")] = taskStep.Task.Reference;
}
}
Trace.Info("Send serialized context through STDIN");
_redirectedStdin.Enqueue(JsonUtility.ToString(pluginContext));
foreach (var plugin in _logPlugins)
{
context.Output($"Plugin: '{plugin.Value.FriendlyName}' is running in background.");
}
}
return(Task.CompletedTask);
}
public Task StartAsync(IExecutionContext context, List <IStep> steps, CancellationToken token)
{
Trace.Entering();
ArgUtil.NotNull(context, nameof(context));
List <PluginInfo> enabledPlugins = new List <PluginInfo>();
if (context.Variables.GetBoolean("agent.disablelogplugin") ?? false)
{
// all log plugs are disabled
context.Debug("All log plugins are disabled.");
}
else
{
foreach (var plugin in _logPlugins)
{
if (context.Variables.GetBoolean($"agent.disablelogplugin.{plugin.Key}") ?? false)
{
// skip plugin
context.Debug($"Log plugin '{plugin.Key}' is disabled.");
continue;
}
else
{
enabledPlugins.Add(plugin.Value);
}
}
}
if (enabledPlugins.Count > 0)
{
// Resolve the working directory.
string workingDirectory = HostContext.GetDirectory(WellKnownDirectory.Work);
ArgUtil.Directory(workingDirectory, nameof(workingDirectory));
// Agent.PluginHost
string file = Path.Combine(HostContext.GetDirectory(WellKnownDirectory.Bin), $"Agent.PluginHost{Util.IOUtil.ExeExtension}");
ArgUtil.File(file, $"Agent.PluginHost{Util.IOUtil.ExeExtension}");
// Agent.PluginHost's arguments
string arguments = $"log \"{_instanceId.ToString("D")}\"";
var processInvoker = HostContext.CreateService <IProcessInvoker>();
processInvoker.OutputDataReceived += (object sender, ProcessDataReceivedEventArgs e) =>
{
if (!string.IsNullOrEmpty(e.Data))
{
_outputs.Enqueue(e.Data);
}
};
processInvoker.ErrorDataReceived += (object sender, ProcessDataReceivedEventArgs e) =>
{
if (!string.IsNullOrEmpty(e.Data))
{
_outputs.Enqueue(e.Data);
}
};
_pluginHostProcess = processInvoker.ExecuteAsync(workingDirectory: workingDirectory,
fileName: file,
arguments: arguments,
environment: null,
requireExitCodeZero: true,
outputEncoding: Encoding.UTF8,
killProcessOnCancel: true,
redirectStandardIn: _redirectedStdin,
cancellationToken: token);
// construct plugin context
AgentLogPluginHostContext pluginContext = new AgentLogPluginHostContext
{
PluginAssemblies = new List <string>(),
Repositories = context.Repositories,
Endpoints = context.Endpoints,
Variables = new Dictionary <string, VariableValue>(),
Steps = new Dictionary <string, Pipelines.TaskStepDefinitionReference>()
};
// plugins
pluginContext.PluginAssemblies.AddRange(_logPlugins.Values.Select(x => x.AssemblyName));
// variables
foreach (var publicVar in context.Variables.Public)
{
pluginContext.Variables[publicVar.Key] = publicVar.Value;
}
foreach (var privateVar in context.Variables.Private)
{
pluginContext.Variables[privateVar.Key] = new VariableValue(privateVar.Value, true);
}
// steps
foreach (var step in steps)
{
var taskStep = step as ITaskRunner;
if (taskStep != null)
{
pluginContext.Steps[taskStep.ExecutionContext.Id.ToString("D")] = taskStep.Task.Reference;
}
}
Trace.Info("Send serialized context through STDIN");
_redirectedStdin.Enqueue(JsonUtility.ToString(pluginContext));
foreach (var plugin in _logPlugins)
{
context.Output($"Plugin: '{plugin.Value.FriendlyName}' is running in background.");
}
}
return(Task.CompletedTask);
}