[BUG] sending batch every minute but still gets error intermittently "The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'"

[ankygupta9999]

Describe the bug
I am sending a message batch to eventhub via EventHubProducerClient every Minute. But still intermittently the link tracker closes the link stating no activity since 30 minutes (Send or receive)

The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'

Exception or Stack Trace

2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionRemoteClose connectionId[ehub_dev], entityName[MM_9999990000007], condition[Error{condition=null, description='null', info=null}]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionRemoteClose closing a local session for connectionId[MM_9999990000007], entityName[ehub_dev], condition[null], description[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.ReactorConnection - connectionId[MM_9999990000007] sessionName[ehub_dev]: Error occurred. Removing and disposing session.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.ReactorSession - connectionId[MM_9999990000007], sessionId[ehub_dev], errorCondition[n/a]: Disposing of session.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SendLinkHandler - onLinkRemoteClose connectionId[MM_9999990000007], linkName[cbs:sender], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SendLinkHandler - processOnClose connectionId[MM_9999990000007], linkName[cbs:sender], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] WARN  c.a.c.a.i.RequestResponseChannel - Retry #1. Transient error occurred. Retrying after 60000 ms.
The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26, errorContext[NAMESPACE: ehub_nspace.servicebus.windows.net, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 98]
2021-01-13 18:25:26 [single-1       ] ERROR c.a.c.a.i.RequestResponseChannel - cbs - Exception in RequestResponse links. Disposing and clearing unconfirmed sends.
The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26, errorContext[NAMESPACE: ehub_nspace.servicebus.windows.net, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 98]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ReceiveLinkHandler - onLinkRemoteClose connectionId[MM_9999990000007], linkName[cbs:receiver], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ReceiveLinkHandler - processOnClose connectionId[MM_9999990000007], linkName[cbs:receiver], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionRemoteClose connectionId[cbs-session], entityName[MM_9999990000007], condition[Error{condition=null, description='null', info=null}]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionRemoteClose closing a local session for connectionId[MM_9999990000007], entityName[cbs-session], condition[null], description[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.ReactorConnection - connectionId[MM_9999990000007] sessionName[cbs-session]: Error occurred. Removing and disposing session.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.ReactorSession - connectionId[MM_9999990000007], sessionId[cbs-session], errorCondition[n/a]: Disposing of session.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ConnectionHandler - onConnectionRemoteClose hostname[dummy.servicebus.windows.net:443], connectionId[MM_9999990000007], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SendLinkHandler - onLinkLocalClose connectionId[MM_9999990000007], linkName[cbs:sender], errorCondition[amqp:connection:forced], errorDescription[The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:9999b13b12345f12a12d, SystemTracker:gateway5, Timestamp:2021-01-13T12:55:26]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ReceiveLinkHandler - onLinkLocalClose connectionId[MM_9999990000007], linkName[cbs:receiver], errorCondition[null], errorDescription[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ConnectionHandler - onConnectionLocalClose hostname[dummy.servicebus.windows.net:443], connectionId[MM_9999990000007], errorCondition[null], errorDescription[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ConnectionHandler - onConnectionUnbound hostname[dummy.servicebus.windows.net:443], connectionId[MM_9999990000007], state[CLOSED], remoteState[CLOSED]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SendLinkHandler - onLinkFinal connectionId[MM_9999990000007], linkName[ehub_dev]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionFinal connectionId[MM_9999990000007], entityName[ehub_dev], condition[null], description[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SendLinkHandler - onLinkFinal connectionId[MM_9999990000007], linkName[cbs:sender]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ReceiveLinkHandler - onLinkFinal connectionId[MM_9999990000007], linkName[cbs:receiver]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.SessionHandler - onSessionFinal connectionId[MM_9999990000007], entityName[cbs-session], condition[null], description[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.handler.ConnectionHandler - onConnectionFinal hostname[dummy.servicebus.windows.net:443], connectionId[MM_9999990000007], errorCondition[null], errorDescription[null]
2021-01-13 18:25:26 [single-1       ] INFO  c.a.m.e.i.EventHubConnectionProcessor - namespace[ehub_nspace.servicebus.windows.net] entityPath[ehub_dev]: Channel is closed.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.m.e.i.EventHubReactorAmqpConnection - connectionId[MM_9999990000007]: Disposing of connection.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.ReactorConnection - connectionId[MM_9999990000007], errorCondition[n/a]: Disposing of ReactorConnection.
2021-01-13 18:25:26 [single-1       ] INFO  c.a.c.a.i.AmqpExceptionHandler - Shutdown received: ReactorExecutor.close() was called., isTransient[false], initiatedByClient[true]

Repro Steps
Start a code which keeps sending a batch with dummy message to eventhub every minute.

Expected behavior
It should not close the connection by itself if a continuous sending of batch is being done by the process i.e. every 1 minute.

Setup (please complete the following information):

• OS: MAC
• IDE : IntelliJ
• Version of the Library used : azure-messaging-eventhub 5.3.1 and azure-eventhub 3.2.2

Additional context
Add any other context about the problem here.

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

• Bug Description Added
• Repro Steps Added
• Setup information Added

[joshfree]

@srnagar can you please take a look?

[srnagar]

@ankygupta9999 I am taking a look at this issue. When you see the error message, can you confirm that the message you tried to send failed or did the message get sent successfully but there were some timeout errors in the logs?

[ankygupta9999]

Most of the times, it connects and sends the message fine but at times, it tries few times based on amqpretry options and not able to connect again.

[conniey]

We recently released 5.7.0, which should alleviate this problem. However, could you turn on AZURE_LOG_LEVEL=INFO to give us more information around the time when it's failing? This would help us diagnose it.

[ramya-rao-a]

Hey @ankygupta9999

We will be closing this issue as we have not heard back from you regarding the logs that were asked.
Like @conniey said, we believe the issue should be resolved in the recent versions of the package.
Please feel free to open a new issue if you are still seeing problems