Question - handling connection closure with reason "shutdown"

Hey @cressie176,
I have an application consuming a queue. Currently, when there is a maintenance of our RMQ cluster (and I guess that RMQ node is stopped and replaced or restarted). My application gets "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" message and it stops consuming the queue until I manually restart the application. Within the application I initialize its subscription to queue in following way:
const broker = await Broker.create(...);

broker.on("error",
  err => logger.error("RabbitBroker (rascal) - error", err)
);

const subscription = await broker.subscribe(...);
subscription
  .on("message", (message, content, ackOrNack) => {
    ...
  })
  .on("error",
    err => logger.error("Subscription error", err)
  );

During last maintenance, it logged those two messages (emitting an error events for both subscription and broker):
ERROR Subscription error - Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"

ERROR RabbitBroker (rascal) - error - Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"

When an error event is emitted for broker or subscription is there any chance that it will recover? Can my app detect somehow that connection won't be restored/rebuild in this case? I am thinking about terminating the application and letting underlying (container) orchestrator to restart it - but I am afraid there could be other error event types where restarting could be harmful.
Thank you for making this awesome library and supporting its users!

Hi @matej-prokop,
With Rascal's default configuration should re-connect and resubscribe automatically. If you've defined multiple hosts in the connection configuration it will cycle through them on an incremental backoff indefinitely until one of the connections succeeds, then start consuming. Even if there's only one host it should repeatedly retry using the same logic.
Can you turn on debug by setting the DEBUG environment variable to rascal:* or rascal:Vhost*. This will show you whether rascal is trying to reconnect. When I do this with rascal's simple example and restart the docker container I get the following output...
 DEBUG=rascal:Vhost* node index.js
  rascal:Vhost Initialising vhost: / +0ms
  rascal:Vhost Creating regular channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true } +36ms
  rascal:Vhost Creating confirm channel pool { autostart: true, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, rejectionDelayMillis: 1000, testOnBorrow: true } +2ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost vhost: / was initialised with connection: 287a703c-78d6-4821-97de-3a710a41a9d1 +1ms
  rascal:Vhost Requested channel. Outstanding channel requests: 1 +3ms
  rascal:Vhost Created confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e from connection: 287a703c-78d6-4821-97de-3a710a41a9d1 +4ms
  rascal:Vhost Created confirm channel: 2ea038e5-619f-4093-9c85-1ec9b0d656a7 from connection: 287a703c-78d6-4821-97de-3a710a41a9d1 +0ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +998ms
  rascal:Vhost Borrowed confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +2ms
  rascal:Vhost Releasing confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +6ms
2021-06-22T05:13:59.088Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +991ms
  rascal:Vhost Borrowed confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:00.088Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +997ms
  rascal:Vhost Borrowed confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:01.090Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +999ms
  rascal:Vhost Borrowed confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:02.093Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Borrowed confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +3ms
2021-06-22T05:14:03.098Z: hello world
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 287a703c-78d6-4821-97de-3a710a41a9d1, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +209ms
Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:64:33)
    at Socket.go (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:478:48)
    at Socket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21) {
  code: 320
} {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:64:33)
    at Socket.go (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:478:48)
    at Socket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21) {
  code: 320
}
  rascal:Vhost Requested channel. Outstanding channel requests: 1 +2ms
  rascal:Vhost Will attempt reconnection in in 1100ms +2ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +787ms
  rascal:Vhost Handling connection error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake initially from connection: 287a703c-78d6-4821-97de-3a710a41a9d1, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +317ms
Error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake
    at Socket.endWhileOpening (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:260:17)
    at Socket.emit (events.js:327:22)
    at endReadableNT (internal/streams/readable.js:1327:12)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
  rascal:Vhost Will attempt reconnection in in 3681ms +2ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 1, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +684ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 2, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 3, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Handling connection error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake initially from connection: 287a703c-78d6-4821-97de-3a710a41a9d1, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +994ms
Error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake
    at Socket.endWhileOpening (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:260:17)
    at Socket.emit (events.js:327:22)
    at endReadableNT (internal/streams/readable.js:1327:12)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
  rascal:Vhost Will attempt reconnection in in 6611ms +2ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 4, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +3ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 5, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 6, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 7, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 8, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 9, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 10, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Handling connection error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: connect ECONNREFUSED <IP_ADDRESS>:5672 initially from connection: 287a703c-78d6-4821-97de-3a710a41a9d1, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +595ms
Error: connect ECONNREFUSED <IP_ADDRESS>:5672
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) {
  errno: -61,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '<IP_ADDRESS>',
  port: 5672
} {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
  rascal:Vhost Will attempt reconnection in in 12747ms +4ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 11, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +401ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 12, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 13, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 14, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 15, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 16, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 17, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 18, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 19, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 20, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 21, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 22, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 23, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Handling connection error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake initially from connection: 287a703c-78d6-4821-97de-3a710a41a9d1, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +321ms
Error: Failed to connect to: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: Socket closed abruptly during opening handshake
    at Socket.endWhileOpening (/Users/steve/Development/guidesmiths/rascal/node_modules/amqplib/lib/connection.js:260:17)
    at Socket.emit (events.js:327:22)
    at endReadableNT (internal/streams/readable.js:1327:12)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
  rascal:Vhost vhost: / was initialised with connection: 55736839-b556-4105-90a6-4d3b819ad04d +19ms
  rascal:Vhost Destroying channel: 0d2802cc-095b-499f-9be7-d99a294f4e9e +1ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost Created confirm channel: 2fd3e6d3-9138-4bf8-85cb-182b3d6d4486 from connection: 55736839-b556-4105-90a6-4d3b819ad04d +5ms
  rascal:Vhost Created confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b from connection: 55736839-b556-4105-90a6-4d3b819ad04d +1ms
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 23, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 22, size: 2, available: 0, borrowed: 1, min: 1, max: 5 } +3ms
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 22, size: 2, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
2021-06-22T05:14:04.103Z: hello world
  rascal:Vhost Created confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322 from connection: 55736839-b556-4105-90a6-4d3b819ad04d +2ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 21, size: 2, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
2021-06-22T05:14:05.106Z: hello world
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 21, size: 2, available: 1, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 20, size: 2, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 19, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
2021-06-22T05:14:06.109Z: hello world
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 19, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 18, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
2021-06-22T05:14:07.114Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 18, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 17, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
2021-06-22T05:14:08.114Z: hello world
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 17, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +2ms
  rascal:Vhost Created confirm channel: e581692f-4779-488a-a0b9-e3998ebda658 from connection: 55736839-b556-4105-90a6-4d3b819ad04d +1ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 16, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
2021-06-22T05:14:09.115Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 16, size: 3, available: 1, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 15, size: 3, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 14, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
2021-06-22T05:14:10.119Z: hello world
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 14, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 13, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
2021-06-22T05:14:11.123Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 13, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 12, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
2021-06-22T05:14:12.124Z: hello world
  rascal:Vhost Borrowed confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 12, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 11, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 11, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
