Rabbitmq-server: Connection lost when QoS set to zero

[augi]

Server: RabbitMQ 3.6.0, Erlang 18.2
Client: amqp-client 3.6.5 on JVM 8

There is custom Consumer written in Scala that consumes messages from a queue.

If QoS on the channel is set to zero (or isn't set at all) then following exception appears in our ExceptionHandler (that just logs):

UnexpectedConnectionDriverException on amqp://[email protected]:5672/scavenger

java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.io.BufferedInputStream.fill(Unknown Source)
    at java.io.BufferedInputStream.read1(Unknown Source)
    at java.io.BufferedInputStream.read(Unknown Source)
    at java.io.DataInputStream.readFully(Unknown Source)
    at java.io.DataInputStream.readFully(Unknown Source)
    at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:116)
    at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:138)
    at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:541)
    at java.lang.Thread.run(Unknown Source)

And following basicAck throws this exception:

java.net.SocketException: Connection reset by peer: socket write error
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
    at java.io.BufferedOutputStream.flush(Unknown Source)
    at java.io.DataOutputStream.flush(Unknown Source)
    at com.rabbitmq.client.impl.SocketFrameHandler.flush(SocketFrameHandler.java:149)
    at com.rabbitmq.client.impl.AMQConnection.flush(AMQConnection.java:521)
    at com.rabbitmq.client.impl.AMQCommand.transmit(AMQCommand.java:124)
    at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:333)
    at com.rabbitmq.client.impl.AMQChannel.transmit(AMQChannel.java:309)
    at com.rabbitmq.client.impl.AMQChannel.transmit(AMQChannel.java:302)
    at com.rabbitmq.client.impl.ChannelN.basicAck(ChannelN.java:1042)

The server log contains this error:

=ERROR REPORT==== 26-Oct-2016::00:02:23 ===
closing AMQP connection <0.7908.1769> (10.1.54.70:54182 -> 10.1.54.79:5672):
{writer,send_failed,{error,enotconn}}

If QoS is set to non-zero value then everything works well (there is no crash).

[michaelklishin]

So what is the expectation here? Setting QoS prefetch to 0 makes no sense. I don't think the spec dictates what kind of error should be returned but treating it as a "hard error" (in AMQP 0-9-1 parlance) doesn't sound unreasonable to me. Hard errors result in immediate connection closure.

Can you please post a few earlier log entries and entries around the same time in the SASL log?

[augi]

The problem is that QoS set to 0 is the default in Java client so it's not nice that the server crashes in this default settings. The expectation is that the server shouldn't close the connection, and if it's reasonable to close the connection then it should be done _in a nice way_ (not in a way that leads to UnexpectedConnectionDriverException in Java client).

The surrounding log entries from main log are related to different connections and they have no effect as the crash is 100% reproducible in our environment. SASL log contains no entries related to these incidents (the last messages is more than hour before the crash).

Btw. the connection is not closed immediately after creating the channel, the connection is closed after some time (also some messages are consumed).

[michaelklishin]

If this was the case it would be reported all over the place but you are the first person to report it in at least a few years. By default there is no QoS prefetch value set at all.

If the SASL log contains no entries then there were no unhandled exceptions in the server. This is very likely something application or environment specific. Please take it to rabbitmq-users and provide full logs and a snippet of code (Scala is fine) to reproduce.

[michaelklishin]

If the connection isn't closed immediately — and the reason is ENOTCONN, which means a socket is no longer active — then it's even less clear cut that the QoS setting is to blame.

[michaelklishin]

I cannot reproduce:

scala> val c = cf.newConnection
c: com.rabbitmq.client.Connection = amqp://[email protected]:5672/

