azure-sdk-for-python: Async Eventhub Consumer with Pyamqp: Link Detached after long idle period Results in High "User Errors" volume

• package: azure-eventhub
• version: 5.11.1
• OS: Debian Container (kubernetes pod): python:3.11-slim-bullseye
• Python version: 3.11.2

Describe the bug Long idle periods (greater than 1 hour) sometimes result in very high volume of “User Errors” reported in the metrics blade for our Eventhub. These high “User Error” volumes are correlated with our Consumer Clients not receiving events after idle period has ended and Producers have started publishing events again.

After setting log-level to DEBUG for our application, we have been able to correlate these “User Errors” with some errors in socket management in the _pyamqp module of the azure-eventhub package (see more details below).

Our consumer’s log volume (when set at DEBUG) roughly correlates with User Errors volume (see screenshots) and seems to indicate a problem with socket connection being closed.

Lastly, our apps sometimes recover from this, but in other cases our Consumer Client pods must be restarted to begin consuming events again. (We had an outage this week as a result of this issue.)

To Reproduce Steps to reproduce the behavior:

1. Build an async Eventhub Consumer similar to this example (Note: our app is very close to this example with some arbitrary processing in the event handler; the errors in question happen after long idle periods.)
2. Run the consumer with log-level set to DEBUG and no events going into Eventhub for longer than 1 hour (our event volume is closely tied to US Business Hours).
3. Set Eventhub to “Disabled”. (This seems to simulate the server socket disconnect.)
4. Re-enable Eventhub and see if Consumer Client can reconnect (ours go into failure loops).
5. Check Azure Eventhub until “User Errors” volume spikes (see screenshot) and correlate with logs.

Expected behavior

1. No “User Errors” managing closed sockets for idle consumers.
2. Idle consumers with closed connections are able to reconnect.
3. Also, less important but surprising behavior in _pyamqp module: errors in this library are called out in log.info calls (not log.error?), so not readily apparent with our typical logging setups (Example).

Screenshots A. User Errors Reported by Azure Eventhub metrics blade:

B. Log Volume Correlated with high “User Errors”:

Additional context Here are the log messages we see in order when this happens (full debug log dump available):

1. "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not read frame due to exception: Server unexpectedly closed connection')"
2. “Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>”
3. "An error occurred when detaching the link: AMQPConnectionError(‘Error condition: ErrorCondition.SocketError\n Error Description: Can not read frame due to exception: Server unexpectedly closed connection’)"
4. “Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>”
5. “Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>”
6. “An error occurred when detaching the link: AMQPConnectionError(‘Error condition: ErrorCondition.SocketError\n Error Description: Can not read frame due to exception: Server unexpectedly closed connection’)”
7. “Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>”
8. “Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>”
9. “An error occurred when ending the session: AMQPConnectionError(‘Error condition: ErrorCondition.SocketError\n Error Description: Can not read frame due to exception: Server unexpectedly closed connection’)”
10. “Session state changed: <SessionState.MAPPED: 3> -> <SessionState.UNMAPPED: 0>”
11. “An error occurred when closing the connection: AMQPConnectionError(‘Error condition: ErrorCondition.SocketError\n Error Description: Can not read frame due to exception: Server unexpectedly closed connection’)”
12. “Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.END: 13>”
13. “Connection state changed: None -> <ConnectionState.START: 0>”
14. GO THROUGH CONNECTION FLOW
15. “CBS completed opening with status: <ManagementOpenResult.OK: 1>”
16. “Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>”
17. “Cannot get source or target. Detaching link”
18. “Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.DETACHED: 0>”
19. “Unable to attach new link: ValueError(‘Invalid link’)”
20. “Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ERROR: 6>”
21. “Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>”
22. GOTO 1

Notes:

• The above flow seems to loop endlessly until we restart our consumer pods
• All of the above error messages are logged at level INFO (would prefer to have WARN or ERROR instead).
• At step 14 it looks like something has succeeeded, so it’s unclear why the consumer goes into a loop afterward and can’t recover.
• We set idle_timeout on a guess that it could help with long idle periods, but it has not.
• There are hundreds of “User Errors” per minute but it’s not clear to us what the Eventhub server itself is registering as a “User Error”?
• Our Consumers run in kubernetes pods and we also see this happen on Eventhubs with 1-24 partitions in different environments.

Also, worth mentioning that we have a Microsoft Support ticket: TrackingID#2302210010000022.