[BUG] EventProcessorClient stops consuming d2c messages after timeout exception until the application gets restarted

[weissmarcel]

Describe the bug
In certain scenarios a event processor client disposal gets initiated (maybe due to tmp connection problems?)
In this specific case the EventProcessorClient seemingly could not recover from that disposal due to a timeout exception that was thrown in the end:

"May 1, 2025 @ 01:41:30.273,INFO,""{""""az.sdk.message"""":""""Exception occurred disposing of consumer client."""",""""exception"""":""""Timeout on blocking read for 10000000000 NANOSECONDS"""",""""partitionId"""":""""0""""}"",""device-messaging"",""com.azure.messaging.eventhubs.PartitionPump"""

Afterwards no more d2c messages were consumed until the whole app service was restarted.

Exception or Stack Trace
"May 1, 2025 @ 01:41:30.273,INFO,""{""""az.sdk.message"""":""""Exception occurred disposing of consumer client."""",""""exception"""":""""Timeout on blocking read for 10000000000 NANOSECONDS"""",""""partitionId"""":""""0""""}"",""device-messaging"",""com.azure.messaging.eventhubs.PartitionPump""" "May 1, 2025 @ 01:41:24.274,INFO,""{""""az.sdk.message"""":""""Processing all pending tasks and closing old reactor."""",""""connectionId"""":""""MF_993d98_1744635821932""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorExecutor""" "May 1, 2025 @ 01:41:24.274,INFO,""{""""az.sdk.message"""":""""connection close finished."""",""""entityPath"""":""""XXXXX-iothub"""",""""connectionId"""":""""MF_993d98_1744635821932""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnectionCache""" "May 1, 2025 @ 01:41:24.274,INFO,""{""""az.sdk.message"""":""""onConnectionShutdown. Shutting down."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""isTransient"""":false,""""isInitiatedByClient"""":false,""""shutdownMessage"""":""""connectionId[MF_993d98_1744635821932] Reactor selectable is disposed."""",""""namespace"""":""""iothub-ns-XXXXXXXXXXXXXX.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnection""" "May 1, 2025 @ 01:41:24.274,INFO,""{""""az.sdk.message"""":""""onConnectionShutdown. Shutting down."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""isTransient"""":false,""""isInitiatedByClient"""":false,""""shutdownMessage"""":""""Finished processing pending tasks."""",""""namespace"""":""""iothub-nsXXXXX125-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnection""" "May 1, 2025 @ 01:41:24.274,INFO,""{""""az.sdk.message"""":""""Reactor selectable is being disposed."""",""""connectionId"""":""""MF_993d98_1744635821932""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorDispatcher""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onLinkRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""cbs:receiver"""",""""entityPath"""":""""$cbs""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ReceiveLinkHandler2""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onTransportClosed"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXXXXX25-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ConnectionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onLinkFinal"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""cbs:sender"""",""""entityPath"""":""""$cbs""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SendLinkHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onLinkRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""cbs:sender"""",""""entityPath"""":""""$cbs""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SendLinkHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onConnectionRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXXXX5-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ConnectionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onSessionFinal."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""XXXXXX-iothub/ConsumerGroups/$default/Partitions/0"""",""""sessionId"""":""""H_fdd09e_1744635821951""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SessionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onConnectionFinal"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXXXX8125-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ConnectionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onSessionRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""cbs-session"""",""""sessionId"""":""""H_2fc381_1744635821957""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SessionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onConnectionUnbound"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXXXXX125-d01856aab8.servicebus.windows.net"""",""""state"""":""""CLOSED"""",""""remoteState"""":""""CLOSED""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ConnectionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onSessionFinal."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""cbs-session"""",""""sessionId"""":""""H_2fc381_1744635821957""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SessionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onSessionRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""XXXXXX-iothub/ConsumerGroups/$default/Partitions/0"""",""""sessionId"""":""""H_fdd09e_1744635821951""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.SessionHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onTransportClosed"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXX8125-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.GlobalIOHandler""" "May 1, 2025 @ 01:41:20.296,INFO,""{""""az.sdk.message"""":""""onLinkFinal"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""cbs:receiver"""",""""entityPath"""":""""$cbs""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ReceiveLinkHandler2""" "May 1, 2025 @ 01:41:20.273,INFO,""{""""az.sdk.message"""":""""Closing executor."""",""""connectionId"""":""""MF_993d98_1744635821932""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnection""" "May 1, 2025 @ 01:41:20.273,INFO,""{""""az.sdk.message"""":""""session disposal is completed"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""cbs-session"""",""""sessionId"""":""""H_2fc381_1744635821957""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorSession""" "May 1, 2025 @ 01:41:20.273,INFO,""{""""az.sdk.message"""":""""onConnectionLocalClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""hostName"""":""""iothub-ns-XXXXXX-d01856aab8.servicebus.windows.net""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ConnectionHandler""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""onLinkFinal"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ReceiveLinkHandler2""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""Closed consumer."""",""""partitionId"""":""""0""""}"",""device-messaging"",""com.azure.messaging.eventhubs.EventHubPartitionAsyncConsumer""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""Disposing of ReactorConnection."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""isTransient"""":false,""""isInitiatedByClient"""":true,""""shutdownMessage"""":""""Disposed by client.""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnection""" "May 1, 2025 @ 01:41:20.272,WARN,""{""""az.sdk.message"""":""""MessageFlux reached a terminal completion-state, signaling it downstream."""",""""messageFlux"""":""""mf_83df71_1744635821923"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.MessageFlux""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""Closing consumer."""",""""partitionId"""":""""0""""}"",""device-messaging"",""com.azure.messaging.eventhubs.PartitionPumpManager""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""closing the channel-cache."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""cbs""""}"",""device-messaging"",""com.azure.core.amqp.implementation.RequestResponseChannelCache""" "May 1, 2025 @ 01:41:20.272,WARN,""{""""az.sdk.message"""":""""Terminal completion signal from Upstream|Receiver arrived at MessageFlux."""",""""messageFlux"""":""""mf_83df71_1744635821923"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.MessageFlux""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""Closing partition processor with close reason EVENT_PROCESSOR_SHUTDOWN"""",""""partitionId"""":""""0""""}"",""device-messaging"",""com.azure.messaging.eventhubs.implementation.PartitionProcessor""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""session disposal is completed"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""XXXXX-iothub/ConsumerGroups/$default/Partitions/0"""",""""sessionId"""":""""H_fdd09e_1744635821951""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorSession""" "May 1, 2025 @ 01:41:20.272,WARN,""{""""az.sdk.message"""":""""Receiver emitted terminal completion."""",""""messageFlux"""":""""mf_83df71_1744635821923"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.MessageFlux""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""Receiving completed."""",""""linkName"""":""""0_e298df_1744635821918"""",""""partitionId"""":""""0"""",""""signalType"""":""""onComplete""""}"",""device-messaging"",""com.azure.messaging.eventhubs.EventHubConsumerAsyncClient""" "May 1, 2025 @ 01:41:20.272,INFO,""{""""az.sdk.message"""":""""closing connection (Terminating the connection recovery support.)."""",""""entityPath"""":""""XXXXX-iothub"""",""""connectionId"""":""""MF_993d98_1744635821932""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorConnectionCache""" "May 1, 2025 @ 01:41:20.271,INFO,""{""""az.sdk.message"""":""""Complete. Removing receive link."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""sessionName"""":""""XXXXX-iothub/ConsumerGroups/$default/Partitions/0"""",""""sessionId"""":""""H_fdd09e_1744635821951"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.ReactorSession""" "May 1, 2025 @ 01:41:20.271,INFO,""{""""az.sdk.message"""":""""Local link state is not closed."""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXXX-iothub/ConsumerGroups/$default/Partitions/0"""",""""state"""":""""ACTIVE""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ReceiveLinkHandler2""" "May 1, 2025 @ 01:41:20.271,INFO,""{""""az.sdk.message"""":""""onLinkRemoteClose"""",""""connectionId"""":""""MF_993d98_1744635821932"""",""""linkName"""":""""0_e298df_1744635821918"""",""""entityPath"""":""""XXXXX-iothub/ConsumerGroups/$default/Partitions/0""""}"",""device-messaging"",""com.azure.core.amqp.implementation.handler.ReceiveLinkHandler2"""

