search

onebeyond / rascal

A config driven wrapper for amqp.node supporting multi-host connections, automatic error recovery, redelivery flood protection, transparent encryption / decryption and channel pooling.
MIT License
451 stars 69 forks source link

Rascal automatically reconnects but does not resubscribe #175

Closed dg-eparizzi closed 3 years ago

dg-eparizzi commented 3 years ago

When subscribed to a queue configured like this:

"subscriptions": {
    "data_logs_to_influxdb": {
      "queue": "data_logs_to_influxdb",
      "contentType": "application/json",
      "prefetch": 5000
    }
  }

If RabbitMQ is restarted, Rascal detects this and tries to reconnect based on the retry configuration:

"connection": {
    "url": "amqp://rabbitmq:5672",
    "heartbeat": 1,
    "socketOptions": {
      "timeout": 1000
    },
    "retry": {
      "min": 1000,
      "max": 30000,
      "factor": 2,
      "strategy": "exponential"
    }
  }

When RabbitMQ goes back up, Rascal successfully reconnects (I see the connection in RabbitMQ admin UI), but there's no channel. It does not resubscribe to the queue.

What might be the problem here? Using rascal 13.1.0 and handling errors on every place described by the readme (consumer does not crash when RabbitMQ is restarted).

Here are the logs emitted by the consumer (a Nest.js standalone app) when RabbitMQ is restarted.

[Nest] 38   - 10/25/2021, 3:35:03 PM   [MessageBrokerService] RabbitMQ broker error: Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" +34509ms

[Nest] 38   - 10/25/2021, 3:35:03 PM   [MessageBrokerService] Error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" +11ms

[Nest] 38   - 10/25/2021, 3:35:03 PM   @ntegral/nestjs-sentry:  Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" +1ms

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

    at Object.accept (/code/node_modules/amqplib/lib/connection.js:91:15)

    at Connection.mainAccept (/code/node_modules/amqplib/lib/connection.js:64:33)

    at Socket.go (/code/node_modules/amqplib/lib/connection.js:478:48)

    at Socket.emit (events.js:400:28)

    at Socket.emit (domain.js:475:12)

    at emitReadable_ (internal/streams/readable.js:555:12)

    at processTicksAndRejections (internal/process/task_queues.js:81:21)

[Nest] 38   - 10/25/2021, 3:35:05 PM   [MessageBrokerService] RabbitMQ broker error: Error: Failed to connect to: amqp://rabbitmq:5672. Original message was: connect ECONNREFUSED 172.18.0.2:5672 +1629ms

[Nest] 38   - 10/25/2021, 3:35:08 PM   [MessageBrokerService] RabbitMQ broker error: Error: Failed to connect to: amqp://rabbitmq:5672. Original message was: connect ECONNREFUSED 172.18.0.2:5672 +3405ms

[Nest] 38   - 10/25/2021, 3:35:14 PM   [MessageBrokerService] RabbitMQ broker error: Error: Failed to connect to: amqp://rabbitmq:5672. Original message was: connect ECONNREFUSED 172.18.0.2:5672 +5678ms

[Nest] 38   - 10/25/2021, 3:35:27 PM   [MessageBrokerService] RabbitMQ broker error: Error: Failed to connect to: amqp://rabbitmq:5672. Original message was: connect ECONNREFUSED 172.18.0.2:5672 +13660ms
cressie176 commented 3 years ago

Hi @dg-eparizzi,

There's nothing I'm aware of which would cause Rascal not to resubscribe to the consumer after disconnecting. I typically test after any significant change using one of the example projects and a local docker container. If you enable debug, you'll see what Rascal is attempting under the hood. Just set the DEBUG environment variable to rascal:*.

cressie176 commented 3 years ago

There was a similar sounding issue which only manifested using AWS MQ, which was fixed in rascal@13.0.4

Might be worth reading, as it will give you plenty of example debug.

cressie176 commented 3 years ago

One more thought occurs - what version of RabbitMQ are you running and how are you initiating shutdown? The previous time this happened AWS was gracefully closing channels and blocking new ones before dropping the connection. This caused rascal to hang while trying to resubscribe. It's possibly another variation of the same problem.

dg-eparizzi commented 3 years ago

One more thought occurs - what version of RabbitMQ are you running and how are you initiating shutdown? The previous time this happened AWS was gracefully closing channels and blocking new ones before dropping the connection. This caused rascal to hang while trying to resubscribe. It's possibly another variation of the same problem.

I'm just testing this locally using Docker. Latest rabbitmq:3-management image (3.9.8). And I just simply stop and restart the RabbitMQ container. Is that graceful shutdown impeding Rascal to resubscribe to the queue after reconnecting?

cressie176 commented 3 years ago

