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