Azure-sdk-for-js: [Service Bus] ECONNRESET when onDetached crashing application

[snuffykl]

• Package Name: @azure/service-bus
• Package Version: 1.1.6
• Operating system: node10:alpine (docker image)
• [x] nodejs
  
  
  
  • version:
  
  
• [ ] browser
  
  
  
  • name/version:
  
  
• [ ] typescript
  
  
  
  • version:
  
  
• Is the bug related to documentation in
  
  
  
  • [ ] README.md
  
  
  • [ ] source code documentation
  
  
  • [ ] SDK API docs on https://docs.microsoft.com
  
  

Describe the bug
After upgrade to 1.1.6, we have noticed that there is this ECONNRESET that is crashing our application for our API/Event-Listener(Sender message) & Task-Email-Listener(Receiver message) service that consume @azure/[email protected]

To Reproduce
Steps to reproduce the behavior:

1. Playing around with disconnection(instability) of network able to reproduce this issue. My suspicion was at TCP level the old AMQP connection-1 is trying to connect still (FIN_WAIT1). Below are the logs from our Test environment for our Listener & API under additional context.

Expected behavior

1. Should throw to client the error or dispose the previous connection(if recreate new connection is the issue) instead of crashing the application. It is possible that might be an uncaughtException from the library. We gotten consistent error logs when this happen.

Screenshots
If applicable, add screenshots to help explain your problem.
Note: This screenshot is from my local environment (minikube) when I am trying to replicate the issue with disconnect my wifi.

Additional context
API logs (Sender message)

May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-1] Connection got event: disconnected
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.615Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.617Z rhea-promise:error [connection-1] The connection is open ? -> false
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.618Z azure:service-bus:error The connection "connection-1" has been updated to "connection-2".
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.618Z azure:service-bus:error [connection-2] state: { wasConnectionCloseCalled: false, numClients: 1 }
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.618Z azure:service-bus:error [connection-2] connection.close() was not called from the sdk and there were some clients. We should reconnect.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.918Z azure:service-bus:error [connection-2] calling detached on client 'taskEmail/c05b1656-7937-6d42-811f-d8676378fb25'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.918Z azure:service-bus:error [connection-2] calling detached on sender 'taskEmail-a481f20d-0376-8140-b832-3e09e4243c38'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.919Z rhea-promise:error [connection-1] The sender is open ? -> false
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.920Z rhea-promise:error [connection-1] The session is open ? -> false
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.920Z azure:service-bus:error [connection-2] close() method of Sender 'taskEmail-a481f20d-0376-8140-b832-3e09e4243c38' with address 'taskEmail' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.920Z azure:service-bus:error [connection-2] Sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e' with address 'taskEmail' is open? -> false
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.920Z azure:service-bus:error [connection-2] Sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e' with address 'taskEmail' is open? -> false
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.921Z azure:service-bus:error [connection-2] The sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e' with address 'taskEmail' is not open and is not currently establishing itself. Hence let's try to connect.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Connection got event: connection_open
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.937Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Session got event: session_open
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.938Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Link got event: sender_open
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.939Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Link got event: sender_flow
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.940Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Link got event: sendable
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.940Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:23 GMT rhea:events [connection-2] Link got event: receiver_open
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.941Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.941Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
May 01 21:50:23 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:23.941Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver 'cbs-e0c798ee-06d6-254a-830c-f07b4257b1e3'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Received disposition for outgoing transfers
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: accepted
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.007Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: settled
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.008Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: message
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.123Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.123Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.123Z azure:service-bus:error [connection-2] Trying to create sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e'...
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Session got event: session_open
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.178Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: sender_open
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.180Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: sender_flow
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.180Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Fri, 01 May 2020 13:50:24 GMT rhea:events [connection-2] Link got event: sendable
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.180Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.181Z azure:service-bus:error [connection-2] Sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e' with address 'taskEmail' has established itself.
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.181Z azure:service-bus:error [connection-2] Promise to create the sender resolved. Created sender with name: taskEmail-d84a15e1-f279-574f-9359-35465064f73e
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm] 2020-05-01T13:50:24.181Z azure:service-bus:error [connection-2] Sender 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e' created with sender options: { name: 'taskEmail-d84a15e1-f279-574f-9359-35465064f73e',
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm]   target: { address: 'taskEmail' },
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm]   onError: [Function],
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm]   onClose: [Function],
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm]   onSessionError: [Function],
May 01 21:50:24 api core[task-svc-deployment-57fdf5ccf8-dgtvm]   onSessionClose: [Function] }
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm] /task-svc/node_modules/applicationinsights/out/AutoCollection/Exceptions.js:37
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm]                         throw THIS_IS_APPLICATION_INSIGHTS_RETHROWING_YOUR_EXCEPTION; // Error originated somewhere else in your app
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm]                         ^
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm] Error: read ECONNRESET
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm]     at TLSWrap.onStreamRead [as _originalOnread] (internal/stream_base_commons.js:111:27)
May 01 21:50:30 api core[task-svc-deployment-57fdf5ccf8-dgtvm]     at TLSWrap.<anonymous> (/task-svc/node_modules/async-listener/glue.js:188:31)