This is one of the tests that I run, although I was using a slightly older version of rabbitmq:3-management (3.8.14). I've updated the container and re-run my tests everything works fine. Steps to reproduce...

git clone git@github.com:guidesmiths/rascal.git
cd rascal
npm i
cd examples/simple
DEBUG='rascal:*' node index
# observe messages being published and consumed in the other terminal
docker stop $NAME_OF_RABBITMQ_CONTAINER
# observe connection error in the other terminal

docker restart $NAME_OF_RABBITMQ_CONTAINER
# wait for reconnection 
# observe messages being published and consumed in the other terminal

Because rascal waits using an exponential backoff, it can take a little while for the reconnection to be successful. Sample debug as follows...

  rascal:SubscriberSession Acknowledging message: eb996750-90e1-4ab9-a1bf-6e1804d43172 on channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f +996ms
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 4 unacknowledged messages +0ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +997ms
  rascal:Vhost Borrowed confirm channel: 5ab2ad25-4401-4bb1-8a8f-343bbf1ba850. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1s
  rascal:Vhost Releasing confirm channel: 5ab2ad25-4401-4bb1-8a8f-343bbf1ba850. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +3ms
  rascal:Subscription Received message: 77e4a688-7307-413c-a311-b639a9e8e704 from queue: demo_q +1s
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 5 unacknowledged messages +5ms
2021-10-26T15:02:35.348Z: hello world
  rascal:SubscriberSession Acknowledging message: 96c7db4d-d9ad-41f8-b82f-76adf2f2f256 on channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f +996ms
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 4 unacknowledged messages +0ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +998ms
  rascal:Vhost Borrowed confirm channel: 774f3e1e-f72f-4360-832d-14e416871a03. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1s
  rascal:Vhost Releasing confirm channel: 774f3e1e-f72f-4360-832d-14e416871a03. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +4ms
  rascal:Subscription Received message: 337492d4-da34-4136-9a8e-265d04cd1d11 from queue: demo_q +1s
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 5 unacknowledged messages +5ms
2021-10-26T15:02:36.349Z: hello world
  rascal:SubscriberSession Acknowledging message: 7f329900-1c76-4d5c-ab1e-2226dd445fee on channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f +997ms
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 4 unacknowledged messages +0ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +997ms
  rascal:Vhost Borrowed confirm channel: 110d2627-4896-4caa-943f-91a5622b350e. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1s
  rascal:Vhost Releasing confirm channel: 110d2627-4896-4caa-943f-91a5622b350e. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +3ms
  rascal:Subscription Received message: 4b6e70f5-1b1e-4a58-a94e-169a631d7315 from queue: demo_q +1s
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 5 unacknowledged messages +4ms
2021-10-26T15:02:37.351Z: hello world
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:SubscriberSession Acknowledging message: b72121a2-e7f4-4eef-98cf-e02d9d00a85d on channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f +1s
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 4 unacknowledged messages +0ms
  rascal:Vhost Borrowed confirm channel: aa1af3d4-9c63-47a8-9cac-f32cb8bec0d6. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +1ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1s
  rascal:Vhost Releasing confirm channel: aa1af3d4-9c63-47a8-9cac-f32cb8bec0d6. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 4, borrowed: 1, min: 1, max: 5 } +4ms
  rascal:Subscription Received message: 1f785307-2a23-4ebc-87ba-f26dea455f45 from queue: demo_q +1s
  rascal:SubscriberSession Channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f has 5 unacknowledged messages +4ms
2021-10-26T15:02:38.355Z: hello world
  rascal:SubscriberSession Removing channel: 33c2a350-1b8e-4d6c-aca4-bf240b6ee21f from session +332ms
  rascal:Vhost Destroying confirm channel: 774f3e1e-f72f-4360-832d-14e416871a03 for vhost: / due to error or close event +332ms
  rascal:Vhost Destroying confirm channel: 0cc7c929-f323-42ce-ae9d-9b9bcc185474 for vhost: / due to error or close event +0ms
  rascal:Vhost Destroying confirm channel: 5ab2ad25-4401-4bb1-8a8f-343bbf1ba850 for vhost: / due to error or close event +0ms
  rascal:Vhost Destroying confirm channel: aa1af3d4-9c63-47a8-9cac-f32cb8bec0d6 for vhost: / due to error or close event +0ms
  rascal:Vhost Destroying confirm channel: 110d2627-4896-4caa-943f-91a5622b350e for vhost: / due to error or close event +0ms
  rascal:Vhost Handling connection error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" initially from connection: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +0ms
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: / +0ms
  rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +40s
  rascal:Subscription Handling channel error: Connection closed: 320 (CONNECTION-FORCED) with message "CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'" from demo_sub using channel: null +333ms
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:Subscription Subscribing to queue: demo_q +0ms
  rascal:Vhost Requested channel. Outstanding channel requests: 1 +1ms
  rascal:Vhost Will attempt reconnection in in 1047ms +2ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 0, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +661ms
