Check if connection is live
co-sic opened this issue · 12 comments
I want to be able to check at certain time intervals if the broker is connected to the queue but i could not find a way to do that. Is there an easy way to do that? We had some problems with the connection to the queue where rascal was not able to reconnect and there was no error thrown and we would like to integrate the rabbitmq connection into the health check of our container, so it can be restarted if there is none.
Hi @co-sic,
Unfortunately there's no connection check (e.g. a ping) in the AMQP protocol. Potentially Rascal could include an option to "check" the default exchange at a regular interval, however I don't see what value this could give beyond RabbitMQ's existing heartbeat functionality (which arguably is better implemented through TCP Keep Alive anyway).
That said, whenever a connection errors, or is detected as dropped, amqplib should emit an error/close event. Rascal can automatically recover from these, but will still emit an error. It has a similar feature for queue consumers. This functionality has been stable for quite some time, and while it's possible there's a bug somewhere, in the majority of reports, usually there's something wrong with the application code, rather than Rascal, amqplib or RabbitMQ. If you are able to reproduce the issue in a simple test project I can take a look.
Regarding incorporating connection status into a heathcheck - since Rascal is designed to recover connections if possible, this shouldn't be necessary, but you could certainly include some logic in your error event handler. I can also investigate adding a "stats" parameter to the error event emitter to include the retry statistics. Another approach you could consider, would be both publishing and subscribing to a healthcheck queue. If you published a message every second, but did not receive a message for 2 seconds, you would know that something was wrong. If you were to take this approach then consider setting the max-length parameter to 1 in the queue definition.
Thanks for your detailed answer. The error only happens very randomly, we had the problem now 2 times in the last month. We will try to reproduce it and if we can, i open a new issue. But we also thought about your suggestion of a healthcheck queue, i we think we really need it, we will implement that.
So we just encountered the error again:
at processTicksAndRejections (node:internal/process/task_queues:82:21)
at emitReadable_ (node:internal/streams/readable:578:12)
at TLSSocket.emit (node:domain:475:12)
at TLSSocket.emit (node:events:390:28)
at Object.onceWrapper (node:events:509:28)
at TLSSocket.recv (/home/node/app/node_modules/amqplib/lib/connection.js:499:12)
at /home/node/app/node_modules/amqplib/lib/connection.js:160:12
at /home/node/app/node_modules/amqplib/lib/connection.js:166:32
at onOpenOk (/home/node/app/node_modules/amqplib/lib/connection.js:254:5)
at succeed (/home/node/app/node_modules/amqplib/lib/connection.js:272:13)
Error: Unexpected close
11-30-2021 14:27:04 [error]: undefined uncaughtException: Unexpected close
we were wondering why our on error callback for the subscription and/or the broker was not triggered. We check the amqplib library for Unexpected close and found this in the connection.js:
function succeed(ok) {
self.stream.removeListener('end', endWhileOpening);
self.stream.removeListener('error', endWhileOpening);
self.stream.on('error', self.onSocketError.bind(self));
self.stream.on('end', self.onSocketError.bind(
self, new Error('Unexpected close')));
self.on('frameError', self.onSocketError.bind(self));
self.acceptLoop();
openCallback(null, ok);
}
So is this on 'end' event catched/handled by rascal? We are a bit confused how that error is handled.
The amqplib 'end' event is translated to an 'error' event here. After the connection is acquired, rascal attaches error handlers to the connection to intercept the error event, however since it's also important to bring them to the application's attention, rascal re-emits them from the Vhost instance. All events are forwarded from the Vhost to the broker, so you will need to attach error handlers to the broker instance to avoid them crashing your application. My guess is that somehow you are missing this step. There's some documentation about this here.
export async function initializeBroker(options?: {
onError?: (err: any, connection: { vhost: string; connectionUrl: string }) => void;
}) {
const broker = await Broker.create(BrokerConfiguration);
broker.on('error', (err, { vhost, connectionUrl }) => {
log({
level: 'error',
message: err.message,
label: `amqp-message-queues.broker`,
});
options?.onError?.(err, { vhost, connectionUrl });
});
return broker;
}
this is the first function i call, before initializing the subscriptions. And we still get the error. Currently it is occuring always 1 minute after startup is finished, and the last log from rascal was printed.
The only thing I see missing is a try / catch surrounding the initializeBroker function body. If Rascal never connects it will yield an error rather than emitting one. Given that the it is always occurring 1 minute after startup is finished, then I wonder if there's a socket timeout issue, and the connection is never actually successful.
If this was the case though, startup wouldn't have finished.
Can you enable debug (by setting DEBUG to rascal:*) so we can see more clearly what's happening
We have a try catch in the main app, there this function is called. I already enabled debug with rascal, here are the logs from app startup to the connection error:
at processTicksAndRejections (node:internal/process/task_queues:82:21)
at emitReadable_ (node:internal/streams/readable:578:12)
at TLSSocket.emit (node:domain:475:12)
at TLSSocket.emit (node:events:390:28)
at Object.onceWrapper (node:events:509:28)
at TLSSocket.recv (/home/node/app/node_modules/amqplib/lib/connection.js:499:12)
at /home/node/app/node_modules/amqplib/lib/connection.js:160:12
at /home/node/app/node_modules/amqplib/lib/connection.js:166:32
at onOpenOk (/home/node/app/node_modules/amqplib/lib/connection.js:254:5)
at succeed (/home/node/app/node_modules/amqplib/lib/connection.js:272:13)
Error: Unexpected close
12-01-2021 08:30:30 [error]: undefined uncaughtException: Unexpected close
at processTicksAndRejections (node:internal/process/task_queues:82:21)
at emitReadable_ (node:internal/streams/readable:578:12)
at TLSSocket.emit (node:domain:475:12)
at TLSSocket.emit (node:events:390:28)
at Object.onceWrapper (node:events:509:28)
at TLSSocket.recv (/home/node/app/node_modules/amqplib/lib/connection.js:499:12)
at /home/node/app/node_modules/amqplib/lib/connection.js:160:12
at /home/node/app/node_modules/amqplib/lib/connection.js:166:32
at onOpenOk (/home/node/app/node_modules/amqplib/lib/connection.js:254:5)
at succeed (/home/node/app/node_modules/amqplib/lib/connection.js:272:13)
Error: Unexpected close
12-01-2021 08:30:30 [error]: invoice-service.undefined uncaughtException: Unexpected close
2021-12-01T08:30:30.561Z rascal:Vhost Handling connection error: Unexpected close initially from connection: 4468d317-fd4f-4dd7-ae29-bf5be41455ed, amqps://admin:***@b-bae9c12a-0c61-4e0a-a6ca-a14deb85ca58.mq.eu-central-1.amazonaws.com:5671?heartbeat=10&connection_timeout=10000&channelMax=100
2021-12-01T08:29:35.047Z rascal:SubscriberSession Opening subscriber session: amq.ctag-Nw1ZJDi6ENCPpsPxtSJIwQ on channel: ad4e41d3-731f-4bec-a738-59657849b4bb
2021-12-01T08:29:35.043Z rascal:Vhost Created confirm channel: ad4e41d3-731f-4bec-a738-59657849b4bb from connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:35.042Z rascal:SubscriberSession Opening subscriber session: amq.ctag-d9lk6sVsAyGuuR5pVGdXHA on channel: 07f16a3e-aa94-486c-ade7-ec1c88ca8d2f
2021-12-01T08:29:35.037Z rascal:Vhost Created confirm channel: 07f16a3e-aa94-486c-ade7-ec1c88ca8d2f from connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:35.035Z rascal:SubscriberSession Opening subscriber session: amq.ctag-UoGkVBNSrT9_xMEF2Y68Hw on channel: d1f300a9-924b-40d8-b6d1-dba732b49966
2021-12-01T08:29:35.029Z rascal:Vhost Created confirm channel: d1f300a9-924b-40d8-b6d1-dba732b49966 from connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:35.028Z rascal:SubscriberSession Opening subscriber session: amq.ctag-T64N0Yn8beeRKZHWfvlKZA on channel: c09a24f0-30b9-468d-a0a6-76eabde54609
2021-12-01T08:29:35.014Z rascal:Vhost Created confirm channel: c09a24f0-30b9-468d-a0a6-76eabde54609 from connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:35.007Z rascal:Vhost Requested channel. Outstanding channel requests: 3
2021-12-01T08:29:35.007Z rascal:Subscription Subscribing to queue: billing_order_queue
2021-12-01T08:29:35.006Z rascal:Vhost Requested channel. Outstanding channel requests: 2
2021-12-01T08:29:35.006Z rascal:Subscription Subscribing to queue: billing_offer_queue
2021-12-01T08:29:35.006Z rascal:Vhost Requested channel. Outstanding channel requests: 1
2021-12-01T08:29:35.006Z rascal:Subscription Subscribing to queue: billing_credit_queue
2021-12-01T08:29:35.005Z rascal:Vhost Requested channel. Outstanding channel requests: 1
2021-12-01T08:29:35.005Z rascal:Subscription Subscribing to queue: billing_invoice_queue
2021-12-01T08:29:34.926Z rascal:Subscription Initialising subscription: /billing_order_queue
2021-12-01T08:29:34.926Z rascal:Subscription Initialising subscription: /billing_offer_queue
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: /billing_credit_queue
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: /billing_invoice_queue
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: billing_order_subscription
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: billing_offer_subscription
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: billing_credit_subscription
2021-12-01T08:29:34.925Z rascal:Subscription Initialising subscription: billing_invoice_subscription
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /billing_order_queue
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /billing_offer_queue
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /billing_credit_queue
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /billing_invoice_queue
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: /billing_exchange
2021-12-01T08:29:34.924Z rascal:Publication Initialising publication: billing_order_publication
2021-12-01T08:29:34.923Z rascal:Publication Initialising publication: billing_offer_publication
2021-12-01T08:29:34.923Z rascal:Publication Initialising publication: billing_credit_publication
2021-12-01T08:29:34.923Z rascal:Publication Initialising publication: billing_invoice_publication
2021-12-01T08:29:34.922Z rascal:Vhost vhost: / was initialised with connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:34.922Z rascal:Vhost Creating confirm channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true, acquireTimeoutMillis: 15000, destroyTimeoutMillis: 1000 }
2021-12-01T08:29:34.921Z rascal:Vhost Creating regular channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true, acquireTimeoutMillis: 15000, destroyTimeoutMillis: 1000 }
2021-12-01T08:29:34.910Z rascal:tasks:closeChannel Closing channel
2021-12-01T08:29:34.908Z rascal:tasks:applyBindings Binding queue: billing_order_queue to exchange: billing_exchange with binding key: billing.order
2021-12-01T08:29:34.906Z rascal:tasks:applyBindings Binding queue: billing_offer_queue to exchange: billing_exchange with binding key: billing.offer
2021-12-01T08:29:34.903Z rascal:tasks:applyBindings Binding queue: billing_credit_queue to exchange: billing_exchange with binding key: billing.credit
2021-12-01T08:29:34.874Z rascal:tasks:applyBindings Binding queue: billing_invoice_queue to exchange: billing_exchange with binding key: billing.invoice
2021-12-01T08:29:34.872Z rascal:tasks:assertQueues Asserting queue: billing_order_queue
2021-12-01T08:29:34.870Z rascal:tasks:assertQueues Asserting queue: billing_offer_queue
2021-12-01T08:29:34.868Z rascal:tasks:assertQueues Asserting queue: billing_credit_queue
2021-12-01T08:29:34.866Z rascal:tasks:assertQueues Asserting queue: billing_invoice_queue
2021-12-01T08:29:34.863Z rascal:tasks:assertExchanges Asserting exchange: billing_exchange
2021-12-01T08:29:34.859Z rascal:tasks:createChannel Creating channel
2021-12-01T08:29:34.859Z rascal:tasks:createConnection Obtained connection: f7bf32f5-0c96-4445-841f-60c8ab51d99b
2021-12-01T08:29:34.730Z rascal:tasks:createConnection Connecting to broker using url: amqps://admin:***@b-bae9c12a-0c61-4e0a-a6ca-a14deb85ca58.mq.eu-central-1.amazonaws.com:5671?heartbeat=10&connection_timeout=10000&channelMax=100
2021-12-01T08:29:34.729Z rascal:Vhost Initialising vhost: /
2021-12-01T08:29:34.728Z rascal:Broker Initialising broker
2021-12-01T08:29:34.723Z rascal:config:configure Configuring counter: stub
2021-12-01T08:29:34.723Z rascal:config:configure Configuring subscription: /billing_order_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: /billing_offer_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: /billing_credit_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: /billing_invoice_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: billing_order_subscription
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: billing_offer_subscription
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: billing_credit_subscription
2021-12-01T08:29:34.722Z rascal:config:configure Configuring subscription: billing_invoice_subscription
2021-12-01T08:29:34.722Z rascal:config:configure Configuring publication: /billing_order_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring publication: /billing_offer_queue
2021-12-01T08:29:34.722Z rascal:config:configure Configuring publication: /billing_credit_queue
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: /billing_invoice_queue
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: /
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: /billing_exchange
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: billing_order_publication
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: billing_offer_publication
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: billing_credit_publication
2021-12-01T08:29:34.721Z rascal:config:configure Configuring publication: billing_invoice_publication
2021-12-01T08:29:34.720Z rascal:config:configure Configuring subscription: billing_order_subscription
2021-12-01T08:29:34.720Z rascal:config:configure Configuring subscription: billing_offer_subscription
2021-12-01T08:29:34.720Z rascal:config:configure Configuring subscription: billing_credit_subscription
2021-12-01T08:29:34.720Z rascal:config:configure Configuring subscription: billing_invoice_subscription
2021-12-01T08:29:34.720Z rascal:config:configure Configuring publication: billing_order_publication
2021-12-01T08:29:34.720Z rascal:config:configure Configuring publication: billing_offer_publication
2021-12-01T08:29:34.720Z rascal:config:configure Configuring publication: billing_credit_publication
2021-12-01T08:29:34.719Z rascal:config:configure Configuring publication: billing_invoice_publication
2021-12-01T08:29:34.719Z rascal:config:configure Configuring binding: contract_invoice_binding_order
2021-12-01T08:29:34.719Z rascal:config:configure Configuring binding: contract_invoice_binding_offer
2021-12-01T08:29:34.719Z rascal:config:configure Configuring binding: contract_invoice_binding_credit
2021-12-01T08:29:34.719Z rascal:config:configure Configuring binding: contract_invoice_binding_invoice
2021-12-01T08:29:34.715Z rascal:config:configure Configuring queue: billing_order_queue
2021-12-01T08:29:34.715Z rascal:config:configure Configuring queue: billing_offer_queue
2021-12-01T08:29:34.715Z rascal:config:configure Configuring queue: billing_credit_queue
2021-12-01T08:29:34.715Z rascal:config:configure Configuring queue: billing_invoice_queue
2021-12-01T08:29:34.714Z rascal:config:configure Configuring exchange:
2021-12-01T08:29:34.714Z rascal:config:configure Configuring exchange: billing_exchange
2021-12-01T08:29:34.708Z rascal:config:configure Configuring vhost: /
just for reference, here ist the code there this is called:
import { server } from 'apollo';
import cookieParser from 'cookie-parser';
import 'dotenv/config';
import express from 'express';
import { db, initOrm } from 'mikro-orm/orm';
import { log } from './logger';
import { initializeRabbitMQ } from './rabbitmq';
import { getStorage } from './mikro-orm/storage';
const app = express();
(async () => {
try {
// Middleware
app.use(express.json());
app.use(express.urlencoded({ extended: false }));
app.use(cookieParser());
// Mikro ORM
await initOrm();
// @ts-ignore
app.use((_req, _res, next) => getStorage().run(db.orm.em.fork(true, true), next));
// RabbitMQ
await initializeRabbitMQ();
await server.start();
server.applyMiddleware({ app });
log({ level: 'info', message: 'App started', label: 'app' });
} catch (error: any) {
log({ level: 'error', message: error.message, label: 'app' });
}
})();
export default app;import {
initializeBroker,
subscribeToBillingCreditQueue,
subscribeToBillingInvoiceQueue,
subscribeToBillingOfferQueue,
subscribeToBillingOrderQueue,
} from '@gastromatic/amqp-message-queues';
import { db } from 'mikro-orm/orm';
import {
handleCreditMessage,
handleInvoiceMessage,
handleOfferMessage,
handleOrderMessage,
} from '../services/queue-handling';
import { getStorage } from '../mikro-orm/storage';
export async function initializeRabbitMQ() {
const broker = await initializeBroker();
await subscribeToBillingInvoiceQueue(broker, async (message) => {
await getStorage().run(db.orm.em.fork(true, true), () => handleInvoiceMessage(message));
});
await subscribeToBillingCreditQueue(broker, async(message) => {
await getStorage().run(db.orm.em.fork(true, true), () => handleCreditMessage(message));
});
await subscribeToBillingOfferQueue(broker, async (message) => {
await getStorage().run(db.orm.em.fork(true, true), () => handleOfferMessage(message));
});
await subscribeToBillingOrderQueue(broker, async (message) => {
await getStorage().run(db.orm.em.fork(true, true), () => handleOrderMessage(message));
});
}And i already shared the code of the initializeBroker in my last comment
Thanks. I'll try to reproduce.
Can you post an example of your subscribe code please? e.g. whatever is in subscribeToBillingInvoiceQueue
The following code works fine for me...
const rascal = require('rascal');
const Broker = rascal.BrokerAsPromised;
(async () => {
try {
await initializeRabbitMQ();
console.log('Started');
} catch (error) {
console.log(error);
}
async function initializeRabbitMQ() {
const broker = await initializeBroker({
vhosts: {
'/': {
queues: ['test-q']
}
}
});
const subscription = await broker.subscribe('/test-q');
subscription.on('message', (messge, content, ackOrNack) => {
// Not publishing any messages so nothing to do here
});
subscription.on('error', console.log)
}
async function initializeBroker(options) {
const broker = await Broker.create(options);
broker.on('error', console.log);
return broker;
}
})();I'm inducing the Unexpected Close by inserting the following code here.
setTimeout(() => {
console.log('Ending channel stream');
channel.connection.stream.end()
}, 10000);The debug is as follows
rascal:config:configure Configuring vhost: / +0ms
rascal:config:configure Configuring exchange: +6ms
rascal:config:configure Configuring queue: test-q +0ms
rascal:config:configure Configuring publication: / +1ms
rascal:config:configure Configuring publication: /test-q +0ms
rascal:config:configure Configuring subscription: /test-q +0ms
rascal:config:configure Configuring counter: stub +0ms
rascal:Broker Initialising broker +0ms
rascal:Vhost Initialising vhost: / +0ms
rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672 +0ms
rascal:tasks:createConnection Obtained connection: 148fdec9-773b-46fd-8ef9-edb26a3cddc8 +19ms
rascal:tasks:createChannel Creating channel +0ms
rascal:tasks:assertQueues Asserting queue: test-q +0ms
rascal:tasks:closeChannel Closing channel +0ms
rascal:Vhost Creating regular channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true, acquireTimeoutMillis: 15000, destroyTimeoutMillis: 1000 } +29ms
rascal:Vhost Creating confirm channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true, acquireTimeoutMillis: 15000, destroyTimeoutMillis: 1000 } +2ms
rascal:Vhost vhost: / was initialised with connection: 148fdec9-773b-46fd-8ef9-edb26a3cddc8 +1ms
rascal:Publication Initialising publication: / +0ms
rascal:Publication Initialising publication: /test-q +0ms
rascal:Subscription Initialising subscription: /test-q +0ms
rascal:Subscription Subscribing to queue: test-q +2ms
rascal:Vhost Requested channel. Outstanding channel requests: 1 +3ms
Started
rascal:Vhost Created confirm channel: 41f1184f-cb27-4db9-beeb-4f9dc0d03755 from connection: 148fdec9-773b-46fd-8ef9-edb26a3cddc8 +7ms
rascal:SubscriberSession Opening subscriber session: amq.ctag-w0zQ67BiBCoXGer0oJdXFw on channel: 41f1184f-cb27-4db9-beeb-4f9dc0d03755 +0ms
Ending channel stream
rascal:Vhost Handling connection error: Unexpected close initially from connection: 148fdec9-773b-46fd-8ef9-edb26a3cddc8, amqp://guest:***@localhost:5672 +10s
Error: Unexpected close
at succeed (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:272:13)
at onOpenOk (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:254:5)
at /Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:166:32
at /Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:160:12
at Socket.recv (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:499:12)
at Object.onceWrapper (node:events:513:28)
at Socket.emit (node:events:394:28)
at emitReadable_ (node:internal/streams/readable:571:12)
at processTicksAndRejections (node:internal/process/task_queues:82:21) { vhost: '/', connectionUrl: 'amqp://guest:***@localhost:5672' }
rascal:Vhost Initialising vhost: / +1ms
rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672 +10s
rascal:Subscription Handling channel error: Unexpected close from /test-q using channel: 41f1184f-cb27-4db9-beeb-4f9dc0d03755 +10s
Error: Unexpected close
at succeed (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:272:13)
at onOpenOk (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:254:5)
at /Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:166:32
at /Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:160:12
at Socket.recv (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:499:12)
at Object.onceWrapper (node:events:513:28)
at Socket.emit (node:events:394:28)
at emitReadable_ (node:internal/streams/readable:571:12)
at processTicksAndRejections (node:internal/process/task_queues:82:21)
rascal:SubscriberSession Removing channel: 41f1184f-cb27-4db9-beeb-4f9dc0d03755 from session +10s
rascal:Subscription Subscribing to queue: test-q +2ms
rascal:Vhost Requested channel. Outstanding channel requests: 1 +4ms
rascal:tasks:createConnection Obtained connection: 2995b402-2e37-4762-ba94-35a1621d3565 +11ms
rascal:tasks:createChannel Creating channel +10s
rascal:tasks:assertQueues Asserting queue: test-q +10s
rascal:tasks:closeChannel Closing channel +10s
rascal:Vhost vhost: / was initialised with connection: 2995b402-2e37-4762-ba94-35a1621d3565 +13ms
rascal:Vhost Created confirm channel: e8c28c9e-d1b4-4d10-beb3-785d86c97368 from connection: 2995b402-2e37-4762-ba94-35a1621d3565 +3ms
rascal:SubscriberSession Opening subscriber session: amq.ctag-pv3jtgw8jSaEUSlsn4EPSw on channel: e8c28c9e-d1b4-4d10-beb3-785d86c97368 +20ms
I noticed one odd thing in your debug. Connection 4468d317-fd4f-4dd7-ae29-bf5be41455ed emitted the unexpected close, but is not the connection used in the initialisation. Do you have any idea where this could have come from?
Thank you for your answer, it helped a lot! I fixed the problem with the error been thrown instead of handled in the onError callback, it was due to an old rascal version. After i updated from v13.1.1 to v14.2.1 the error is now handled correctly.
After you hint with the different connection id we now realized that the unexpected close was coming from another pod in our cluster. When we deploy a new version, the old pod is shutting down after the new one is live, and we had the logs from both in the same namespace.
We had 2 time where the connection was lost and not restablished in the last month but we don't know the reason. But we will monitor it now with the enhanced rascal logs and hopefully find the reason or not have the problem anymore.
Thanks for your time!
A pleasure. Glad you got it sorted.