2021-06-22T05:14:13.127Z: hello world
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 10, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
2021-06-22T05:14:14.131Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 10, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Created confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c from connection: 55736839-b556-4105-90a6-4d3b819ad04d +1ms
  rascal:Vhost Releasing confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 9, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
2021-06-22T05:14:15.132Z: hello world
  rascal:Vhost Borrowed confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 9, size: 4, available: 1, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 8, size: 4, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:16.133Z: hello world
  rascal:Vhost Borrowed confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 8, size: 4, available: 1, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 7, size: 4, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 6, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +1ms
2021-06-22T05:14:17.133Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 6, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 5, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:18.135Z: hello world
  rascal:Vhost Borrowed confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 5, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 4, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:19.136Z: hello world
  rascal:Vhost Borrowed confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 4, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 3, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:20.139Z: hello world
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 3, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 2, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +1ms
2021-06-22T05:14:21.143Z: hello world
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 2, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 1, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:22.144Z: hello world
  rascal:Vhost Borrowed confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 1, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:23.148Z: hello world
  rascal:Vhost Borrowed confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
  rascal:Vhost Created confirm channel: 21800d97-5677-40d1-a8f9-7b90d5c7cebd from connection: 55736839-b556-4105-90a6-4d3b819ad04d +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 0, borrowed: 4, min: 1, max: 5 } +0ms
2021-06-22T05:14:24.152Z: hello world
2021-06-22T05:14:25.154Z: hello world
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 2, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: e581692f-4779-488a-a0b9-e3998ebda658. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 3, borrowed: 2, min: 1, max: 5 } +1ms
2021-06-22T05:14:26.157Z: hello world
  rascal:Vhost Releasing confirm channel: d4a262a4-dd06-4a14-b462-cd208a816c7c. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
2021-06-22T05:14:27.160Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +628ms
  rascal:Vhost Borrowed confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 33cc0b58-2775-493d-b61d-8adbcddee85b. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:28.164Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +999ms
  rascal:Vhost Borrowed confirm channel: 21800d97-5677-40d1-a8f9-7b90d5c7cebd. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 21800d97-5677-40d1-a8f9-7b90d5c7cebd. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:29.168Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Borrowed confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: c2b28680-5088-4d9a-aab9-71be7d0ec322. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +4ms
2021-06-22T05:14:30.173Z: hello world

Just chipping in here. We see this on one of our applications every week during the maintenance window for our RabbitMQ instance running on Amazon MQ, but rascal recovers as expected and everything continues as normal.

Thank you for replying! So far I didn't manage to reproduce the issue when having DEBUG=rascal:Vhost*. Within my setup, there is Amazon MQ cluster (three RabbitMQ broker nodes behind a Network Load Balancer) so my application has single host defined as connection (pointing at the load balancer).
I tried to both (A) restart brokers within the cluster and (B) upgrade instances with brokers (forcing all brokers instance to be replaced by new instances). Nevertheless, my application always reconnected and continued processing messages from the queue.
I don't know yet why during the cluster maintenance done by AWS team, it wasn't the case.
I have one more idea to try. My app consumes an input queue, process a message and then post message (processing result) into another output queue. During my test I was producing invalid test messages so the app was discarding messages so it wasn't publishing anything (into output queue). I will try another test with valid messages so the app will also be publishing. Idea is that it could be that result publications "hangs" => causing my app not fetching more messages because previous messages wasn't acked.
BTW: Is it OK to re-use one instance of rascal Broker (created by `Broker.create()) for both subscribing and publishing at one time?

Is it OK to re-use one instance of rascal Broker (created by `Broker.create()) for both subscribing and publishing at one time?

Yes, it's fine. I have read that if you really need best performance then it's best to use a separate connections for publishing and subscribe, which you get automatically if the vhosts are different, but I wouldn't worry about it unless you need 1000s of messages a second.

Idea is that it could be that result publications "hangs" => causing my app not fetching more messages because previous messages wasn't acked.

Publications are paused when the connection / channel dies and also automatically attempt to reconnect. Any messages that are published while disconnected are queued in memory, so not likely to be this.

So when testing with publications to RMQ, I see that publications stucks when I restart brokers in Amazon MQ cluster. So I put together simple script that allows me to reproduce the issue:
  for (let i = 0; i < 10000; i++) {
    console.log(`Publikuju ${i}`);
    await rabbitPublisher
      .publish({ payload, overrides })
      .catch(logger.error(`Failed to publish notification to RMQ`));
  }

Where rabbitPublisher is my custom wrapper:
publish: ({ payload, overrides = {} }) => {
  return new Promise((resolve, reject) => {
    rabbitBroker
      .getRascalBroker()  // returns "singleton" instance created by Broker.create()
      .then(broker => {
        broker.publish(
          publicationName,
          payload,
          overridesWithDefaults,
          (err, publication) => {
            if (err) {
              reject(err);
            } else {
              publication.on("success", resolve).on("error", reject);
            }
          }
        );
      })
      .catch(reject);
  });
}

Here is output of script above:
mprokop$ DEBUG=rascal:Vhost* node adhoc/rmq-publisher.js
  rascal:Vhost Initialising vhost: / +0ms
  rascal:Vhost Creating regular channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, testOnBorrow: true, rejectionDelayMillis: 1000 } +2s
  rascal:Vhost Creating confirm channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, testOnBorrow: true, rejectionDelayMillis: 1000 } +3ms
  rascal:Vhost vhost: / was initialised with connection: 348a7a21-b57e-483b-9994-4ea3ba4b319c +0ms
info: Started RabbitBroker (rascal).
Publikuju 0
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 0, available: 0, borrowed: 0, min: 1, max: 5 } +5ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Created confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6 from connection: 348a7a21-b57e-483b-9994-4ea3ba4b319c +476ms
  rascal:Vhost Borrowed confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +244ms
Publikuju 1
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +237ms
Publikuju 2

......

Publikuju 717
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +244ms
Publikuju 718
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Destroying confirm channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +152ms
  rascal:Vhost Destroying channel: f2c8a52e-4d51-4d0d-90c5-6d20a3ac68e6 +1ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 348a7a21-b57e-483b-9994-4ea3ba4b319c, amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +2ms
error: RabbitBroker (rascal) - error message=Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'", stack=Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/myfolder/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/myfolder/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myfolder/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21), code=320
  rascal:Vhost Initialising vhost: / +0ms