Error: The channel has been closed. Unable to ack message
    at Immediate._onImmediate (/Users/steve/Development/guidesmiths/rascal/lib/amqp/SubscriberSession.js:109:16)
    at processImmediate (internal/timers.js:461:21)
  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: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +389ms
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: / +0ms
  rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +1s
  rascal:Vhost Will attempt reconnection in in 2534ms +5ms
Error: The channel has been closed. Unable to ack message
    at Immediate._onImmediate (/Users/steve/Development/guidesmiths/rascal/lib/amqp/SubscriberSession.js:109:16)
    at processImmediate (internal/timers.js:461:21)
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 1, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +607ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 2, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
Error: The channel has been closed. Unable to ack message
    at Immediate._onImmediate (/Users/steve/Development/guidesmiths/rascal/lib/amqp/SubscriberSession.js:109:16)
    at processImmediate (internal/timers.js:461:21)
  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: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +927ms
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:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +3s
  rascal:Vhost Will attempt reconnection in in 5115ms +1ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 3, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +74ms
Error: The channel has been closed. Unable to ack message
    at Immediate._onImmediate (/Users/steve/Development/guidesmiths/rascal/lib/amqp/SubscriberSession.js:109:16)
    at processImmediate (internal/timers.js:461:21)
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 4, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
Error: The channel has been closed. Unable to ack message
    at Immediate._onImmediate (/Users/steve/Development/guidesmiths/rascal/lib/amqp/SubscriberSession.js:109:16)
    at processImmediate (internal/timers.js:461:21)
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 5, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 6, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 7, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 8, size: 5, available: 5, 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 127.0.0.1:5672 initially from connection: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +29ms
Error: connect ECONNREFUSED 127.0.0.1:5672
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) {
  errno: -61,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 5672
} {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +1ms
  rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +5s
  rascal:Vhost Will attempt reconnection in in 10367ms +1ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 9, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +971ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 10, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 11, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 12, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 13, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 14, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 15, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 16, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 17, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 18, size: 5, available: 5, 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 127.0.0.1:5672 initially from connection: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +365ms
Error: connect ECONNREFUSED 127.0.0.1:5672
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) {
  errno: -61,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 5672
} {
  vhost: '/',
  connectionUrl: 'amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100'
}
  rascal:Vhost Initialising vhost: / +0ms
  rascal:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +10s
  rascal:Vhost Will attempt reconnection in in 17181ms +4ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 19, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +636ms
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 20, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 21, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 22, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 23, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 24, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 25, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 26, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 27, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 28, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 29, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 30, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 31, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 32, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 33, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 34, size: 5, available: 5, borrowed: 0, min: 1, max: 5 } +1s
  rascal:Vhost Requested confirm channel. { vhost: '/', mode: 'confirm', queue: 35, size: 5, available: 5, 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: 2d15e6e4-93ad-48ce-a787-235993e3a195, amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +516ms
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:tasks:createConnection Connecting to broker using url: amqp://guest:***@localhost:5672?heartbeat=10&connection_timeout=10000&channelMax=100 +17s
  rascal:tasks:createConnection Obtained connection: 75db44e2-19a1-4295-bead-c8011be28c84 +10ms
  rascal:tasks:createChannel Creating channel +1m
  rascal:tasks:assertExchanges Asserting exchange: demo_ex +1m
  rascal:tasks:assertQueues Asserting queue: demo_q +1m
  rascal:tasks:applyBindings Binding queue: demo_q to exchange: demo_ex with binding key: a.b.c +1m
  rascal:tasks:closeChannel Closing channel +1m
  rascal:Vhost vhost: / was initialised with connection: 75db44e2-19a1-4295-bead-c8011be28c84 +19ms
  rascal:Vhost Destroying confirm channel: 0cc7c929-f323-42ce-ae9d-9b9bcc185474 for vhost: / +0ms
  rascal:Vhost Destroying confirm channel: 5ab2ad25-4401-4bb1-8a8f-343bbf1ba850 for vhost: / +0ms
  rascal:Vhost Destroying confirm channel: 774f3e1e-f72f-4360-832d-14e416871a03 for vhost: / +1ms
  rascal:Vhost Destroying confirm channel: 110d2627-4896-4caa-943f-91a5622b350e for vhost: / +0ms
  rascal:Vhost Destroying confirm channel: aa1af3d4-9c63-47a8-9cac-f32cb8bec0d6 for vhost: / +0ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost Created confirm channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce from connection: 75db44e2-19a1-4295-bead-c8011be28c84 +4ms
  rascal:Vhost Created confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b from connection: 75db44e2-19a1-4295-bead-c8011be28c84 +0ms
  rascal:Vhost Borrowed confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 35, size: 1, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +37s
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Releasing confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 34, size: 2, available: 0, borrowed: 1, min: 1, max: 5 } +2ms
  rascal:Vhost Borrowed confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 34, size: 2, available: 0, borrowed: 1, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +2ms
  rascal:SubscriberSession Opening subscriber session: amq.ctag-nNd9E68IM-18NVHEkJ314A on channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce +36s
  rascal:Subscription Received message: dd684e0a-ccc9-470e-a11d-d52f414a3675 from queue: demo_q +36s
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 1 unacknowledged messages +0ms
2021-10-26T15:02:39.356Z: hello world
  rascal:Vhost Created confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070 from connection: 75db44e2-19a1-4295-bead-c8011be28c84 +2ms
  rascal:Vhost Borrowed confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 33, size: 2, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +2ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +0ms
  rascal:Vhost Releasing confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 32, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
  rascal:Subscription Received message: eba4eabf-2ae9-43b2-bed0-bb4093c90905 from queue: demo_q +2ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 2 unacknowledged messages +2ms
