private async Task CheckpointAsync(ProcessorPartitionContext context)
{
bool checkpointed = false;
if (_batchCheckpointFrequency == 1)
{
await _checkpointer.CheckpointAsync(context).ConfigureAwait(false);
checkpointed = true;
}
else
{
// only checkpoint every N batches
if (++_batchCounter >= _batchCheckpointFrequency)
{
_batchCounter = 0;
await _checkpointer.CheckpointAsync(context).ConfigureAwait(false);
checkpointed = true;
}
}
if (checkpointed)
{
_logger.LogDebug(GetOperationDetails(context, "CheckpointAsync"));
}
}
/// <inheritdoc />
public override sealed async Task PartitionStopAsync(ProcessorPartitionContext partitionContext, ProcessingStoppedReason reason, CancellationToken cancellationToken)
{
await base.PartitionStopAsync(partitionContext, reason, cancellationToken).ConfigureAwait(false);
using (Logger.BeginScope("Processor stopping"))
{
if (_checkpointTo == null)
{
Logger.LogInformation("Shutting down but no checkpoint data available on partition {partitionId}", partitionContext.PartitionId);
}
else if (reason == ProcessingStoppedReason.OwnershipLost)
{
Logger.LogWarning("Cannot checkpoint, ownership was lost for partition {partitionId}, last known sequence number: {checkpointTo}", partitionContext.PartitionId, _checkpointTo.SequenceNumber);
}
else
{
try
{
Logger.LogInformation("Graceful shutdown on partition {partitionId}, forcing checkpoint to sequence number {sequenceNumber}", partitionContext.PartitionId, _checkpointTo.SequenceNumber);
var tokenSource = new CancellationTokenSource(3000);
var checkpointSuccess = await _checkpointPolicy.CheckpointAsync(_checkpointTo, true, tokenSource.Token).ConfigureAwait(false);
Logger.LogInformation("Completed checkpoint on partition {partitionId} result {result}", partitionContext.PartitionId, checkpointSuccess);
}
catch (Exception e)
{
Logger.LogError(e, "Error checkpointing on partition {partitionId} during graceful shutdown, duplicate data expected", partitionContext.PartitionId);
}
}
var derivedTokenSource = new CancellationTokenSource(3000);
await ProcessorStoppingAsync(reason, derivedTokenSource.Token).ConfigureAwait(false);
}
}
public Task ProcessErrorAsync(ProcessorPartitionContext context, Exception error)
{
string errorDetails = $"Processing error (Partition Id: '{context.PartitionId}', Owner: '{context.Owner}', EventHubPath: '{context.EventHubPath}').";
Utility.LogException(error, errorDetails, _logger);
return(Task.CompletedTask);
}
public Task CloseAsync(ProcessorPartitionContext context, ProcessingStoppedReason reason)
{
// signal cancellation for any in progress executions
_cts.Cancel();
_logger.LogDebug(GetOperationDetails(context, $"CloseAsync, {reason.ToString()}"));
return(Task.CompletedTask);
}
/// <inheritdoc />
public virtual Task PartitionInitializeAsync(ProcessorPartitionContext partitionContext, CancellationToken cancellationToken)
{
using (Logger.BeginScope("OnInitialize"))
{
Logger.LogInformation("Initializing partition {partitionId}", partitionContext.PartitionId);
}
return(Task.CompletedTask);
}
/// <inheritdoc />
public async Task PartitionProcessAsync(IEnumerable <EventData> events, ProcessorPartitionContext partitionContext, CancellationToken cancellationToken)
{
using (Logger.BeginScope("Processing Event Batch"))
{
if (events != null)
{
try
{
if (!PoisonCheckCompleted)
{
// Check if the are any evens in the list
var messageEnumerator = events.GetEnumerator();
var hasMessages = messageEnumerator.MoveNext();
if (hasMessages)
{
if (await IsMessagePoisoned(messageEnumerator.Current, cancellationToken).ConfigureAwait(false) ?? false)
{
Logger.LogWarning("Removing poison message, providing remainder of batch on partition {partitionId} for processing sequence number {sequenceNumber}.", partitionContext.PartitionId, messageEnumerator.Current.SequenceNumber);
var updatedList = events.ToList();
updatedList.RemoveAt(0);
events = updatedList;
Logger.LogWarning("Removed poison message, providing remainder of batch on partition {partitionId} for processing {count} message remaining.", partitionContext.PartitionId, updatedList.Count);
}
}
}
Logger.LogDebug("Starting custom processing of batch for partition {partitionId}", partitionContext.PartitionId);
await ProcessBatchAsync(events, cancellationToken).ConfigureAwait(false);
if (_checkpointTo != null)
{
Logger.LogDebug("Starting policy checkpoint for partition {partitionId}", partitionContext.PartitionId);
var checkpointResult = await _checkpointPolicy.CheckpointAsync(_checkpointTo, false, cancellationToken).ConfigureAwait(false);
Logger.LogDebug("Completed policy checkpoint for partition {partitionId}, result: {result}", partitionContext.PartitionId, checkpointResult);
}
}
catch (Exception e)
{
Logger.LogError(e, "Error raised by customer batch processor on partition {partitionId}", partitionContext.PartitionId);
throw;
}
}
else if (_checkpointTo != default && _checkpointTo.SequenceNumber > _checkpointPolicy.SequenceNumber)
{
if (_checkpointTo != null)
{
Logger.LogDebug("No events received, starting policy checkpoint for partition {partitionId}", partitionContext.PartitionId);
var checkpointResult = await _checkpointPolicy.CheckpointAsync(_checkpointTo, false, cancellationToken).ConfigureAwait(false);
Logger.LogDebug("Completed policy checkpoint for partition {partitionId}, result: {result}", partitionContext.PartitionId, checkpointResult);
}
}
}
}
/// <inheritdoc />
public virtual Task PartitionHandleErrorAsync(Exception exception, ProcessorPartitionContext partitionContext, string operationDescription, CancellationToken cancellationToken)
{
using (Logger.BeginScope("OnError"))
{
ErrorCounter.Increment();
Logger.LogError(exception, "Erron partition {partitionId}, {operationDescription}", partitionContext.PartitionId, operationDescription);
}
return(Task.CompletedTask);
}
/// <inheritdoc />
public override sealed async Task InitializeAsync(ILogger logger, IMetricFactory metricFactory, ProcessorPartitionContext partitionContext)
{
_metricFactory = metricFactory;
_partitionContext = partitionContext;
await base.InitializeAsync(logger, metricFactory, partitionContext).ConfigureAwait(false);
await _checkpointPolicy.InitializeAsync(Logger, metricFactory, partitionContext, CancellationToken.None).ConfigureAwait(false);
await InitializeInstanceAsync().ConfigureAwait(false);
}
/// <inheritdoc />
public virtual Task PartitionStopAsync(ProcessorPartitionContext partitionContext, ProcessingStoppedReason reason, CancellationToken cancellationToken)
{
using (Logger.BeginScope("OnStop"))
{
Logger.LogInformation("Stopping partition {partitionId}, reason {reason}", partitionContext.PartitionId, Enum.GetName(typeof(ProcessingStoppedReason), reason));
if (reason == ProcessingStoppedReason.Shutdown)
{
Logger.LogInformation("Checkpointing in graceful shutdown for partition {partitionId}", partitionContext.PartitionId, Enum.GetName(typeof(ProcessingStoppedReason), reason));
}
}
return(Task.CompletedTask);
}
private static string GetOperationDetails(ProcessorPartitionContext context, string operation)
{
StringWriter sw = new StringWriter();
using (JsonTextWriter writer = new JsonTextWriter(sw)
{
Formatting = Formatting.None
})
{
writer.WriteStartObject();
WritePropertyIfNotNull(writer, "operation", operation);
writer.WritePropertyName("partitionContext");
writer.WriteStartObject();
WritePropertyIfNotNull(writer, "partitionId", context.PartitionId);
WritePropertyIfNotNull(writer, "owner", context.Owner);
WritePropertyIfNotNull(writer, "eventHubPath", context.EventHubPath);
writer.WriteEndObject();
// Log partition lease
if (context.Lease != null)
{
writer.WritePropertyName("lease");
writer.WriteStartObject();
WritePropertyIfNotNull(writer, "offset", context.Lease.Offset.ToString(CultureInfo.InvariantCulture));
WritePropertyIfNotNull(writer, "sequenceNumber", context.Lease.SequenceNumber.ToString(CultureInfo.InvariantCulture));
writer.WriteEndObject();
}
// Log RuntimeInformation if EnableReceiverRuntimeMetric is enabled
if (context.LastEnqueuedEventProperties != null)
{
writer.WritePropertyName("lastEnquedEventProperties");
writer.WriteStartObject();
WritePropertyIfNotNull(writer, "offset", context.LastEnqueuedEventProperties.Value.Offset?.ToString(CultureInfo.InvariantCulture));
WritePropertyIfNotNull(writer, "sequenceNumber", context.LastEnqueuedEventProperties.Value.SequenceNumber?.ToString(CultureInfo.InvariantCulture));
WritePropertyIfNotNull(writer, "enqueuedTimeUtc", context.LastEnqueuedEventProperties.Value.EnqueuedTime?.ToString("o", CultureInfo.InvariantCulture));
writer.WriteEndObject();
}
writer.WriteEndObject();
}
return(sw.ToString());
}
/// <inheritdoc />
public virtual Task <bool> InitializeAsync(ILogger logger, IMetricFactory metricFactory, ProcessorPartitionContext context, CancellationToken cancellationToken)
{
Guard.NotNull(nameof(logger), logger);
Guard.NotNull(nameof(metricFactory), metricFactory);
Guard.NotNull(nameof(context), context);
Logger = logger;
using (Logger.BeginScope("Initializing Policy Manager"))
{
MetricFactory = metricFactory;
Context = context;
Logger.LogInformation("Initializing policy manager {name}", Name);
_checkpointExecutedCounter = MetricFactory.CreateCounter("cpol-execution-count", "Counts the number of times a checkpoint has been performed", false, new string[0]);
_checkpointErrorCounter = MetricFactory.CreateCounter("cpol-error-count", "Counts the number of times a checkpoint has generated an error", false, new string[0]);
_checkpointRequestedCounter = MetricFactory.CreateCounter("cpol-requested-count", "Counts the number of times a checkpoint has been requested", false, new string[0]);
}
return(Task.FromResult(true));
}
/// <summary>
/// Updates the poison message information and checks the provided message for poison status, This should only be called on the first message received in a batch, all others should always return false
/// </summary>
/// <param name="data">The event data to check for poisoned message status</param>
/// <param name="partitionContext">The partition context associated with the processor</param>
/// <param name="cancellationToken">A token to monitor for abort requests</param>
/// <returns>True if the message is safe to process, false if poisoned</returns>
protected async Task <bool> UpdatePoisonMonitorStatusAsync(EventData data, ProcessorPartitionContext partitionContext, CancellationToken cancellationToken)
{
var shouldProcess = false;
try
{
Logger.LogInformation("Partition {partitionId} checking if Sequence Number {sequenceNumber} is poisoned", partitionContext.PartitionId, data.SequenceNumber);
if (await _poisonMonitor.IsPoisonedMessageAsync(partitionContext.PartitionId, data.SequenceNumber, cancellationToken).ConfigureAwait(false))
{
var handled = false;
for (var handleIndex = 0; handleIndex < 3 && !handled; handleIndex++)
{
try
{
Logger.LogWarning("Partition {partitionId} found Sequence Number {sequenceNumber} is poisoned", partitionContext.PartitionId, data.SequenceNumber);
handled = await HandlePoisonMessageAsync(data, partitionContext, cancellationToken).ConfigureAwait(false);
}
catch (Exception e)
{
Logger.LogError(e, "Partition {partitionId} error handling poison message {sequenceNumber}", partitionContext.PartitionId, data.SequenceNumber);
}
}
var checkpointSuccess = false;
for (var checkpointAttempt = 0; checkpointAttempt < 3 && !checkpointSuccess; checkpointAttempt++)
{
// Immediately checkpoint to move this forward and do not process further
await _checkpointPolicy.CheckpointAsync(data, true, cancellationToken).ConfigureAwait(false);
checkpointSuccess = true;
}
}
else
{
Logger.LogInformation("Partition {partitionId} Sequence Number {sequenceNumber} is not poisoned", partitionContext.PartitionId, data.SequenceNumber);
shouldProcess = true;
PoisonData poisonData = null;
for (var retrieveAttempt = 0; retrieveAttempt < 3 && poisonData == null; retrieveAttempt++)
{
try
{
poisonData = await _poisonMonitor.GetPoisonDataAsync(partitionContext.PartitionId, cancellationToken).ConfigureAwait(false);
}
catch (Exception e)
{
Logger.LogError(e, "Error retrieving poison message data for partition {partitionId}", partitionContext.PartitionId);
}
}
if (poisonData.SequenceNumber == -1)
{
poisonData.SequenceNumber = data.SequenceNumber;
poisonData.ReceiveCount = 0;
}
else if (poisonData.SequenceNumber == data.SequenceNumber)
{
poisonData.ReceiveCount = poisonData.ReceiveCount + 1;
}
else
{
poisonData.ReceiveCount = 1;
poisonData.SequenceNumber = data.SequenceNumber;
}
var updateSuccess = false;
for (var retrieveAttempt = 0; retrieveAttempt < 3 && !updateSuccess; retrieveAttempt++)
{
try
{
updateSuccess = await _poisonMonitor.UpdatePoisonDataAsync(poisonData, cancellationToken).ConfigureAwait(false);
}
catch (Exception e)
{
Logger.LogError(e, "Error updating poison message data for partition {partitionId}", partitionContext.PartitionId);
}
}
}
}
catch (Exception e)
{
Logger.LogError(e, "Unknown error cannot in poison message handling for partition {partitionId} with sequence Number {sequenceNumber}, ignoring message", partitionContext.PartitionId, data.SequenceNumber);
}
return(shouldProcess);
}
/// <inheritdoc />
protected override Task <bool> HandlePoisonMessageAsync(EventData data, ProcessorPartitionContext partitionContext, CancellationToken cancellationToken)
{
// Perform custom processing here for poisoned message, e.g. store to raw store
return(base.HandlePoisonMessageAsync(data, partitionContext, cancellationToken));
}
public Task OpenAsync(ProcessorPartitionContext context)
{
_logger.LogDebug(GetOperationDetails(context, "OpenAsync"));
return(Task.CompletedTask);
}
public async Task ProcessEventsAsync(ProcessorPartitionContext context, IEnumerable <EventData> messages)
{
var triggerInput = new EventHubTriggerInput
{
Events = messages.ToArray(),
PartitionContext = context
};
TriggeredFunctionData input = null;
if (_singleDispatch)
{
// Single dispatch
int eventCount = triggerInput.Events.Length;
List <Task> invocationTasks = new List <Task>();
for (int i = 0; i < eventCount; i++)
{
if (_cts.IsCancellationRequested)
{
break;
}
EventHubTriggerInput eventHubTriggerInput = triggerInput.GetSingleEventTriggerInput(i);
input = new TriggeredFunctionData
{
TriggerValue = eventHubTriggerInput,
TriggerDetails = eventHubTriggerInput.GetTriggerDetails(context)
};
Task task = TryExecuteWithLoggingAsync(input, triggerInput.Events[i]);
invocationTasks.Add(task);
}
// Drain the whole batch before taking more work
if (invocationTasks.Count > 0)
{
await Task.WhenAll(invocationTasks).ConfigureAwait(false);
}
}
else
{
// Batch dispatch
input = new TriggeredFunctionData
{
TriggerValue = triggerInput,
TriggerDetails = triggerInput.GetTriggerDetails(context)
};
using (_logger.BeginScope(GetLinksScope(triggerInput.Events)))
{
await _executor.TryExecuteAsync(input, _cts.Token).ConfigureAwait(false);
}
}
// Checkpoint if we processed any events.
// Don't checkpoint if no events. This can reset the sequence counter to 0.
// Note: we intentionally checkpoint the batch regardless of function
// success/failure. EventHub doesn't support any sort "poison event" model,
// so that is the responsibility of the user's function currently. E.g.
// the function should have try/catch handling around all event processing
// code, and capture/log/persist failed events, since they won't be retried.
if (messages.Any())
{
context.CheckpointEvent = messages.Last();
await CheckpointAsync(context).ConfigureAwait(false);
}
}
/// <inheritdoc />
public virtual Task InitializeAsync(ILogger logger, IMetricFactory metricFactory, ProcessorPartitionContext partitionContext)
{
Logger = logger;
using (Logger.BeginScope("Initialize batch processor"))
{
Logger.LogInformation("Initializing batch processor for partition {partitionId}", partitionContext.PartitionId);
MessageCounter = metricFactory.CreateCounter($"hcp-message-count-{partitionContext.PartitionId}", "The number of messages that have been processed by partition {partitionContext.PartitionId}", false, new string[0]);
ErrorCounter = metricFactory.CreateCounter($"hcp-error-count-{partitionContext.PartitionId}", "The number of errors that have been processed by partition {partitionContext.PartitionId}", false, new string[0]);
}
return(Task.CompletedTask);
}
/// <summary>
/// Implement to provide custom handling of poison messages, by default it will be logged and disposed of
/// </summary>
/// <param name="data">The message that is poisoned</param>
/// <param name="partitionContext">A partition context associated with the current processor</param>
/// <param name="cancellationToken">A token to monitor for abort and cancellation requests</param>
/// <returns>True if successfully completed the handling. If it fails the handler will be invoked again to a maximum of 3 times total</returns>
protected virtual Task <bool> HandlePoisonMessageAsync(EventData data, ProcessorPartitionContext partitionContext, CancellationToken cancellationToken)
{
Logger.LogWarning("Partition {partitionId}, consider poison message Sequence Number {sequenceNumber} handled", partitionContext.PartitionId, data.SequenceNumber);
return(Task.FromResult(true));
}
async Task ICheckpointer.CheckpointAsync(ProcessorPartitionContext context)
{
await context.CheckpointAsync().ConfigureAwait(false);
}