Event-Listener logs (Sender message)

May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-1] Connection got event: disconnected
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.559Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.561Z rhea-promise:error [connection-1] The connection is open ? -> false
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.561Z azure:service-bus:error The connection "connection-1" has been updated to "connection-2".
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.561Z azure:service-bus:error [connection-2] state: { wasConnectionCloseCalled: false, numClients: 1 }
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.561Z azure:service-bus:error [connection-2] connection.close() was not called from the sdk and there were some clients. We should reconnect.
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.861Z azure:service-bus:error [connection-2] calling detached on client 'taskEmail/acef0b8f-f2dd-784c-9fb8-9f709d6fa85e'.
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.862Z azure:service-bus:error [connection-2] calling detached on sender 'taskEmail-67f9998c-2493-e443-96cd-ee449c0d30df'.
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.863Z rhea-promise:error [connection-1] The sender is open ? -> false
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.863Z rhea-promise:error [connection-1] The session is open ? -> false
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.863Z azure:service-bus:error [connection-2] close() method of Sender 'taskEmail-67f9998c-2493-e443-96cd-ee449c0d30df' with address 'taskEmail' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.864Z azure:service-bus:error [connection-2] Sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e' with address 'taskEmail' is open? -> false
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.864Z azure:service-bus:error [connection-2] Sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e' with address 'taskEmail' is open? -> false
May 02 11:27:20 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.864Z azure:service-bus:error [connection-2] The sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e' with address 'taskEmail' is not open and is not currently establishing itself. Hence let's try to connect.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Connection got event: connection_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.981Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Session got event: session_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.982Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Link got event: sender_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.984Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Link got event: sender_flow
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.984Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Link got event: sendable
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.984Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:20 GMT rhea:events [connection-2] Link got event: receiver_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.987Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.987Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:20.987Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver 'cbs-98e5da56-c783-c343-9a5b-4cfc9649749f'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Received disposition for outgoing transfers
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: accepted
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.050Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: settled
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.051Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: message
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.051Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.051Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.052Z azure:service-bus:error [connection-2] Trying to create sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e'...
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Session got event: session_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.110Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: sender_open
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.112Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: sender_flow
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.112Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] Sat, 02 May 2020 03:27:21 GMT rhea:events [connection-2] Link got event: sendable
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.112Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.112Z azure:service-bus:error [connection-2] Sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e' with address 'taskEmail' has established itself.
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.113Z azure:service-bus:error [connection-2] Promise to create the sender resolved. Created sender with name: taskEmail-df9392a8-c922-d34d-a615-498a81279c1e
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] 2020-05-02T03:27:21.113Z azure:service-bus:error [connection-2] Sender 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e' created with sender options: { name: 'taskEmail-df9392a8-c922-d34d-a615-498a81279c1e',
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g]   target: { address: 'taskEmail' },
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g]   onError: [Function],
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g]   onClose: [Function],
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g]   onSessionError: [Function],
May 02 11:27:21 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g]   onSessionClose: [Function] }
May 02 11:27:22 event-listener core[task-svc-listener-deployment-7d678b5b65-n849g] operation-name="on" svc-name="event-listener" timestamp="2020-05-02T03:27:22.754Z" type="error" msg="Process uncaughtException: Error: read ECONNRESET" stack-trace="Error: Process uncaughtException: Error: read ECONNRESET |     at Object.logError [as error] (/task-svc/app/utils/logger.js:24:13) |     at process.on (/task-svc/app/event/index.js:24:10) |     at process.emit (events.js:203:15) |     at process._fatalException (internal/bootstrap/node.js:497:27) |     at process._asyncFatalException [as _fatalException] (/task-svc/node_modules/async-listener/glue.js:211:34)"

