[rabbitmq-discuss] Socket Exceptions

[James Wolstenholme]

Hello -

I'm in the early days of testing RabbitMQ and have been experiencing the
symptoms described below when letting my sample applications run
uninterrupted for 500,000 - 1,000,000 messages or so. Unfortunately the
errors appear inconsistently (ie after different numbers of consumed
messages) and do not always appear on every run. I've included the output
from my client application (very similar to the ConsumerMain class included
in the examples - I've also had the 'read timed out' exception raised when
running that class 'as is') as well as the log contents entries from rabbit
at the point of the exception.

Out testing environment is described below.

2x
    * 4 core AMD Opteron
    * 8G memory
    * eth0 interface with MTU set to 9000
    * Centos OS - kernel version 2.6.18

One of these machines is the RabbitMQ server and hosts the consumer
application, the other hosts only the producer application. The rabbit
connection and channel are configured as follows.

Multiple threads are generating messages from the producer application
Version = 1.0.0 alpha
Ack sent = yes, every 50 messages
framesize = 9000 (our message size is 200 objects * 40 bytes + 12 byte
header = 8012 bytes)
queue type = direct
persistent = true (using ChannelN.MINIMAL_PERSISTENT_BASIC_PROPERTIES)
transactional = false

This is designed as a performance test and so is hammering as much load
through the applications as possible. I appreciate that it may be difficult
to diagnose the issue from this description but I would like to know if this
is something that has been seen before or if there is a way I can modify the
level of logging to get more information about the problems from RabbitMQ
itself.

Thanks & regards

James Wolstenholme
Software Engineer


==============
Connection reset
==============

RabbitMQ log

=INFO REPORT==== 30-Jul-2007::14:52:05 ===
Rolling persister log to "/usr/local/lib/erlang/lib/rabbitmq-
server-1.0.0-alpha/mnesia/rabbit/rabbit_persister.LOG.previous"

=ERROR REPORT==== 30-Jul-2007::14:52:42 ===
Reader timeout (3 s) in state frame_header

=INFO REPORT==== 30-Jul-2007::14:53:03 ===
< 0.166.0>: Clean connection shutdown.


Consumer application stdout

     [java] 117544 ms: Received 210538 - 285 since last report (80 Hz) -
objects :  42107600
     [java] AMQConnection.mainLoop: exception java.net.SocketException:
Connection reset
     [java] java.net.SocketException: Connection reset
     [java]     at java.net.SocketInputStream.read(SocketInputStream.java
:168)
     [java]     at java.net.SocketInputStream.read (SocketInputStream.java
:182)
     [java] Shutdown signal terminating consumer.
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketException: Connection reset)
     [java]     at java.io.DataInputStream.readUnsignedByte (
DataInputStream.java:271)
     [java]     at com.rabbitmq.client.Frame.readFrom(Frame.java:84)
     [java]     at com.rabbitmq.client.AMQConnection.readFrame(
AMQConnection.java:212)
     [java]     at com.rabbitmq.client.AMQConnection.mainLoop (
AMQConnection.java:239)
     [java]     at com.rabbitmq.client.AMQConnection$1.run(
AMQConnection.java:131)
     [java]     at java.lang.Thread.run(Thread.java:619)
     [java] Channel 1 received shutdown signal:
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketException: Connection reset)
     [java] Channel 0 received shutdown signal:
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketException : Connection reset)


============
Read timed out
============

RabbitMQ log

=INFO REPORT==== 30-Jul-2007::15:15:01 ===
<0.230.0>: Opening channel 1

=ERROR REPORT==== 30-Jul-2007::15:16:44 ===
Error in process <0.220.0> on node 'rabbit at tfweb01' with exit value:
{{badmatch,{error,closed}},[{rabbit_writer,send,2},{rabbit_writer,internal_send_command,5},{rabbit_writer,do_deliver,9},{rabbit_writer,handle_message,2},{rabbit_writer,mainloop,1}]}


=ERROR REPORT==== 30-Jul-2007::15:16:44 ===
Error in process <0.181.0> on node 'rabbit at tfweb01' with exit value:
{{badmatch,{error,enotconn}},[{rabbit_reader,switch_callback,3},{rabbit_reader,mainloop,1},{rabbit_reader,start_connection,1}]}


=INFO REPORT==== 30-Jul-2007::15:16:44 ===
Requeueing 1 messages, 365175 already on queue


Consumer application stdout

     [java] 101002 ms: Received 66492 - 693 since last report (708 Hz) -
objects :  13298400
     [java] AMQConnection.mainLoop: exception
java.net.SocketTimeoutException: Read timed out
     [java] java.net.SocketTimeoutException: Read timed out
     [java]     at java.net.SocketInputStream.socketRead0 (Native Method)
     [java]     at java.net.SocketInputStream.read(SocketInputStream.java
:129)
     [java]     at java.io.DataInputStream.readFully(DataInputStream.java
:178)
     [java]     at java.io.DataInputStream.readFully (DataInputStream.java
:152)
     [java]     at com.rabbitmq.client.Frame.readFrom(Frame.java:101)
     [java]     at com.rabbitmq.client.AMQConnection.readFrame(
AMQConnection.java:212)
     [java]     at com.rabbitmq.client.AMQConnection.mainLoop (
AMQConnection.java:239)
     [java]     at com.rabbitmq.client.AMQConnection$1.run(
AMQConnection.java:131)
     [java]     at java.lang.Thread.run(Thread.java:619)
     [java] Channel 1 received shutdown signal:
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketTimeoutException: Read timed out)
     [java] Shutdown signal terminating consumer.
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketTimeoutException : Read timed out)
     [java] Channel 0 received shutdown signal:
com.rabbitmq.client.ShutdownSignal (hard error; reason:
java.net.SocketTimeoutException: Read timed out)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.rabbitmq.com/pipermail/rabbitmq-discuss/attachments/20070730/a9b39cff/attachment.htm