/// <summary>
/// Handles the specified request. All pre/post behaviors will be called.
/// </summary>
/// <param name="request">The request.</param>
/// <param name="cancellationToken">The cancellation token.</param>
public override async Task <CommandResponse <TResponse> > Handle(TCommand request, CancellationToken cancellationToken)
{
var parentSpan = this.Tracer?.CurrentSpan;
if (request.Properties.ContainsKey(CommandPropertyKeys.TraceId) && request.Properties.ContainsKey(CommandPropertyKeys.TraceSpanId))
{
// dehydrate parent span
parentSpan = new Span(request.Properties.GetValueOrDefault(CommandPropertyKeys.TraceId) as string, request.Properties.GetValueOrDefault(CommandPropertyKeys.TraceSpanId) as string);
parentSpan.SetSampled(request.Properties.GetValueOrDefault(CommandPropertyKeys.TraceSampled).To <bool>());
}
// TODO: log scope (correlationid)?
using (var scope = this.Tracer?.BuildSpan(
$"command {request.GetType().PrettyName()}".ToLowerInvariant(),
LogKeys.AppCommand,
SpanKind.Consumer,
parentSpan).Activate(this.Logger))
using (var timer = new Foundation.Timer())
{
var commandName = typeof(TCommand).PrettyName();
this.Logger.LogJournal(LogKeys.AppCommand, $"command handle (name={commandName}, handler={this.GetType().PrettyName()}, id={request.Id})", LogPropertyKeys.TrackHandleCommand);
var result = await this.ExecutePreHandleBehaviorsAsync(request).AnyContext();
if (result.Cancelled) // abort if a pre behavior did not succeed
{
timer.Stop();
this.Logger.LogInformation($"{{LogKey:l}} command cancelled (name={commandName}, handler={this.GetType().PrettyName()}, id={request.Id}) {result.CancelledReason} -> took {timer.Elapsed.Humanize()}", LogKeys.AppCommand);
return(new CommandResponse <TResponse>(result.CancelledReason)); // TODO: log reason
}
var response = await this.HandleRequest(request, cancellationToken).AnyContext();
await this.ExecutePostHandleBehaviorsAsync(result, response).AnyContext();
timer.Stop();
if (result.Cancelled) // abort if a post behavior did not succeed
{
this.Logger.LogInformation($"{{LogKey:l}} command cancelled (name={commandName}, handler={this.GetType().PrettyName()}, id={request.Id}) {result.CancelledReason} -> took {timer.Elapsed.Humanize()}", LogKeys.AppCommand);
return(new CommandResponse <TResponse>(result.CancelledReason)); // TODO: log reason
}
this.Logger.LogInformation($"{{LogKey:l}} command handled (name={commandName}, handler={this.GetType().PrettyName()}, id={request.Id}, cancelled={response.Cancelled}) -> took {timer.Elapsed.Humanize()}", LogKeys.AppCommand);
return(response);
}
}
protected override async Task <HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
var correlationId = request.GetCorrelationId();
var requestId = request.GetRequestId();
await this.LogHttpRequest(request, correlationId, requestId).AnyContext();
using (var timer = new Foundation.Timer())
{
var response = await base.SendAsync(request, cancellationToken).AnyContext();
timer.Stop();
await this.LogHttpResponse(response, requestId, timer.Elapsed).AnyContext();
return(response);
}
}
private async Task ExecuteJobAsync(JobRegistration registration, IJob job, CancellationToken cancellationToken, string[] args = null)
{
if (registration?.Key.IsNullOrEmpty() == false && job != null)
{
try
{
async Task ExecuteAsync()
{
var correlationId = IdGenerator.Instance.Next;
using (var timer = new Foundation.Timer())
using (this.logger.BeginScope(new Dictionary <string, object>
{
[LogPropertyKeys.CorrelationId] = correlationId
}))
{
// TODO: publish domain event (job started)
this.logger.LogJournal(LogKeys.JobScheduling, $"job started: {{JobKey:l}} (id={registration.Identifier}, type={job.GetType().PrettyName()}, isReentrant={registration.IsReentrant}, timeout={registration.Timeout:c})", LogPropertyKeys.TrackStartJob, args: new[] { registration.Key });
//using (var scope = this.tracer?.BuildSpan($"job run {registration.Key}", LogKeys.JobScheduling, SpanKind.Producer).Activate(this.logger))
//{ // current span is somehow not available in created jobs (ServiceProviderJobFactory)
try
{
await job.ExecuteAsync(correlationId, cancellationToken, args).AnyContext();
this.logger.LogJournal(LogKeys.JobScheduling, $"job finished: {{JobKey:l}} (id={registration.Identifier}, type={job.GetType().PrettyName()})", LogPropertyKeys.TrackFinishJob, args: new[] { registration.Key });
}
catch (Exception ex)
{
this.logger.LogError(ex, $"{{LogKey:l}} job failed: {{JobKey:l}} (id={registration.Identifier}, type={job.GetType().PrettyName()}) {ex.GetFullMessage()}", args: new[] { LogKeys.JobScheduling, registration.Key });
}
// TODO: publish domain event (job finished)
}
}
if (!registration.IsReentrant)
{
if (this.mutex.TryAcquireLock(registration.Key))
{
try
{
await ExecuteAsync().AnyContext();
}
finally
{
this.mutex.ReleaseLock(registration.Key);
}
}
else
{
this.logger.LogWarning($"{{LogKey:l}} already executing (key={{JobKey:l}}, type={job.GetType().PrettyName()})", LogKeys.JobScheduling, registration.Key);
}
}
else
{
await ExecuteAsync().AnyContext();
}
}
catch (OperationCanceledException ex)
{
// TODO: publish domain event (job failed)
this.logger.LogWarning(ex, $"{{LogKey:l}} canceled (key={{JobKey:l}}), type={job.GetType().PrettyName()})", LogKeys.JobScheduling, registration.Key);
//this.errorHandler?.Invoke(ex);
}
catch (Exception ex)
{
// TODO: publish domain event (job failed)
this.logger.LogError(ex.InnerException ?? ex, $"{{LogKey:l}} failed (key={{JobKey:l}}), type={job.GetType().PrettyName()})", LogKeys.JobScheduling, registration.Key);
this.errorHandler?.Invoke(ex.InnerException ?? ex);
}
}
}