error: Failed to publish notification to RMQ message=channel closed, stack=Error: channel closed
    at ConfirmChannel.<anonymous> (/myfolder/node_modules/amqplib/lib/channel.js:39:18)
    at ConfirmChannel.emit (events.js:327:22)
    at ConfirmChannel.C.toClosed (/myfolder/node_modules/amqplib/lib/channel.js:175:8)
    at Connection.C._closeChannels (/myfolder/node_modules/amqplib/lib/connection.js:394:18)
    at Connection.C.toClosed (/myfolder/node_modules/amqplib/lib/connection.js:401:8)
    at Object.accept (/myfolder/node_modules/amqplib/lib/connection.js:96:18)
    at Connection.mainAccept (/myfolder/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myfolder/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)
Publikuju 719
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +3ms
 rascal:Vhost vhost: / was initialised with connection: 56b6dce8-4bff-4172-b673-c9a1020a22ec +2s
 rascal:Vhost Handling connection error: Heartbeat timeout initially from connection: 56b6dce8-4bff-4172-b673-c9a1020a22ec, amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +29m
error: RabbitBroker (rascal) - error message=Heartbeat timeout, stack=Error: Heartbeat timeout
    at Heart.<anonymous> (/myfolder/node_modules/amqplib/lib/connection.js:427:19)
    at Heart.emit (events.js:315:20)
    at Heart.runHeartbeat (/myfolder/node_modules/amqplib/lib/heartbeat.js:88:17)
    at listOnTimeout (internal/timers.js:554:17)
    at processTimers (internal/timers.js:497:7)
  rascal:Vhost Initialising vhost: / +1ms
  rascal:Vhost Will attempt reconnection in in 585ms +15s
  rascal:Vhost Handling connection error: Failed to connect to: amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: connect ETIMEDOUT initially from connection: 56b6dce8-4bff-4172-b673-c9a1020a22ec, amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +595ms
error: RabbitBroker (rascal) - error message=Failed to connect to: amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: connect ETIMEDOUT, stack=Error: Failed to connect to: amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: connect ETIMEDOUT
    at TLSSocket.<anonymous> (/myfolder/node_modules/amqplib/lib/connect.js:172:20)
    at Object.onceWrapper (events.js:421:28)
    at TLSSocket.emit (events.js:315:20)
    at TLSSocket.Socket._onTimeout (net.js:483:8)
    at listOnTimeout (internal/timers.js:554:17)
    at processTimers (internal/timers.js:497:7)
  rascal:Vhost Initialising vhost: / +3ms
  rascal:Vhost vhost: / was initialised with connection: 1ddbe475-40de-42c6-9444-c842de43edc2 +5s
^C
mprokop$ DEBUG=rascal:Vhost* node adhoc/rmq-publisher.js
  rascal:Vhost Initialising vhost: / +0ms
  rascal:Vhost Creating regular channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, testOnBorrow: true, rejectionDelayMillis: 1000 } +3s
  rascal:Vhost Creating confirm channel pool { autostart: false, max: 5, min: 1, evictionRunIntervalMillis: 10000, idleTimeoutMillis: 60000, testOnBorrow: true, rejectionDelayMillis: 1000 } +3ms
  rascal:Vhost vhost: / was initialised with connection: 5dc9f4ab-4267-4028-aa22-98efa158a0cb +1ms
info: Started RabbitBroker (rascal).
Publikuju 0
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 0, available: 0, borrowed: 0, min: 1, max: 5 } +5ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +2ms
  rascal:Vhost Created confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073 from connection: 5dc9f4ab-4267-4028-aa22-98efa158a0cb +484ms
  rascal:Vhost Borrowed confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +250ms
Publikuju 1
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Vhost Releasing confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +238ms
Publikuju 2
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Vhost Releasing confirm channel: 82f7f05a-b041-4def-9ecc-afd25a3c2073. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +240ms

Comments:

after publishing message #718 connection is closed (brokers within the cluster being restarted)
note that then there is nothing going on for 29 mins see  +29m, then we see another two errors by no more messages are being published (as I would expect)
then I killed my test script (see ^C within output) and immediately started the script again, you can see that suddenly it start publishing messages without any issues

