Rascal reestabilishes connection and subscription sessions but handlers are not being executed
pbsf opened this issue · 4 comments
pbsf commented
First of all, thanks for the awesome library!
We're seeing issues with handlers after reconnecting from broker errors. What is currently happening is that the reconnection works as can be seen on the RabbitMQ dashboard and logs, but the subscription handlers are not being executed and the unacked messages log keep increasing as seen below:
rascal:Subscription Received message: df259ee1-7654-4273-9fe2-c9defe6878f6 from queue: MyQueue +8m
rascal:SubscriberSession Channel: 134e7341-435c-42f2-9943-23dc8da95394 has 1 unacknowledged messages +2ms
rascal:Subscription Received message: 965e3bbc-e637-42f1-8978-d50ab4060baf from queue: MyQueue +3ms
rascal:SubscriberSession Channel: 134e7341-435c-42f2-9943-23dc8da95394 has 2 unacknowledged messages +2ms
...
The fix we are doing to avoid the issue above is to kill our application so that it will restart and reconnect to Rabbit and the handlers will work as expected:
const obsBroker = from(BrokerAsPromised.create(withDefaultConfig(brokerConfig)));
obsBroker.subscribe(broker => {
broker.on('error', function (err) {
Logger.error('Broker error', err);
// Workaround below:
setTimeout(function(){ process.exit(1); }, 5000);
});
But from reading the documentation it doesn't look like we would need the workaround above. Any ideas on what we could be missing?
Our brokerConfig is as follows:
vhosts: {
'/': {
queues: {
'MyQueue': { assert: false, check: true }
},
subscriptions: {
'MySub': { queue: 'MyQueue' }
}
}
}
Rascal version: 14.4.0
RabbitMQ version: 3.9.15
cressie176 commented
Hi @pbsf,
This is very odd. The subscriptions should automatically recover and invoke the on-message handler. I'll see if I can reproduce. Can you tell me what version of node.js you are using please?
cressie176 commented
I've downloaded and rabbitmq:3.9.15 using the following command
docker run -d --name rascal-rabbitmq -p 5672:5672 -p 15672:15672 rabbitmq:3.9.15-management
Then started examples/simple which published and consumes messages containing the text ${date}: hello world
nvm use 18
Now using node v18.1.0 (npm v8.8.0)
DEBUG='rascal:SubscriberSession,rascal:Subscription' node index.js
I allow the application to run for a bit, then pause the container and wait for the heartbeat timeout. Then I unpause the container, and see the messages start being published and consumed again. Here's the output. You can see the subscriber recovering just fine. Any idea what could be different? What type of broker error did you experience?
rascal:Subscription Initialising subscription: demo_sub +0ms
rascal:Subscription Initialising subscription: /demo_q +1ms
rascal:Subscription Subscribing to queue: demo_q +2ms
rascal:SubscriberSession Opening subscriber session: amq.ctag-IZnDNbLISKeQ_FK30Np84w on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:Subscription Received message: 31e15fcd-fd42-48eb-a6c7-9a5406658948 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:46:44.598Z: hello world
rascal:SubscriberSession Acknowledging message: 31e15fcd-fd42-48eb-a6c7-9a5406658948 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +5ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: c6f6f5b3-6f2d-4785-879b-c2b18577a543 from queue: demo_q +995ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +990ms
2022-05-10T22:46:45.599Z: hello world
rascal:SubscriberSession Acknowledging message: c6f6f5b3-6f2d-4785-879b-c2b18577a543 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +1ms
rascal:Subscription Received message: 85225f6d-b675-4517-870c-40c476bcddbb from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:46:46.601Z: hello world
rascal:SubscriberSession Acknowledging message: 85225f6d-b675-4517-870c-40c476bcddbb on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 03956c7a-c756-4b64-a66f-bd47c026f472 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:46:47.602Z: hello world
rascal:SubscriberSession Acknowledging message: 03956c7a-c756-4b64-a66f-bd47c026f472 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
Error: Timedout after 10000ms waiting for broker to confirm publication to: demo_ex
at Timeout._onTimeout (/Users/steve/Development/guidesmiths/rascal/lib/amqp/Publication.js:216:10)
at listOnTimeout (node:internal/timers:564:17)
at process.processTimers (node:internal/timers:507:7) added623-a87c-463f-9f20-45aea20de39c
TimeoutError: ResourceRequest timed out
at ResourceRequest._fireTimeout (/Users/steve/Development/guidesmiths/rascal/node_modules/generic-pool/lib/ResourceRequest.js:62:17)
at Timeout.bound (/Users/steve/Development/guidesmiths/rascal/node_modules/generic-pool/lib/ResourceRequest.js:8:15)
at listOnTimeout (node:internal/timers:564:17)
at process.processTimers (node:internal/timers:507:7) 2517a13a-4b6a-4996-b525-09d6ff58567f
rascal:Subscription Received message: added623-a87c-463f-9f20-45aea20de39c from queue: demo_q +18s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +18s
2022-05-10T22:46:48.605Z: hello world
rascal:SubscriberSession Acknowledging message: added623-a87c-463f-9f20-45aea20de39c on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: aa35cba6-b1f7-4dbb-b114-635d0fcd6dc7 from queue: demo_q +3ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +3ms
2022-05-10T22:46:50.612Z: hello world
rascal:SubscriberSession Acknowledging message: aa35cba6-b1f7-4dbb-b114-635d0fcd6dc7 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: d25a923a-2d06-4405-ba04-4f4ef64b568b from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:46:51.616Z: hello world
rascal:SubscriberSession Acknowledging message: d25a923a-2d06-4405-ba04-4f4ef64b568b on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: f898bcda-4343-43a5-8d37-64a5a3d4a597 from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:46:52.620Z: hello world
rascal:SubscriberSession Acknowledging message: f898bcda-4343-43a5-8d37-64a5a3d4a597 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 4cee50c0-956e-4652-ae74-e8d5c24f81c4 from queue: demo_q +1ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1ms
2022-05-10T22:46:53.620Z: hello world
rascal:SubscriberSession Acknowledging message: 4cee50c0-956e-4652-ae74-e8d5c24f81c4 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 05c7fb4a-f236-45db-9221-5de7e0a7fc2c from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:46:54.623Z: hello world
rascal:SubscriberSession Acknowledging message: 05c7fb4a-f236-45db-9221-5de7e0a7fc2c on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 269db732-87ab-4697-8bc8-f376b4dda7b0 from queue: demo_q +1ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1ms
2022-05-10T22:46:55.628Z: hello world
rascal:SubscriberSession Acknowledging message: 269db732-87ab-4697-8bc8-f376b4dda7b0 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: fc487347-3f9c-453b-9bdf-270e34c4f8cc from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:46:56.632Z: hello world
rascal:SubscriberSession Acknowledging message: fc487347-3f9c-453b-9bdf-270e34c4f8cc on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: c13e6786-b520-4b1d-beaf-9276e47bbde7 from queue: demo_q +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +0ms
2022-05-10T22:46:57.632Z: hello world
rascal:SubscriberSession Acknowledging message: c13e6786-b520-4b1d-beaf-9276e47bbde7 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 47e48e9c-e6dd-4da4-9a3b-26dab86d97a2 from queue: demo_q +1ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1ms
2022-05-10T22:46:58.633Z: hello world
rascal:SubscriberSession Acknowledging message: 47e48e9c-e6dd-4da4-9a3b-26dab86d97a2 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: bdd0f69e-5ab7-416c-8299-fe2aa5e1048e from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:46:59.636Z: hello world
rascal:SubscriberSession Acknowledging message: bdd0f69e-5ab7-416c-8299-fe2aa5e1048e on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 52d3bc26-0107-4f77-8940-6ab09f42e860 from queue: demo_q +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +0ms
2022-05-10T22:47:00.640Z: hello world
rascal:SubscriberSession Acknowledging message: 52d3bc26-0107-4f77-8940-6ab09f42e860 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +1ms
rascal:Subscription Received message: bac1d139-f412-4bbe-a592-e328c896d65e from queue: demo_q +1ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +0ms
2022-05-10T22:47:01.645Z: hello world
rascal:SubscriberSession Acknowledging message: bac1d139-f412-4bbe-a592-e328c896d65e on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 2915666c-4c9a-4498-a955-6848092e3d09 from queue: demo_q +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +0ms
2022-05-10T22:47:02.645Z: hello world
rascal:SubscriberSession Acknowledging message: 2915666c-4c9a-4498-a955-6848092e3d09 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 4fc0e95f-ac03-4830-9722-c05bb948cdfe from queue: demo_q +2ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +2ms
2022-05-10T22:47:03.649Z: hello world
rascal:SubscriberSession Acknowledging message: 4fc0e95f-ac03-4830-9722-c05bb948cdfe on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 04e268de-cc67-4642-9fe1-cd46d62050c8 from queue: demo_q +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +0ms
2022-05-10T22:47:04.649Z: hello world
rascal:SubscriberSession Acknowledging message: 04e268de-cc67-4642-9fe1-cd46d62050c8 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 7cbae64c-f940-41a2-8e23-9ce581806ee5 from queue: demo_q +103ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +103ms
2022-05-10T22:47:05.652Z: hello world
rascal:SubscriberSession Acknowledging message: 7cbae64c-f940-41a2-8e23-9ce581806ee5 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: ad4ba95d-bb4c-4510-ba1d-7134d1fca3ba from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:06.656Z: hello world
rascal:SubscriberSession Acknowledging message: ad4ba95d-bb4c-4510-ba1d-7134d1fca3ba on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 0651b787-1fab-4947-805a-009d38816eff from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:07.656Z: hello world
rascal:SubscriberSession Acknowledging message: 0651b787-1fab-4947-805a-009d38816eff on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: ff4a801a-65fe-4d3d-a393-66da2de86678 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:08.660Z: hello world
rascal:SubscriberSession Acknowledging message: ff4a801a-65fe-4d3d-a393-66da2de86678 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: fc2956f3-82a3-44b9-980c-e3b4ebae3fc5 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:09.661Z: hello world
rascal:SubscriberSession Acknowledging message: fc2956f3-82a3-44b9-980c-e3b4ebae3fc5 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: c27830c5-e426-4dd6-86af-019ff2a91802 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:10.665Z: hello world
rascal:SubscriberSession Acknowledging message: c27830c5-e426-4dd6-86af-019ff2a91802 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
rascal:Subscription Received message: 6714f224-c160-46a8-be45-326e0127e899 from queue: demo_q +1s
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 1 unacknowledged messages +1s
2022-05-10T22:47:11.669Z: hello world
rascal:SubscriberSession Acknowledging message: 6714f224-c160-46a8-be45-326e0127e899 on channel: 6637407d-31ef-4a98-8043-e56a846bd795 +0ms
rascal:SubscriberSession Channel: 6637407d-31ef-4a98-8043-e56a846bd795 has 0 unacknowledged messages +0ms
cressie176 commented
Maybe try adding in some extra debug into this function
cressie176 commented
@pbsf any update?