If using single dispatch, this is a bug in which the extension would sometimes log the incorrect trigger details of the EH message.
This is because, regardless of whether the user specified single dispatch or batch processing, the extension request a batch from the EH SDK regardless. However, in the case of a single dispatch, the extension loops over each message in the batch, and dispatches a new execution for each one.
However, the way it does that is that it first creates an EventHubTriggerInput object, which is created by calling GetSingleEventTriggerInput, which, instead of creating an object with just a singular event, creates a data object with the Events property set to all the events received in the batch. This data structure is properly used during executing user code to execute only on the individual message. However, in the case of logging, if it's a single dispatch, we always just log the details of the first event in the Events property, which will be the same for all events in the batch.
What this means is that, e.g., if a batch of 4 unique events is received from the SDK, and single dispatch is being used, user code will run 4 times, processing each message once, but there will be 4 identical log statements, logging the details of the first event in the batch, and also incorrectly logging the Count as 4 instead of 1.
Repro
Create an EventHub
Create a backlog of 4 event in the EventHub, for example by sending messages through the ServiceBusExplorer
Create a single dispatch EventHub-triggered function on the EventHub you just created, logging details of the message received:
public static class EventHubTrigger1
{
[FunctionName("EventHubTrigger1")]
public static void Run([EventHubTrigger("webjobstesthub", Connection ="eventHubConnection")] EventData myEventHubMessage, DateTime enqueuedTimeUtc, Int64 sequenceNumber, string offset, ILogger log)
{
log.LogInformation($"Event: {Encoding.UTF8.GetString(myEventHubMessage.Body)}");
log.LogInformation($"EnqueuedTimeUtc={enqueuedTimeUtc}");
log.LogInformation($"SequenceNumber={sequenceNumber}");
log.LogInformation($"Offset={offset}");
}
}
Run your function
Expected Behavior
In the logs, I expect to see unique TriggerDetails: ... log for each execution with unique offset, enqueue time, sequence number, that match those I log from inside my function.
Actual Behavior
Logs of the trigger details are identical for all messages in the batch, and are mismatched from logs from inside my function. For example:
Summary
If using single dispatch, this is a bug in which the extension would sometimes log the incorrect trigger details of the EH message.
This is because, regardless of whether the user specified single dispatch or batch processing, the extension request a batch from the EH SDK regardless. However, in the case of a single dispatch, the extension loops over each message in the batch, and dispatches a new execution for each one.
However, the way it does that is that it first creates an
EventHubTriggerInputobject, which is created by callingGetSingleEventTriggerInput, which, instead of creating an object with just a singular event, creates a data object with theEventsproperty set to all the events received in the batch. This data structure is properly used during executing user code to execute only on the individual message. However, in the case of logging, if it's a single dispatch, we always just log the details of the first event in theEventsproperty, which will be the same for all events in the batch.What this means is that, e.g., if a batch of 4 unique events is received from the SDK, and single dispatch is being used, user code will run 4 times, processing each message once, but there will be 4 identical log statements, logging the details of the first event in the batch, and also incorrectly logging the
Countas 4 instead of 1.Repro
Expected Behavior
In the logs, I expect to see unique
TriggerDetails: ...log for each execution with unique offset, enqueue time, sequence number, that match those I log from inside my function.Actual Behavior
Logs of the trigger details are identical for all messages in the batch, and are mismatched from logs from inside my function. For example:
Known workarounds
Upgrade to latest version (v5.x) of the extension
Extension Version
I have verified this behaviour with the latest version of the track 1 extension: Microsoft.Azure.WebJobs.Extensions.EventHubs v4.3.1.
I verified that this issue has been fixed in the latest version of the track 2 extension (v5.x)