I started to suspect that there could be actually something wrong with my rabbitPublisher wrapper (maybe I am not handling some events emitted by rascal causing promise from rabbitPublisher.publish to never resolve/reject. Anyway, I wanted to share with you my findings so far - maybe you will see what is wrong immediately.

Tried to set publication timeout but it didn't help. Nevertheless, I added some debug logging into my rabbitPublisher wrapper:
...

broker.publish(
  publicationName,
  payload,
  overridesWithDefaults,
  (err, publication) => {
    if (err) {
      reject(err);
    } else {
      console.log("Got publication object");
      publication
        .on("success", () => {
          console.log("Message was success");
          resolve();
        })
        .on("error", err => {
          console.log("Message was error");
          reject(err);
        })
        .on("return", () => {
          console.log("Message was returned");
          resolve();
        });
    }
  }

...

and found that very last thing that my script logs is Got publication object but publication doesn't fire any event. Meaning non of success, error or return are called. Causing "parent" promise to never resolve

I did one more test - updating my test script to have its own timeout:
  for (let i = 0; i < 10000; i++) {
    ...
    await Promise.race([
      rabbitPublisher
        .publish({ payload, overrides })
        .catch(
          errorHandler.handleError(`Failed to publish notification to RMQ`)
        ),
      new Promise(res =>
        setTimeout(() => {
          res();
        }, 30000)
      )
    ]);
  }

causing that even when publication of a message stucks (no event is emitted), it will try to publish another message after 30 seconds. Interestingly, it seems that "publication" gets into some weird state (after Amazon MQ cluster restart) because any future attempt to publish a message stucks. When I restart my script is start working again... until I restart Amazon MQ cluster again.

Hi @matej-prokop,
Thanks for sharing the debug. It does reveal something interesting...
rascal:Vhost vhost: / was initialised with connection: 56b6dce8-4bff-4172-b673-c9a1020a22ec
+2s

rascal:Vhost Handling connection error: Heartbeat timeout initially from connection: 56b6dce8-4bff-4172-b673-c9a1020a22ec, amqps://myuser:***@b-b38e98a9-c9b7-55df-ba64-e5402bf53cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100
+29m

Rascal must have successfully reconnected after the original connection error in order to log this message.
The next message is 29 minutes later, however if you followed my instructions this could just be because we only enabled the Vhost logging. It's probably best if we enable all debug as I suspect there was more going on between these two messages which would shed further light. Can you set the DEBUG environment variable to just rascal:* so we see everything please?

Depending on your version of Rascal, one issue could be that the channel pool used by the publisher attempts to create a channel and fails. There is a bug in the underlying channel pool used by rascal, which caused it to spin into a tight loop. This was fixed in 10.2.3, so I recommend upgrading to the latest version if this is the case.

All my tests were done with rascal 13.0.2 and amqplib 0.7.1 so it must be something else. I will retry with DEBUG=rascal:* and share output here.

Output with DEBUG=rascal:* (while having custom timeout in place https://github.com/guidesmiths/rascal/issues/156#issuecomment-868562983 - trying to publishing another message after 30s even if previous publishing hasn't finished yet):
...

info: Publishing message #457
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
Got publication
  rascal:Vhost Borrowed confirm channel: 3c573fdd-7b3f-4522-8e9f-e77c0be0cad9. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 140 bytes to confirm exchange: my-pipeline-exchange with routingKeys: user.1. +251ms
  rascal:Vhost Releasing confirm channel: 3c573fdd-7b3f-4522-8e9f-e77c0be0cad9. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +353ms
info: Publishing message #458
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
Got publication
  rascal:Vhost Borrowed confirm channel: 3c573fdd-7b3f-4522-8e9f-e77c0be0cad9. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 140 bytes to confirm exchange: my-pipeline-exchange with routingKeys: user.1. +354ms
  rascal:Vhost Destroying confirm channel: 3c573fdd-7b3f-4522-8e9f-e77c0be0cad9. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +306ms
  rascal:Vhost Destroying channel: 3c573fdd-7b3f-4522-8e9f-e77c0be0cad9 +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 53870274-af97-4698-b27d-84aae18fd6e7, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +0ms
error: RabbitBroker (rascal) - error message=Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'", stack=Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/myproject/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/myproject/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myproject/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21), code=320
  rascal:Vhost Initialising vhost: / +1ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +2m
error: Failed to publish notification to RMQ message=channel closed, stack=Error: channel closed
    at ConfirmChannel.<anonymous> (/myproject/node_modules/amqplib/lib/channel.js:39:18)
    at ConfirmChannel.emit (events.js:327:22)
    at ConfirmChannel.C.toClosed (/myproject/node_modules/amqplib/lib/channel.js:175:8)
    at Connection.C._closeChannels (/myproject/node_modules/amqplib/lib/connection.js:394:18)
    at Connection.C.toClosed (/myproject/node_modules/amqplib/lib/connection.js:401:8)
    at Object.accept (/myproject/node_modules/amqplib/lib/connection.js:96:18)
    at Connection.mainAccept (/myproject/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myproject/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)
info: Publishing message #459
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +2ms
Got publication
  rascal:Vhost Will attempt reconnection in in 852ms +270ms
  rascal:Vhost Handling connection error: Failed to connect to: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: read ECONNRESET initially from connection: 53870274-af97-4698-b27d-84aae18fd6e7, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +853ms
error: RabbitBroker (rascal) - error message=Failed to connect to: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: read ECONNRESET, stack=Error: read ECONNRESET
    at TLSWrap.onStreamRead (internal/stream_base_commons.js:209:20), errno=-54, code=ECONNRESET, syscall=read
  rascal:Vhost Initialising vhost: / +0ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +1s
  rascal:tasks:createConnection Obtained connection: 71e04b7d-cd0a-41f4-844c-ce476de89a99 +2s
  rascal:tasks:createChannel Creating channel +2m
  rascal:tasks:assertExchanges Asserting exchange: my-pipeline-exchange +2m
  rascal:tasks:closeChannel Closing channel +2m
  rascal:Vhost vhost: / was initialised with connection: 71e04b7d-cd0a-41f4-844c-ce476de89a99 +2s
info: Publishing message #460
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +27s
Got publication
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 71e04b7d-cd0a-41f4-844c-ce476de89a99, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +22s
error: RabbitBroker (rascal) - error message=Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'", stack=Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/myproject/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/myproject/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myproject/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21), code=320
  rascal:Vhost Initialising vhost: / +0ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +49s
  rascal:tasks:createConnection Obtained connection: 8678e2ee-aeb2-4165-9190-dfdda647960b +1s
  rascal:tasks:createChannel Creating channel +50s
  rascal:tasks:assertExchanges Asserting exchange: my-pipeline-exchange +50s
  rascal:tasks:closeChannel Closing channel +50s
  rascal:Vhost vhost: / was initialised with connection: 8678e2ee-aeb2-4165-9190-dfdda647960b +2s
info: Publishing message #461
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +6s
Got publication
info: Publishing message #462
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 2, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #463
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 3, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
^C

Hi @matej-prokop,
Thanks for the extra debug. It shows that the connection was successfully re-established, but that attempts to borrow channels from the pool never yield a result. You can see the queue growing (1, 2, 3) but never released - available is 0 and borrowed is zero.
It's possible that there's a bug somewhere and channel allocation, which is paused while the connection is unavailable, is somehow never resumed when it recovers. It could also be that the channel pool has somehow choked. I'll see if I can reproduce.

I'm able to reproduce. Looks like the queue is still paused. Will fix ASAP. Thanks for your help uncovering this.

Seems intermittent. I haven't been able to reproduce again since adding more debug.

Interesting. On my end, it seems to be happening constantly. If you won't manage to reproduce again with additional debug logging. Let me know. I can add debug logging on my end or you can publish a beta version of rascal with additional debug logging. Then I can use it to provide you more context.

Thanks @matej-prokop.
It would be helpful to add paused to the channel pool stats function
    function stats() {
      return {
        vhost: self.name,
        mode,
        paused: poolQueue.paused,
        queue: poolQueue.length(),
        size: pool.size,
        available: pool.available,
        borrowed: pool.borrowed,
        min: pool.min,
        max: pool.max,
      };
    }

and also some extra logging here so we can see the channel allocation should be resumed. e.g.
  function resumeChannelAllocation() {
    debug('Resuming channel allocation on connection %s', connection._rascal_id);
    channelCreator.resume();
    regularChannelPool && regularChannelPool.resume();
    confirmChannelPool && confirmChannelPool.resume();
    debug('Confirm Channel Stats: %o', confirmChannelPool.stats());
    paused = false;
    self.emit('resumed', { vhost: self.name });
  }

@cressie176 thank you for providing clear instructions!
Here is its output:
...

info: Publishing message #1061
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 1, borrowed: 0, min: 1, max: 5 } +1ms
Got publication
  rascal:Vhost Borrowed confirm channel: c7222f81-12a5-4c7b-ac21-c241b4124f4e. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Publication Publishing 141 bytes to confirm exchange: my-pipeline-exchange with routingKeys: user.1. +306ms
  rascal:Vhost Destroying confirm channel: c7222f81-12a5-4c7b-ac21-c241b4124f4e. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +69ms
  rascal:Vhost Destroying channel: c7222f81-12a5-4c7b-ac21-c241b4124f4e +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 15e9a994-9457-448e-8120-d8a9558cc5a3, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +1ms
error: RabbitBroker (rascal) - error message=Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'", stack=Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'"
    at Object.accept (/myproject/node_modules/amqplib/lib/connection.js:91:15)
    at Connection.mainAccept (/myproject/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myproject/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21), code=320
  rascal:Vhost Initialising vhost: / +1ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +5m
error: Failed to publish notification to RMQ message=channel closed, stack=Error: channel closed
    at ConfirmChannel.<anonymous> (/myproject/node_modules/amqplib/lib/channel.js:39:18)
    at ConfirmChannel.emit (events.js:327:22)
    at ConfirmChannel.C.toClosed (/myproject/node_modules/amqplib/lib/channel.js:175:8)
    at Connection.C._closeChannels (/myproject/node_modules/amqplib/lib/connection.js:394:18)
    at Connection.C.toClosed (/myproject/node_modules/amqplib/lib/connection.js:401:8)
    at Object.accept (/myproject/node_modules/amqplib/lib/connection.js:96:18)
    at Connection.mainAccept (/myproject/node_modules/amqplib/lib/connection.js:64:33)
    at TLSSocket.go (/myproject/node_modules/amqplib/lib/connection.js:478:48)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)
info: Publishing message #1062
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: true, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +3ms
Got publication
  rascal:Vhost Will attempt reconnection in in 791ms +530ms
  rascal:Vhost Handling connection error: Failed to connect to: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: read ECONNRESET initially from connection: 15e9a994-9457-448e-8120-d8a9558cc5a3, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +794ms
error: RabbitBroker (rascal) - error message=Failed to connect to: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100. Original message was: read ECONNRESET, stack=Error: read ECONNRESET
    at TLSWrap.onStreamRead (internal/stream_base_commons.js:209:20), errno=-54, code=ECONNRESET, syscall=read
  rascal:Vhost Initialising vhost: / +1ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +1s
  rascal:tasks:createConnection Obtained connection: ae199624-7b8f-4c4b-8486-cf9ad886b69e +1s
  rascal:tasks:createChannel Creating channel +5m
  rascal:tasks:assertExchanges Asserting exchange: my-pipeline-exchange +5m
  rascal:tasks:closeChannel Closing channel +5m
  rascal:Vhost Resuming channel allocation on connection ae199624-7b8f-4c4b-8486-cf9ad886b69e +2s
  rascal:Vhost Confirm Channel Stats: { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +1ms
  rascal:Vhost vhost: / was initialised with connection: ae199624-7b8f-4c4b-8486-cf9ad886b69e +0ms
info: Publishing message #1063
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +27s
Got publication
info: Publishing message #1064
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #1065
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 2, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
  rascal:Vhost Handling connection error: Unexpected close initially from connection: ae199624-7b8f-4c4b-8486-cf9ad886b69e, amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +13s
error: RabbitBroker (rascal) - error message=Unexpected close, stack=Error: Unexpected close
    at succeed (/myproject/node_modules/amqplib/lib/connection.js:272:13)
    at onOpenOk (/myproject/node_modules/amqplib/lib/connection.js:254:5)
    at /myproject/node_modules/amqplib/lib/connection.js:166:32
    at /myproject/node_modules/amqplib/lib/connection.js:160:12
    at TLSSocket.recv (/myproject/node_modules/amqplib/lib/connection.js:499:12)
    at Object.onceWrapper (events.js:421:28)
    at TLSSocket.emit (events.js:315:20)
    at emitReadable_ (internal/streams/readable.js:569:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)
  rascal:Vhost Initialising vhost: / +1ms
  rascal:tasks:createConnection Connecting to broker using url: amqps://myuser:***@b-b34f98b9-c9b8-45df-bb63-e5402bf50cc9.mq.us-east-1.amazonaws.com:12346?heartbeat=10&connection_timeout=10000&channelMax=100 +2m
  rascal:tasks:createConnection Obtained connection: c5fdf669-c62b-4e9f-8873-780ff96247c5 +2s
  rascal:tasks:createChannel Creating channel +2m
  rascal:tasks:assertExchanges Asserting exchange: my-pipeline-exchange +2m
  rascal:tasks:closeChannel Closing channel +2m
  rascal:Vhost Resuming channel allocation on connection c5fdf669-c62b-4e9f-8873-780ff96247c5 +2s
  rascal:Vhost Confirm Channel Stats: { vhost: '/', mode: 'confirm', paused: false, queue: 3, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +0ms
  rascal:Vhost vhost: / was initialised with connection: c5fdf669-c62b-4e9f-8873-780ff96247c5 +0ms
info: Publishing message #1066
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 3, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +15s
Got publication
info: Publishing message #1067
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 4, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #1068
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 5, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #1069
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 6, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #1070
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 7, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #1071
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 8, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
^C

But I can confirm that the issue doesn't happen in 100% cases.  On my first attempt after adding additional debug logging, it reconnected and continued with publishing messages as expected. (If you will want I have output for that run saved and can share it here if that would help).

So that's very interesting. It says the queue isn't paused. Are you able to add some further debug where the queue task executes and [attempts to acquire a channel[(https://github.com/guidesmiths/rascal/blob/master/lib/amqp/Vhost.js#L306-L312) from the pool please?
    poolQueue = async.queue((__, next) => {
      debug('Attempting to acquire channel');
      pool.acquire().then((channel) => {
        debug('Channel acquired');
        setImmediate(() => {
          next(null, channel);
        });
      }).catch(next);
    }, 1);

You might also try adding a custom pool.use function and logging what happens there. What I find curious is that there are no available resources in the pool, even though the minimum size is 1. It suggests that even though we are requesting resources from the pool, that the pool isn't able to create them for some reason.

Output when having Attempting to acquire channel and Channel acquired debug in place:
...
rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: true, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +3ms
Got publication
  rascal:tasks:createConnection Obtained connection: bdc30721-4bbf-4a84-9236-2961f60e0560 +1s
  rascal:tasks:createChannel Creating channel +3m
  rascal:tasks:assertExchanges Asserting exchange: events-pipeline-exchange +3m
  rascal:tasks:closeChannel Closing channel +3m
  rascal:Vhost Resuming channel allocation on connection bdc30721-4bbf-4a84-9236-2961f60e0560 +2s
  rascal:Vhost Confirm Channel Stats: { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +0ms
  rascal:Vhost vhost: / was initialised with connection: bdc30721-4bbf-4a84-9236-2961f60e0560 +0ms
  rascal:Vhost Attempting to acquire channel +1ms
info: Publishing message #776
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +28s
Got publication
info: Publishing message #777
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #778
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 2, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publicationrascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: true, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +3ms
Got publication
  rascal:tasks:createConnection Obtained connection: bdc30721-4bbf-4a84-9236-2961f60e0560 +1s
  rascal:tasks:createChannel Creating channel +3m
  rascal:tasks:assertExchanges Asserting exchange: events-pipeline-exchange +3m
  rascal:tasks:closeChannel Closing channel +3m
  rascal:Vhost Resuming channel allocation on connection bdc30721-4bbf-4a84-9236-2961f60e0560 +2s
  rascal:Vhost Confirm Channel Stats: { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +0ms
  rascal:Vhost vhost: / was initialised with connection: bdc30721-4bbf-4a84-9236-2961f60e0560 +0ms
  rascal:Vhost Attempting to acquire channel +1ms
info: Publishing message #776
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 0, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +28s
Got publication
info: Publishing message #777
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 1, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication
info: Publishing message #778
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', paused: false, queue: 2, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } +30s
Got publication

I am not sure how to use pool.use to get any useful information out of it. However, what I find interesting is that both available and borrowed stats for pool are 0. See { vhost: '/', mode: 'confirm', paused: false, queue: 2, size: 1, available: 0, borrowed: 0, min: 1, max: 5 } within logs - because that means that pool isn't ready (according to this line). Therefore, I am assuming that call to acquire a resource is waiting for some available resource (but it is never created)
I just did a quick tour through code of rascal and node-pool and my guess is that pool isn't ready because channel isn't created. I added a few more debug lines and I see that method for creating channel is being called (here) but its callback is never executed (meaning this callback is not executed.

Ignore my suggestion about pool.use - looks like it's for something else. Sorry.
I also suspect it's because the channel isn't created. In my (working) output I see the output
rascal:Vhost vhost: / was initialised with connection: 9f014e1d-ea36-43b1-8bc2-8e0ea520a6de +0ms
rascal:Vhost Vhost: / was initialised. Resuming channel creation +0ms

The second of these is because when the connection failed initially, the pool destroyed all broken channels and attempted refill the pool when the connection recovers. The connection recovery is indicated by the vhost_initialised event. When this is emitted the the channel will be created. I don't see this output in your logs, and suspect this relates to why the pool is never refilled.

Out of curiosity, what node version are you on and what steps are you following to reproduce?

Nodejs: v14.16.0
Steps to reproduce: I have Amazon MQ cluster, then I start my script (I shared parts of it earlier here) that publishes messages (one by one) in loop and then I go to AWS console > Amazon MQ > Actions > Restart broker

@cressie176 I can create publicly accessible Amazon MQ cluster and share cred with you. Using that you should be able to reproduce the issue on your end. Would it be OK if I share credentials with you via some direct message? (For instance, I can use LinkedIn)

Hi @matej-prokop,
That would be very helpful. Maybe use my public gpg key to encrypt the credentials and email them to me. Happy to share email over linkedin.

👍 OK, you can find code that I use to reproduce the issue here: https://github.com/matej-prokop/rascal-156-repro
(Sending you password via LinkedIn)

Hi @cressie176, update README in https://github.com/matej-prokop/rascal-156-repro with instruction how to restart Amazon MQ cluster via AWS CLI. So you should be able to follow all steps to reproduce the issue now 🤞
(Sharing access secret for AWS CLI again via DM)
Let me know if that works for you. Thank you!

Hi @matej-prokop,
Thanks for your patience and help investigating this issue. I've been able to reproduce the problem using the AWS RabbitMQ broker and can see where the problem lies.
The issue is that the pooled channels are being destroyed before the the connection error is handled. Consequently the pool is attempting to recreate them before the connection is set to undefined. As a result, the code attempts to create the channel using a duff connection and never continuing to register the vhost_initialised event listener which is create the channel once the connection has been restored.
I will take some more time to unpick, but thanks to your help at least we understand the cause.

Fix on the way. The issue was that when attempting to create the channel, amqplib emitted a close event. This meant the createChannel's callback was never called, and the pool was waiting forever.
I've changed the code to add both close and error event handlers to the connection just prior to requesting a channel. These ensure that the pool always gets a response, and therefore doesn't get stuck.

Published as<EMAIL_ADDRESS>

Big thank you for preparing the fix and publishing new version of rascal so quickly! I have already verified that the fix works for me so I am closing this issue.
BTW: Based on investigation of this issues, I am proposing one minor update: https://github.com/guidesmiths/rascal/pull/159 so please consider if it is something you want to have in rascal


share log panel between two routes

@oferitz Fixed what we discussed, may I merge this in?

@sagivf sure


Add dark mode (prefers-color-scheme: dark) to documentation

Migrated from GitLab: https://gitlab.com/meltano/meltano/-/issues/2276
Originally created by @DouweM on 2020-08-18 21:01:44

View 1 previous comment from the original issue on GitLab

Addressed via new docs.

@tayloramurphy This will be addressed by the doc update Brightscout it working on, right? I'd say it can be closed if that is the case.

Correct!


Intro disappears immediately after starting up neovim

Describe the bug

I got the fresh kickstart installation I haven't changed anything, When i launch neovim the intro screen disappears immediately
To Reproduce

...

Desktop

OS: Arch linux
Terminal: Alacritty

Neovim Version

Latest version

Hi.
What does "latest version" mean please?
What do you see when you run:
nvim --version

from your terminal?

Hi.
What does "latest version" mean please?
What do you see when you run:
nvim --version

from your terminal?

NVIM v0.10.0-dev-2465+ga7788c2e25
Build type: RelWithDebInfo
LuaJIT 2.1.1702233742
Run "nvim -V1 -v" for more info

OK thanks so you're definitely running a recent enough version.
What happens when you type:
nvim --clean

OK thanks so you're definitely running a recent enough version.
What happens when you type:
nvim --clean

it does show the intro

OK.
Did you git clone the kickstart.nvim repository?

Also what happens if you run:
cat  ~/.local/state/nvim/log

I can confirm that I also don't see the intro screen, or to be precise, it shows for a split second and then disappears. It doesn't bother me, but I went and commented out a bunch of plugins to narrow down the cause and it seems that if I disable these plugins then the intro is showing again:

folke/which-key.nvim
nvim-telescope/telescope.nvim
folke/todo-comments.nvim

@n4s3 can you try this change just to confirm we're seeing the same:
diff --git a/init.lua b/init.lua
index 0506b3e..1047598 100644
--- a/init.lua
+++ b/init.lua
@@ -272,6 +272,7 @@ require('lazy').setup {

   { -- Useful plugin to show you pending keybinds.
     'folke/which-key.nvim',
+    enabled = false,
     event = 'VeryLazy', -- Sets the loading event to 'VeryLazy'
     config = function() -- This is the function that runs, AFTER loading
       require('which-key').setup()
@@ -296,6 +297,7 @@ require('lazy').setup {

   { -- Fuzzy Finder (files, lsp, etc)
     'nvim-telescope/telescope.nvim',
+    enabled = false,
     event = 'VeryLazy',
     branch = '0.1.x',
     dependencies = {
@@ -738,7 +740,7 @@ require('lazy').setup {
   },

   -- Highlight todo, notes, etc in comments
-  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },
+  --{ 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },

   { -- Collection of various small independent plugins/modules
     'echasnovski/mini.nvim',

Also what happens if you run:
nvim

and then:
cat  ~/.local/state/nvim/log

Yes I cloned the repo.
thats the outupt of the log
ERR 2024-02-23T21:30:50.667 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:50.688 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:51.377 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:51.571 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:51.626 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.230 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.389 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.552 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.710 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.909 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:52.937 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:53.287 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
[C]: in function 'nvim_exec2'
vim/_editor.lua: in function 'cmd'
.../share/nvim/lazy/which-key.nvim/lua/which-key/layout.lua:97: in function 'trail'
.../share/nvim/lazy/which-key.nvim/lua/which-key/layout.lua:212: in function 'layout'
...al/share/nvim/lazy/which-key.nvim/lua/which-key/view.lua:313: in function 'on_keys'
...al/share/nvim/lazy/which-key.nvim/lua/which-key/view.lua:255: in function 'open'
...al/share/nvim/lazy/which-key.nvim/lua/which-key/init.lua:49: in function 'show'
[string ":lua"]:1: in main chunk
ERR 2024-02-23T21:30:53.379 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-23T21:30:54.695 nvim.26680.0 decor_provider_invoke:47: error in provider treesitter/highlighter:line: Error executing lua: /usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: Invalid 'col': out of range
stack traceback:
[C]: in function 'nvim_buf_set_extmark'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:263: in function 'fn'
/usr/share/nvim/runtime/lua/vim/treesitter/languagetree.lua:345: in function 'for_each_tree'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:214: in function 'on_line_impl'
/usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:290: in function </usr/share/nvim/runtime/lua/vim/treesitter/highlighter.lua:284>
ERR 2024-02-28T01:19:58.095 nvim.716.0 loop_close:174: uv_loop_close() hang?
[--I] signal   0x63ca8d3beaa8
[-AI] async    0x63ca8d3be8f0
[R--] check    0x63ca8dd16d70

I can confirm that I also don't see the intro screen, or to be precise, it shows for a split second and then disappears. It doesn't bother me, but I went and commented out a bunch of plugins to narrow down the cause and it seems that if I disable these plugins then the intro is showing again:
* folke/which-key.nvim

* nvim-telescope/telescope.nvim

* folke/todo-comments.nvim

@n4s3 can you try this change just to confirm we're seeing the same:
diff --git a/init.lua b/init.lua
index 0506b3e..1047598 100644
--- a/init.lua
+++ b/init.lua
@@ -272,6 +272,7 @@ require('lazy').setup {

   { -- Useful plugin to show you pending keybinds.
     'folke/which-key.nvim',
+    enabled = false,
     event = 'VeryLazy', -- Sets the loading event to 'VeryLazy'
     config = function() -- This is the function that runs, AFTER loading
       require('which-key').setup()
@@ -296,6 +297,7 @@ require('lazy').setup {

   { -- Fuzzy Finder (files, lsp, etc)
     'nvim-telescope/telescope.nvim',
+    enabled = false,
     event = 'VeryLazy',
     branch = '0.1.x',
     dependencies = {
@@ -738,7 +740,7 @@ require('lazy').setup {
   },

   -- Highlight todo, notes, etc in comments
-  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },
+  --{ 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },

   { -- Collection of various small independent plugins/modules
     'echasnovski/mini.nvim',

I tried it nothing changed

@n4s3 are you using the plain text mode nvim or any of the gui frontends? (using the gui frontends I also never get the intro but in text mode it shows)
Did the intro show up for you before the kickstart rewrite?
You can try by checking out this commit which is the last one before the rewrite:
2024-02-05 7af594f rgarber11 Add Build Step to LuaSnip (#611)

Yeah I'm seeing no intro on Mac either.
I suppose this is one of those "Advanced users won't care but new users will" scenarios.

@n4s3 are you using the plain text mode nvim or any of the gui frontends? (using the gui frontends I also never get the intro but in text mode it shows)
Did the intro show up for you before the kickstart rewrite? You can try by checking out this commit which is the last one before the rewrite:
2024-02-05 7af594f rgarber11 Add Build Step to LuaSnip (#611)

yes it did

I can confirm that I also don't see the intro screen, or to be precise, it shows for a split second and then disappears. It doesn't bother me, but I went and commented out a bunch of plugins to narrow down the cause and it seems that if I disable these plugins then the intro is showing again:
* folke/which-key.nvim

* nvim-telescope/telescope.nvim

* folke/todo-comments.nvim

@n4s3 can you try this change just to confirm we're seeing the same:
diff --git a/init.lua b/init.lua
index 0506b3e..1047598 100644
--- a/init.lua
+++ b/init.lua
@@ -272,6 +272,7 @@ require('lazy').setup {

   { -- Useful plugin to show you pending keybinds.
     'folke/which-key.nvim',
+    enabled = false,
     event = 'VeryLazy', -- Sets the loading event to 'VeryLazy'
     config = function() -- This is the function that runs, AFTER loading
       require('which-key').setup()
@@ -296,6 +297,7 @@ require('lazy').setup {

   { -- Fuzzy Finder (files, lsp, etc)
     'nvim-telescope/telescope.nvim',
+    enabled = false,
     event = 'VeryLazy',
     branch = '0.1.x',
     dependencies = {
@@ -738,7 +740,7 @@ require('lazy').setup {
   },

   -- Highlight todo, notes, etc in comments
-  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },
+  --{ 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },

   { -- Collection of various small independent plugins/modules
     'echasnovski/mini.nvim',

It might be todo-comments then, that's the only one in the 3 that I use in my personal non-kickstart config and I started noticing similar things

Confirmed on my personal config, it seems to be todo-comments
Closed upstream as wontfix, telling users to defer loading of the plugin in config
https://github.com/folke/todo-comments.nvim/issues/210#issuecomment-1586651694

When I change the todo-comments line to:
{ 'folke/todo-comments.nvim', event = 'VimEnter', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false }},
in init.lua, I still see a vanishing intro screen with the latest kickstart.
Am I doing it wrong somehow?

which-key and telescope both declare their own highlight groups I believe. That makes sense, they both have their own UIs.

I wish there were a way to single step through Neovim as it starts up so we could see which plugin does this first.

I think this happens when you tell a plugin to load VeryLazy. I have tried removing it from all plugins and the intro reappears again.

This changes fixed it for me:
diff --git a/init.lua b/init.lua
index fd04574..b4370bb 100644
--- a/init.lua
+++ b/init.lua
@@ -269,7 +269,7 @@ require('lazy').setup {

   { -- Useful plugin to show you pending keybinds.
     'folke/which-key.nvim',
-    event = 'VeryLazy', -- Sets the loading event to 'VeryLazy'
+    event = 'VimEnter', -- Sets the loading event to 'VeryLazy'
     config = function() -- This is the function that runs, AFTER loading
       require('which-key').setup()

@@ -294,7 +294,7 @@ require('lazy').setup {

   { -- Fuzzy Finder (files, lsp, etc)
     'nvim-telescope/telescope.nvim',
-    event = 'VeryLazy',
+    event = 'VimEnter',
     branch = '0.1.x',
     dependencies = {
       'nvim-lua/plenary.nvim',
@@ -735,7 +735,7 @@ require('lazy').setup {
   },

   -- Highlight todo, notes, etc in comments
-  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },
+  { 'folke/todo-comments.nvim', event = 'VimEnter', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },

   { -- Collection of various small independent plugins/modules
     'echasnovski/mini.nvim',

I can confirm that the above patch fixes the issue for me. @taliraj I would suggest you open a PR with the fix, but note that the comment also needs to be updated (Sets the loading event to 'VimEnter')
But I find it strange that this works because I thought that VeryLazy is triggered after VimEnter, at least that what lazy.nvim says:

VeryLazy: triggered after LazyDone and processing VimEnter auto commands

Perhaps there are details not explained in the above description or there's a bug in the VeryLazy event implementation... who knows.

My understanding is that VimEnter happens prior to the first UI draw (see also UIEnter), whereas VeryLazy happens possibly after.

Seems like VeryLazy is typically triggered after UIEnter. https://github.com/folke/lazy.nvim/blob/aedcd79811d491b60d0a6577a9c1701063c2a609/lua/lazy/core/util.lua#L145

I see this issue has already been raised in https://github.com/folke/lazy.nvim :
https://github.com/folke/lazy.nvim/issues/1335
https://github.com/folke/lazy.nvim/issues/1038
both issues closed with no fix.

After UIEnter (VeryLazy) there's no way to avoid the problem. Lazy's docs say that VeryLazy should be used for things "not important for initial UI" (= can cause redraws on load). Folke has said repeatedly that there's no way to work around this in Lazy as its not a bug.
VimEnter or LazyDone are most likely to work, some people said that UIEnter can also be used and is the latest possible point you can use.

@LunarLambda thanks for the explanation, I think I understand now, so any plugin that refreshes the UI needs to be loaded before the UIEnter, if you want to keep the intro screen intact. So the event = 'VimEnter' seems to be a proper fix.
I played around a bit with some debugging so that I can understand better what is going on, this is the order of events (with the VimEnter fix):
User LazyPlugins
User LazyDone
VimEnter
config: which-key (VimEnter)
config: todo-comments (event = VimEnter)
config: telescope (event = VimEnter)
UIEnter
User LazyVimStarted
User LazyLoad
User LazyRender
User VeryLazy
User MasonToolsUpdateCompleted

This is the patch I used to log the events:
diff --git a/init.lua b/init.lua
index 3f53732..02ebe89 100644
--- a/init.lua
+++ b/init.lua
@@ -84,6 +84,18 @@ I hope you enjoy your Neovim journey,
 P.S. You can delete this when you're done too. It's your config now! :)
 --]]

+evlog = ''
+local done = {}
+vim.api.nvim_create_autocmd({ 'VimEnter', 'UIEnter', 'User' }, {
+  callback = function(ev)
+    evstr = ev.event .. ' ' .. ev.match
+    if not done[evstr] then
+      evlog = evlog .. evstr .. '\n'
+    end
+    done[evstr] = true
+  end,
+})
+
 -- Set <space> as the leader key
 -- See `:help mapleader`
 --  NOTE: Must happen before plugins are loaded (otherwise wrong leader will be used)
@@ -269,8 +281,10 @@ require('lazy').setup {

   { -- Useful plugin to show you pending keybinds.
     'folke/which-key.nvim',
-    event = 'VeryLazy', -- Sets the loading event to 'VeryLazy'
+    event = 'VimEnter', -- Sets the loading event to 'VimEnter'
     config = function() -- This is the function that runs, AFTER loading
+      --print('which-key config (event = VimEnter)')
+      evlog = evlog .. 'config: which-key (VimEnter)\n'
       require('which-key').setup()

       -- Document existing key chains
@@ -293,7 +307,7 @@ require('lazy').setup {

   { -- Fuzzy Finder (files, lsp, etc)
     'nvim-telescope/telescope.nvim',
-    event = 'VeryLazy',
+    event = 'VimEnter',
     branch = '0.1.x',
     dependencies = {
       'nvim-lua/plenary.nvim',
@@ -318,6 +332,7 @@ require('lazy').setup {
       -- { 'nvim-tree/nvim-web-devicons' }
     },
     config = function()
+      evlog = evlog .. 'config: telescope (event = VimEnter)\n'
       -- Telescope is a fuzzy finder that comes with a lot of different things that
       -- it can fuzzy find! It's more than just a "file finder", it can search
       -- many different aspects of Neovim, your workspace, LSP, and more!
@@ -734,7 +749,12 @@ require('lazy').setup {
   },

   -- Highlight todo, notes, etc in comments
-  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false } },
+  { 'folke/todo-comments.nvim', dependencies = { 'nvim-lua/plenary.nvim' }, opts = { signs = false },
+    event = 'VimEnter',
+    config = function()
+      evlog = evlog .. 'config: todo-comments (event = VimEnter)\n'
+    end,
+  },

   { -- Collection of various small independent plugins/modules
     'echasnovski/mini.nvim',

Happy I could help out :)


I can't image the chance to POST to "https://smba.trafficmanager.net"

Take the direct line as example, we post to "https://directline.botframework.com", when should we post to "https://smba.trafficmanager.net" ?
And I have tried via the tool of PostMan to post to "https://directline.botframework.com", the response is "Unauthenticated".  The following is the request content and response.
[Request]
POST /apis/v3/conversations HTTP/1.1
Host: smba.trafficmanager.net
Content-Type: application/json
Authorization: Bearer [The token I got before]
{
"type": "message",
。。。。。。。
}
[Response]
{
"error": {
"code": "BadArgument",
"message": "Unauthenticated"
}
}

Document Details
⚠ Do not edit this section. It is required for docs.microsoft.com ➟ GitHub issue linking.

ID: 03c49826-bbc8-1589-7b80-ad46c6cbcac6
Version Independent ID: 327925a7-ec0d-0d00-f3c6-16f62cdf05b9
Content: Create a bot with the Bot Connector service - Bot Service
Content Source: articles/rest-api/bot-framework-rest-connector-quickstart.md
Service: bot-service
Product: bot-framework
GitHub Login: @RobStand
Microsoft Alias: kamrani

Doesn't seem possible - closing


Pass font to imagemagick

This fixes an issue with adding images to the image library.
I couldn't figure out why this worked before.
My guess is that somehow image magick has some default font of Arial or Times that it is trying to find. And when ITSI was running on a its old server this font had been installed.
https://www.pivotaltracker.com/story/show/150455863

I've tested this on itsi-test.portal.concord.org and it fixed the problem. So I went ahead and cherry picked it into the 1.18.x branch and tagged that with 1.18.2.  I'll update itsi.portal.concord.org with it tonight.