To Reproduce
Steps to reproduce the behavior:
I am not able to reproduce this issue manually. It could happen that the EventProcessorClient and the scheduled partition pumps run smooth for several weeks and rarely such a scenario occurs that breaks the client d2c msg consumption without a proper recovery.

Expected behavior
The EventProcessorClient should be able to recover from any network issues (e.g. latencies) and should continue consuming d2c messages from the different partitions without the need of a manual restart of the whole app service.

Setup (please complete the following information):

• OS: Alpine Linux v3.21

• Library/Libraries:

•  		<groupId>com.azure</groupId>
   		<artifactId>azure-messaging-eventhubs</artifactId>
   		<version>5.20.2</version>
  
   		<groupId>com.microsoft.azure.sdk.iot</groupId>
   		<artifactId>iot-service-client</artifactId>
   		<version>2.1.9</version>
  
   		<groupId>com.azure</groupId>
   		<artifactId>azure-core</artifactId>
   		<version>1.55.3</version>
  

• Java version: openjdk 21.0.6 2025-01-21 LTS

• Frameworks: [Quarkus]

[joshfree]

@anuchandy can you follow up with @weissmarcel on this question about Event Hubs?

[joshfree]

From an offline conversation, @conniey is going to follow up instead

[conniey]

Can you provide logs a 5 minutes before it stops processing and 5 minutes after it hangs? From the current logs, it looks like a user-initiated EventProcessorClient.stop() so I'm trying to get a full picture.

[weissmarcel]

Hi @conniey,

the only additional log entries 5 mins before and after are from PartitionBasedLoadBalancer.
Those are only INFO logs about the scheduled load balancing iterations.

To me it looks like this shutdown was not initiated by our code. Otherwise I would see additional custom log entries from our code that we write whenever we stop the EventProcessor client.

I was searching our logs for other scenarios where an EventProcessor shutdown was processed and it seems that in other cases the recovery did work properly. No restart of the application was needed and d2c messages were still consumed. The only difference I saw was that there was no timeout exception in the end ("Timeout on blocking read for 10000000000").

So my assumption is that this exception during the EventProcessorShutdown is killing the scheduled partition pumps and is not recovering from it?

[conniey]

Whenever a receiver is shutdown due to timeout, our load balancing loop will find this stale partition and restart the partition pump. We stop the partition pump and load balancing loops if EventProcessorClient.stop() is called; else they run indefinitely.

Hmm if there is nothing showing up in INFO logs.. Would you be able to get DEBUG logs? In the meantime, I can take a look at those info logs to see what else i might be missing.