{"action":"created","issue":{"url":"https://api.github.com/repos/amqp/rhea/issues/92","repository_url":"https://api.github.com/repos/amqp/rhea","labels_url":"https://api.github.com/repos/amqp/rhea/issues/92/labels{/name}","comments_url":"https://api.github.com/repos/amqp/rhea/issues/92/comments","events_url":"https://api.github.com/repos/amqp/rhea/issues/92/events","html_url":"https://github.com/amqp/rhea/issues/92","id":337709811,"node_id":"MDU6SXNzdWUzMzc3MDk4MTE=","number":92,"title":"Questions: Connection recovery/reconnect","user":{"login":"amarzavery","id":4521223,"node_id":"MDQ6VXNlcjQ1MjEyMjM=","avatar_url":"https://avatars3.githubusercontent.com/u/4521223?v=4","gravatar_id":"","url":"https://api.github.com/users/amarzavery","html_url":"https://github.com/amarzavery","followers_url":"https://api.github.com/users/amarzavery/followers","following_url":"https://api.github.com/users/amarzavery/following{/other_user}","gists_url":"https://api.github.com/users/amarzavery/gists{/gist_id}","starred_url":"https://api.github.com/users/amarzavery/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/amarzavery/subscriptions","organizations_url":"https://api.github.com/users/amarzavery/orgs","repos_url":"https://api.github.com/users/amarzavery/repos","events_url":"https://api.github.com/users/amarzavery/events{/privacy}","received_events_url":"https://api.github.com/users/amarzavery/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":12,"created_at":"2018-07-03T00:58:17Z","updated_at":"2018-08-10T21:10:26Z","closed_at":null,"author_association":"COLLABORATOR","body":"1. Is it true that a connection_close event will always follow by disconnected event? If yes, then why do we need two events? What is the best practice for a consumer of rhea? Should the consumer be listening to both `connection_close` and `disconnected`? What is it that you would expect a consumer to differently in both the handlers?\r\n2. Due to an idle timeout enforced by Azure EventHubs (not related to the heartbeat/keepAlive concept of AMQP) when a link is inactive (no pending receive or a message being sent), or when the connection does not have any sender/receiver, the connection is forcibly disconnected. Since the reconnect limit to 100; rhea successfully establishes the connection. However, it does not reconnect the sender/receiver links that were present on the connection. Is this the expected behavior?"},"comment":{"url":"https://api.github.com/repos/amqp/rhea/issues/comments/412207397","html_url":"https://github.com/amqp/rhea/issues/92#issuecomment-412207397","issue_url":"https://api.github.com/repos/amqp/rhea/issues/92","id":412207397,"node_id":"MDEyOklzc3VlQ29tbWVudDQxMjIwNzM5Nw==","user":{"login":"amarzavery","id":4521223,"node_id":"MDQ6VXNlcjQ1MjEyMjM=","avatar_url":"https://avatars3.githubusercontent.com/u/4521223?v=4","gravatar_id":"","url":"https://api.github.com/users/amarzavery","html_url":"https://github.com/amarzavery","followers_url":"https://api.github.com/users/amarzavery/followers","following_url":"https://api.github.com/users/amarzavery/following{/other_user}","gists_url":"https://api.github.com/users/amarzavery/gists{/gist_id}","starred_url":"https://api.github.com/users/amarzavery/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/amarzavery/subscriptions","organizations_url":"https://api.github.com/users/amarzavery/orgs","repos_url":"https://api.github.com/users/amarzavery/repos","events_url":"https://api.github.com/users/amarzavery/events{/privacy}","received_events_url":"https://api.github.com/users/amarzavery/received_events","type":"User","site_admin":false},"created_at":"2018-08-10T21:10:25Z","updated_at":"2018-08-10T21:10:25Z","author_association":"COLLABORATOR","body":"@grs - Now I do get the disconnected event. However, when I attempt to reconnect, I get the same connection-forced error back with the same tracking Id that was received last time. It looks like the remote peer still thinks that the connection is open. Btw, this (manual reconnect after receiving the disconnected event) used to work fine previously.\r\n\r\nLogs for reference:\r\n\r\n```bash\r\n\r\n-------> Initial error <--------------\r\n rhea:raw [connection-1] RECV: 266 0000010a02000000005318c0fd0100531dc0f703a316616d71703a636f6e6e656374696f6e3a666f72636564a1db54686520636f6e6e656374696f6e2077617320696e61637469766520666f72206d6f7265207468616e2074686520616c6c6f77656420333030303030206d696c6c697365636f6e647320616e6420697320636c6f73656420627920636f6e7461696e657220274c696e6b547261636b6572272e20547261636b696e6749643a62323165383466396264363534393661393939386138353533633630653763615f4731332c2053797374656d547261636b65723a67617465776179352c2054696d657374616d703a382f31302f3230313820383a35303a303620504d40 +0ms\r\n  rhea:frames [connection-1]:0 <- close#18 {\"error\":{\"condition\":\"amqp:connection:forced\",\"description\":\"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b21e84f9bd65496a9998a8553c60e7ca_G13, SystemTracker:gateway5, Timestamp:8/10/2018 8:50:06 PM\"}}  +0ms\r\n  rhea:events [connection-1] Connection got event: connection_error +1ms\r\n  rhea:events [082aebdf-b22c-0843-b703-f187b42d3cf7] Container got event: connection_error +0ms\r\n\r\nrhea:events [connection-1] Connection got event: connection_close +0ms\r\n  azure:event-hubs:connectionContext [connection-1] connection close happened. +5m\r\n  rhea:frames [connection-1]:0 -> detach#16 {\"handle\":1,\"closed\":true}  +2ms\r\n  rhea:raw [connection-1] SENT: 23 0000001702000000005316d00000000700000002520141 +2ms\r\n  rhea:frames [connection-1]:0 -> end#17 {}  +0ms\r\n  rhea:raw [connection-1] SENT: 12 0000000c0200000000531745 +0ms\r\n  rhea:frames [connection-1]:0 -> close#18 {}  +0ms\r\n  rhea:raw [connection-1] SENT: 12 0000000c0200000000531845 +0ms\r\n\r\n--------------> disconnected event <----------------------------\r\n  rhea:events [connection-1] Connection got event: disconnected +330ms\r\n  azure:event-hubs:error [connection-1] Error (context.connection.error) occurred on the amqp connection: c {\r\n  azure:event-hubs:error   value: \r\n  azure:event-hubs:error    [ Typed { type: [Object], value: 'amqp:connection:forced' },\r\n  azure:event-hubs:error      Typed {\r\n  azure:event-hubs:error        type: [Object],\r\n  azure:event-hubs:error        value: 'The connection was inactive for more than the allowed 300000 milliseconds and is closed by container \\'LinkTracker\\'. TrackingId:b21e84f9bd65496a9998a8553c60e7ca_G13, SystemTracker:gateway5, Timestamp:8/10/2018 8:50:06 PM' },\r\n  azure:event-hubs:error      Typed { type: [Object], value: null } ] } +5m\r\n  azure:event-hubs:error [connection-1] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET\r\n  azure:event-hubs:error     at _errnoException (util.js:992:11)\r\n  azure:event-hubs:error     at TLSWrap.onread (net.js:618:25) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' } +0ms\r\n\r\n....still doing something after 5 minutes. We should get here even if the connection goes down and try to reconnect....\r\n\r\n  azure:event-hubs:error [connection-1] Receiver '7b02fa30-4c01-494f-add1-be3703501150' with address 'test1/ConsumerGroups/$default/Partitions/0' is open? -> undefined +8s\r\n  azure:event-hubs:receiverbatching [connection-1] Receiver '7b02fa30-4c01-494f-add1-be3703501150', setting the prefetch count to 0. +5m\r\n  azure:event-hubs:error [connection-1] Receiver '7b02fa30-4c01-494f-add1-be3703501150' with address 'test1/ConsumerGroups/$default/Partitions/0' is open? -> undefined +1ms\r\n  azure:event-hubs:error [connection-1] The receiver '7b02fa30-4c01-494f-add1-be3703501150' with address 'test1/ConsumerGroups/$default/Partitions/0' is not open and is not currently establishing itself. Hence let's try to connect. +0ms\r\n  azure:event-hubs:linkEntity [connection-1] Acquiring cbs lock: 'negotiateCbs-dfd05c53-a7dc-474c-a4db-0a21696f8bc7' for creating the cbs session while creating the BatchingReceiver: '7b02fa30-4c01-494f-add1-be3703501150' with address: 'test1/ConsumerGroups/$default/Partitions/0'. +5m\r\n\r\n----------------------> Reconnect attempt <-----------------------\r\n\r\n  azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection. +5m\r\n  rhea:io [connection-1] connected 10.104.141.137:57377 -> 52.226.36.235:5671 +10s\r\n  rhea:frames [connection-1] -> { protocol_id: 3, major: 1, minor: 0, revision: 0 } +10s\r\n  rhea:io [connection-1] read 8 bytes +271ms\r\n  rhea:frames [connection-1] <- { protocol_id: 3, major: 1, minor: 0, revision: 0 } +271ms\r\n  rhea:io [connection-1] read 63 bytes +77ms\r\n  rhea:io [connection-1] got frame of size 63 +0ms\r\n  rhea:raw [connection-1] RECV: 63 0000003f02010000005340c03201e02f04b3000000074d53534243425300000005504c41494e00000009414e4f4e594d4f55530000000845585445524e414c +10s\r\n  rhea:frames [connection-1]:undefined <- sasl_mechanisms#40 {\"sasl_server_mechanisms\":[\"MSSBCBS\",\"PLAIN\",\"ANONYMOUS\",\"EXTERNAL\"]}  +78ms\r\n  rhea:frames [connection-1]:0 -> function Typed(type, value, code, descriptor) {\r\n    this.type = type;\r\n    this.value = value;\r\n    if (code) {\r\n        this.array_constructor = {'typecode':code};\r\n        if (descriptor) {\r\n            this.array_constructor.descriptor = descriptor;\r\n        }\r\n    }\r\n} [\"ANONYMOUS\",{\"type\":\"Buffer\",\"data\":[0,82,111,111,116,77,97,110,97,103,101,83,104,97,114,101,100,65,99,99,101,115,115,75,101,121]},\"eastusjs.servicebus.windows.net\"]  +0ms\r\n  rhea:raw [connection-1] SENT: 92 0000005c02010000005341d00000004c00000003a309414e4f4e594d4f5553a01a00526f6f744d616e6167655368617265644163636573734b6579a11f6561737475736a732e736572766963656275732e77696e646f77732e6e6574 +0ms\r\n  rhea:io [connection-1] read 26 bytes +79ms\r\n  rhea:io [connection-1] got frame of size 26 +0ms\r\n  rhea:raw [connection-1] RECV: 26 0000001a02010000005344c00d025000a00857656c636f6d6521 +78ms\r\n  rhea:frames [connection-1]:undefined <- sasl_outcome#44 {\"additional_data\":{\"type\":\"Buffer\",\"data\":[87,101,108,99,111,109,101,33]}}  +78ms\r\n  rhea:frames [connection-1]:0 -> open#10 {\"transport\":\"tls\",\"host\":\"eastusjs.servicebus.windows.net\",\"username\":\"RootManageSharedAccessKey\",\"port\":5671,\"servername\":\"eastusjs.servicebus.windows.net\",\"id\":\"connection-1\",\"container_id\":\"082aebdf-b22c-0843-b703-f187b42d3cf7\",\"hostname\":\"eastusjs.servicebus.windows.net\",\"properties\":{\"product\":\"MSJSClient\",\"version\":\"0.2.6\",\"platform\":\"(x64-Darwin-17.7.0)\",\"framework\":\"Node/v8.11.2\",\"user-agent\":\"/js-event-hubs\"}}  +0ms\r\n  rhea:raw [connection-1] SENT: 228 000000e402000000005310d0000000d40000000aa12430383261656264662d623232632d303834332d623730332d663138376234326433636637a11f6561737475736a732e736572766963656275732e77696e646f77732e6e657440404040404040d10000007d0000000aa30770726f64756374a10a4d534a53436c69656e74a30776657273696f6ea105302e322e36a308706c6174666f726da113287836342d44617277696e2d31372e372e3029a3096672616d65776f726ba10c4e6f64652f76382e31312e32a30a757365722d6167656e74a10e2f6a732d6576656e742d68756273 +1ms\r\n\r\n---------> Disconnected event with same error and tracking id from before <-------\r\n\r\n  rhea:events [connection-1] Connection got event: disconnected +10s\r\n  azure:event-hubs:error [connection-1] Error (context.connection.error) occurred on the amqp connection: c {\r\n  azure:event-hubs:error   value: \r\n  azure:event-hubs:error    [ Typed { type: [Object], value: 'amqp:connection:forced' },\r\n  azure:event-hubs:error      Typed {\r\n  azure:event-hubs:error        type: [Object],\r\n  azure:event-hubs:error        value: 'The connection was inactive for more than the allowed 300000 milliseconds and is closed by container \\'LinkTracker\\'. TrackingId:b21e84f9bd65496a9998a8553c60e7ca_G13, SystemTracker:gateway5, Timestamp:8/10/2018 8:50:06 PM' },\r\n  azure:event-hubs:error      Typed { type: [Object], value: null } ] } +3s\r\n  azure:event-hubs:error [connection-1] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect. +0ms\r\n  rhea-promise:error [connection-1] Error occurred while establishing amqp connection: c {\r\n  rhea-promise:error   value: \r\n  rhea-promise:error    [ Typed { type: [Object], value: 'amqp:connection:forced' },\r\n  rhea-promise:error      Typed {\r\n  rhea-promise:error        type: [Object],\r\n  rhea-promise:error        value: 'The connection was inactive for more than the allowed 300000 milliseconds and is closed by container \\'LinkTracker\\'. TrackingId:b21e84f9bd65496a9998a8553c60e7ca_G13, SystemTracker:gateway5, Timestamp:8/10/2018 8:50:06 PM' },\r\n  rhea-promise:error      Typed { type: [Object], value: null } ] } +5m\r\n  azure:amqp-common:error [connection-1] An error occured while establishing the cbs links: { ConnectionForcedError: The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:b21e84f9bd65496a9998a8553c60e7ca_G13, SystemTracker:gateway5, Timestamp:8/10/2018 8:50:06 PM\r\n  azure:amqp-common:error     at Object.translate (/Users/amarz/sdk/rh/final/azure-event-hubs-node/client/lib/amqp-common/errors.ts:454:19)\r\n  azure:amqp-common:error     at CbsClient.init (/Users/amarz/sdk/rh/final/azure-event-hubs-node/client/lib/amqp-common/cbs.ts:98:13)\r\n  azure:amqp-common:error     at <anonymous>\r\n  azure:amqp-common:error     at process._tickDomainCallback (internal/process/next_tick.js:228:7)\r\n  azure:amqp-common:error   name: 'ConnectionForcedError',\r\n  azure:amqp-common:error   translated: true,\r\n  azure:amqp-common:error   retryable: true,\r\n  azure:amqp-common:error   info: null,\r\n  azure:amqp-common:error   condition: 'amqp:connection:forced' } +11s\r\n```\r\n\r\nWhat could be going wrong over here?"}}
{"actor":{"display_login":"amarzavery"}}