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

[quanceptHW]

I used this C SDK to consume the msg from eventhub, the following error always happens in consumer side. It will cause that underlying connection is closed, SAS CBS PUT operation failed, then msg receiving stopped.

<- [DETACH] {0,true, {amqp:connection:forced,The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b4579bf8c0544384816472e551456d48_G6, SystemTracker:gateway5, Timestamp:10/23/2018 3:34:27 AM,NULL}}

-> [DETACH]* {0}

Error: Time:Tue Oct 23 11:34:27 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-uamqp-c\src\amqp_management.c Func:_on_message_sender_state_changed Line:388 Error, on_message_sender_state_changed called, new state: 4

Error: Time:Tue Oct 23 11:34:27 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-uamqp-c\src\cbs.c Func:_on_underlying_amqp_management_error Line:179 Unexpected AMQP error in CBS_STATE_OPEN state

<- [DETACH] {1,true, {amqp:connection:forced,The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b4579bf8c0544384816472e551456d48_G6, SystemTracker:gateway5, Timestamp:10/23/2018 3:34:27 AM,NULL}}

-> [DETACH]* {1}

<- [END]* {NULL}

-> [END]* {}

<- [CLOSE] { {amqp:connection:forced,The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b4579bf8c0544384816472e551456d48_G6, SystemTracker:gateway5, Timestamp:10/23/2018 3:34:27 AM,NULL}}

-> [CLOSE]* {}

[dcristoloveanu]

Hi @quanceptHW

Sorry for the delay. This looks quite interesting. Let me have a look at the idle connection timeout code and see if I can find/repro the issue. I'll come back with my finding shorty.

Cheers, /Dan

[dcristoloveanu]

Pasting detailed log for reference:

<- [TRANSFER]* {2,22027,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22027,22027,true, {}}

myReceiveCount: 87169

<- [TRANSFER]* {2,22028,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22028,22028,true, {}}

myReceiveCount: 87170

<- [TRANSFER]* {2,22029,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22029,22029,true, {}}

myReceiveCount: 87171

<- [TRANSFER]* {2,22030,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22030,22030,true, {}}

myReceiveCount: 87172

<- [TRANSFER]* {2,22031,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22031,22031,true, {}}

myReceiveCount: 87173

<- [TRANSFER]* {2,22032,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22032,22032,true, {}}

myReceiveCount: 87174

<- [TRANSFER]* {2,22033,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22033,22033,true, {}}

myReceiveCount: 87175

<- [TRANSFER]* {2,22034,<>,0,true,false,NULL,NULL,NULL,NULL,true}

-> [DISPOSITION] {true,22034,22034,true, {}}

myReceiveCount: 87176

-> -> [TRANSFER][TRANSFER]-> -> [TRANSFER][TRANSFER] {0,36,<25 00 00 00>,0,false,false} {0,36,<25 00 00 00>,0,false,false}

• {0,36,<25 00 00 00>,0,false,false}* {0,36,<25 00 00 00>,0,false,false}

<- [DISPOSITION]<- <- [DISPOSITION][DISPOSITION] {true,36,NULL,true, {},NULL}

• {true,36,NULL,true,* {},NULL}

• {true,36,NULL,true,* {},NULL}

<- Error: Time:Tue Oct 23 11:30:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

Error: Time:Tue Oct 23 11:30:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Error: Time:Tue Oct 23 11:30:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

Invalid argument (list=NULL)

[DISPOSITION] {true,36,NULL,true, {},NULL}

