Client connection frame writer runs into a TCP socket write timeout: {writer,send_failed,timeout}

[GitJadhav]

Describe the bug

The following RabbitMQ error message {writer,send_failed,timeout} closed the AMQP connection , with the following stack trace on the RabbitMQ Server logs

RABBITMQ SERVER LOGS

```

023-12-06 08:29:20.599227-08:00 [error] <0.20029.3> closing AMQP connection <0.20029.3> (10.135.45.50:44966 -> 10.61.253.65:5671):
2023-12-06 08:29:20.599227-08:00 [error] <0.20029.3> {writer,send_failed,timeout}
2023-12-06 08:30:17.035437-08:00 [warning] <0.32602.3> closing AMQP connection <0.32602.3> (10.135.45.51:53066 -> 10.61.253.65:5671, vhost: '/iap', user: 'pronghorn'):
2023-12-06 08:30:17.035437-08:00 [warning] <0.32602.3> client unexpectedly closed TCP connection
2023-12-06 08:30:17.037256-08:00 [warning] <0.32605.3> closing AMQP connection <0.32605.3> (10.135.45.51:53076 -> 10.61.253.65:5671, vhost: '/iap', user: 'pronghorn'):
2023-12-06 08:30:17.037256-08:00 [warning] <0.32605.3> client unexpectedly closed TCP connection
2023-12-06 08:30:17.044659-08:00 [info] <0.32640.3> closing AMQP connection <0.32640.3> (10.135.45.51:53084 -> 10.61.253.65:5671, vhost: '/iap', user: 'pronghorn')
2023-12-06 08:30:17.914379-08:00 [info] <0.1509.6> accepting AMQP connection <0.1509.6> (10.135.45.51:35238 -> 10.61.253.65:5671)
2023-12-06 08:30:17.917092-08:00 [info] <0.1506.6> accepting AMQP connection <0.1506.6> (10.135.45.51:35234 -> 10.61.253.65:5671)
2023-12-06 08:30:17.968441-08:00 [info] <0.1506.6> connection <0.1506.6> (10.135.45.51:35234 -> 10.61.253.65:5671): user 'pronghorn' authenticated and granted access to vhost '/iap'
2023-12-06 08:30:17.968975-08:00 [info] <0.1509.6> connection <0.1509.6> (10.135.45.51:35238 -> 10.61.253.65:5671): user 'pronghorn' authenticated and granted access to vhost '/iap'
2023-12-06 08:30:17.995188-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Adding mirror on node rabbit@ppollpghn00072: <26578.4501.1>
2023-12-06 08:30:18.001337-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Adding mirror on node rabbit@ppollpghn00071: <26577.3586.1>
2023-12-06 08:30:20.961830-08:00 [info] <0.1545.6> accepting AMQP connection <0.1545.6> (10.135.45.51:35246 -> 10.61.253.65:5671)
2023-12-06 08:30:21.089238-08:00 [info] <0.1545.6> connection <0.1545.6> (10.135.45.51:35246 -> 10.61.253.65:5671): user 'pronghorn' authenticated and granted access to vhost '/iap'
2023-12-06 08:30:22.472235-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: 0 messages to synchronise
2023-12-06 08:30:22.472546-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: batch size: 4096
2023-12-06 08:30:22.515167-08:00 [info] <0.1557.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: all mirrors already synced
2023-12-06 08:30:22.515392-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: 0 messages to synchronise
2023-12-06 08:30:22.515520-08:00 [info] <0.1532.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: batch size: 4096
2023-12-06 08:30:22.515944-08:00 [info] <0.1559.6> Mirrored queue 'InventoryBulkUpload:39b318c1-9ae8-4c7f-bd69-9700c577e04d' in vhost '/iap': Synchronising: all mirrors already synced
,,,

Sharing the logs seen on the Client side ( Our product )

CLIENT LOGS

``` Dec 06 08:28:51 ppollpghn00092 node[2091259]: 2023-12-06T16:28:51.937Z - error: audit_id=undefined, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@tmobile/app-sync_queue/cog.js:976, message=[ 'ppollpghn00092 is not the working server: ppollpghn0008e.' ] Dec 06 08:28:55 ppollpghn00092 node[2091318]: 2023-12-06T16:28:55.290Z - info: audit_id=98576c40-ba91-424f-b0c4-a5d34290357b, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@tmobile/app-trailblazer/service/business.js:618, message=[ Dec 06 08:28:55 ppollpghn00092 node[2091318]: 'Querying for shelves using this device name input: ARACHR32% - Response from server: Recieved 200 status, body length: 1 - Pronghorn user = ACervan36' Dec 06 08:28:55 ppollpghn00092 node[2091318]: ] Dec 06 08:29:25 ppollpghn00092 node[2090045]: 2023-12-06T16:29:25.294Z - error: audit_id=undefined, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@itential/database/dist/index.js:1, message=[ 'Connection to MongoDB has been lost' ] Dec 06 08:29:26 ppollpghn00092 node[2090045]: 2023-12-06T16:29:26.579Z - error: audit_id=undefined, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@itential/network/dist/Network.js:1, message=[ 'Connection to RabbitMQ has been lost: Unexpected close' ] Dec 06 08:29:26 ppollpghn00092 node[2090045]: [IAP RabbitMQ] IAP listener AMQPCM disconnected. Error: Unexpected close Dec 06 08:29:26 ppollpghn00092 node[2090045]: at succeed (/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/amqplib/lib/connection.js:280:13) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at onOpenOk (/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/amqplib/lib/connection.js:262:5) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at /opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/amqplib/lib/connection.js:165:32 Dec 06 08:29:26 ppollpghn00092 node[2090045]: at /opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/amqplib/lib/connection.js:159:12 Dec 06 08:29:26 ppollpghn00092 node[2090045]: at TLSSocket.recv (/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/amqplib/lib/connection.js:507:12) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at Object.onceWrapper (node:events:627:28) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at TLSSocket.emit (node:events:513:28) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at emitReadable_ (node:internal/streams/readable:578:12) Dec 06 08:29:26 ppollpghn00092 node[2090045]: at processTicksAndRejections (node:internal/process/task_queues:82:21) Dec 06 08:29:26 ppollpghn00092 node[2090045]: 2023-12-06T16:29:26.637Z - error: audit_id=70fd0185-e5a6-4c61-8fdf-75762e26feb5, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@itential/database/dist/index.js:1, message=[ 'Connection to MongoDB has been restored' ] Dec 06 08:29:29 ppollpghn00092 node[2091731]: 2023-12-06T16:29:29.742Z - trace: audit_id=undefined, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@itential/service/dist/Service.js:1, message=[ 'netbrain : has received a emit message of type: 10' ] Dec 06 08:29:51 ppollpghn00092 node[2091259]: 2023-12-06T16:29:51.937Z - error: audit_id=undefined, origin=/opt/Itential/pronghorn/itential-premium-20221-patch2_2022.1.12/node_modules/@tmobile/app-sync_queue/cog.js:976, message=[ 'ppollpghn00092 is not the working server: ppollpghn0008e.' ]

