Azure/azure-sdk-for-js

Message receiver does not resolve neither reject after internet connection loss

epomatti opened this issue ยท 17 comments

  • Package Name: @azure/service-bus
  • Package Version: 1.1.3
  • Operating system: Ubuntu 18
  • nodejs
    • version: v12.16.1
  • typescript
    • version:
  • browser
    • name/version:
  • Is the bug related to documentation in

Describe the bug

We noticed messages accumulating in our servicebus queue and figured out that the problem was related to our back-end. We discovered this:

The method receiver.receiveMessages is locking undefenitelly when the internet connection is out for a couple of minutes (10 minutes is one way to reproduce it).

If the offline period is short (couple of seconds) the method receiver.receiveMessages call recovers and starts consuming messages again. We observed the problem only with a couple of minutes without internet. Once that couple of minutes pass, the method receiver.receiveMessages will not resolve anymore and will not consume any more messages, requiring the restart of the application.

The client is also not logging any error or exception. It simply stays blocked at const messages = await this.receiver.receiveMessages(10);.

// We use this to keep consuming messages
async handle() {
  while (true) {
    try {
      await this.handleMessages();
    } catch (e) {
      Logger.error(e);
    }
  }
}

// This is the actual code
async handleMessages() {
  try {
    const { connection, queueName } = this.properties;
    this.sbClient = ServiceBusClient.createFromConnectionString(connection);
    this.queueClient = this.sbClient.createQueueClient(queueName);
    this.receiver = this.queueClient.createReceiver(ReceiveMode.receiveAndDelete);
    const messages = await this.receiver.receiveMessages(10);
    messages.forEach(({ body }) => this.service.execute(body.data));
    await this.queueClient.close();
  } finally {
    await this.sbClient.close();
  }
}

To Reproduce
Steps to reproduce the behavior:

  1. Start the code to receive messages
  2. Turn-off internet connection
  3. Enqueue a message in the queue
  4. Await 10 minutes
  5. Turn-on internet connection

Messages will not be received from the queue, and the program will need to be restarted to receive messages again.

This problem won't happen if the internet offline period is very short (couple of seconds).

Expected behavior
The receiving of messages should resolve automatically, or the process should throw an exception indicating that the consumption has failed and cannot be resolved.

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

Additional context
Add any other context about the problem here.

@chradek another service bus issue, if you could please take a look when able

@evandropomatti
Thanks for reporting this issue. I noticed that your handleMessages sample doesn't have a catch block. Would it be possible to add a catch to your try and log any errors you hit?

The other thing is you may need to close your sbClient in the finally block after closing your queue client. When I ran your modified sample locally I was able to catch errors from the receive call. If you can verify if an error is being thrown that might give us some clues.

If an error is being thrown by your receive call, then the service bus client doesn't get closed (just the queue client does since it is in the finally block). I notice this is running in a loop, so it might be possible that there's an issue with too many open service bus connections.

@chradek Thanks for the feedback. However I was not able to get errors when my internet is out for a long time.

I modified the code, and also extracted it so it's easier to debug.

Now the program just exits without exception or error after 1:20 min waiting to receive messages.

Just to be clear:

  1. I start the program and it locks at the receiveMessages operation.
  2. I turn off the Wi-Fi
  3. After 1:20 minutes the program terminates without warning.
const { ServiceBusClient, ReceiveMode } = require("@azure/service-bus");

require("dotenv").config();

const connectionString = process.env.SERVICE_BUS_CONNECTION_STRING || "<connection string>";
const queueName = process.env.QUEUE_NAME || "<queue name>";

async function main() {
  while (true) {
    try {
      this.sbClient = ServiceBusClient.createFromConnectionString(connectionString);
      this.queueClient = this.sbClient.createQueueClient(queueName);
      this.receiver = this.queueClient.createReceiver(ReceiveMode.receiveAndDelete);
      // Clients locks here and keep waiting for messages
      console.log("Waiting for messages: " + new Date());
      const messages = await this.receiver.receiveMessages(10);
      messages.forEach(({ body }) => console.log(body));
      await this.queueClient.close();
    } catch (e) {
      console.error(e);
    } finally {
      console.log("Program ended: " + new Date());
      await this.sbClient.close();
    }
  }
}

main().catch((err) => {
  console.log("Error occurred: ", err);
});

Output:

