private static void LogTaskSummary(EtlSessionSerilogAdapter serilogAdapter, IEtlTask task, TaskResult result, int longestTaskName)
{
var spacing1 = "".PadRight(longestTaskName - task.Name.Length);
var spacing1WithoutName = "".PadRight(longestTaskName);
if (result.ExceptionCount == 0)
{
serilogAdapter.Log(LogSeverity.Information, false, null, null, "{Task}{spacing1} run-time is {Elapsed}, result is {Result}, CPU time: {CpuTime}, total allocations: {AllocatedMemory}, allocation difference: {MemoryDifference}",
task.Name, spacing1, task.Statistics.RunTime, "success", task.Statistics.CpuTime, task.Statistics.TotalAllocations, task.Statistics.AllocationDifference);
}
else
{
serilogAdapter.Log(LogSeverity.Information, false, null, null, "{Task}{spacing1} run-time is {Elapsed}, result is {Result}, CPU time: {CpuTime}, total allocations: {AllocatedMemory}, allocation difference: {MemoryDifference}",
task.Name, spacing1, task.Statistics.RunTime, "failed", task.Statistics.CpuTime, task.Statistics.TotalAllocations, task.Statistics.AllocationDifference);
}
if (task.IoCommandCounters.Count > 0)
{
var maxKeyLength = task.IoCommandCounters.Max(x => x.Key.ToString().Length);
var maxInvocationLength = task.IoCommandCounters.Max(x => x.Value.InvocationCount.ToString(ValueFormatter.DefaultIntegerFormat, CultureInfo.InvariantCulture).Length);
foreach (var kvp in task.IoCommandCounters.OrderBy(kvp => kvp.Key.ToString()))
{
if (kvp.Value.AffectedDataCount != null)
{
serilogAdapter.Log(LogSeverity.Information, false, null, null, "{spacing1} {Kind}{spacing2} {InvocationCount}{spacing3} {AffectedDataCount}", spacing1WithoutName,
kvp.Key.ToString(),
"".PadRight(maxKeyLength - kvp.Key.ToString().Length, ' '),
kvp.Value.InvocationCount,
"".PadRight(maxInvocationLength - kvp.Value.InvocationCount.ToString(ValueFormatter.DefaultIntegerFormat, CultureInfo.InvariantCulture).Length, ' '),
kvp.Value.AffectedDataCount);
}
else
{
serilogAdapter.Log(LogSeverity.Information, false, null, null, "{spacing1} {Kind}{spacing2} {InvocationCount}", spacing1WithoutName,
kvp.Key.ToString(),
"".PadRight(maxKeyLength - kvp.Key.ToString().Length, ' '),
kvp.Value.InvocationCount);
}
}
}
}
private static void LogTaskCounters(EtlSessionSerilogAdapter serilogAdapter, IEtlTask task)
{
if (task.IoCommandCounters.Count == 0)
{
return;
}
const string kind = "kind";
const string invocation = "invoc.";
const string affected = "affected";
var maxKeyLength = Math.Max(kind.Length, task.IoCommandCounters.Max(x => x.Key.ToString().Length));
var maxInvocationLength = Math.Max(invocation.Length, task.IoCommandCounters.Max(x => x.Value.InvocationCount.ToString(ValueFormatter.DefaultIntegerFormat, CultureInfo.InvariantCulture).Length));
serilogAdapter.Log(LogSeverity.Debug, false, null, null, "{Kind}{spacing1} {InvocationCount}{spacing2} {AffectedDataCount}", kind,
"".PadRight(maxKeyLength - kind.Length, ' '),
invocation,
"".PadRight(maxInvocationLength - invocation.Length, ' '),
affected);
foreach (var kvp in task.IoCommandCounters.OrderBy(kvp => kvp.Key.ToString()))
{
if (kvp.Value.AffectedDataCount != null)
{
serilogAdapter.Log(LogSeverity.Debug, false, null, null, "{Kind}{spacing1} {InvocationCount}{spacing2} {AffectedDataCount}", kvp.Key.ToString(),
"".PadRight(maxKeyLength - kvp.Key.ToString().Length, ' '),
kvp.Value.InvocationCount,
"".PadRight(maxInvocationLength - kvp.Value.InvocationCount.ToString(ValueFormatter.DefaultIntegerFormat, CultureInfo.InvariantCulture).Length, ' '),
kvp.Value.AffectedDataCount);
}
else
{
serilogAdapter.Log(LogSeverity.Debug, false, null, null, "{Kind}{spacing1} {InvocationCount}", kvp.Key.ToString(),
"".PadRight(maxKeyLength - kvp.Key.ToString().Length, ' '), kvp.Value.InvocationCount);
}
}
}
public static ExecutionResult Execute(CommandContext commandContext, CompiledModule module, string[] commands)
{
var result = ExecutionResult.Success;
var etlContext = new EtlContext();
try
{
var listeners = commandContext.HostConfiguration.GetSessionListeners(null);
if (listeners?.Count > 0)
{
etlContext.Listeners.AddRange(listeners);
}
}
catch (Exception ex)
{
var formattedMessage = ex.FormatExceptionWithDetails();
etlContext.Log(LogSeverity.Fatal, null, "{ErrorMessage}", formattedMessage);
etlContext.LogOps(LogSeverity.Fatal, null, "{ErrorMessage}", formattedMessage);
}
var instance = Environment.MachineName;
var arguments = GetArguments(module, instance);
var environmentSettings = new EnvironmentSettings();
module.Startup.Configure(environmentSettings);
var taskCreators = new Dictionary <string, Func <IEtlSessionArguments, IEtlTask> >(module.Startup.Commands, StringComparer.InvariantCultureIgnoreCase);
var sessionId = "s" + DateTime.Now.ToString("yyMMdd-HHmmss-ff", CultureInfo.InvariantCulture);
var session = new EtlSession(sessionId, etlContext, arguments);
etlContext.TransactionScopeTimeout = environmentSettings.TransactionScopeTimeout;
var logger = CreateLogger(environmentSettings, commandContext.DevLogFolder, commandContext.OpsLogFolder);
var opsLogger = CreateOpsLogger(environmentSettings, commandContext.DevLogFolder, commandContext.OpsLogFolder);
var ioLogger = CreateIoLogger(environmentSettings, commandContext.DevLogFolder, commandContext.OpsLogFolder);
var serilogAdapter = new EtlSessionSerilogAdapter(logger, opsLogger, ioLogger, commandContext.DevLogFolder, commandContext.OpsLogFolder);
etlContext.Listeners.Add(serilogAdapter);
serilogAdapter.Log(LogSeverity.Information, false, null, null, "session {SessionId} started", sessionId);
if (!string.IsNullOrEmpty(environmentSettings.SeqSettings.Url))
{
etlContext.Log(LogSeverity.Debug, null, "all session logs will be sent to SEQ listening on {SeqUrl}", environmentSettings.SeqSettings.Url);
}
var sessionStartedOn = Stopwatch.StartNew();
var sessionExceptionCount = 0;
var taskResults = new List <KeyValuePair <IEtlTask, TaskResult> >();
try
{
foreach (var command in commands)
{
IEtlTask task = null;
if (taskCreators.TryGetValue(command, out var taskCreator))
{
task = taskCreator.Invoke(arguments);
}
else
{
var taskType = module.TaskTypes.Find(x => string.Equals(x.Name, command, StringComparison.InvariantCultureIgnoreCase));
if (taskType != null)
{
task = (IEtlTask)Activator.CreateInstance(taskType);
}
}
if (task == null)
{
serilogAdapter.Log(LogSeverity.Error, false, null, null, "unknown task/flow type: " + command);
break;
}
try
{
try
{
var taskResult = session.ExecuteTask(null, task);
taskResults.Add(new KeyValuePair <IEtlTask, TaskResult>(task, taskResult));
sessionExceptionCount += taskResult.ExceptionCount;
if (sessionExceptionCount > 0)
{
etlContext.Log(LogSeverity.Error, task, "failed, terminating execution");
result = ExecutionResult.ExecutionFailed;
etlContext.Close();
break; // stop processing tasks
}
}
catch (Exception ex)
{
etlContext.Log(LogSeverity.Error, task, "failed, terminating execution, reason: ", task.Statistics.RunTime, ex.Message);
result = ExecutionResult.ExecutionFailed;
etlContext.Close();
break; // stop processing tasks
}
}
catch (TransactionAbortedException)
{
}
LogTaskCounters(serilogAdapter, task);
}
session.Stop();
if (taskResults.Count > 0)
{
serilogAdapter.Log(LogSeverity.Information, false, null, null, "-------");
serilogAdapter.Log(LogSeverity.Information, false, null, null, "SUMMARY");
serilogAdapter.Log(LogSeverity.Information, false, null, null, "-------");
var longestTaskName = taskResults.Max(x => x.Key.Name.Length);
foreach (var kvp in taskResults)
{
LogTaskSummary(serilogAdapter, kvp.Key, kvp.Value, longestTaskName);
}
}
etlContext.Close();
}
catch (TransactionAbortedException)
{
}
return(result);
}
