consumer disconnects with no reason

[Yair Ogen]

I have a very strange situation. 

Using amqp-client latest (3.6.1), I register a consumer handler.

If I use auto-ack - all is ok. However, I need to selectively ack or nack later in my application. I therefor disable auto-ack and I use the channel number to acquire the channel later on and call cak or nack as needed. The code tro ack or nack is done in another thread.

In this scenario not all my messages are nacked and I see the consumer disconnects although no apparent reason. No errors in the log.

Could there be some race condition on the channel?

[Izek Greenfield]

I Have the same problem!!

[Michael Klishin]

Have you inspected RabbitMQ logs? Have you enabled automatic connection recovery?

On Thu, Apr 7, 2016 at 12:41 PM, Izek Greenfield <ize...@gmail.com> wrote:

I Have the same problem!!

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Yair Ogen]

Michael,

Do you mean the server logs? Because client lib doesn't log anything.

Yes, we are using auto recovery and it works fine for cases where server restarts or in a cluster where one node fails clients reconnect to another nodes in the cluster.  

I suspect a different issue here.

[Michael Klishin]

Yes, server logs. All channel-level exceptions are logged (and a channel exception closes the channel,

so all consumers it might have will also be gone).

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Yair Ogen]

Log file is empty, but startup log is full of these events (>200M of errors in startup):

Error in log handler
====================
Event: {info_msg,<0.165.0>,
                 {<0.166.0>,"Starting RabbitMQ ~s on Erlang ~s~n~s~n~s~n",
                  ["3.5.4","18.1",
                   "Copyright (C) 2007-2015 Pivotal Software, Inc.",
                   "Licensed under the MPL.  See http://www.rabbitmq.com/"]}}
Error: function_clause
Stack trace: [{error_logger_file_h,write_event,
                  [{<0.47.0>,
                    "/var/log/rabbitmq/rab...@rabbitmq001-master.log",[]},
                   {info_msg,<0.165.0>,
                       {<0.166.0>,
                        "Starting RabbitMQ ~s on Erlang ~s~n~s~n~s~n",
                        ["3.5.4","18.1",
                         "Copyright (C) 2007-2015 Pivotal Software, Inc.",
                         "Licensed under the MPL.  See http://www.rabbitmq.com/"]}}],
                  [{file,"error_logger_file_h.erl"},{line,114}]},
              {error_logger_file_h,handle_event,2,
                  [{file,"error_logger_file_h.erl"},{line,79}]},
              {rabbit_error_logger_file_h,safe_handle_event,3,[]},
              {gen_event,server_update,4,[{file,"gen_event.erl"},{line,538}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,520}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,522}]},
              {gen_event,handle_msg,5,[{file,"gen_event.erl"},{line,261}]},
              {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]


              RabbitMQ 3.5.4. Copyright (C) 2007-2015 Pivotal Software, Inc.
  ##  ##      Licensed under the MPL.  See http://www.rabbitmq.com/
  ##  ##
  ##########  Logs: /var/log/rabbitmq/rab...@rabbitmq001-master.log
  ######  ##        /var/log/rabbitmq/rab...@rabbitmq001-master-sasl.log
  ##########

              Starting broker...Error in log handler 

[Yair Ogen]

This seems to be a problem with Erlang 18.1.1. I'm trying to update rabbit server (that turned to be 2.5.x) and re-check.

[Michael Klishin]

That means  RabbitMQ cannot log to a file because you run 3.5.4 on Erlang 18.1.

The oldest version that supports Erlang 18.x is 3.5.7 IIRC.

> --
> You received this message because you are subscribed to the Google Groups "rabbitmq-users"
> group.
> To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.

> To post to this group, send an email to rabbitm...@googlegroups.com.

[Izek Greenfield]

So which erlang version we need for latest rabbitMQ?

[Michael Klishin]

 On 7 April 2016 at 13:39:48, Izek Greenfield (ize...@gmail.com) wrote:
> So which erlang version we need for latest rabbitMQ?

http://www.rabbitmq.com/which-erlang.html describes the minimum required version.

You can run RabbitMQ 3.5.7 or 3.6.x on Erlang 18.x, e.g. 18.3.

[John F]

We would like to know that too.

Is there a page that shows versions of RabbitMQ and the oldest/newest versions of Erlang can be used? Maybe even which OpenSSL version is required?

[Michael Klishin]

For 3.6.x and 3.5.7, there is no upper bound (among officially released versions, at least).

Minimum version requirements are listed on http://www.rabbitmq.com/which-erlang.html.