pomatti@NT-03024:~/Projects/demo-servicebus$ node src/dequeue.js
Waiting for messages: Mon Mar 09 2020 14:12:28 GMT-0300 (Brasilia Standard Time)
pomatti@NT-03024:~/Projects/demo-servicebus$ 

If the Wi-Fi connection is normal, the program keeps executing.

pomatti@NT-03024:~/Projects/demo-servicebus$ node src/dequeue.js
Waiting for messages: Mon Mar 09 2020 14:18:42 GMT-0300 (Brasilia Standard Time)
Program ended: Mon Mar 09 2020 14:19:43 GMT-0300 (Brasilia Standard Time)
Waiting for messages: Mon Mar 09 2020 14:19:43 GMT-0300 (Brasilia Standard Time)
Program ended: Mon Mar 09 2020 14:20:44 GMT-0300 (Brasilia Standard Time)
Waiting for messages: Mon Mar 09 2020 14:20:44 GMT-0300 (Brasilia Standard Time)

@evandropomatti
That's really interesting that the process is exiting in the case where your internet is disabled for 1:20 minutes. That shouldn't happen unless the client was closed, which also shouldn't happen unless receiveMessages returns with messages or an error! It's also odd that the finally block doesn't seem to get called in this case.

Can you turn on some logging so we can see what might be happening in the SDK? If you set the DEBUG environment variable to *error that will send logs to stderr. Unfortunately when I try to reproduce this I immediately get a network error from the receiveMessages call, but I haven't tried in Ubuntu yet.

@chradek this was the output.

The program failed at 60 seconds, and then exited 20 seconds later.

pomatti@NT-03024:~/Projects/demo-servicebus$ npm start

> demo-servicebus@1.0.0 start /home/pomatti/Projects/demo-servicebus
> NODE_ENV=dev DEBUG=*error node src/dequeue.js

Waiting for messages: Wed Mar 11 2020 16:41:50 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3' with address 'developer-queue-pomatti' is open? -> undefined +0ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3' with address 'developer-queue-pomatti' is open? -> undefined +1ms
  azure:service-bus:error [connection-1] The receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3' with address 'developer-queue-pomatti' is not open and is not currently establishing itself. Hence let's try to connect. +0ms
  azure:service-bus:error [connection-1] Trying to create receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3' with options {
  azure:service-bus:error   name: 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'developer-queue-pomatti' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +601ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3' with address 'developer-queue-pomatti' has established itself. +185ms
  azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
  azure:service-bus:error     at writeAfterEnd (_stream_writable.js:264:14)
  azure:service-bus:error     at TLSSocket.Writable.write (_stream_writable.js:313:5)
  azure:service-bus:error     at Transport.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/transport.js:56:16)
  azure:service-bus:error     at SaslClient.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/sasl.js:320:26)
  azure:service-bus:error     at Connection.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:471:28)
  azure:service-bus:error     at Connection._write_frame (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:715:10)
  azure:service-bus:error     at Session.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:456:21)
  azure:service-bus:error     at Session._write_flow (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:639:10)
  azure:service-bus:error     at Receiver.link._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/link.js:125:26)
  azure:service-bus:error     at Session._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:611:27) {
  azure:service-bus:error   code: 'ERR_STREAM_WRITE_AFTER_END'
  azure:service-bus:error } +1m
  azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 } +2ms
  azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect. +1ms
  azure:service-bus:error [connection-1] calling detached on client 'developer-queue-pomatti/80d380fa-6fd6-8d4b-ab76-41251300a0ac'. +301ms
  azure:service-bus:error [connection-1] calling detached on batching receiver 'developer-queue-pomatti-356104fb-bd8c-6a45-b5f8-3606632420a3'. +0ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +0ms
  rhea-promise:error [connection-1] The session is open ? -> false +1ms

โ”Œโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”
โ”‚                  npm update check failed                  โ”‚
โ”‚            Try running with sudo or get access            โ”‚
โ”‚           to the local update config store via            โ”‚
โ”‚ sudo chown -R $USER:$(id -gn $USER) /home/pomatti/.config โ”‚
โ””โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”˜
pomatti@NT-03024:~/Projects/demo-servicebus$ 

I switched the timeout on receiveMessages to 10 seconds (instead of the default 60) and the error changed a bit:

pomatti@NT-03024:~/Projects/demo-servicebus$ npm start

> demo-servicebus@1.0.0 start /home/pomatti/Projects/demo-servicebus
> NODE_ENV=dev DEBUG=*error node src/dequeue.js