2021-10-26T15:02:40.356Z: hello world
  rascal:Vhost Borrowed confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 32, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1ms
  rascal:Vhost Releasing confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 31, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
  rascal:Subscription Received message: ff732e2d-4579-4579-8492-4317b3c7c376 from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 3 unacknowledged messages +1ms
2021-10-26T15:02:41.358Z: hello world
  rascal:Vhost Borrowed confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 31, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1ms
  rascal:Subscription Received message: b217c934-15fa-4efc-8bdf-9037455cef9e from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 4 unacknowledged messages +1ms
2021-10-26T15:02:42.361Z: hello world
  rascal:Vhost Releasing confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 30, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 30, size: 3, available: 0, borrowed: 2, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1ms
  rascal:Vhost Created confirm channel: a9b4ae3f-9d51-431c-b9ac-9d9d1090130b from connection: 75db44e2-19a1-4295-bead-c8011be28c84 +1ms
  rascal:Subscription Received message: 149d60e0-da4c-410e-b4d7-e5eb6e3bbbf0 from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 5 unacknowledged messages +1ms
2021-10-26T15:02:43.365Z: hello world
  rascal:Vhost Borrowed confirm channel: a9b4ae3f-9d51-431c-b9ac-9d9d1090130b. { vhost: '/', mode: 'confirm', queue: 29, size: 3, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +2ms
  rascal:Vhost Creating pooled confirm channel for vhost: / +1ms
  rascal:Vhost Releasing confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 28, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Vhost Borrowed confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 28, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +0ms
  rascal:Vhost Releasing confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 27, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Subscription Received message: f5a3d03e-24ca-472a-92d6-c6bbaa38c2f3 from queue: demo_q +2ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 6 unacknowledged messages +2ms
2021-10-26T15:02:44.367Z: hello world
  rascal:Vhost Borrowed confirm channel: c5dfff87-76b3-49cb-a69e-7f9a50c1082b. { vhost: '/', mode: 'confirm', queue: 27, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +1ms
  rascal:Subscription Received message: db435269-ab8a-49d7-b4d0-e534ccc8d760 from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 7 unacknowledged messages +1ms
2021-10-26T15:02:45.367Z: hello world
  rascal:Vhost Releasing confirm channel: a9b4ae3f-9d51-431c-b9ac-9d9d1090130b. { vhost: '/', mode: 'confirm', queue: 26, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Vhost Borrowed confirm channel: a9b4ae3f-9d51-431c-b9ac-9d9d1090130b. { vhost: '/', mode: 'confirm', queue: 26, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +0ms
  rascal:Publication Publishing 37 bytes to confirm exchange: demo_ex with routingKeys: a.b.c +2ms
  rascal:Vhost Releasing confirm channel: 3f31a3eb-6f2b-4657-8aee-6c33cd81b070. { vhost: '/', mode: 'confirm', queue: 25, size: 4, available: 0, borrowed: 3, min: 1, max: 5 } +1ms
  rascal:Subscription Received message: 9cca64e1-7218-49ad-8393-fb6c408f4311 from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 8 unacknowledged messages +2ms
2021-10-26T15:02:47.373Z: hello world
  rascal:Subscription Received message: a6823402-f72e-41e5-b72f-0812fc156a5c from queue: demo_q +1ms
  rascal:SubscriberSession Channel: 0d719c79-debe-41f5-984d-b4920ca6d4ce has 9 unacknowledged messages +0ms
2021-10-26T15:02:46.372Z: hello world
dg-eparizzi commented 3 years ago

The error was in my application. Sorry for the trouble.

cressie176 commented 3 years ago

No trouble. Glad you found it @dg-eparizzi.