Events passed to processEvents are not always ordered by sequenceNumber

[03byron]

• Package Name: @azure/event-hubs
• Package Version: 8.19.2
• Operating system: Docker: node:18.12.1-alpine
• nodejs
  • version: 18.12.1

Describe the bug
The list of events passed into the processEvents callback is not always ordered by sequenceNumber. This leads to processing the events in a wrong order. If that is intended it would be good to mention it in the documentation.

It does not happen very often - we see 6 occurrences in the last 4 hours. We processed ~117k events in that timeframe.

To Reproduce
Steps to reproduce the behavior:

1. Setup an event consumer:

async function processEvents(events: ReceivedEventData[], context: PartitionContext) {
  if (events.length === 0) {
    return;
  }
  if (
    events.some((event, index) => {
      return (
        !!events[index + 1] && // its not the last event in the list
        event.sequenceNumber > events[index + 1].sequenceNumber // Current sequence number is larger than the next one
      ); 
    })
  ) {
    console.error(`Events received in wrong order: ${events.map(({ sequenceNumber }) => sequenceNumber).join(' ,')}`);
  }
}

2. Observe the log for the above message.

Expected behavior
No error should appear in the log as events should be sorted by sequenceNumber.

Additional context
The samples we have contain all consecutive events in one call to processEvents. They are just not ordered appropriately.

We see log messages like:

Example 1

Events received in wrong order: 78716749 ,78716747 ,78716748 ,78716750 ,78716751 ,78716752 ,78716753 ,78716754 ,78716755 ,78716756 ,78716757 ,78716758 ,78716759 ,78716760 ,78716761 ,78716762 ,78716763 ,78716764 ,78716765 ,78716766 ,78716767 ,78716768 ,78716769 ,78716770 ,78716771 ,78716772 ,78716773 ,78716774 ,78716775 ,78716776 ,78716777 ,78716778 ,78716779

Example 2

Events received in wrong order: 402880 ,402881 ,402882 ,402877 ,402878 ,402879 ,402883 ,402884 ,402885 ,402886 ,402887 ,402888 ,402889 ,402890 ,402891 ,402892 ,402893 ,402894 ,402895 ,402896 ,402897 ,402898 ,402899 ,402900

[deyaaeldeen]

Thanks for the report! Could you share the subscription id, EH namespace, and the Event Hub name, in addition to an approximate time window when the behavior was observed?

[03byron]

Hi @deyaaeldeen - thank you for the reply. We provided the requested details via a service ticket (ID 2212010050000732). Some findings worth sharing in the meantime:

1. We see the issue on at least two different event streams
2. We see the issue on at least two nodejs implementations made by different teams. However, they do not receive the same wrongly ordered sequences.
3. We have one other nodejs implementation that differs a bit: Its subscribes once a day to a single partition(instead of all), processes all events collected since yesterday and sleeps again until the next day (whilst the others always listen). We could not find the issue in this process.

Because of the above observations our assumption is a race condition in the js sdk.

[deyaaeldeen]

Thanks a lot for sharing the details and the additional observations!

We have one other nodejs implementation that differs a bit: Its subscribes once a day to a single partition(instead of all), processes all events collected since yesterday and sleeps again until the next day (whilst the others always listen). We could not find the issue in this process.

From the above, do I understand it correctly that you observe the issue when the consumer subscribed to multiple partitions at the same time but not when subscribed to a single one?

Please note that events are ordered in each partition individually but not across all partitions, i.e., sequence numbers are meaningful only within the context of a single partition. For a single processEvents call, the input event list comes from a single partition so I am puzzled that the issue happens when connecting to multiple partitions but not to one.

I will ask the service team to take a look. In the meantime, please keep us posted on any further observations.

[03byron]

From the above, do I understand it correctly that you observe the issue when the consumer subscribed to multiple partitions at the same time but not when subscribed to a single one?

Correct.

Please note that events are ordered in each partition individually but not across all partitions, i.e., sequence numbers are meaningful only within the context of a single partition. For a single processEvents call, the input event list comes from a single partition so I am puzzled that the issue happens when connecting to multiple partitions but not to one.

Yes, we are aware of this. One explanation might be the load. A subscription for a single partition has to process a lot less events than one that subscribes to all partitions. Over the last three days I can see the error only on those regions with the highest load.

Another observation which is not yet fully validated: We stumbled upon the issue because we saw that events that tried to update an entity failed because the create event for that entity was processed after the update. We see this pattern in all our affected nodejs implementation. However, we don't see it in java based implementations of the same stream. We will add explicit detection of the order and validate this observation.

[thomasstoermer]

We have been able to reproduce the issue with a simple test client:

1. Create event hub with 32 partitions
2. Produce 20,000 events on each partition
3. Start a consumer processing all 32 partitions using:
   • SubscribeOptions described below
   • processEvents handler described below using a random short processing delay simulation
4. After several thousand events the error should occur

export async function processEvents(events: ReceivedEventData[], context: PartitionContext) {
    if (events.length === 0) {
        return;
    }
    if (
        events.some((event, index) => {
            return (
                !!events[index + 1] && // its not the last event in the list
                event.sequenceNumber > events[index + 1].sequenceNumber // Current sequence number is larger than the next one
            );
        })
    ) {
        console.error(`Events received in wrong order: ${events.map(({ sequenceNumber }) => sequenceNumber).join(' ,')}`);
    }
    const randomDelay = randomNumber(1,10) * 10;
    // simulate processing delay
    return new Promise<void>((resolve) => {
        setTimeout(() => {
            resolve()
        }, randomDelay);
    });
}

function randomNumber(min: number, max: number) {
    return Math.floor(Math.random() * (max - min + 1) + min)
}

SubscribeOptions:

const subscribeOptions: SubscribeOptions = {
    maxWaitTimeInSeconds: 2,
    maxBatchSize: 100,
    startPosition: earliestEventPosition
}

[03byron]

Update from the internal support ticket: There is a race condition in the js sdk, only. Recommended workaround until there is a fix is to set maxWaitTimeInSeconds to 60. We can confirm that this reduces the frequency of the error but it does not solve the issue completely.

[deyaaeldeen]

Hi @03byron, thanks for your patience! @azure/event-hubs@5.9.0 has been released today and it contains a fix to this issue. Could you please upgrade to it and confirm whether the issue is indeed fixed?

[03byron]

Hi @deyaaeldeen, the issue is indeed solved with version 5.9.0. I don't see any occurrences since we updated two days ago. Thank you.

[ghost]

Hi @03byron. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text “/unresolve” to remove the “issue-addressed” label and continue the conversation.

[ghost]

Hi @03byron, since you haven’t asked that we “/unresolve” the issue, we’ll close this out. If you believe further discussion is needed, please add a comment “/unresolve” to reopen the issue.