Waiting for messages: Wed Mar 11 2020 16:50:20 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8' with address 'developer-queue-pomatti' is open? -> undefined +0ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8' with address 'developer-queue-pomatti' is open? -> undefined +1ms
  azure:service-bus:error [connection-1] The receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8' with address 'developer-queue-pomatti' is not open and is not currently establishing itself. Hence let's try to connect. +0ms
  azure:service-bus:error [connection-1] Trying to create receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8' with options {
  azure:service-bus:error   name: 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'developer-queue-pomatti' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +1s
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8' with address 'developer-queue-pomatti' has established itself. +221ms
  azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 } +29s
  azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect. +0ms
  azure:service-bus:error [connection-1] calling detached on client 'developer-queue-pomatti/fea67cad-1424-5c44-9384-33531412cf67'. +302ms
  azure:service-bus:error [connection-1] calling detached on batching receiver 'developer-queue-pomatti-f00ecc1b-acc6-7643-bd86-af724ec3b1b8'. +1ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +0ms
  rhea-promise:error [connection-1] The session is open ? -> false +1ms

โ”Œโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”
โ”‚                  npm update check failed                  โ”‚
โ”‚            Try running with sudo or get access            โ”‚
โ”‚           to the local update config store via            โ”‚
โ”‚ sudo chown -R $USER:$(id -gn $USER) /home/pomatti/.config โ”‚
โ””โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”˜
pomatti@NT-03024:~/Projects/demo-servicebus$ 

@chradek I was running on WSL 2 Ubuntu, so to make sure I installed the program on my Windows and the same problem happened.

The PR #6601 attempted to fix this exact problem when #6065 was logged.

Error (context.error) occurred on the amqp connection

This log gets written as a prefix to the error seen when the underlying AMQP connection fires one of the below events

  • disconnected
  • error
  • protocolError

In the PR #6601, we placed the fix to be triggered when the disconnected event occurs on the AMQP connection.

@chradek, When you are trying to repro the case, I believe the disconnected event is getting fired and we see the package behave as expected.

In @evandropomatti's case I believe one of the other 2 events might be getting fired.

@evandropomatti, To confirm this, can you add rhea:eventsto your debug variable? That should start logging all the events that rhea fires. I want to see what event accompanied the ERR_STREAM_WRITE_AFTER_END error. You may have to remove the 10 sec timeout you are passing in

Hi @ramya-rao-a, here is the output.

Just so you know I'm at home now and got the same results.

pomatti@NT-03024:~/Projects/demo-servicebus$ npm start

> demo-servicebus@1.0.0 start /home/pomatti/Projects/demo-servicebus
> NODE_ENV=dev DEBUG=rhea:events,*error node src/dequeue.js

Waiting for messages: Sat Mar 21 2020 18:39:19 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347' with address 'developer-queue-pomatti' is open? -> undefined +0ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347' with address 'developer-queue-pomatti' is open? -> undefined +1ms
  azure:service-bus:error [connection-1] The receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347' with address 'developer-queue-pomatti' is not open and is not currently establishing itself. Hence let's try to connect. +0ms
  rhea:events [connection-1] Connection got event: connection_open +0ms
  rhea:events [connection-1] Session got event: session_open +36ms
  rhea:events [connection-1] Link got event: sender_open +34ms
  rhea:events [connection-1] Link got event: sender_flow +1ms
  rhea:events [connection-1] Link got event: sendable +1ms
  rhea:events [connection-1] Link got event: receiver_open +37ms
  rhea:events [connection-1] Received disposition for outgoing transfers +157ms
  rhea:events [connection-1] Link got event: accepted +1ms
  rhea:events [connection-1] Link got event: settled +1ms
  rhea:events [connection-1] Link got event: message +7ms
  azure:service-bus:error [connection-1] Trying to create receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347' with options {
  azure:service-bus:error   name: 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'developer-queue-pomatti' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +2s
  rhea:events [connection-1] Session got event: session_open +128ms
  rhea:events [connection-1] Link got event: receiver_open +34ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347' with address 'developer-queue-pomatti' has established itself. +159ms
  rhea:events [connection-1] Connection got event: disconnected +1m
  azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
  azure:service-bus:error     at writeAfterEnd (_stream_writable.js:264:14)
  azure:service-bus:error     at TLSSocket.Writable.write (_stream_writable.js:313:5)
  azure:service-bus:error     at Transport.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/transport.js:56:16)
  azure:service-bus:error     at SaslClient.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/sasl.js:320:26)
  azure:service-bus:error     at Connection.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:471:28)
  azure:service-bus:error     at Connection._write_frame (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:715:10)
  azure:service-bus:error     at Session.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:456:21)
  azure:service-bus:error     at Session._write_flow (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:639:10)
  azure:service-bus:error     at Receiver.link._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/link.js:125:26)
  azure:service-bus:error     at Session._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:611:27) {
  azure:service-bus:error   code: 'ERR_STREAM_WRITE_AFTER_END'
  azure:service-bus:error } +1m
  azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 } +2ms
  azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect. +0ms
  azure:service-bus:error [connection-1] calling detached on client 'developer-queue-pomatti/6197850a-eebf-ba47-9b50-d35d886eb2de'. +300ms
  azure:service-bus:error [connection-1] calling detached on batching receiver 'developer-queue-pomatti-04086d81-0054-5a4d-80fb-0b785d529347'. +1ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +0ms
  rhea-promise:error [connection-1] The session is open ? -> false +1ms