Task-Email-Listener (Receiver message)

May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:02 GMT rhea:events [connection-2] Connection got event: disconnected
May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:02.775Z rhea-promise:translate [connection-2] Translating the context for event: 'disconnected'.
May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:02.776Z rhea-promise:error [connection-2] The connection is open ? -> false
May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:02.777Z azure:service-bus:error The connection "connection-2" has been updated to "connection-3".
May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:02.777Z azure:service-bus:error [connection-3] state: { wasConnectionCloseCalled: false, numClients: 1 }
May 01 19:05:02 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:02.777Z azure:service-bus:error [connection-3] connection.close() was not called from the sdk and there were some clients. We should reconnect.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.078Z azure:service-bus:error [connection-3] calling detached on client 'taskEmail/e4b040ca-aa11-0c42-8dc5-f04a281fb734'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.078Z azure:service-bus:error [connection-3] calling detached on streaming receiver 'taskEmail-adc5d656-8ed5-7245-a585-da7778c9856b'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.079Z rhea-promise:error [connection-2] The receiver is open ? -> false
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.079Z rhea-promise:receiver [connection-2] receiver has been closed, now closing it's session.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.080Z rhea-promise:error [connection-2] The session is open ? -> false
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.080Z azure:service-bus:error [connection-3] Receiver 'taskEmail-adc5d656-8ed5-7245-a585-da7778c9856b' with address 'taskEmail' is open? -> false
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.080Z azure:service-bus:error [connection-3] The receiver 'taskEmail-adc5d656-8ed5-7245-a585-da7778c9856b' with address 'taskEmail' is not open and is not currently establishing itself. Hence let's try to connect.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Connection got event: connection_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.097Z rhea-promise:translate [connection-3] Translating the context for event: 'connection_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Session got event: session_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.098Z rhea-promise:translate [connection-3] Translating the context for event: 'session_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: sender_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.099Z rhea-promise:translate [connection-3] Translating the context for event: 'sender_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: sender_flow
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.100Z rhea-promise:translate [connection-3] Translating the context for event: 'sender_flow'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: sendable
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.100Z rhea-promise:translate [connection-3] Translating the context for event: 'sendable'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: receiver_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.101Z rhea-promise:receiver [connection-3] receiver got event: 'receiver_open'. Re-emitting the translated context.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.101Z rhea-promise:translate [connection-3] Translating the context for event: 'receiver_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.101Z rhea-promise:receiver [connection-3] Resolving the promise with amqp receiver 'cbs-58a99fab-0555-e744-947f-8f93518aa6a6'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Received disposition for outgoing transfers
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: accepted
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.163Z rhea-promise:translate [connection-3] Translating the context for event: 'accepted'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: settled
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.163Z rhea-promise:translate [connection-3] Translating the context for event: 'settled'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: message
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.163Z rhea-promise:receiver [connection-3] receiver got event: 'message'. Re-emitting the translated context.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.163Z rhea-promise:translate [connection-3] Translating the context for event: 'message'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.164Z azure:service-bus:error [connection-3] Trying to create receiver 'taskEmail-5f3fcc05-7e32-4044-8af4-3bc83b2cc430' with options { name: 'taskEmail-5f3fcc05-7e32-4044-8af4-3bc83b2cc430',
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   autoaccept: false,
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   rcv_settle_mode: 1,
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   snd_settle_mode: 0,
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   source: { address: 'taskEmail' },
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   credit_window: 0,
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onMessage: [Function: onMessage],
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onClose: [Function: onClose],
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onSessionClose: [Function: onSessionClose],
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onError: [Function],
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onSessionError: [Function],
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]   onSettled: [Function] }
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Session got event: session_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.225Z rhea-promise:translate [connection-3] Translating the context for event: 'session_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.225Z rhea-promise:receiver [connection-3] Added event handler for event 'message' on rhea-promise 'receiver'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.225Z rhea-promise:receiver [connection-3] Added event handler for event 'receiver_error' on rhea-promise 'receiver'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.225Z rhea-promise:receiver [connection-3] Added event handler for event 'receiver_close' on rhea-promise 'receiver'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.225Z rhea-promise:receiver [connection-3] Added event handler for event 'settled' on rhea-promise 'receiver'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Fri, 01 May 2020 11:05:03 GMT rhea:events [connection-3] Link got event: receiver_open
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.226Z rhea-promise:receiver [connection-3] receiver got event: 'receiver_open'. Re-emitting the translated context.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.227Z rhea-promise:translate [connection-3] Translating the context for event: 'receiver_open'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.227Z rhea-promise:receiver [connection-3] Resolving the promise with amqp receiver 'taskEmail-5f3fcc05-7e32-4044-8af4-3bc83b2cc430'.
May 01 19:05:03 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] 2020-05-01T11:05:03.227Z azure:service-bus:error [connection-3] Receiver 'taskEmail-5f3fcc05-7e32-4044-8af4-3bc83b2cc430' with address 'taskEmail' has established itself.
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] /task-svc/node_modules/applicationinsights/out/AutoCollection/Exceptions.js:37
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]                         throw THIS_IS_APPLICATION_INSIGHTS_RETHROWING_YOUR_EXCEPTION; // Error originated somewhere else in your app
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]                         ^
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl] Error: read ECONNRESET
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]     at TLSWrap.onStreamRead [as _originalOnread] (internal/stream_base_commons.js:111:27)
May 01 19:05:12 task-email-listener core[task-svc-listener-deployment-f6fcbf89-xf2tl]     at TLSWrap.<anonymous> (/task-svc/node_modules/async-listener/glue.js:188:31)