,,,

RESULTS
This caused the current task to stall and our job was stuck in RUNNING state
NOTE - There was no restart of Client Application during this error - {writer,send_failed,timeout}

Reproduction steps

1.Testbed Architecture
Running our software in HA mode ( 3 Servers )
RabbitMQ Server Specs
RabbitMQ 3.11.7 , Erlang 25.2.1
3 Node Cluster
Shovel in on-confirm mode
{rabbitmq_shovel,
[{defaults,
[{prefetch_count,1000},
{ack_mode,on_confirm},
{publish_fields,[]},
{publish_properties,[]},
{reconnect_delay,5}]}]},
2.Running an Application with huge data related workflows
3.RabbitMQ closed AMQP connection for the following error message - {writer,send_failed,timeout}
...

Expected behavior

RabbitMQ write failure due to timeout must not impact inflight jobs in the queue

Additional context

Is there any configuration to enable Retry Mechanism during write failure due to timeout?

GOOGLE RESEARCH
https://groups.google.com/g/rabbitmq-users/c/5gxTSKimLjU
A write to a client connection socket timed out.

[michaelklishin]

The message indicates a TCP socket write failure on the RabbitMQ end. It is a symptom (just like missed heartbeats), not the root cause.

Your applications must be ready to deal with failing TCP connections. Unacknowledged messages on such connections will be automatically requeued
and redelivered (when there is an online consumer to deliver to and the prefetch settings allow for more deliveries to it).

[michaelklishin]

@GitJadhav this is no a bug and RabbitMQ cannot magically avoid TCP socket operation failures.