โ”Œโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”
โ”‚                  npm update check failed                  โ”‚
โ”‚            Try running with sudo or get access            โ”‚
โ”‚           to the local update config store via            โ”‚
โ”‚ sudo chown -R $USER:$(id -gn $USER) /home/pomatti/.config โ”‚
โ””โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”˜
pomatti@NT-03024:~/Projects/demo-servicebus$ 

Thanks for the logs @evandropomatti

We can see from the logs that the callback for the disconnected event on the AMQP connection object is indeed being called, and the client reacts as expected by calling the appropriate method on the batching receiver. Please make the below changes and share the logs again so that we can determine why the batching receiver is not responding as expected:

  • Add azure:service-bus:receiverbatching to you debug env variable, so that we can start seeing the logs from the batching receiver
  • It looks like you have some other code that is causing the program to exit, otherwise a non resolving promise in the code you shared above should have resulted in the program never exiting. Please remove the code that is causing the program to exit so that we dont exit before getting all the relevant logs

@chradek, @richardpark-msft, @HarshaNalluru,
Regardless of the findings from above, it might be in our best interest to add a timer to the drain credits code path. This is the only code path I can see where a broken connection can result in the promise not being resolved. Thoughts?

cc @buccfer since we have been discussing this issue offline via emails

@ramya-rao-a

The code that I provided is the only code that I am running. I extracted it to isolate the problem.

I've uploaded the code if you want to try it:
https://github.com/evandropomatti/servicebus-timeout

Here is the output:

pomatti@NT-03024:~/Projects/demo-servicebus$ npm start

> demo-servicebus@1.0.0 start /home/pomatti/Projects/demo-servicebus
> NODE_ENV=dev DEBUG=rhea:events,*error,azure:service-bus:receiverbatching node src/dequeue.js