[ramya-rao-a]

Thanks for reporting @snuffykl

Can you run the same with the previous version of the package (1.1.5) to confirm that you don't see this behavior there? Am trying to confirm that it is the changes in 1.1.6 that is causing this.

Also, if you are able to consistently repro this, can you share the code you are using so that we can try with exactly the same? If you can strip out your application specific code and share the rest via a github repo, we can clone and try it from our end.

Anything we should know about your minikube set up?

@chradek,
Given that we had extensively tested the change to use new connection objects when disconnect event is fired, my guess would be that this is an environment specific issue. Perhaps we should try out in minikube as well

[snuffykl]

Hi @ramya-rao-a I've created a sample application for it. Most of k8s deployment is in there. The difference was the error where ETIMEDOUT(minikube) vs ECONNRESET(Azure AKS). However both errror will crash the application. Take not ETIMEDOUT will take a little longer to crash compare to ECONNRESET.

In addition, I've tested with 1.1.5 also it has the same outcome of crashing the application.

https://github.com/snuffykl/http-sender-amqp

[ramya-rao-a]

Thanks @snuffykl
We will try to get a repro from our end to investigate the root cause and give an update here ASAP

[chradek]

@snuffykl
Can you share which version of @azure/service-bus you were on previously that did not have this behavior? If you can provide the versions of rhea and rhea-promise your app had installed, that would be helpful as well.

