Azure-sdk-for-js: Unable to open the amqp connection "connection-2" due to operation timeout

[veeresh-work]

@ramya-rao-a

• Package Name: "@azure/service-bus":
• Package Version: "1.1.7" , "1.1.6", "1.1.5"
• Operating system: centOS
• [y] nodejs yes
  
  
  
  • version: v10.20.2
  
  

Describe the bug
Every now and then we are not able to push the message to the queue. The same code works other times. When we do bump into this issue, even the retry fails. For the retry we create a new sbClient, queueClient and sender object but still it fails

To Reproduce
Steps to reproduce the behavior:

1. No specific steps. The same code works other times

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context

code :

const { ServiceBusClient } = require('@azure/service-bus');

// more code

static async _pushToQueue(msg) {
    const sbClient = ServiceBusClient.createFromConnectionString(
      process.env.QUEUE_CONNECTION_STRING,
    );
    const queueClient = sbClient.createQueueClient(process.env.SCAN_QUEUE_NAME);
    const sender = queueClient.createSender();

    try {
      const message = {
        body: msg,
        label: 'test',
      };
      logger.info(`Sending message: ${JSON.stringify(message.body)}`);
      const ret = await sender.send(message);


      await queueClient.close();
    } catch (err) {
      logger.error(
        `Error in pushing message for user`,
      );
      throw err;
    } finally {
      await sbClient.close();
    }
}

// more code

Adding logs below with this env variable :

export DEBUG=azure:service-bus:error,azure-amqp-common:error,rhea-promise:error,rhea:events,rhea:frames,rhea:io,rhea:flow

Explanation of attached logs:

1. At 22:39:04.06 , first push to queue was attempted.
2. After multiple automatic retry it errored at 22:42:22.072
3. We initiated a retry at 22:42:22.095 . Which involves creating of queueClient and everything
4. Even that errored out by 22:45:46.112
5. The logs that follow are just "msg complete", and "msg receive" in another file which apparently succeeded