Waiting for messages: Mon Mar 30 2020 12:04:32 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' with address 'developer-queue-pomatti' is open? -> undefined +0ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad', setting max concurrent calls to 0. +0ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' with address 'developer-queue-pomatti' is open? -> undefined +1ms
  azure:service-bus:error [connection-1] The receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' with address 'developer-queue-pomatti' is not open and is not currently establishing itself. Hence let's try to connect. +0ms
  rhea:events [connection-1] Connection got event: connection_open +0ms
  rhea:events [connection-1] Session got event: session_open +211ms
  rhea:events [connection-1] Link got event: sender_open +107ms
  rhea:events [connection-1] Link got event: sender_flow +14ms
  rhea:events [connection-1] Link got event: sendable +1ms
  rhea:events [connection-1] Link got event: receiver_open +46ms
  rhea:events [connection-1] Received disposition for outgoing transfers +136ms
  rhea:events [connection-1] Link got event: accepted +1ms
  rhea:events [connection-1] Link got event: settled +1ms
  rhea:events [connection-1] Link got event: message +4ms
  azure:service-bus:error [connection-1] Trying to create receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' with options {
  azure:service-bus:error   name: 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'developer-queue-pomatti' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +2s
  rhea:events [connection-1] Session got event: session_open +121ms
  rhea:events [connection-1] Link got event: receiver_open +92ms
  azure:service-bus:error [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' with address 'developer-queue-pomatti' has established itself. +210ms
  azure:service-bus:receiverbatching Promise to create the receiver resolved. Created receiver with name:  developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad +2s
  azure:service-bus:receiverbatching [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad' created with receiver options: {
  azure:service-bus:receiverbatching   name: 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad',
  azure:service-bus:receiverbatching   autoaccept: true,
  azure:service-bus:receiverbatching   rcv_settle_mode: 0,
  azure:service-bus:receiverbatching   snd_settle_mode: 1,
  azure:service-bus:receiverbatching   source: { address: 'developer-queue-pomatti' },
  azure:service-bus:receiverbatching   credit_window: 0,
  azure:service-bus:receiverbatching   onMessage: [Function: onReceiveMessage],
  azure:service-bus:receiverbatching   onError: [Function: onReceiveError],
  azure:service-bus:receiverbatching   onSessionError: [Function: onSessionError],
  azure:service-bus:receiverbatching   onSettled: [Function: onSettled],
  azure:service-bus:receiverbatching   onClose: [Function: onReceiveClose],
  azure:service-bus:receiverbatching   onSessionClose: [Function: onSessionClose]
  azure:service-bus:receiverbatching } +0ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad', adding credit for receiving 10 messages. +1ms
  azure:service-bus:receiverbatching [connection-1] Setting the wait timer for 60 seconds for receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad'. +1ms
  azure:service-bus:receiverbatching [connection-1] Batching Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad'  max wait time in seconds 60 over. +1m
  azure:service-bus:receiverbatching [connection-1] Receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad': Draining leftover credits(10). +8ms
  rhea:events [connection-1] Connection got event: disconnected +1m
  azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
  azure:service-bus:error     at writeAfterEnd (_stream_writable.js:264:14)
  azure:service-bus:error     at TLSSocket.Writable.write (_stream_writable.js:313:5)
  azure:service-bus:error     at Transport.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/transport.js:56:16)
  azure:service-bus:error     at SaslClient.write (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/sasl.js:320:26)
  azure:service-bus:error     at Connection.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:471:28)
  azure:service-bus:error     at Connection._write_frame (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/connection.js:715:10)
  azure:service-bus:error     at Session.output (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:456:21)
  azure:service-bus:error     at Session._write_flow (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:639:10)
  azure:service-bus:error     at Receiver.link._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/link.js:125:26)
  azure:service-bus:error     at Session._process (/home/pomatti/Projects/demo-servicebus/node_modules/rhea/lib/session.js:611:27) {
  azure:service-bus:error   code: 'ERR_STREAM_WRITE_AFTER_END'
  azure:service-bus:error } +1m
  azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 } +8ms
  azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect. +2ms
  azure:service-bus:error [connection-1] calling detached on client 'developer-queue-pomatti/8b1a44c6-1ba2-0440-9782-a0dd5fbaecc1'. +319ms
  azure:service-bus:error [connection-1] calling detached on batching receiver 'developer-queue-pomatti-5ee37280-925c-8640-b59b-66b8ef3c23ad'. +2ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +0ms
  rhea-promise:error [connection-1] The session is open ? -> false +5ms

โ”Œโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”
โ”‚                  npm update check failed                  โ”‚
โ”‚            Try running with sudo or get access            โ”‚
โ”‚           to the local update config store via            โ”‚
โ”‚ sudo chown -R $USER:$(id -gn $USER) /home/pomatti/.config โ”‚
โ””โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”˜
pomatti@NT-03024:~/Projects/demo-servicebus$ 

@evandropomatti We just released an update to the @azure/service-bus library which improves the way we react to connection issues and do the recovery. Can you please try version 1.1.6 and let us know if you are still seeing this issue?

@ramya-rao-a Updated it to 1.1.6 and the program is not terminating now, but there's another problem:

Once the internet connection is back online the receiver is not getting any messages.

Steps to reproduce:

  1. Start the receiver: npm start in my code example
  2. Turn off the internet connection
  3. Wait 1:20 min
  4. Turn on the internet connection
  5. Add messages to the queue: node src/enqueue.js
  6. Messages added to queue are not being consumed

It took me over 15 minutes to write this response and no messages were consumed. The only workaround was to restart the node app.

I made some changes to my repo so you might want to pull:

https://github.com/evandropomatti/servicebus-timeout

image

Or you might just wanna check the log:

$ npm run debug