I have been able to reproduce an ECONNRESET error that crashes the process. In my case I notice this when I use iptables rules to drop all incoming traffic from the service, wait for 2 disconnect events, then re-allow incoming traffic from the service. After a minute or two I get this issue.

I haven't gotten your example running yet but will work on doing so (I'm new to kubernetes/helm so was running into some issues I think with the version of helm I was installing).

[chradek]

@snuffykl
I was able to get your repo running, so thank you for that! I tried disconnecting and reconnecting a few times after triggering a send while watching the logs. In this case I'm just turning my wifi off, waiting a minute or two, then turning it back on. So far I haven't seen the process-crashing error yet with your sample.

Can you share more info about how often/how long you disconnect/reconnect your internet before seeing this error? Does it happen immediately after turning off your WiFi, or do you have to reconnect your WiFi before you see it? How long after a disconnect or reconnect do you see this happen?

I do have a way to reproduce the ECONNRESET under different conditions, but I do want to try and reproduce using your sample as well so we can be sure if we fix the issue for my sample, it is fixed for yours too.

[snuffykl]

Hi @chradek, regarding helm version am using helm version v2.16.6. If you are using MacOS you can do brew install helm@2

[chradek]

@snuffykl I found a scenario where our amqp dependency, rhea, could cause and uncaught ECONNRESET to be thrown. I created a PR to fix this in rhea that fixes my repro:
https://github.com/amqp/rhea/pull/300

Basically when the connection reaches an idle timeout (60 seconds), the connection is closed and we (service-bus sdk) create a new connection. If you log rhea:io, you should see an entry that includes aborting socket in your logs if you're running into the idle timeout.

[snuffykl]

Hey @chradek that is good news :). I've also enabled rhea:io in my test environment and noticed there is aborting socket before process crashes. Below are the logs from my test environment. I guess my assumption of previous connection(tcp) did not actually destroy was true.