<- [TRANSFER]<- [TRANSFER]<- [TRANSFER]* {1,21755,<25 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

• {1,21765,<25 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

• {1,21765,<25 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

<- [TRANSFER]* {1,22035,<25 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> -> [DISPOSITION][DISPOSITION]-> [DISPOSITION] {true,21765,21765,true, {}} {true,21755,21755,true, {}}

• {true,21765,21765,true,* {}}

-> [DISPOSITION] {true,22035,22035,true, {}}

<- [FLOW]* {37,5000,21767,2147461881,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {37,5000,21757,2147461891,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {37,5000,21767,2147461881,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {37,5000,22037,2147461611,NULL,NULL,NULL,NULL,NULL,true,NULL}

-> -> [TRANSFER][TRANSFER]-> -> [TRANSFER][TRANSFER] {0,37,<26 00 00 00>,0,false,false} {0,37,<26 00 00 00>,0,false,false}

• {0,37,<26 00 00 00>,0,false,false}* {0,37,<26 00 00 00>,0,false,false}

<- <- [DISPOSITION]<- [DISPOSITION][DISPOSITION] {true,37,NULL,true, {},NULL}

<- {true,37,NULL,true, {},NULL}

[DISPOSITION] {true,37,NULL,true, {},NULL}Error: Time:Tue Oct 23 11:31:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 {true,37,NULL,true, {},NULL}Invalid argument (list=NULL)

Error: Time:Tue Oct 23 11:31:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Error: Time:Tue Oct 23 11:31:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

<- Invalid argument (list=NULL)[TRANSFER]

• {1,22036,<26 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,22036,22036,true, {}}

<- <- [TRANSFER]<- [TRANSFER][TRANSFER]* {1,21766,<26 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

• {1,21756,<26 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

• {1,21766,<26 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> -> [DISPOSITION][DISPOSITION]-> [DISPOSITION] {true,21766,21766,true, {}} {true,21756,21756,true, {}}

• {true,21766,21766,true,* {}}

-> -> [TRANSFER][TRANSFER]-> [TRANSFER]* {0,38,<27 00 00 00>,0,false,false}

• {0,38,<27 00 00 00>,0,false,false}

• {0,38,<27 00 00 00>,0,false,false}

-> [TRANSFER]* {0,38,<27 00 00 00>,0,false,false}

<- <- [DISPOSITION][DISPOSITION] {true,38,NULL,true, {},NULL}

• {true,38,NULL,true,* {},NULL}

Error: Time:Tue Oct 23 11:32:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

Error: Time:Tue Oct 23 11:32:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

<- [DISPOSITION] {true,38,NULL,true, {},NULL}

Error: Time:Tue Oct 23 11:32:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

<- [DISPOSITION] {true,38,NULL,true, {},NULL}

<- [TRANSFER]* {1,21767,<27 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21767,21767,true, {}}

<- [TRANSFER]* {1,21757,<27 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21757,21757,true, {}}

<- [TRANSFER]* {1,22037,<27 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,22037,22037,true, {}}

<- [TRANSFER]* {1,21767,<27 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21767,21767,true, {}}

-> -> [TRANSFER][TRANSFER]-> [TRANSFER] {0,39,<28 00 00 00>,0,false,false} {0,39,<28 00 00 00>,0,false,false}

• {0,39,<28 00 00 00>,0,false,false}

-> [TRANSFER]* {0,39,<28 00 00 00>,0,false,false}

<- [DISPOSITION] {true,39,NULL,true, {},NULL}

<- Error: Time:Tue Oct 23 11:33:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

[DISPOSITION]<- [DISPOSITION] {true,39,NULL,true, {},NULL} {true,39,NULL,true, {},NULL}

Error: Time:Tue Oct 23 11:33:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

<- [DISPOSITION] {true,39,NULL,true, {},NULL}

Error: Time:Tue Oct 23 11:33:37 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-c-shared-utility\src\singlylinkedlist.c Func:_singlylinkedlist_get_head_item Line:166 Invalid argument (list=NULL)

<- [TRANSFER]* {1,22038,<28 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,22038,22038,true, {}}

<- [TRANSFER]* {1,21768,<28 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21768,21768,true, {}}

<- [TRANSFER]* {1,21758,<28 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21758,21758,true, {}}

<- [TRANSFER]* {1,21768,<28 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}

-> [DISPOSITION] {true,21768,21768,true, {}}

<- [FLOW]* {40,5000,21770,2147461878,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {40,5000,21760,2147461888,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {40,5000,21770,2147461878,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [FLOW]* {40,5000,22040,2147461608,NULL,NULL,NULL,NULL,NULL,true,NULL}

<- [DETACH] {0,true, {amqp:connection:forced,The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b4579bf8c0544384816472e551456d48_G6, SystemTracker:gateway5, Timestamp:10/23/2018 3:34:27 AM,NULL}}

-> [DETACH]* {0}

Error: Time:Tue Oct 23 11:34:27 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-uamqp-c\src\amqp_management.c Func:_on_message_sender_state_changed Line:388 Error, on_message_sender_state_changed called, new state: 4

Error: Time:Tue Oct 23 11:34:27 2018 File:E:\HuWei\working\1.src\EventHub\deps\azure-uamqp-c\src\cbs.c Func:_on_underlying_amqp_management_error Line:179 Unexpected AMQP error in CBS_STATE_OPEN state

<- [DETACH] {1,true, {amqp:connection:forced,The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b4579bf8c0544384816472e551456d48_G6, SystemTracker:gateway5, Timestamp:10/23/2018 3:34:27 AM,NULL}}

-> [DETACH]* {1}

<- [END]* {NULL}

-> [END]* {}

===================================

[dcristoloveanu]

Hi Wei,

I got to take a closer look at this and the connection unit does have the code in place to send the EMPTY FRAMEs. So I suspect something else is at play here.

Looking closer at the log you sent I can notice some errors regarding singlylinkedlist_get_head_item being called with NULL which is unusual.

Can you help me narrow this down by providing the following:

• SHA of azure-event-hubs-c being used so that I can check out the exact code of the SDK that you are using.
• sample code that you use. The reason for it is: The _LL APIs are meant to be used in a single threaded environment. The APIs without _LL have locks and are thread safe. If _LL APIs are somehow called from multiple threads then races over data will happen and ultimately data used by uAMQP or event Hubs SDK would get corrupted. The fact that there are several TRANSFERS in the log with the same ID can suggest this can be happening here. If data gets corrupted in uAMQP then all bets are off regarding what would happen (depends on which data is corrupted). If some connection data gets corrupted then it could happen that the time data used to send the EMPTY_FRAMES also get corrupted and no EMPTY_FRAME is sent when needed and the server ultimately decides to cut off the connection because of it.

If I have the above items (SHA and sample code - of course remove any credentials from it :-)) then I can help you further debug this.

Cheers, /Dan

[quanceptHW]

Hi Dan， Thanks for your quick feedback.
1) I'm sorry that I can't provide the SHA of original azure-evnt-hubs-c because I had already modified some lib source files myself and have already removed the original downloaded zip file. But I can provide the download date is April 08, 2018. Hope it can help you to locate the source code. The reason why I update it is, in my project I need to consume each msg only once. Neither duplicated consume nor miss of msg is acceptable. After some investigation in github or stackoverflow, I found there is a property "amqp.annotation.x-opt-offset" which is supported by EventHub server, then I introduce it to code and design a new API : EVENTHUBRECEIVER_RESULT EventHubReceiver_ReceiveFromStartOffsetAsync ( EVENTHUBRECEIVER_HANDLE eventHubReceiverHandle, EVENTHUBRECEIVER_ASYNC_CALLBACK onEventReceiveCallback, void onEventReceiveUserContext, EVENTHUBRECEIVER_ASYNC_ERROR_CALLBACK onEventReceiveErrorCallback, void onEventReceiveErrorUserContext, uint64_t startOffset ) which accepts a parameter startOffset as specified offset 2) As for sample code, I will send them to your microsoft email.

BRs