scala> val ch = c.createChannel
ch: com.rabbitmq.client.Channel = AMQChannel(amqp://[email protected]:5672/,1)

scala> ch.basicQos(1)

scala> ch.basicQos(1000)

scala> ch.basicQos(0)

scala> ch.basicQos(1000)

// wait for some 10 seconds

scala> ch.isOpen
res4: Boolean = true

scala> c.isOpen
res5: Boolean = true

RabbitMQ log around the time of this experiment:

=INFO REPORT==== 27-Oct-2016::11:18:28 ===
accepting AMQP connection <0.1212.0> (127.0.0.1:49339 -> 127.0.0.1:5672)

[michaelklishin]

Various attempts to reproduce by fiddling with the global setting, adding a consumer or even using prefetchSize (which RabbitMQ does not support):

scala> ch.basicQos(1000, true)

scala> ch.basicQos(1000, false)

scala> ch.basicQos(0, true)

scala> ch.basicQos(0, false)

scala> ch.basicQos(0, 0, true)

scala> ch.basicQos(0, 0, false)

scala> import com.rabbitmq.client.DefaultConsumer
import com.rabbitmq.client.DefaultConsumer

scala> val cons = new DefaultConsumer(ch)
cons: com.rabbitmq.client.DefaultConsumer = com.rabbitmq.client.DefaultConsumer@67cffead

scala> val q = ch.queueDeclare()
q: com.rabbitmq.client.AMQP.Queue.DeclareOk = #method<queue.declare-ok>(queue=amq.gen-ln7CTGgr_nHPVUaT3Hrm_A, message-count=0, consumer-count=0)

scala> q.getQueue
res18: String = amq.gen-ln7CTGgr_nHPVUaT3Hrm_A

scala> ch.basicConsume(q.getQueue, true, cons)
res19: String = amq.ctag-Lj-GB7qzdUqRcxmOA_1nOA

scala> ch.basicQos(0, 0, false)

scala> ch.basicQos(0, 0, true)

scala> ch.basicQos(0)

scala> ch.basicQos(0, true)

scala> ch.basicQos(100, true)

scala> ch.basicQos(0, true)

[augi]

Ok. So it must be something related to our infrastructure. Thank you for your time!

[airuleguy]

Hey @augi, I'm getting the exact same error under the exact same circumstances. Sometimes it takes a pretty long time until I get the

=ERROR REPORT==== 27-Apr-2017::11:23:24 ===
closing AMQP connection <0.14589.1> (172.16.172.183:34993 -> 10.32.98.232:5672):
{writer,send_failed,{error,enotconn}}

But sooner or later, it ends up happening.

Were you able to sort it out?

_A bit of context_
There is one VM with 5 consumers leeching messages from a particular queue. It works just fine for a while, but then all of a sudden I get this enotconn error and all consumers are disconnected (all 5 share the same connection, different channels, so it's pretty evident that when the connection goes kaput, so will all 5 consumers).
When I attempt to restart the consumer application, here's what rabbit says:

=WARNING REPORT==== 27-Apr-2017::11:35:10 ===
closing AMQP connection <0.10232.1> (172.16.172.183:34467 -> 10.32.98.232:5672):
client unexpectedly closed TCP connection

=INFO REPORT==== 27-Apr-2017::11:36:10 ===
accepting AMQP connection <0.22614.1> (172.16.172.183:36559 -> 10.32.98.232:5672)

=INFO REPORT==== 27-Apr-2017::11:36:11 ===
closing AMQP connection <0.22614.1> (172.16.172.183:36559 -> 10.32.98.232:5672)

=INFO REPORT==== 27-Apr-2017::11:36:17 ===
accepting AMQP connection <0.22703.1> (172.16.172.183:36562 -> 10.32.98.232:5672)

=INFO REPORT==== 27-Apr-2017::11:42:38 ===
accepting AMQP connection <0.26651.1> (172.16.172.183:36705 -> 10.32.98.232:5672)

=ERROR REPORT==== 27-Apr-2017::11:43:09 ===
closing AMQP connection <0.22703.1> (172.16.172.183:36562 -> 10.32.98.232:5672):
{writer,send_failed,{error,enotconn}}

Please if this is not the appropriate place to post the question, direct me to wherever it is.

Cheers!

[augi]

I actually wasn't able to fix this issue :( I also tried to use Lyra library without success (it should be handle much more failures than the standard RabbitMQ Java client).

If this kind of error occurs, we re-establish the connection.

[michaelklishin]

enotconn means the the socket is no longer open (connected). This is not an indication of an issue in a client or the server. That happens from time to time just like other socket operation errors.

[airuleguy]

Hey peeps,

Just to let you guys know, I fixed this issue by reducing the amount of prefetchCount messages. Looks like with a big enough prefetchCount, Rabbit may end up not having room in the transport buffer to accommodate its control packets. It all goes downhill from there.

I'm not sure exactly how that works or if it is even true, but it fixed the issue for me and for others out there. KYP on any updates I come across.

Cheers!