> servicebus-timeout@1.0.0 debug /home/pomatti/Projects/servicebus-timeout
> NODE_ENV=dev DEBUG=rhea:events,*error,azure:service-bus:receiverbatching node src/dequeue.js

Waiting for messages: Fri Apr 24 2020 18:47:45 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' with address 'inboundqueue' is open? -> undefined +0ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f', setting max concurrent calls to 0. +0ms
  azure:service-bus:error [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' with address 'inboundqueue' is open? -> undefined +0ms
  azure:service-bus:error [connection-1] The receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' with address 'inboundqueue' is not open and is not currently establishing itself. Hence let's try to connect. +1ms
  rhea:events [connection-1] Connection got event: connection_open +0ms
  rhea:events [connection-1] Session got event: session_open +33ms
  rhea:events [connection-1] Link got event: sender_open +29ms
  rhea:events [connection-1] Link got event: sender_flow +1ms
  rhea:events [connection-1] Link got event: sendable +0ms
  rhea:events [connection-1] Link got event: receiver_open +25ms
  rhea:events [connection-1] Received disposition for outgoing transfers +114ms
  rhea:events [connection-1] Link got event: accepted +1ms
  rhea:events [connection-1] Link got event: settled +0ms
  rhea:events [connection-1] Link got event: message +1ms
  azure:service-bus:error [connection-1] Trying to create receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' with options {
  azure:service-bus:error   name: 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'inboundqueue' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +703ms
  rhea:events [connection-1] Session got event: session_open +106ms
  rhea:events [connection-1] Link got event: receiver_open +27ms
  azure:service-bus:error [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' with address 'inboundqueue' has established itself. +132ms
  azure:service-bus:receiverbatching Promise to create the receiver resolved. Created receiver with name:  inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f +836ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f' created with receiver options: {
  azure:service-bus:receiverbatching   name: 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f',
  azure:service-bus:receiverbatching   autoaccept: true,
  azure:service-bus:receiverbatching   rcv_settle_mode: 0,
  azure:service-bus:receiverbatching   snd_settle_mode: 1,
  azure:service-bus:receiverbatching   source: { address: 'inboundqueue' },
  azure:service-bus:receiverbatching   credit_window: 0,
  azure:service-bus:receiverbatching   onMessage: [Function: onReceiveMessage],
  azure:service-bus:receiverbatching   onError: [Function: onReceiveError],
  azure:service-bus:receiverbatching   onSessionError: [Function: onSessionError],
  azure:service-bus:receiverbatching   onSettled: [Function: onSettled],
  azure:service-bus:receiverbatching   onClose: [Function: onReceiveClose],
  azure:service-bus:receiverbatching   onSessionClose: [Function: onSessionClose]
  azure:service-bus:receiverbatching } +0ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f', adding credit for receiving 10 messages. +1ms
  azure:service-bus:receiverbatching [connection-1] Setting the wait timer for 60 seconds for receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f'. +0ms
  azure:service-bus:receiverbatching [connection-1] Batching Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f'  max wait time in seconds 60 over. +1m
  azure:service-bus:receiverbatching [connection-1] Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f': Draining leftover credits(10). +0ms
  rhea:events [connection-1] Connection got event: disconnected +1m
  azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
  azure:service-bus:error     at writeAfterEnd (_stream_writable.js:265:14)
  azure:service-bus:error     at TLSSocket.Writable.write (_stream_writable.js:314:5)
  azure:service-bus:error     at Transport.write (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/transport.js:56:16)
  azure:service-bus:error     at SaslClient.write (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/sasl.js:320:26)
  azure:service-bus:error     at Connection.output (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/connection.js:492:28)
  azure:service-bus:error     at Connection._write_frame (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/connection.js:736:10)
  azure:service-bus:error     at Session.output (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/session.js:456:21)
  azure:service-bus:error     at Session._write_flow (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/session.js:639:10)
  azure:service-bus:error     at Receiver.link._process (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/link.js:125:26)
  azure:service-bus:error     at Session._process (/home/pomatti/Projects/servicebus-timeout/node_modules/rhea/lib/session.js:611:27) {
  azure:service-bus:error   code: 'ERR_STREAM_WRITE_AFTER_END'
  azure:service-bus:error } +1m
  rhea-promise:error [connection-1] The connection is open ? -> false +0ms
  azure:service-bus:error The connection "connection-1" has been updated to "connection-2". +3ms
  azure:service-bus:error [connection-2] state: { wasConnectionCloseCalled: false, numClients: 1 } +1ms
  azure:service-bus:error [connection-2] connection.close() was not called from the sdk and there were some clients. We should reconnect. +0ms
  azure:service-bus:error [connection-2] calling detached on client 'inboundqueue/078089f7-810f-774a-8d74-36b1c86c82d6'. +301ms
  azure:service-bus:error [connection-2] calling detached on batching receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f'. +0ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +304ms
  rhea-promise:error [connection-1] The session is open ? -> false +0ms

Thanks @evandropomatti

I still cannot replicate the issue using your repo. Around the 1 minute mark, I get Error: getaddrinfo ENOTFOUND error thrown for the current receiveMessages call and then for every subsequent call right away. When I enable my wifi, I start receiving messages again. This could be a difference in behavior of the underlying libraries based on the OS being used. I tried on a Mac, @chradek I believe used Windows and you are on Ubuntu.

But, there was something in the logs you shared which I missed earlier which is that the disconnect event is being fired after the request to drain credits which is after the 60 second timeout.

Batching Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f'  max wait time in seconds 60 over. +1m
Receiver 'inboundqueue-2422dac5-4f68-c44e-a838-70114ee5d45f': Draining leftover credits(10). +0ms
Connection got event: disconnected +1m
Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end

And I can see the place in our code where we are missing to resolve/reject the promise. I have created a draft PR to start the discussion in the team on a potential solution for this. Please see #8552. We will report back when we have an update.

@ramya-rao-a I tried on Windows and the problem of the process terminating is still happening. Here are the logs.

PS C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout> $env:NODE_ENV="dev"
PS C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout> $env:DEBUG="rhea:events,*error,azure:service-bus:receiverbatching"
PS C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout> node src/dequeue.js
Waiting for messages: Mon Apr 27 2020 14:25:56 GMT-0300 (Brasilia Standard Time)
  azure:service-bus:error [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' with address 'inbound-queue' is open? -> undefined +0ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1', setting max concurrent calls to 0. +0ms
  azure:service-bus:error [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' with address 'inbound-queue' is open? -> undefined +2ms
  azure:service-bus:error [connection-1] The receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' with address 'inbound-queue' is not open and is not currently establishing itself. Hence let's try to connect. +0ms
  rhea:events [connection-1] Connection got event: connection_open +0ms
  rhea:events [connection-1] Session got event: session_open +44ms
  rhea:events [connection-1] Link got event: sender_open +49ms
  rhea:events [connection-1] Link got event: sender_flow +7ms
  rhea:events [connection-1] Link got event: sendable +1ms
  rhea:events [connection-1] Link got event: receiver_open +42ms
  rhea:events [connection-1] Received disposition for outgoing transfers +118ms
  rhea:events [connection-1] Link got event: accepted +1ms
  rhea:events [connection-1] Link got event: settled +1ms
  rhea:events [connection-1] Link got event: message +9ms
  azure:service-bus:error [connection-1] Trying to create receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' with options {
  azure:service-bus:error   name: 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1',
  azure:service-bus:error   autoaccept: true,
  azure:service-bus:error   rcv_settle_mode: 0,
  azure:service-bus:error   snd_settle_mode: 1,
  azure:service-bus:error   source: { address: 'inbound-queue' },
  azure:service-bus:error   credit_window: 0,
  azure:service-bus:error   onMessage: [Function: onReceiveMessage],
  azure:service-bus:error   onError: [Function: onReceiveError],
  azure:service-bus:error   onSessionError: [Function: onSessionError],
  azure:service-bus:error   onSettled: [Function: onSettled],
  azure:service-bus:error   onClose: [Function: onReceiveClose],
  azure:service-bus:error   onSessionClose: [Function: onSessionClose]
  azure:service-bus:error } +763ms
  rhea:events [connection-1] Session got event: session_open +114ms
  rhea:events [connection-1] Link got event: receiver_open +74ms
  azure:service-bus:error [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' with address 'inbound-queue' has established itself. +187ms
  azure:service-bus:receiverbatching Promise to create the receiver resolved. Created receiver with name:  inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1 +951ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1' created with receiver options: {
  azure:service-bus:receiverbatching   name: 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1',
  azure:service-bus:receiverbatching   autoaccept: true,
  azure:service-bus:receiverbatching   rcv_settle_mode: 0,
  azure:service-bus:receiverbatching   snd_settle_mode: 1,
  azure:service-bus:receiverbatching   source: { address: 'inbound-queue' },
  azure:service-bus:receiverbatching   credit_window: 0,
  azure:service-bus:receiverbatching   onMessage: [Function: onReceiveMessage],
  azure:service-bus:receiverbatching   onError: [Function: onReceiveError],
  azure:service-bus:receiverbatching   onSessionError: [Function: onSessionError],
  azure:service-bus:receiverbatching   onSettled: [Function: onSettled],
  azure:service-bus:receiverbatching   onClose: [Function: onReceiveClose],
  azure:service-bus:receiverbatching   onSessionClose: [Function: onSessionClose]
  azure:service-bus:receiverbatching } +1ms
  azure:service-bus:receiverbatching [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1', adding credit for receiving 10 messages. +4ms
  azure:service-bus:receiverbatching [connection-1] Setting the wait timer for 60 seconds for receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1'. +2ms
  azure:service-bus:receiverbatching [connection-1] Batching Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1'  max wait time in seconds 60 over. +1m
  azure:service-bus:receiverbatching [connection-1] Receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1': Draining leftover credits(10). +2ms
  rhea:events [connection-1] Connection got event: disconnected +1m
  azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
  azure:service-bus:error     at writeAfterEnd (_stream_writable.js:264:14)
  azure:service-bus:error     at TLSSocket.Writable.write (_stream_writable.js:313:5)
  azure:service-bus:error     at Transport.write (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\transport.js:56:16)
  azure:service-bus:error     at SaslClient.write (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\sasl.js:320:26)
  azure:service-bus:error     at Connection.output (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\connection.js:492:28)
  azure:service-bus:error     at Connection._write_frame (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\connection.js:736:10)
  azure:service-bus:error     at Session.output (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\session.js:456:21)
  azure:service-bus:error     at Session._write_flow (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\session.js:639:10)
  azure:service-bus:error     at Receiver.link._process (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\link.js:125:26)
  azure:service-bus:error     at Session._process (C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout\node_modules\rhea\lib\session.js:611:27) {
  azure:service-bus:error   code: 'ERR_STREAM_WRITE_AFTER_END'
  azure:service-bus:error } +1m
  rhea-promise:error [connection-1] The connection is open ? -> false +0ms
  azure:service-bus:error The connection "connection-1" has been updated to "connection-2". +8ms
  azure:service-bus:error [connection-2] state: { wasConnectionCloseCalled: false, numClients: 1 } +1ms
  azure:service-bus:error [connection-2] connection.close() was not called from the sdk and there were some clients. We should reconnect. +1ms
  azure:service-bus:error [connection-2] calling detached on client 'inbound-queue/f1f8a708-1bcf-754a-97e3-e4e49a67a6cf'. +306ms
  azure:service-bus:error [connection-2] calling detached on batching receiver 'inbound-queue-aa3423cf-193c-f443-86ee-0ae390dc14b1'. +2ms
  rhea-promise:error [connection-1] The receiver is open ? -> false +312ms
  rhea-promise:error [connection-1] The session is open ? -> false +1ms
events.js:288
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at TLSWrap.onStreamRead (internal/stream_base_commons.js:205:27)
Emitted 'error' event on TLSSocket instance at:
    at emitErrorNT (internal/streams/destroy.js:92:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
    at processTicksAndRejections (internal/process/task_queues.js:84:21) {
  errno: 'ECONNRESET',
  code: 'ECONNRESET',
  syscall: 'read'
}
PS C:\Users\evandro.pomatti.HBSISNET\Projects\servicebus-timeout>

Thanks for your patience @evandropomatti

We just released another update for the @azure/service-bus package with version 1.1.7 which should cover the problem you are seeing here. Checkout the changelog for 1.1.7 for more details.

Please give the latest version a try and let us know if you still see any issues

@ramya-rao-a I tested on Ubuntu 20.04 and Windows 10 and the client operation was maintained after connectivity loss. Great job team!

There's one more thing:

While testing (normal, no debug logs) I found one minor adjustment that the team might want to take a look at, while you're at it.

On Linux, when the connectivity is lost, an error message is printed from time to time. That's ok.

But on Windows the client dumps an absurd amount of the same error message. It can quickly run through any log and rotate it, or making it difficult for anyone to follow the logs. I think the behavior on Windows should be the same on Linux. It is almost like a constant loop.

Like I said minor, but it's a thing.

image