2020-05-20T22:39:04.058Z INFO: Sending message: {"memberid":"### redacted ###"} contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:39:04.060Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:39:04.060Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:39:04.060Z azure:service-bus:error [connection-2] The sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:39:24.573Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:39:24.573Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:39:24.573Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:40:04.062Z rhea-promise:error [connection-2] Unable to open the amqp connection "connection-2" due to operation timeout.
2020-05-20T22:40:04.063Z azure:service-bus:error [connection-2] An error occurred while creating the sender devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88 { Error: Unable to open the amqp connection "connection-2" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:40:10.065Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:40:10.065Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:40:10.065Z azure:service-bus:error [connection-2] The sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:40:17.112Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:40:17.112Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:40:17.112Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:40:32.083Z rhea:frames [connection-1]:0 -> empty
2020-05-20T22:41:04.220Z rhea:io [connection-1] read 35 bytes
2020-05-20T22:41:04.221Z rhea:io [connection-1] got frame of size 35
2020-05-20T22:41:04.221Z rhea:frames [connection-1]:0 <- flow#13 {"next_incoming_id":1,"incoming_window":5000,"next_outgoing_id":2,"outgoing_window":2046,"echo":true} 
2020-05-20T22:41:10.065Z rhea-promise:error [connection-2] Unable to open the amqp connection "connection-2" due to operation timeout.
2020-05-20T22:41:10.066Z azure:service-bus:error [connection-2] An error occurred while creating the sender devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88 { Error: Unable to open the amqp connection "connection-2" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:41:16.067Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:41:16.067Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is open? -> undefined
2020-05-20T22:41:16.068Z azure:service-bus:error [connection-2] The sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:41:56.780Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:41:56.780Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:41:56.780Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:42:16.070Z rhea-promise:error [connection-2] Unable to open the amqp connection "connection-2" due to operation timeout.
2020-05-20T22:42:16.070Z azure:service-bus:error [connection-2] An error occurred while creating the sender devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88 { Error: Unable to open the amqp connection "connection-2" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:42:22.072Z azure:service-bus:error [connection-2] Sender 'devqueue-8154dfd7-6624-1946-9a3a-9a900d59ce88': An error occurred while sending the message: { body:
   { memberid: '### redacted ###'},
  label: 'test' }
Error: { Error: Unable to open the amqp connection "connection-2" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:42:22.072Z ERROR: Error in pushing message for user account ### redactecd ### to queue contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:42:22.074Z ERROR: Error in scheduling scan for user ### redacted ###'s contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:42:22.074Z ERROR: Error in scanning email for user ### redacted ###  error:Unable to open the amqp connection "connection-2" due to operation timeout. contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:42:22.081Z INFO: Removed account lock for user ### redacted ### contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:42:22.094Z ERROR: Rescheduling the scan after error for user ### redacted ### contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:42:22.095Z INFO: Sending message: {"memberid":"### redacted ###"}
2020-05-20T22:42:22.095Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:42:22.095Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:42:22.096Z azure:service-bus:error [connection-3] The sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:42:32.084Z rhea:frames [connection-1]:0 -> empty
2020-05-20T22:42:49.325Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:42:49.325Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:42:49.325Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:43:02.089Z rhea:frames [connection-1]:0 -> transfer#14 {"delivery_id":1,"delivery_tag":{"type":"Buffer","data":[49]}} <Buffer 00 53 70 45 00 53 73 d0 00 00 00 5c 00 00 00 05 a1 24 62 37 32 37 39 39 34 63 2d 33 35 32 30 2d 32 38 34 37 2d 61 32 65 38 2d 30 38 37 66 66 35 63 34 ... >
2020-05-20T22:43:02.089Z rhea:io [connection-1] read 24 bytes
2020-05-20T22:43:02.089Z rhea:io [connection-1] got frame of size 24
2020-05-20T22:43:02.090Z rhea:frames [connection-1]:0 <- disposition#15 {"role":true,"first":1,"settled":true,"state":[]} 
2020-05-20T22:43:02.090Z rhea:events [connection-1] Received disposition for outgoing transfers
2020-05-20T22:43:02.090Z rhea:events [connection-1] Link got event: accepted
2020-05-20T22:43:02.090Z rhea:events [connection-1] Link got event: settled
2020-05-20T22:43:02.090Z rhea:io [connection-1] read 142 bytes
2020-05-20T22:43:02.090Z rhea:io [connection-1] got frame of size 142
2020-05-20T22:43:02.090Z rhea:frames [connection-1]:0 <- transfer#14 {"handle":1,"delivery_id":1,"delivery_tag":{"type":"Buffer","data":[2,0,0,0]}} <Buffer 00 53 73 c0 33 0d 40 40 40 40 40 a1 24 62 37 32 37 39 39 34 63 2d 33 35 32 30 2d 32 38 34 37 2d 61 32 65 38 2d 30 38 37 66 66 35 63 34 61 65 38 36 40 ... >
2020-05-20T22:43:02.091Z rhea:events [connection-1] Link got event: message
2020-05-20T22:43:02.091Z rhea:frames [connection-1]:0 -> disposition#15 {"role":true,"first":1,"last":1,"settled":true,"state":[]} 
2020-05-20T22:43:02.091Z rhea:frames [connection-1]:2 -> begin#11 {"incoming_window":2048,"outgoing_window":4294967295} 
2020-05-20T22:43:02.154Z rhea:io [connection-1] read 34 bytes
2020-05-20T22:43:02.154Z rhea:io [connection-1] got frame of size 34
2020-05-20T22:43:02.154Z rhea:frames [connection-1]:2 <- begin#11 {"remote_channel":2,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2020-05-20T22:43:02.154Z rhea:events [connection-1] Session got event: session_open
2020-05-20T22:43:02.156Z rhea:frames [connection-1]:2 -> attach#12 {"name":"8e523a33-4569-1b4b-8186-1ce6cbbbca05","source":[],"target":["devqueue/$management"]} 
2020-05-20T22:43:02.157Z rhea:io [connection-1] read 122 bytes
2020-05-20T22:43:02.157Z rhea:io [connection-1] got frame of size 122
2020-05-20T22:43:02.157Z rhea:frames [connection-1]:2 <- attach#12 {"name":"8e523a33-4569-1b4b-8186-1ce6cbbbca05","role":true,"source":[null,null,null,null,null,null,null,null,null,null,null],"target":["devqueue/$management",null,null,null,null,null,null],"max_message_size":262144} 
2020-05-20T22:43:02.157Z rhea:events [connection-1] Link got event: sender_open
2020-05-20T22:43:02.158Z rhea:io [connection-1] read 38 bytes
2020-05-20T22:43:02.158Z rhea:io [connection-1] got frame of size 38
2020-05-20T22:43:02.158Z rhea:frames [connection-1]:2 <- flow#13 {"incoming_window":5000,"next_outgoing_id":1,"outgoing_window":2048,"link_credit":1000} 
2020-05-20T22:43:02.158Z rhea:events [connection-1] Link got event: sender_flow
2020-05-20T22:43:02.158Z rhea:events [connection-1] Link got event: sendable
2020-05-20T22:43:02.158Z rhea:frames [connection-1]:2 -> attach#12 {"name":"095225a3-80e5-2048-bdf1-656d5de330e7","handle":1,"role":true,"source":["devqueue/$management"],"target":["095225a3-80e5-2048-bdf1-656d5de330e7"]} 
2020-05-20T22:43:02.159Z rhea:io [connection-1] read 160 bytes
2020-05-20T22:43:02.159Z rhea:io [connection-1] got frame of size 160
2020-05-20T22:43:02.159Z rhea:frames [connection-1]:2 <- attach#12 {"name":"095225a3-80e5-2048-bdf1-656d5de330e7","handle":1,"source":["devqueue/$management",null,null,null,null,null,null,null,null,null,null],"target":["095225a3-80e5-2048-bdf1-656d5de330e7",null,null,null,null,null,null],"max_message_size":{"type":"Buffer","data":[255,255,255,255,255,255,255,255]}} 
2020-05-20T22:43:02.159Z rhea:events [connection-1] Link got event: receiver_open
2020-05-20T22:43:02.160Z rhea:frames [connection-1]:2 -> flow#13 {"incoming_window":2048,"outgoing_window":4294967295,"handle":1,"link_credit":1000} 
2020-05-20T22:43:02.161Z rhea:frames [connection-1]:2 -> transfer#14 {"delivery_tag":{"type":"Buffer","data":[48]}} <Buffer 00 53 70 45 00 53 73 d0 00 00 00 53 00 00 00 05 a1 24 66 33 30 30 39 37 66 31 2d 39 63 62 66 2d 62 39 34 33 2d 61 63 39 65 2d 31 34 38 34 62 32 37 31 ... >
2020-05-20T22:43:02.344Z rhea:io [connection-1] read 23 bytes
2020-05-20T22:43:02.345Z rhea:io [connection-1] got frame of size 23
2020-05-20T22:43:02.345Z rhea:frames [connection-1]:2 <- disposition#15 {"role":true,"settled":true,"state":[]} 
2020-05-20T22:43:02.345Z rhea:events [connection-1] Received disposition for outgoing transfers
2020-05-20T22:43:02.345Z rhea:events [connection-1] Link got event: accepted
2020-05-20T22:43:02.345Z rhea:events [connection-1] Link got event: settled
2020-05-20T22:43:02.373Z rhea:io [connection-1] read 206 bytes
2020-05-20T22:43:02.373Z rhea:io [connection-1] got frame of size 206
2020-05-20T22:43:02.373Z rhea:frames [connection-1]:2 <- transfer#14 {"handle":1,"delivery_tag":{"type":"Buffer","data":[1,5,185,0]}} <Buffer 00 53 73 c0 33 0d 40 40 40 40 40 a1 24 66 33 30 30 39 37 66 31 2d 39 63 62 66 2d 62 39 34 33 2d 61 63 39 65 2d 31 34 38 34 62 32 37 31 36 65 37 62 40 ... >
2020-05-20T22:43:02.374Z rhea:events [connection-1] Link got event: message
2020-05-20T22:43:02.375Z rhea:frames [connection-1]:2 -> disposition#15 {"role":true,"settled":true,"state":[]} 
2020-05-20T22:43:02.375Z INFO: New expiration time : Wed May 20 2020 22:48:02 GMT+0000 (Coordinated Universal Time) for msg from user ### redacted ### contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:43:22.098Z rhea-promise:error [connection-3] Unable to open the amqp connection "connection-3" due to operation timeout.
2020-05-20T22:43:22.098Z azure:service-bus:error [connection-3] An error occurred while creating the sender devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b { Error: Unable to open the amqp connection "connection-3" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:43:30.101Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:43:30.101Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:43:30.101Z azure:service-bus:error [connection-3] The sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:43:54.976Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:43:54.976Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:43:54.976Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:44:04.204Z rhea:io [connection-1] read 35 bytes
2020-05-20T22:44:04.204Z rhea:io [connection-1] got frame of size 35
2020-05-20T22:44:04.204Z rhea:frames [connection-1]:0 <- flow#13 {"next_incoming_id":2,"incoming_window":5000,"next_outgoing_id":3,"outgoing_window":2045,"echo":true} 
2020-05-20T22:44:30.106Z rhea-promise:error [connection-3] Unable to open the amqp connection "connection-3" due to operation timeout.
2020-05-20T22:44:30.106Z azure:service-bus:error [connection-3] An error occurred while creating the sender devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b { Error: Unable to open the amqp connection "connection-3" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:44:38.109Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:44:38.110Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is open? -> undefined
2020-05-20T22:44:38.110Z azure:service-bus:error [connection-3] The sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b' with address 'devqueue' is not open and is not currently establishing itself. Hence let's try to connect.
2020-05-20T22:44:56.763Z rhea:io [connection-1] read 8 bytes
2020-05-20T22:44:56.763Z rhea:io [connection-1] got frame of size 8
2020-05-20T22:44:56.764Z rhea:frames [connection-1]:0 <- empty
2020-05-20T22:44:58.253Z rhea:io [connection-2] connected undefined:undefined -> undefined:undefined
2020-05-20T22:44:58.254Z rhea:frames [connection-2] -> { protocol_id: 3, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.338Z rhea:io [connection-2] connected undefined:undefined -> undefined:undefined
2020-05-20T22:44:58.367Z rhea:io [connection-3] connected undefined:undefined -> undefined:undefined
2020-05-20T22:44:58.367Z rhea:frames [connection-3] -> { protocol_id: 3, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.377Z rhea:io [connection-3] connected undefined:undefined -> undefined:undefined
2020-05-20T22:44:58.598Z rhea:io [connection-3] connected 10.142.133.57:47210 -> 23.99.80.186:5671
2020-05-20T22:44:58.599Z rhea:io [connection-2] connected 10.142.133.57:47208 -> 23.99.80.186:5671
2020-05-20T22:44:58.600Z rhea:io [connection-3] read 8 bytes
2020-05-20T22:44:58.600Z rhea:frames [connection-3] <- { protocol_id: 3, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.600Z rhea:io [connection-3] read 63 bytes
2020-05-20T22:44:58.600Z rhea:io [connection-3] got frame of size 63
2020-05-20T22:44:58.600Z rhea:frames [connection-3]:0 <- sasl_mechanisms#40 {"sasl_server_mechanisms":["MSSBCBS","PLAIN","ANONYMOUS","EXTERNAL"]} 
2020-05-20T22:44:58.600Z rhea:frames [connection-3]:0 -> sasl_init#41 {"mechanism":"ANONYMOUS","initial_response":{"type":"Buffer","data":[0,115,101,110,100,45,108,105,115,116,101,110]},"hostname":"muw1-olp-piimeter-int-svb.servicebus.windows.net"} 
2020-05-20T22:44:58.601Z rhea:io [connection-2] read 8 bytes
2020-05-20T22:44:58.601Z rhea:frames [connection-2] <- { protocol_id: 3, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.601Z rhea:io [connection-2] read 63 bytes
2020-05-20T22:44:58.601Z rhea:io [connection-2] got frame of size 63
2020-05-20T22:44:58.601Z rhea:frames [connection-2]:0 <- sasl_mechanisms#40 {"sasl_server_mechanisms":["MSSBCBS","PLAIN","ANONYMOUS","EXTERNAL"]} 
2020-05-20T22:44:58.601Z rhea:frames [connection-2]:0 -> sasl_init#41 {"mechanism":"ANONYMOUS","initial_response":{"type":"Buffer","data":[0,115,101,110,100,45,108,105,115,116,101,110]},"hostname":"muw1-olp-piimeter-int-svb.servicebus.windows.net"} 
2020-05-20T22:44:58.601Z rhea:io [connection-3] read 26 bytes
2020-05-20T22:44:58.601Z rhea:io [connection-3] got frame of size 26
2020-05-20T22:44:58.601Z rhea:frames [connection-3]:0 <- sasl_outcome#44 {"additional_data":{"type":"Buffer","data":[87,101,108,99,111,109,101,33]}} 
2020-05-20T22:44:58.602Z rhea:frames [connection-3] -> { protocol_id: 0, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.602Z rhea:io [connection-2] read 26 bytes
2020-05-20T22:44:58.602Z rhea:io [connection-2] got frame of size 26
2020-05-20T22:44:58.602Z rhea:frames [connection-2]:0 <- sasl_outcome#44 {"additional_data":{"type":"Buffer","data":[87,101,108,99,111,109,101,33]}} 
2020-05-20T22:44:58.602Z rhea:frames [connection-2] -> { protocol_id: 0, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.602Z rhea:io [connection-3] read 8 bytes
2020-05-20T22:44:58.602Z rhea:frames [connection-3] <- { protocol_id: 0, major: 1, minor: 0, revision: 0 }
2020-05-20T22:44:58.603Z rhea:io [connection-2] read 8 bytes
2020-05-20T22:44:58.603Z rhea:frames [connection-2] <- { protocol_id: 0, major: 1, minor: 0, revision: 0 }
2020-05-20T22:45:02.378Z rhea:frames [connection-1]:0 -> empty
2020-05-20T22:45:38.110Z rhea-promise:error [connection-3] Unable to open the amqp connection "connection-3" due to operation timeout.
2020-05-20T22:45:38.110Z azure:service-bus:error [connection-3] An error occurred while creating the sender devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b { Error: Unable to open the amqp connection "connection-3" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:45:46.112Z azure:service-bus:error [connection-3] Sender 'devqueue-84cd84a2-1e83-a442-8a53-cb0bb1774a7b': An error occurred while sending the message: { body:
   { memberid: '### redacted ###'},
  label: 'test' }
Error: { Error: Unable to open the amqp connection "connection-3" due to operation timeout.
    at Timeout.actionAfterTimeout (/apps/node_modules/rhea-promise/dist/lib/connection.js:137:35)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) name: 'MessagingError', translated: true, retryable: true }
2020-05-20T22:45:46.112Z ERROR: Error in pushing message contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:45:46.112Z ERROR: Error in scheduling scan contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:45:46.112Z ERROR: Error in processFn. Think about deadlettering it or deferring it. MessagingError: Unable to open the amqp connection "connection-3" due to operation timeout. contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:45:46.113Z azure:service-bus:error [connection-1] Receiver 'devqueue-9ca8b43c-695e-d949-bd8b-75a5ec460311' with address 'devqueue' is open? -> true
2020-05-20T22:45:46.113Z azure:service-bus:error [connection-1] Receiver 'devqueue-9ca8b43c-695e-d949-bd8b-75a5ec460311' with address 'devqueue' is open? -> true
2020-05-20T22:45:46.113Z rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"first":6,"last":6,"state":[]} 
2020-05-20T22:45:46.136Z rhea:io [connection-1] read 24 bytes
2020-05-20T22:45:46.136Z rhea:io [connection-1] got frame of size 24
2020-05-20T22:45:46.137Z rhea:frames [connection-1]:1 <- disposition#15 {"first":6,"settled":true,"state":[]} 
2020-05-20T22:45:46.137Z rhea:events [connection-1] Received disposition for incoming transfers
2020-05-20T22:45:46.137Z rhea:events [connection-1] Link got event: settled
2020-05-20T22:45:46.138Z INFO: msg completed sucessfully for user ### redacted ### contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba
2020-05-20T22:45:46.138Z INFO: JOB END contextID: 0d459189-e3c1-4eee-81f2-d810b78c5cba


2020-05-20T22:45:46.138Z INFO: JOB START INSTANCE_ID: undefined
2020-05-20T22:45:46.139Z azure:service-bus:error [connection-1] Receiver 'devqueue-9ca8b43c-695e-d949-bd8b-75a5ec460311' with address 'devqueue' is open? -> true
2020-05-20T22:45:46.139Z azure:service-bus:error [connection-1] Receiver 'devqueue-9ca8b43c-695e-d949-bd8b-75a5ec460311' with address 'devqueue' is open? -> true
2020-05-20T22:45:46.139Z azure:service-bus:error [connection-1] Receiver 'devqueue-9ca8b43c-695e-d949-bd8b-75a5ec460311' with address 'devqueue' is open? -> true
2020-05-20T22:45:46.139Z rhea:frames [connection-1]:1 -> flow#13 {"next_incoming_id":7,"incoming_window":2048,"outgoing_window":4294967295,"delivery_count":7,"link_credit":1} 
2020-05-20T22:45:46.141Z rhea:io [connection-1] read 506 bytes
2020-05-20T22:45:46.141Z rhea:io [connection-1] got frame of size 506
2020-05-20T22:45:46.141Z rhea:frames [connection-1]:1 <- transfer#14 {"delivery_id":7,"delivery_tag":{"type":"Buffer","data":[155,23,112,48,57,102,90,69,164,111,132,19,141,192,233,46]},"batchable":true} <Buffer 00 53 70 c0 0a 05 40 40 70 48 19 08 00 40 43 00 53 71 c1 24 02 a3 10 78 2d 6f 70 74 2d 6c 6f 63 6b 2d 74 6f 6b 65 6e 98 30 70 17 9b 66 39 45 5a a4 6f ... >
2020-05-20T22:45:46.141Z rhea:events [connection-1] Link got event: message
2020-05-20T22:45:46.141Z INFO: Received 1 message : {"memberid":"### redacted ###" contextID: 7ea86281-9c28-4be5-8778-1b8219041587

[ramya-rao-a]

Thanks for reporting @veeresh-work

The logs clearly show that every attempt to make a connection to the service is failing with the timeout error.

It could be possible that the service has been down or being upgraded during these times. Can you check the activity logs in the portal for any signs for such an activity? You can also log a support ticket via the portal to get help in figuring out what was happening to the service during these times

[veeresh-work]

@ramya-rao-a : Thanks for looking into this. Its very unlikely that the service-bus itself is down at that time. Even in the logs (towards the end) you will notice the same worker was able to receive a message with [ connection-1 ]. Also note that all the log entries tagged with [connection-1] are from the same worker in another file, actively renewing the lock on another message from the same queue. code: receiver.renewMessageLock(msg) .

Apparently that renew msg lock on [connection-1] succeeds around the same time while [connection-3] is failing to send a msg to the queue.

This issue is happening quite regularly, atleast couple of times in a day. While one worker experiences this issue, the other workers continue to send and receive message without any issue.

The activity logs for service bus on the portal doesn't seem to indicate anything bad. Tried Failed Operation, Latest 50 logs etc .

[ramya-rao-a]

Do you see this issue only with the worker that sends messages to the queue or even with the one that is receiving the messages? Can you share the code snippet you are using to receive the messages?

We have a 60 second timeout when trying to establish a connection with the service. The send operation has retry policy which consists of 3 attempts each. Since you are using a new SB client, queue client and sender for each message, a new connection needs to be set up for each message, increasing your chances of seeing the timeout error.

We recommend that you re-use the sender instead. This way a connection once set up can be re-used. For any reason if the connection fails in the middle, the next send() operation on the sender will do the job to bring the connection back up and continue sending.

[veeresh-work]

@ramya-rao-a
So I changed the code to maintain a single instance of sbClient and queueClient per worker and that has reduced the amqp errors. In fact I haven't seen any in the past couple of days. Thanks for the suggestion.

I had also raised a azure support ticket and they are looking into it. They noticed around 22 latency issues during the time mentioned in the logs and are investigating it.

[ramya-rao-a]

Thanks @veeresh-work for getting back on this

We will close this issue as the code refactoring will help your case and the Azure support ticket you created will give more information on the latency issues.

Please do create a new issue if you see any other problems or have any feedback for the Service Bus package