/// <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); } } }