public void TestCriticalErrorsDiagnosticTracedOnlyOnce() { var tracer = new Tracer("MyTracer"); var context = new OperationContext(new Context(TestGlobal.Logger)); Exception exception = null; var result = context.CreateOperation( tracer, () => { exception = GetException(); if (exception != null) { throw GetException(); } return(BoolResult.Success); }) .WithOptions(traceOperationFinished: true) .Run(); // Check that the exception's stack trace appears in the final output only ones. var fullOutput = GetFullOutput(); var firstIndex = fullOutput.IndexOf(result.Diagnostics); var lastIndex = fullOutput.LastIndexOf(result.Diagnostics); Assert.NotEqual(firstIndex, -1); // The first and the last indices should be equal if the output contains a diagnostic message only once. firstIndex.Should().Be(lastIndex, "Diagnostic message should appear in the output message only once."); }
public void TraceErrorsOnly() { var tracer = new Tracer("MyTracer"); var context = new OperationContext(new Context(TestGlobal.Logger)); // Running a successful operation first var result = context.CreateOperation( tracer, () => new CustomResult()) .TraceErrorsOnlyIfEnabled(enableTracing: true) .Run(caller: "success"); // The operation should not be traced, because it was successful. var fullOutput = GetFullOutput(); fullOutput.Should().NotContain("success"); // Running an operation that fails. string error = "My Error"; result = context.CreateOperation( tracer, () => new CustomResult(new BoolResult(error), error)) .TraceErrorsOnlyIfEnabled(enableTracing: true) .Run(caller: "failure"); result.Succeeded.Should().BeFalse(); // The output should have an error fullOutput = GetFullOutput(); fullOutput.Should().Contain("failure"); fullOutput.Should().Contain(error); // Running an operation that fails another time, but this time the tracing is off error = "My Error2"; result = context.CreateOperation( tracer, () => new CustomResult(new BoolResult(error), error)) .TraceErrorsOnlyIfEnabled(enableTracing: true) .Run(caller: "failure2"); result.Succeeded.Should().BeFalse(); // The error should not be in the output fullOutput = GetFullOutput(); fullOutput.Should().Contain("failure2"); fullOutput.Should().Contain(error); }
private async Task ProcessEventsAsync(OperationContext context, List <EventData> messages) { // Tracking raw messages count. Counters[ReceivedEventHubEventsCount].Add(messages.Count); CacheActivityTracker.AddValue(CaSaaSActivityTrackingCounters.ReceivedEventHubMessages, messages.Count); // Creating nested context for all the processing operations. context = context.CreateNested(nameof(EventHubContentLocationEventStore)); if (messages.Count == 0) { // This probably does not actually occur, but just in case, ignore empty message batch. // NOTE: We do this after logging to ensure we notice if the we are getting empty message batches. return; } var state = new SharedEventProcessingState(context, this, messages); if (_eventProcessingBlocks != null) { await context .CreateOperation(Tracer, () => sendToActionBlockAsync(state)) .WithOptions(traceOperationStarted: false, endMessageFactory: r => $"TotalQueueSize={Interlocked.Read(ref _queueSize)}") .RunAsync(caller: "SendToActionBlockAsync") .TraceIfFailure(context); } else { await ProcessEventsCoreAsync(new ProcessEventsInput(state, messages, actionBlockIndex : -1, store : this), EventDataSerializer); } async Task <BoolResult> sendToActionBlockAsync(SharedEventProcessingState st) { // This local function "sends" a message into an action block based on the sender's hash code to process events in parallel from different machines. // (keep in mind, that the data from the same machine should be processed sequentially, because events order matters). // Then, it creates a local counter for each processing operation to track the results for the entire batch. foreach (var messageGroup in messages.GroupBy(GetProcessingIndex)) { int actionBlockIndex = messageGroup.Key; var eventProcessingBlock = _eventProcessingBlocks ![actionBlockIndex]; var input = new ProcessEventsInput(st, messageGroup, actionBlockIndex, this); var sendAsyncTask = eventProcessingBlock.SendAsync(input); if (sendAsyncTask.Status == TaskStatus.WaitingForActivation) { // The action block is busy. It means that its most likely full. Tracer.Debug(context, $"Action block {actionBlockIndex} is busy. Block's queue size={eventProcessingBlock.InputCount}."); } bool success = await sendAsyncTask; if (!success) { // NOTE: This case should not actually occur. // Complete the operation in case we couldn't send to the action block to prevent pending event queue from getting backlogged. input.Complete(); return(new BoolResult("Failed to add message to an action block.")); } }
public void TraceOperationStartedEmitsComponentAndOperation() { var tracer = new Tracer("MyTracer"); var mock = new StructuredLoggerMock(); var context = new OperationContext(new Context(mock)); // Running a successful operation first var result = context.CreateOperation( tracer, () => new CustomResult()) .Run(caller: "success"); mock.LogOperationStartedArgument.OperationName.Should().Be("success"); mock.LogOperationStartedArgument.TracerName.Should().Be("MyTracer"); }
public void TraceSlowSuccessfulOperationsEvenWhenErrorsOnlyFlagIsProvided() { var tracer = new Tracer("MyTracer"); var context = new OperationContext(new Context(TestGlobal.Logger)); // Running a fast operation first var result = context.CreateOperation( tracer, () => { return(new CustomResult()); }) .WithOptions(traceErrorsOnly: true) .Run(caller: "FastOperation"); // Check that the exception's stack trace appears in the final output only ones. var fullOutput = GetFullOutput(); fullOutput.Should().NotContain("FastOperation"); // Running a slow operation now result = context.CreateOperation( tracer, () => { // Making the operation intentionally slow. Thread.Sleep(10); return(new CustomResult()); }) .WithOptions(traceErrorsOnly: true, silentOperationDurationThreshold: TimeSpan.FromMilliseconds(0)) .Run(caller: "SlowOperation"); // Check that the exception's stack trace appears in the final output only ones. fullOutput = GetFullOutput(); fullOutput.Should().Contain("SlowOperation"); }
public async Task <BoolResult> ExecuteBatchOperationAsync(Context context, IRedisBatch batch, CancellationToken cancellationToken) { var operationContext = new OperationContext(context, cancellationToken); var result = await operationContext .CreateOperation( _tracer, async() => { using (Counters[RedisOperation.All].Start()) using (Counters[RedisOperation.Batch].Start()) using (Counters[batch.Operation].Start()) { Counters[RedisOperation.BatchSize].Add(batch.BatchSize); try { await _redisRetryStrategy.ExecuteAsync( context, async() => { var database = await GetDatabaseAsync(context); await batch.ExecuteBatchOperationAndGetCompletion(context, database); }, cancellationToken, _configuration.TraceTransientFailures); await batch.NotifyConsumersOfSuccess(); return(BoolResult.Success); } catch (Exception ex) { batch.NotifyConsumersOfFailure(ex); return(new BoolResult(ex)); } } }) .TraceErrorsOnlyIfEnabled( _configuration.TraceOperationFailures, endMessageFactory: r => $"Database={_configuration.DatabaseName}, ConnectionErrors={_connectionErrorCount}") .RunAsync(); HandleOperationResult(context, result); return(result); }
public void EndMessageFactoryIsCalledForFailedCase() { var tracer = new Tracer("MyTracer"); var context = new OperationContext(new Context(TestGlobal.Logger)); var result = context.CreateOperation( tracer, () => { return(new Result <int>(new Exception("Error42"))); }) .WithOptions(endMessageFactory: r => r.Succeeded ? "ExtraSuccess" : "ExtraFailure") .Run(); // Check that the exception's stack trace appears in the final output only ones. var fullOutput = GetFullOutput(); fullOutput.Should().Contain("ExtraFailure"); fullOutput.Should().Contain("Error42"); }
private async Task <T> PerformDatabaseOperationAsync <T>(Context context, Func <IDatabase, Task <T> > operation, Counter stopwatch, CancellationToken token) { var operationContext = new OperationContext(context, token); var result = await operationContext .CreateOperation( _tracer, async() => { using (Counters[RedisOperation.All].Start()) using (stopwatch.Start()) { try { var r = await _redisRetryStrategy.ExecuteAsync( context, async() => { var database = await GetDatabaseAsync(context); return(await operation(database)); }, token, _configuration.TraceTransientFailures, _configuration.DatabaseName); return(new Result <T>(r, isNullAllowed: true)); } catch (Exception e) { return(new Result <T>(e)); } } }) .TraceErrorsOnlyIfEnabled( _configuration.TraceOperationFailures, endMessageFactory: r => $"ConnectionErrors={_connectionErrorCount}") .RunAsync(); HandleOperationResult(context, result); return(result.ThrowIfFailure()); }
public void FailureIsNotCriticalIfCanceled() { var tracer = new Tracer("MyTracer"); var cts = new CancellationTokenSource(); var context = new OperationContext(new Context(TestGlobal.Logger), cts.Token); cts.Cancel(); var result = context.CreateOperation( tracer, () => { context.Token.ThrowIfCancellationRequested(); return(BoolResult.Success); }) .WithOptions(traceOperationFinished: true, isCritical: true) .Run(); result.IsCancelled.Should().BeTrue(); result.IsCriticalFailure.Should().BeFalse(); }
private async Task ProcessEventsAsync(OperationContext context, List <EventData> messages) { // Creating nested context for all the processing operations. context = context.CreateNested(); string asyncProcessing = _eventProcessingBlocks != null ? "on" : "off"; Tracer.Info(context, $"{Tracer.Name}: Received {messages.Count} events from Event Hub. Async processing is '{asyncProcessing}'."); if (messages.Count == 0) { // This probably does not actually occur, but just in case, ignore empty message batch. // NOTE: We do this after logging to ensure we notice if the we are getting empty message batches. return; } var state = new SharedEventProcessingState(context, this, messages); if (_eventProcessingBlocks != null) { await context .CreateOperation(Tracer, () => sendToActionBlockAsync()) .WithOptions(traceOperationStarted: false, endMessageFactory: r => $"TotalQueueSize={Interlocked.Read(ref _queueSize)}") .RunAsync(caller: "SendToActionBlockAsync") .TraceIfFailure(context); } else { await ProcessEventsCoreAsync(new ProcessEventsInput(state, messages, actionBlockIndex : -1, store : this), EventDataSerializer); } async Task <BoolResult> sendToActionBlockAsync() { // This local function "sends" a message into an action block based on the sender's hash code to process events in parallel from different machines. // (keep in mind, that the data from the same machine should be processed sequentially, because events order matters). // Then, it creates a local counter for each processing operation to track the results for the entire batch. foreach (var messageGroup in messages.GroupBy(GetProcessingIndex)) { int actionBlockIndex = messageGroup.Key; var eventProcessingBlock = _eventProcessingBlocks ![actionBlockIndex];
public async Task <BoolResult> ExecuteBatchOperationAsync(Context context, IRedisBatch batch, CancellationToken cancellationToken) { var operationContext = new OperationContext(context, cancellationToken); var result = await operationContext .CreateOperation( _tracer, async() => { using (Counters[RedisOperation.All].Start()) using (Counters[RedisOperation.Batch].Start()) using (Counters[batch.Operation].Start()) { Counters[RedisOperation.BatchSize].Add(batch.BatchSize); try { // Need to register the cancellation here and not inside the ExecuteAsync callback, // because the cancellation can happen before the execution of the given callback. // And we still need to cancel the batch operations to finish all the tasks associated with them. using (CancellationTokenRegistration registration = operationContext.Token.Register( () => { cancelTheBatch(reason: "a given cancellation token is cancelled"); })) { await _redisRetryStrategy.ExecuteAsync( context, async() => { var(database, databaseClosedCancellationToken) = await GetDatabaseAsync(context); CancellationTokenSource?linkedCts = null; if (_configuration.CancelBatchWhenMultiplexerIsClosed) { // The database may be closed during a redis call. // Linking two tokens together and cancelling the batch if one of the cancellations was requested. // We want to make sure the following: the task returned by this call and the tasks for each and individual // operation within a batch are cancelled. // To do that, we need to "Notify" all the batches about the cancellation inside the Register callback // and ExecuteBatchOperationAndGetCompletion should respect the cancellation token and throw an exception // if the token is set. linkedCts = CancellationTokenSource.CreateLinkedTokenSource(databaseClosedCancellationToken); linkedCts.Token.Register( () => { string reason = operationContext.Token.IsCancellationRequested ? "a given cancellation token is cancelled" : "the multiplexer is closed"; cancelTheBatch(reason: reason); }); // It is fine that the second cancellation token is not passed to retry strategy. // Retry strategy only retries on redis exceptions and all the rest, like TaskCanceledException or OperationCanceledException // are be ignored. } // We need to dispose the token source to unlink it from the tokens the source was created from. // This is important, because the database cancellation token can live a long time // referencing a lot of token sources created here. using (linkedCts) { await batch.ExecuteBatchOperationAndGetCompletion(context, database, linkedCts?.Token ?? CancellationToken.None); } }, cancellationToken, _configuration.TraceTransientFailures); await batch.NotifyConsumersOfSuccess(); return(BoolResult.Success); } } catch (TaskCanceledException e) { return(new BoolResult(e) { IsCancelled = true }); } catch (OperationCanceledException e) { return(new BoolResult(e) { IsCancelled = true }); } catch (Exception ex) { batch.NotifyConsumersOfFailure(ex); return(new BoolResult(ex)); } } }) .TraceErrorsOnlyIfEnabled( _configuration.TraceOperationFailures, endMessageFactory: r => $"Operation={batch.Operation}, Database={_configuration.DatabaseName}, ConnectionErrors={_connectionErrorCount}") .RunAsync(); HandleOperationResult(context, result); return(result); void cancelTheBatch(string reason) { context.Debug($"Cancelling {batch.Operation} against {batch.DatabaseName} because {reason}."); batch.NotifyConsumersOfCancellation(); } }