I don't know what "huge data related workflows" means exactly but large messages in AMQP 0-9-1 are
sent in 128 kiB chunks. This means that even if a message of 1 GiB is sent, it won't be a single massive socket write.

That said, large messages should be put into a suitable blob store and their ID be sent in a message. I'd say anything larger than 32 MiB should be treated that way.

[GitJadhav]

@michaelklishin Thank you for sharing your insights
Sharing the current buffering tuning stats set on our RabbitMQ Server
Path - /etc/rabbitmq/rabbitmq.conf
max_message_size = 536870911 ( default - 128MB , Max - 512MB )
With the above tuning set to 512MB
Our large messages in AMQP 0-9-1 will still be sent in 128kiB chunks??

Path - etc/rabbitmq/rabbitmq-env.conf
RABBITMQ_DISTRIBUTION_BUFFER_SIZE = 2097151 ( default - 192MB , Max - 2GB )

heartbeat = 120

[michaelklishin]

@GitJadhav you do not tune anything with that setting. You simply allow RabbitMQ to accept them. This does not change any TCP socket settings, leave alone any TCP kernel settings.

With messages above 128 MiB you definitely should put them into a blob store, leave along 512 MiB.

And make sure your applications can recover from network failures. For consumers, that's usually fairly straightforward, the algorithm above has been used by several RabbitMQ clients for some ten years.

[michaelklishin]

Please ask yourself what does RABBITMQ_DISTRIBUTION_BUFFER_SIZE control and what does the exception tell you.

The exception tells you that a client connection socket write has experienced a timeout. RABBITMQ_DISTRIBUTION_BUFFER_SIZE is a runtime setting for inter-node communication. Which may also need bumping for environments that may use large messages but it has nothing to do with the exception in question.

Storing large messages in a blob store and passing around their IDs (in messages) will avoid the problem entirely. This and many others, such as consumers performing large heap allocations when a delivery arrives.

[GitJadhav]

@michaelklishin
Thank you for sharing pointers on "automatic requeuing" and "network failures handling" - researching on those atm
Reviewing our RabbitMQ config for TCP socket settings to see if there is any parameter that can be set to handle the TCP socket operation failures
Researching on this options

• Audit our file handlers and ensure its quite large enough
• TCP keep alive or any other rabbitmq TCP socket timeout settings that can be increased as a preventive measure
• Network failures section has a mention of retry logic

I appreciate if you can spare few minutes and provide some assist - TY

CURRENT RABBITMQ CONFIG

``` RabbitMQ Conf Settings 
 listeners.tcp = none # configure tcp listener tcp_listen_options.backlog = 1024 tcp_listen_options.nodelay = true

Current settings running “rabbitmqctl environment “
{tcp_listen_options,[{nodelay,true},{backlog,1024}]},
{tcp_listeners,[]},
{channel_operation_timeout,15000} - ( Range - ?? )

FD descriptors setting - rabbitmqctl status
File Descriptors
Total: 1953, limit: 32671
Sockets: 1947, limit: 29401

Do I need to tune this parameters to extend TCP timeout ??
What command will help me determine our current settings for these listed parameters
tcp_listen_options.linger.on = true ( Is this default - true ??)
tcp_listen_options.linger.timeout = 0 ( Range - ? Is this in sec ? )
tcp_listen_options.sndbuf = ( Is default 128KiB)
tcp_listen_options.recbuf = ( Is default 128KiB )
,,,

[mohanrajanna15]

@michaelklishin How can we get someone to respond to above query? Should we purchase any services from RabbitMQ? Any thoughts can be shared here is appreciated.

[lukebakken]

You can purchase RabbitMQ support from VMware/Broadcom:

https://tanzu.vmware.com/rabbitmq/oss

[michaelklishin]

@GitJadhav I don't understand what your question really is. There isn't a single magical parameter that can help you avoid TCP connection failures. They are inevitable, for clients specifically.

RabbitMQ documentation has large portions of several doc guides or focussed sections in client library docs that explain various failure scenarios and what features are available (as well as what guarantees are and are not offered by them).

Our team won't be doing company-specific audits for free.

[michaelklishin]

Bumping TCP timeouts, or timeouts in general, is not a magical solutions. In fact, there are features in application-level protocols that exist to explicitly undo very long TCP timeouts that are simply not practical in modern distributed systems.

It's the resiliency of applications and key data safety features (publisher confirms, consumer acknowledgements, quorum queues and streams) that you should spend your time on, not bumping timeouts.