private async Task ResetAsync()
{
var consumerName = eventConsumer.Name;
var actionId = Guid.NewGuid().ToString();
try
{
log.LogInformation(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Started")
.WriteProperty("eventConsumer", consumerName));
await eventConsumer.ClearAsync();
await eventConsumerInfoRepository.SetLastHandledEventNumberAsync(consumerName, -1);
log.LogInformation(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Completed")
.WriteProperty("eventConsumer", consumerName));
OnReset?.Invoke();
}
catch (Exception ex)
{
log.LogFatal(ex, w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Completed")
.WriteProperty("eventConsumer", consumerName));
}
}
private async Task ResetAsync(IEventConsumer eventConsumer)
{
var actionId = Guid.NewGuid().ToString();
try
{
log.LogInformation(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Started")
.WriteProperty("eventConsumer", eventConsumer.Name));
await eventConsumer.ClearAsync();
await eventConsumerInfoRepository.SetPositionAsync(eventConsumer.Name, null, true);
log.LogInformation(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Completed")
.WriteProperty("eventConsumer", eventConsumer.Name));
}
catch (Exception ex)
{
log.LogFatal(ex, w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Completed")
.WriteProperty("eventConsumer", eventConsumer.GetType().Name));
throw;
}
}
public async Task MigrateAsync()
{
var version = 0;
try
{
var lastMigrator = migrations.FirstOrDefault();
while (!await migrationStatus.TryLockAsync())
{
log.LogInformation(w => w
.WriteProperty("action", "Migrate")
.WriteProperty("mesage", $"Waiting {LockWaitMs}ms to acquire lock."));
await Task.Delay(LockWaitMs);
}
version = await migrationStatus.GetVersionAsync();
if (lastMigrator != null && lastMigrator.ToVersion != version)
{
var migrationPath = FindMigratorPath(version, lastMigrator.ToVersion).ToList();
var previousMigrations = new List <IMigration>();
foreach (var migration in migrationPath)
{
var name = migration.GetType().ToString();
log.LogInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Started")
.WriteProperty("migrator", name));
using (log.MeasureInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Completed")
.WriteProperty("migrator", name)))
{
await migration.UpdateAsync(previousMigrations.ToList());
version = migration.ToVersion;
}
previousMigrations.Add(migration);
}
}
}
finally
{
await migrationStatus.UnlockAsync(version);
}
}
private async Task <Envelope <IEvent> > HandleAsync(Envelope <IEvent> input)
{
var eventNumber = input.Headers.EventNumber();
if (eventNumber <= lastReceivedEventNumber || !isRunning)
{
return(null);
}
var consumerName = eventConsumer.Name;
var eventId = input.Headers.EventId().ToString();
var eventType = input.Payload.GetType().Name;
try
{
log.LogInformation(w => w
.WriteProperty("action", "HandleEvent")
.WriteProperty("actionId", eventId)
.WriteProperty("state", "Started")
.WriteProperty("eventId", eventId)
.WriteProperty("eventType", eventType)
.WriteProperty("eventConsumer", consumerName));
await eventConsumer.On(input);
log.LogInformation(w => w
.WriteProperty("action", "HandleEvent")
.WriteProperty("actionId", eventId)
.WriteProperty("state", "Completed")
.WriteProperty("eventId", eventId)
.WriteProperty("eventType", eventType)
.WriteProperty("eventConsumer", consumerName));
lastReceivedEventNumber = eventNumber;
return(input);
}
catch (Exception ex)
{
OnError?.Invoke(ex);
log.LogError(ex, w => w
.WriteProperty("action", "HandleEvent")
.WriteProperty("actionId", eventId)
.WriteProperty("state", "Started")
.WriteProperty("eventId", eventId)
.WriteProperty("eventType", eventType)
.WriteProperty("eventConsumer", consumerName));
return(null);
}
}
public async Task MigrateAsync()
{
var version = 0;
try
{
while (!await migrationStatus.TryLockAsync())
{
log.LogInformation(w => w
.WriteProperty("action", "Migrate")
.WriteProperty("mesage", $"Waiting {LockWaitMs}ms to acquire lock."));
await Task.Delay(LockWaitMs);
}
version = await migrationStatus.GetVersionAsync();
while (true)
{
var migrationStep = migrationPath.GetNext(version);
if (migrationStep.Migrations == null || !migrationStep.Migrations.Any())
{
break;
}
foreach (var migration in migrationStep.Migrations)
{
var name = migration.GetType().ToString();
log.LogInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Started")
.WriteProperty("migrator", name));
using (log.MeasureInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Completed")
.WriteProperty("migrator", name)))
{
await migration.UpdateAsync();
}
}
version = migrationStep.Version;
}
}
finally
{
await migrationStatus.UnlockAsync(version);
}
}
public static async Task ProfileAsync(this ISemanticLog log, string actionName, Func <Task> action)
{
using (Profiler.StartSession())
{
try
{
await action();
log.LogInformation(actionName, (c, w) =>
{
w.WriteProperty("action", c);
w.WriteProperty("status", "Completed");
Profiler.Session?.Write(w);
});
}
catch (Exception ex)
{
log.LogWarning(ex, actionName, (c, w) =>
{
w.WriteProperty("action", c);
w.WriteProperty("status", "Failed");
Profiler.Session?.Write(w);
});
throw;
}
}
}
public async Task HandleAsync(CommandContext context, Func <Task> next)
{
var logContext = (id : context.ContextId.ToString(), command : context.Command.GetType().Name);
try
{
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Started")
.WriteProperty("commandType", ctx.command));
using (log.MeasureInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Completed")
.WriteProperty("commandType", ctx.command)))
{
await next();
}
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Succeeded")
.WriteProperty("commandType", ctx.command));
}
catch (Exception ex)
{
log.LogError(ex, logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Failed")
.WriteProperty("commandType", ctx.command));
throw;
}
if (!context.IsCompleted)
{
log.LogFatal(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Unhandled")
.WriteProperty("commandType", ctx.command));
}
}
public override void OnActionExecuted(ActionExecutedContext context)
{
var stopWatch = (Stopwatch)context.HttpContext.Items["Watch"];
stopWatch.Stop();
log.LogInformation(w => w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds));
}
public async Task StartAsync(CancellationToken cancellationToken)
{
foreach (var initializable in initializables.OrderBy(x => x.InitializationOrder))
{
log.LogDebug(w => w
.WriteProperty("action", "InitializeService")
.WriteProperty("status", "Started")
.WriteProperty("service", initializable.ToString()));
await initializable.InitializeAsync(cancellationToken);
log.LogInformation(w => w
.WriteProperty("action", "InitializeService")
.WriteProperty("status", "Finished")
.WriteProperty("service", initializable.ToString()));
}
}
public async Task StartAsync(CancellationToken cancellationToken)
{
foreach (var target in targets)
{
await target.InitializeAsync(cancellationToken);
log.LogInformation(w => w.WriteProperty("initializedSystem", target.GetType().Name));
}
}
private static void Log(ISemanticLog log, Error error)
{
log.LogInformation(w => w
.WriteProperty("system", "Kafka")
.WriteProperty("action", "Failed")
.WriteProperty("errorCode", (int)error.Code)
.WriteProperty("errorCodeText", error.Code.ToString())
.WriteProperty("errorReason", error.Reason));
}
protected override async Task StartAsync(ISemanticLog log, CancellationToken ct)
{
foreach (var target in targets.Distinct())
{
await target.StartAsync(ct);
log.LogInformation(w => w.WriteProperty("backgroundSystem", target.ToString()));
}
}
protected override async Task StartAsync(ISemanticLog log, CancellationToken ct)
{
foreach (var target in targets.Distinct())
{
await target.InitializeAsync(ct);
log.LogInformation(w => w.WriteProperty("initializedSystem", target.GetType().Name));
}
}
public async Task Invoke(HttpContext context)
{
var stopWatch = Stopwatch.StartNew();
await next(context);
stopWatch.Stop();
log.LogInformation(w => w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds));
}
private async Task ClearAsync()
{
var actionId = Guid.NewGuid().ToString();
log.LogInformation(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Started")
.WriteProperty("eventConsumer", eventConsumer.Name));
using (log.MeasureTrace(w => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("state", "Completed")
.WriteProperty("eventConsumer", eventConsumer.Name)))
{
await eventConsumer.ClearAsync();
}
}
private async Task ClearAsync()
{
var logContext = (actionId : Guid.NewGuid().ToString(), consumer : eventConsumer.Name);
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", ctx.actionId)
.WriteProperty("status", "Started")
.WriteProperty("eventConsumer", ctx.consumer));
using (log.MeasureTrace(logContext, (ctx, w) => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", ctx.actionId)
.WriteProperty("status", "Completed")
.WriteProperty("eventConsumer", ctx.consumer)))
{
await eventConsumer.ClearAsync();
}
}
public Task <bool> HandleAsync(CommandContext context)
{
log.LogInformation(w => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("state", "Started")
.WriteProperty("commandType", context.Command.GetType().Name));
return(TaskHelper.False);
}
public async Task InitializeAsync(CancellationToken ct = default)
{
using (var client = factory())
{
await client.ConnectAsync(ct);
if (!await client.DirectoryExistsAsync(path, ct))
{
await client.CreateDirectoryAsync(path, ct);
}
}
log.LogInformation(w => w
.WriteProperty("action", "FTPAssetStoreConfigured")
.WriteProperty("path", path));
}
public void Initialize()
{
var watch = ValueStopwatch.StartNew();
try
{
silo.Value.StartAsync().Wait();
}
finally
{
var elapsedMs = watch.Stop();
log.LogInformation(w => w
.WriteProperty("message", "Silo started")
.WriteProperty("elapsedMs", elapsedMs));
}
}
public async Task StartAsync(CancellationToken cancellationToken)
{
var watch = ValueStopwatch.StartNew();
try
{
await lazySilo.Value.StartAsync(cancellationToken);
}
finally
{
var elapsedMs = watch.Stop();
log.LogInformation(w => w
.WriteProperty("message", "Silo started")
.WriteProperty("elapsedMs", elapsedMs));
}
}
protected override async Task StartAsync(ISemanticLog log, CancellationToken ct)
{
var watch = ValueStopwatch.StartNew();
try
{
await silo.StartAsync(ct);
}
finally
{
var elapsedMs = watch.Stop();
log.LogInformation(w => w
.WriteProperty("message", "Silo started")
.WriteProperty("elapsedMs", elapsedMs));
}
}
public Task InitializeAsync(CancellationToken ct = default(CancellationToken))
{
try
{
if (!directory.Exists)
{
directory.Create();
}
log.LogInformation(w => w
.WriteProperty("action", "FolderAssetStoreConfigured")
.WriteProperty("path", directory.FullName));
return(TaskHelper.Done);
}
catch (Exception ex)
{
throw new ConfigurationException($"Cannot access directory {directory.FullName}", ex);
}
}
public void Dispose()
{
var mesage = string.Join('\n', lines);
log.LogInformation(w => w
.WriteProperty("message", $"CLI executed or template {template}.")
.WriteProperty("template", template)
.WriteArray("steps", a =>
{
foreach (var line in lines)
{
a.WriteValue(line);
}
}));
if (errors.Count > 0)
{
throw new DomainException($"Template failed with {errors[0]}");
}
}
public void Connect()
{
try
{
if (!directory.Exists)
{
directory.Create();
}
log.LogInformation(w => w
.WriteProperty("action", "FolderAssetStoreConfigured")
.WriteProperty("path", directory.FullName));
}
catch
{
if (!directory.Exists)
{
throw new ConfigurationException($"Cannot access directory {directory.FullName}");
}
}
}
public async Task InvokeAsync(HttpContext context, RequestDelegate next)
{
var stopWatch = Stopwatch.StartNew();
using (Profiler.StartSession())
{
try
{
await next(context);
}
finally
{
stopWatch.Stop();
log.LogInformation(w =>
{
Profiler.Session?.Write(w);
w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds);
});
}
}
}
public async Task Invoke(HttpContext context)
{
var stopWatch = Stopwatch.StartNew();
var session = new ProfilerSession();
try
{
requestSession.Start(context, session);
await next(context);
}
finally
{
stopWatch.Stop();
log.LogInformation(w =>
{
session.Write(w);
w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds);
});
}
}
private async Task ProcessAsync()
{
var handlers = CreateHandlers();
var logContext = (jobId : CurrentJob.Id.ToString(), jobUrl : CurrentJob.Url.ToString());
using (Profiler.StartSession())
{
try
{
Log("Started. The restore process has the following steps:");
Log(" * Download backup");
Log(" * Restore events and attachments.");
Log(" * Restore all objects like app, schemas and contents");
Log(" * Complete the restore operation for all objects");
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "restore")
.WriteProperty("status", "started")
.WriteProperty("operationId", ctx.jobId)
.WriteProperty("url", ctx.jobUrl));
using (var reader = await DownloadAsync())
{
using (Profiler.Trace("ReadEvents"))
{
await ReadEventsAsync(reader, handlers);
}
foreach (var handler in handlers)
{
using (Profiler.TraceMethod(handler.GetType(), nameof(IBackupHandler.RestoreAsync)))
{
await handler.RestoreAsync(restoreContext);
}
Log($"Restored {handler.Name}");
}
foreach (var handler in handlers)
{
using (Profiler.TraceMethod(handler.GetType(), nameof(IBackupHandler.CompleteRestoreAsync)))
{
await handler.CompleteRestoreAsync(restoreContext);
}
Log($"Completed {handler.Name}");
}
}
await AssignContributorAsync();
CurrentJob.Status = JobStatus.Completed;
Log("Completed, Yeah!");
log.LogInformation(logContext, (ctx, w) =>
{
w.WriteProperty("action", "restore");
w.WriteProperty("status", "completed");
w.WriteProperty("operationId", ctx.jobId);
w.WriteProperty("url", ctx.jobUrl);
Profiler.Session?.Write(w);
});
}
catch (Exception ex)
{
switch (ex)
{
case BackupRestoreException backupException:
Log(backupException.Message);
break;
case FileNotFoundException fileNotFoundException:
Log(fileNotFoundException.Message);
break;
default:
Log("Failed with internal error");
break;
}
await CleanupAsync(handlers);
CurrentJob.Status = JobStatus.Failed;
log.LogError(ex, logContext, (ctx, w) =>
{
w.WriteProperty("action", "retore");
w.WriteProperty("status", "failed");
w.WriteProperty("operationId", ctx.jobId);
w.WriteProperty("url", ctx.jobUrl);
Profiler.Session?.Write(w);
});
}
finally
{
CurrentJob.Stopped = clock.GetCurrentInstant();
await state.WriteAsync();
}
}
}
public async Task MigrateAsync(CancellationToken ct = default)
{
var version = 0;
try
{
while (!await migrationStatus.TryLockAsync())
{
log.LogInformation(w => w
.WriteProperty("action", "Migrate")
.WriteProperty("mesage", $"Waiting {LockWaitMs}ms to acquire lock."));
await Task.Delay(LockWaitMs, ct);
}
version = await migrationStatus.GetVersionAsync();
while (!ct.IsCancellationRequested)
{
var(newVersion, migrations) = migrationPath.GetNext(version);
if (migrations == null || !migrations.Any())
{
break;
}
foreach (var migration in migrations)
{
var name = migration.GetType().ToString();
log.LogInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Started")
.WriteProperty("migrator", name));
try
{
using (log.MeasureInformation(w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Completed")
.WriteProperty("migrator", name)))
{
await migration.UpdateAsync();
}
}
catch (Exception ex)
{
log.LogFatal(ex, w => w
.WriteProperty("action", "Migration")
.WriteProperty("status", "Failed")
.WriteProperty("migrator", name));
throw new MigrationFailedException(name, ex);
}
}
version = newVersion;
}
}
finally
{
await migrationStatus.UnlockAsync(version);
}
}
private static void Log(ISemanticLog log, string stats)
{
log.LogInformation(w => w
.WriteProperty("system", "Kafka")
.WriteProperty("statistics", stats));
}
private async Task ProcessAsync()
{
using (Profiler.StartSession())
{
try
{
Log("Started. The restore process has the following steps:");
Log(" * Download backup");
Log(" * Restore events and attachments.");
Log(" * Restore all objects like app, schemas and contents");
Log(" * Complete the restore operation for all objects");
log.LogInformation(w => w
.WriteProperty("action", "restore")
.WriteProperty("status", "started")
.WriteProperty("operationId", CurrentJob.Id.ToString())
.WriteProperty("url", CurrentJob.Url.ToString()));
using (Profiler.Trace("Download"))
{
await DownloadAsync();
}
using (var reader = await backupArchiveLocation.OpenArchiveAsync(CurrentJob.Id))
{
using (Profiler.Trace("ReadEvents"))
{
await ReadEventsAsync(reader);
}
foreach (var handler in handlers)
{
using (Profiler.TraceMethod(handler.GetType(), nameof(BackupHandler.RestoreAsync)))
{
await handler.RestoreAsync(CurrentJob.AppId, reader);
}
Log($"Restored {handler.Name}");
}
foreach (var handler in handlers)
{
using (Profiler.TraceMethod(handler.GetType(), nameof(BackupHandler.CompleteRestoreAsync)))
{
await handler.CompleteRestoreAsync(CurrentJob.AppId, reader);
}
Log($"Completed {handler.Name}");
}
}
using (Profiler.Trace("AssignContributor"))
{
await AssignContributorAsync();
Log("Assigned current user as owner");
}
CurrentJob.Status = JobStatus.Completed;
Log("Completed, Yeah!");
log.LogInformation(w =>
{
w.WriteProperty("action", "restore");
w.WriteProperty("status", "completed");
w.WriteProperty("operationId", CurrentJob.Id.ToString());
w.WriteProperty("url", CurrentJob.Url.ToString());
Profiler.Session?.Write(w);
});
}
catch (Exception ex)
{
if (ex is BackupRestoreException backupException)
{
Log(backupException.Message);
}
else
{
Log("Failed with internal error");
}
await CleanupAsync();
CurrentJob.Status = JobStatus.Failed;
log.LogError(ex, w =>
{
w.WriteProperty("action", "retore");
w.WriteProperty("status", "failed");
w.WriteProperty("operationId", CurrentJob.Id.ToString());
w.WriteProperty("url", CurrentJob.Url.ToString());
Profiler.Session?.Write(w);
});
}
finally
{
CurrentJob.Stopped = clock.GetCurrentInstant();
await WriteAsync();
}
}
}