RabbitMQ
doesn't have an OpenSSL version requirement, use whatever's the latest that you can.
FWIW Erlang/OTP only uses OpenSSL for crypto functions but not TLS sessions/state machine,
so in some cases it is not affected by OpenSSL issues.

[Izek Greenfield]

I install now: 

    erlang 18.3

    rabbitmq 3.6.1

Is that OK?

[Izek Greenfield]

I see in sasl log:

=CRASH REPORT==== 7-Apr-2016::13:57:49 ===
  crasher:
    initial call: rabbit_disk_monitor:init/1
    pid: <0.8448.17>
    registered_name: []
    exception exit: unsupported_platform
      in function  gen_server:init_it/6 (gen_server.erl, line 344)
    ancestors: [rabbit_disk_monitor_sup,rabbit_sup,<0.184.0>]
    messages: []
    links: [<0.191.0>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 6772
    stack_size: 27
    reductions: 7230
  neighbours:

what is that?

[Michael Klishin]

Izek,

Would you mind starting a new thread whenever you have a new question? This error has
nothing to do with consumers. You run on a platform where RabbitMQ cannot
determine the amount of free disk space (on *nix it uses `df`). That is not critical
but leaves a process termination ("crash report" in Erlang terms) log entry.

Then disk monitoring is disabled.

[Yair Ogen]

Michael,

Now we solved the log problem but we don't see any errors.

Any ideas?

[Michael Klishin]

On 7 April 2016 at 14:36:08, Yair Ogen (yair...@gmail.com) wrote:
> Now we solved the log problem but we don't see any errors.
>
> Any ideas?

You can capture what's going on on the wire with Wireshark. Perhaps one of your
apps voluntarily uses basic.cancel to cancel a consumer, or you use exclusive
queues, or something of that kind.

See http://rabbitmq.com/amqp-wireshark.html. The same can be done from the command line,
search for "libpcap."

Many events can be captured with https://github.com/rabbitmq/rabbitmq-event-exchange. 

[Yair Ogen]

Michael,

we run tcp dump and we see a strange reset. we also see the windows size is 0 for some odd reason. could it be we exhaust the tcp window and this caused server to disconnect the client? 

tcp configuration form rabbit server node is:

net.core.rmem_default = 262144
net.core.rmem_max = 4194304
net.core.wmem_default = 262144
net.core.wmem_max = 262144

and attached is a screenshot from wireshark.

[Michael Klishin]

See server log files. When TCP window is full it causes congestion but not disconnection, and RabbitMQ does not control that, the OS does.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.

To post to this group, send email to rabbitm...@googlegroups.com.

[Izek Greenfield]

That what we see in the server logs:

=INFO REPORT==== 10-Apr-2016::17:36:52 ===

accepting AMQP connection <0.20756.81> (127.0.0.1:50140 -> 127.0.0.1:5672)

=WARNING REPORT==== 10-Apr-2016::17:37:07 ===

closing AMQP connection <0.20756.81> (127.0.0.1:50140 -> 127.0.0.1:5672):

client unexpectedly closed TCP connection

=INFO REPORT==== 10-Apr-2016::17:39:13 ===

accepting AMQP connection <0.22200.81> (10.56.177.215:64409 -> 10.56.176.100:5672)

=ERROR REPORT==== 10-Apr-2016::17:39:47 ===

closing AMQP connection <0.22200.81> (10.56.177.215:64409 -> 10.56.176.100:5672):

{writer,send_failed,{error,timeout}}

[Michael Klishin]

On 11 abr 2016, at 8:44, Izek Greenfield <ize...@gmail.com> wrote:

That what we see in the server logs:

=INFO REPORT==== 10-Apr-2016::17:36:52 ===

accepting AMQP connection <0.20756.81> (127.0.0.1:50140 -> 127.0.0.1:5672)

=WARNING REPORT==== 10-Apr-2016::17:37:07 ===

closing AMQP connection <0.20756.81> (127.0.0.1:50140 -> 127.0.0.1:5672):

client unexpectedly closed TCP connection

The above is self-explanatory.

=INFO REPORT==== 10-Apr-2016::17:39:13 ===

accepting AMQP connection <0.22200.81> (10.56.177.215:64409 -> 10.56.176.100:5672)

=ERROR REPORT==== 10-Apr-2016::17:39:47 ===

closing AMQP connection <0.22200.81> (10.56.177.215:64409 -> 10.56.176.100:5672):

{writer,send_failed,{error,timeout}}

This is s TCP write timeout.

Sounds like you want to enable heartbeats with the interval of maybe 10 seconds and automatic connection recovery.

[Izek Greenfield]

Now I see this in logs:

=INFO REPORT==== 11-Apr-2016::10:44:05 ===

accepting AMQP connection <0.12560.100> (10.56.177.215:63482 -> 10.56.176.100:5672)

=ERROR REPORT==== 11-Apr-2016::10:44:41 ===

closing AMQP connection <0.12560.100> (10.56.177.215:63482 -> 10.56.176.100:5672):

{inet_error,enotconn}

[Michael Klishin]

ENOTCONN is also a socket error.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Izek Greenfield]

