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
- README.md
- source code documentation
- SDK API docs on https://docs.microsoft.com
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:
- Start the code to receive messages
- Turn-off internet connection
- Enqueue a message in the queue
- Await 10 minutes
- 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.
@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:
- I start the program and it locks at the
receiveMessages
operation. - I turn off the Wi-Fi
- 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:events
to 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
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:
- Start the receiver:
npm start
in my code example - Turn off the internet connection
- Wait 1:20 min
- Turn on the internet connection
- Add messages to the queue:
node src/enqueue.js
- 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
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.