May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-1] aborting socket
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-1] Connection got event: disconnected
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.387Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.389Z rhea-promise:error [connection-1] The connection is open ? -> false
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.390Z azure:service-bus:error The connection "connection-1" has been updated to "connection-2".
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.390Z azure:service-bus:error [connection-2] state: { wasConnectionCloseCalled: false, numClients: 1 }
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.390Z azure:service-bus:error [connection-2] connection.close() was not called from the sdk and there were some clients. We should reconnect.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.691Z azure:service-bus:error [connection-2] calling detached on client 'taskEmail/3e190c6a-ec33-e74a-a149-b0376c63d7ca'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.691Z azure:service-bus:error [connection-2] calling detached on sender 'taskEmail-b8f074fe-8102-6145-8dd5-bac2475d6c73'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.692Z rhea-promise:error [connection-1] The sender is open ? -> false
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.693Z rhea-promise:error [connection-1] The session is open ? -> false
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.693Z azure:service-bus:error [connection-2] close() method of Sender 'taskEmail-b8f074fe-8102-6145-8dd5-bac2475d6c73' with address 'taskEmail' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.693Z azure:service-bus:error [connection-2] Sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b' with address 'taskEmail' is open? -> false
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.694Z azure:service-bus:error [connection-2] Sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b' with address 'taskEmail' is open? -> false
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.694Z azure:service-bus:error [connection-2] The sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b' with address 'taskEmail' is not open and is not currently establishing itself. Hence let's try to connect.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] connected 10.10.0.20:48844 -> xx.xx.xx.xxx:5671
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 8 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 63 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 63
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 26 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 26
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 8 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 70 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 70
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Connection got event: connection_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.711Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 34 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 34
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Session got event: session_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.714Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 106 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 106
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sender_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.718Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 35 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 35
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sender_flow
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.718Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sendable
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.719Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 111 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 111
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: receiver_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.720Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.720Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.720Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver 'cbs-1831a3ee-ef7c-8947-baa8-8ddb02a1c7e0'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 23 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 23
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Received disposition for outgoing transfers
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: accepted
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.781Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: settled
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.782Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 141 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 141
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: message
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.782Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.782Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.783Z azure:service-bus:error [connection-2] Trying to create sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b'...
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 34 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 34
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Session got event: session_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.843Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 188 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 188
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sender_open
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.845Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] read 38 bytes
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:io [connection-2] got frame of size 38
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sender_flow
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.846Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] Tue, 05 May 2020 22:47:47 GMT rhea:events [connection-2] Link got event: sendable
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.846Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.846Z azure:service-bus:error [connection-2] Sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b' with address 'taskEmail' has established itself.
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.846Z azure:service-bus:error [connection-2] Promise to create the sender resolved. Created sender with name: taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] 2020-05-05T22:47:47.846Z azure:service-bus:error [connection-2] Sender 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b' created with sender options: { name: 'taskEmail-866d9187-59ef-ae4b-96ca-9075e90bb13b',
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9]   target: { address: 'taskEmail' },
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9]   onError: [Function],
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9]   onClose: [Function],
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9]   onSessionError: [Function],
May 06 06:47:47 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9]   onSessionClose: [Function] }
May 06 06:47:51 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] operation-name="on" svc-name="event-listener" timestamp="2020-05-05T22:47:51.215Z" type="error" msg="Process uncaughtException: Error: read ECONNRESET" stack-trace="Error: Process uncaughtException: Error: read ECONNRESET |     at Object.logError [as error] (/task-svc/app/utils/logger.js:24:13) |     at process.on (/task-svc/app/event/index.js:24:10) |     at process.emit (events.js:203:15) |     at process._fatalException (internal/bootstrap/node.js:497:27) |     at process._asyncFatalException [as _fatalException] (/task-svc/node_modules/async-listener/glue.js:211:34)"
May 06 06:47:54 event-listener core[task-svc-listener-deployment-659bb4b799-zzkb9] src-file="/task-svc/app/event/index.js" operation-name="line-38" svc-name="event-listener" timestamp="2020-05-05T22:47:54.151Z" type="info" msg="Starting event-listener"

[chradek]

@snuffykl
Would it be possible for you to modify your test environment to include the change from rhea in your app? This would involve making this change in your node_modules/rhea/lib/connection.js file.

Otherwise once the new version of rhea is released you should just need to reinstall your node modules to get the latest version and test.

[Rviku]

@chradek @snuffykl
We've encountered the same issue in our project. I was able to reproduce it also by disconnecting WiFi and I can confirm that with @chradek fix I stopped seeing ECONNRESET

I'm looking forward for the new rhea release.

EDIT: I've tested it on 1.1.5
EDIT2: I've tested it also on 1.1.6 and works also :)

[snuffykl]

@chradek I've deployed the fix that you suggested to my test environment. It looks like it fixes it. No more crashing now and i did a logging Destroyed socket after successfully executed this.socket.destroy(). Just wondering when will rhea publish the new version ?

[chradek]

@Rviku @snuffykl
rhea version 1.0.21 has been released with this fix. If you reinstall your node_modules you should get the latest version of rhea. (Note that you might need to clear any lockfiles, e.g. package-lock.json if you're using them to make sure 1.0.21 gets installed).

I just tested with a clean install of @azure/service-bus and verified that the latest version of rhea was installed.

[chradek]

I'm closing this issue since rhea 1.0.21 is out now and @azure/service-bus will pick it up when installing node modules.

If you continue to face this issue please feel free to post here or open a new issue.

[ramya-rao-a]

We have just released an update to the @azure/service-bus package where the min version of rhea has been updated to 1.0.21 so that any existing application upgrading to latest service bus package will get the latest rhea package as well.

Thanks for reporting @snuffykl!