also we don't see the client do a reconnection after that...

[Izek Greenfield]

And why we don't see any error on the client while this happen we implement the 'ShutdownListener'

[Izek Greenfield]

we add the 'heartbeats' and 'ShutdownListener' we still so connection issues what else could be the cause.  

[Michael Klishin]

Explained in

http://www.rabbitmq.com/heartbeats.html.

Some relevant kernel configuration settings are mentioned in

http://www.rabbitmq.com/networking.html.

On Mon, Apr 11, 2016 at 11:03 AM, Izek Greenfield <ize...@gmail.com> wrote:

And why we don't see any error on the client while this happen we implement the 'ShutdownListener'

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

Also, recovery is implemented using a shutdown listener and user-provided

listeners are currently invoked before it:

https://github.com/rabbitmq/rabbitmq-java-client/pull/136

although it is not common to see complaints about that.

On Mon, Apr 11, 2016 at 11:03 AM, Izek Greenfield <ize...@gmail.com> wrote:

And why we don't see any error on the client while this happen we implement the 'ShutdownListener'

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Izek Greenfield]

We will check the links.

now I see another error:

                        none,0,none,flow,[]}

** Reason for termination ==

** {{badmatch,{error,{channel_operation_timeout,5000}}},

    [{rabbit_channel,terminate,2,[{file,"src/rabbit_channel.erl"},{line,614}]},

     {gen_server2,terminate,3,[{file,"src/gen_server2.erl"},{line,1146}]},

     {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,250}]}]}

** In 'terminate' callback with reason ==

** shutdown

[Michael Klishin]

Search list archives for channel_operation_timeout.

Please consider starting new threads instead of inflating the scope of existing ones. Thank you.

[Izek Greenfield]

This is the same thread. We've seen the error on 5 seconds. so we increased to 15 and still see this error.
We can't understand why the connection is terminated with no trace in client and can't understand the source of disconnect.

[Michael Klishin]

Are there any intermediaries involved, e.g. a load balancer of any kind that clients connect to? If so, see its logs and configuration.

On 11 abr 2016, at 14:08, Izek Greenfield <ize...@gmail.com> wrote:

This is the same thread. We've seen the error on 5 seconds. so we increased to 15 and still see this error.
We can't understand why the connection is terminated with no trace in client and can't understand the source of disconnect.

--

[Izek Greenfield]

no, there is nothing between the server and the client

[Izek Greenfield]

Michael,

I've spent the following hours investigating and I think there's an edge case here not handled by rabbit-client.

If I delayed my off line acks I managed to reproduce the problem and see this stack:

[Exception: java.net.SocketException: Connection reset by peer: socket write error

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:153)

at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)

at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)

at java.io.DataOutputStream.flush(DataOutputStream.java:123)

at com.rabbitmq.client.impl.SocketFrameHandler.flush(SocketFrameHandler.java:150)

at com.rabbitmq.client.impl.AMQConnection.flush(AMQConnection.java:518)

at com.rabbitmq.client.impl.AMQCommand.transmit(AMQCommand.java:125)

at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:334)

at com.rabbitmq.client.impl.AMQChannel.transmit(AMQChannel.java:310)

at com.rabbitmq.client.impl.AMQChannel.transmit(AMQChannel.java:303)

at com.rabbitmq.client.impl.ChannelN.basicAck(ChannelN.java:1043)

at com.rabbitmq.client.impl.recovery.RecoveryAwareChannelN.basicAck(RecoveryAwareChannelN.java:56)

at com.rabbitmq.client.impl.recovery.AutorecoveringChannel.basicAck(AutorecoveringChannel.java:354)

The IOException is thrown to the called API, Why isn't it handled and recovered by AutorecoveringChannel?

Specifically, from the tcpdump (see attached) it seems server correctively sends reset after many client calls with ZeroWindow - but I would argue that client should open new connection for this case.

Further more, it seems I'm not the only one that encountered a problem of rabbit-client not recovering from certain errors hence the birth of this lib:

https://github.com/jhalterman/lyra

What are your thoughts?

[Michael Klishin]

RabbitMQ Java client starts a recovery whenever a shutdown event happens. I/O errors as emitted

by the JDK are the most common cause. The client doesn't know much about TCP edge cases or setup,

and it really can't: if the JDK doesn't throw any exceptions in the I/O loop, as far as RabbitMQ client is concerned,

there is no reason to recover.

Socket write errors, which is what your stack trace suggests, do not currently initiate recovery. The docs make it fairly

clear what automatic recovery does and doesn't do. AutorecoveringChannels in particular **are in no way concerned with connection recovery**

and thus TCP connection loss. Channels are recovered only after their connection is recovered.

Lyra provides more features and tries to cover more cases. I don't remember if it was around when automatic recovery was introduced

into the Java client (circa 2013) but Lyra author is on this list and perhaps can explain why it was originally developed.

We do not recommend for or against Lyra, and have no plans to implement every single

feature that Lyra has. Use it if it works for you.

FWIW you are the first team to report an issue with TCP connection loss of this kind.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Izek Greenfield]

Thanks Michael.
So you're saying we have to deal with this TCP error ourselves or try out Lyra? I.e. now that you do have an actual report of this issue you won't try to address in the core lib?

[Michael Klishin]

We cannot address the root cause: TCP connections being closed. Why I/O exceptions are not thrown

would be interesting to investigate but there is no information about your OS, JDK version, and so on.

I see no reason not to try Lyra. Getting error recovery right is much harder than it sounds.

On Mon, Apr 11, 2016 at 4:43 PM, Izek Greenfield <ize...@gmail.com> wrote:

Thanks Michael.
So you're saying we have to deal with this TCP error ourselves or try out Lyra? I.e. now that you do have an actual report of this issue you won't try to address in the core lib?

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michael Klishin]

Have you checked the SASL log, by the way? It's next to the "regular" RabbitMQ log

and is named accordingly. It contains unhandled exceptions in the server.

If it doesn't have anything relevant I'm at a loss as to why TCP connections can be closed

when congestion control should be applied by the kernel.

[Izek Greenfield]

the SASL log has nothing.

the client run on java1.8 client run on window 10, we see same errors on centos 6.8.

the server run on centos 6.8 latest rabbit and erlang 18.3

[Michael Klishin]

Can you publish a small project that can reproduce the issue?

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Izek Greenfield]

It not so simple from me to build small project for that.

We had test the other driver and get the same behaviour.

I think the main problem that cause the 'ZeroWindow' is the ACK/NACK as I see the server does not get all the ACK my client sends. but the client does think all is ok. so I think the client buffers the acks.... and fill all the buffer. 

[Michael Klishin]

If you mean basic.ack and basic.nack in AMQP 0-9-1, I find it extremely hard to believe that an application layer

protocol can affect TCP behaviour. TCP congestion control is supposed to be transparent to application.

If you can reproduce it with multiple

clients it means the server that closes the connection. Can you post the entire log(s) for a single run of your test?

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Izek Greenfield]

Yes I mean ' basic.ack and basic.nack'. When I run I debug and stop the thread of the ack/nack the application read all the messages. and then if I ack one  by one in debug mode all is working. if I release the breakpoint it stuck.

do you mean application log?   

[Michael Klishin]

 On 12 April 2016 at 14:51:18, Izek Greenfield (ize...@gmail.com) wrote:
> do you mean application log?

I mean RabbitMQ log.

[Artur Drummond]

Hi MK,

I read all the posts and I'm facing the exact same situation.

I'm using RabbitMQ 3.6.5 and a 2 Java (1.8) Clients:

- 1 Client For Posting Messages

- 1 Client For Reading

I can provide you one sample project on github so you can reproduce the problem and try to help us.

I'm not sure if the right place to solve it is on the server side of Rabbit or the client adapter.

We've tried configuring RabbitMQ with the parameters:

{heartbeat, 20}

{rabbit.tcp_listen_options.keepalive, true}

But we've got the same problem: enotcon

Just for the record, the problem occurs in the Customer Client when we force a slow performance (like Thread.Sleep(10)).

Please, say the information that you need to simulate the problem that I'll provide.

On Thursday, April 7, 2016 at 6:39:50 AM UTC-3, Yair Ogen wrote:

I have a very strange situation. 

Using amqp-client latest (3.6.1), I register a consumer handler.

If I use auto-ack - all is ok. However, I need to selectively ack or nack later in my application. I therefor disable auto-ack and I use the channel number to acquire the channel later on and call cak or nack as needed. The code tro ack or nack is done in another thread.

In this scenario not all my messages are nacked and I see the consumer disconnects although no apparent reason. No errors in the log.

Could there be some race condition on the channel?

[Arnaud Cogoluegnes]

A sample project would be welcome. Please tell us more about your environment (OS, RabbitMQ version, Erlang version, exact version of Java).

--

You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.