ActiveMQ Magical Mystery Tour - The 4096 Edition

Chisel chisel at chizography.net
Mon Nov 22 11:36:08 GMT 2010 

 Hi everyone; apologies for being vaguely on-topic. We're having fun with
ActiveMQ and messages where the Net::Stomp frame reaches 4096 characters.

Although it's quite wordy, the internal investigation below describes the
problem far better than I could manage at this time on a Monday.

If anyone has any insight, thoughts, solutions - we'd love to hear from you!


Cheers,


Chiz


Net::Stomp Lost Message Investigation
Table of Contents

   - 1 Problem
   <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-1>
   - 2 Test Environment
   <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-2>
   - 3 Stomp Session Debugging
   <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3>
      - 3.1 Enable stomp debug log in ActiveMQ broker
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_1>
      - 3.2 Net::Stomp script used for broker testing
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_2>
      - 3.3 Stomp Sessions
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_3>
         - 3.3.1 Successful SEND message, failed DISCONNECT message
         <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_3_1>
         - 3.3.2 Failed SEND and DISCONNECT messages
         <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_3_2>
         - 3.3.3 No SEND message
         <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_3_3>
         - 3.3.4 Pause between SEND and DISCONNECT
         <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-3_3_4>
      - 4 TCP Traffic
   <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-4>
      - 4.1 TCP stream of failed messages
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-4_1>
      - 4.2 TCP stream of successful messages
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-4_2>
      - 4.3 TCP stream of messages with pause
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-4_3>
   - 5 AMQ broker log
   <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-5>
      - 5.1 Exception on Stomp message
      <http://10.5.16.35/project/sys-int/stomp-investigation.html#sec-5_1>

  1 Problem

Messages sent to the ActiveMQ broker using Net::Stomp are sometimes lost in
the ether. A failed message is successfully generated and sent by the
Net::Stomp producer, however, it is not enqueued by the broker.
  2 Test Environment

The tests below were executed in the following environment:

   - AMQ broker version 5.3.1 running on Java v1.6.0_20 (svc-oct.dave)
   - Net::Stomp v0.38
   - Producer test script running on Perl v5.8.8 (xtdc1-oct.dave)

The producer tests were repeated on my local debian box with the exact same
results:

   - AMQ broker version 5.3.1 running on Java v1.6.0_20 (svc-oct.dave)
   - Net::Stomp v0.38
   - Producer test script running on Perl v5.10.1

  3 Stomp Session Debugging
 3.1 Enable stomp debug log in ActiveMQ broker

http://activemq.apache.org/stomp.html#Stomp-Debugging
  3.2 Net::Stomp script used for broker testing

sub sender {

    my ($byte_length, $body) = @_;

    my $send = Net::Stomp->new({ hostname => 'svc-oct.dave',
                                 port     => '61613' });

    $send->connect( { login    => 'hello',
                      passcode => 'there' });

    $send->send({ 'destination'    => '/queue/mjr.queue.thing',
                  #'content-length' => $byte_length,
                  'body'           => "$body"
                });

    # uncomment the below line to insert 0.05 second delay
    # usleep 50000;

    $send->disconnect;
}

  3.3 Stomp Sessions
 3.3.1 Successful SEND message, failed DISCONNECT message

Messages that are successfully enqueued appear in the stomp debug log. SEND
message payload 100 characters long. The DISCONNECT message sent immediately
after the SEND does not appear in the debug log.

2010-11-03 15:10:12,245 [10.0.0.1:38379 <http://10.5.0.58:38379>]
TRACE StompTransportFilter           - Received:
CONNECT
passcode:there
login:hello


2010-11-03 15:10:12,245 [10.0.0.1:38379 <http://10.5.0.58:38379>]
TRACE StompTransportFilter           - Sending:
CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180024


2010-11-03 15:10:12,247 [10.5.0.58:38379] TRACE StompTransportFilter
        - Received:
SEND
destination:/queue/mjr.queue.thing

xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

  3.3.2 Failed SEND and DISCONNECT messages

Messages that are not enqueued are not present in the broker's stomp debug
log. SEND message payload 4096 characters long. Both the SEND and DISCONNECT
messages are missing from the debug log.

2010-11-03 15:19:08,718 [10.0.0.1:57192 <http://10.5.0.58:57192>]
TRACE StompTransportFilter           - Received:
CONNECT
passcode:there
login:hello


2010-11-03 15:19:08,718 [10.0.0.1:57192 <http://10.5.0.58:57192>]
TRACE StompTransportFilter           - Sending:
CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180025

  3.3.3 No SEND message

If the SEND message is omitted then the DISCONNECT message is successfully
received.

2010-11-03 15:20:21,397 [10.0.0.1:57197 <http://10.5.0.58:57197>]
TRACE StompTransportFilter           - Received:
CONNECT
passcode:there
login:hello


2010-11-03 15:20:21,397 [10.0.0.1:57197 <http://10.5.0.58:57197>]
TRACE StompTransportFilter           - Sending:
CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180026

2010-11-03 15:20:21,398 [10.0.0.1:57197 <http://10.5.0.58:57197>]
TRACE StompTransportFilter           - Received:
DISCONNECT

  3.3.4 Pause between SEND and DISCONNECT

Inserting a 0.5 second pause between the SEND and DISCONNECT messages
results in both messages being successfully processed. With this pause in
place all SEND payloads are successfully enqueued, regardless of size.

CONNECT
passcode:there
login:hello


2010-11-03 15:27:52,471 [10.0.0.1:53576 <http://10.5.0.58:53576>]
TRACE StompTransportFilter           - Sending:
CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180053


2010-11-03 15:27:52,472 [10.0.0.1:53576 <http://10.5.0.58:53576>]
TRACE StompTransportFilter           - Received:
SEND
destination:/queue/mjr.queue.thing

xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

2010-11-03 15:27:52,522 [10.0.0.1:53576 <http://10.5.0.58:53576>]
TRACE StompTransportFilter           - Received:
DISCONNECT

   4 TCP Traffic
 4.1 TCP stream of failed messages

SEND message with payload of 4096 characters long. The TCP traffic trace
(via wireshark) shows the TCP stream ending in the middle of the SEND
payload. This conversation stops after 4055 characters of the SEND payload.

CONNECT
passcode:there
login:hello

.CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180055

.
SEND
destination:/queue/mjr.queue.thing

xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx…xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
<- [ends here with no null byte]


  4.2 TCP stream of successful messages

SEND message with payload of 100 characters. The TCP traffic trace shows the
TCP stream including the complete SEND command with a terminating null byte,
however, the DISCONNECT command is never sent.

CONNECT
passcode:there
login:hello

.CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180055

.
SEND
destination:/queue/mjr.queue.thing

xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx…xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.


  4.3 TCP stream of messages with pause

SEND message with payload of 4096 characters. Insert 0.5 second pause
between the SEND and DISCONNECT messages. The TCP traffic trace shows the
TCP stream including the complete SEND and DISCONNECT commands and the
corresponding null terminators.

CONNECT
passcode:there
login:hello

.CONNECTED
session:ID:svc-oct.dave.net-a-porter.com-59936-1288280088467-3:180062

.
SEND
destination:/queue/mjr.queue.thing

xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx…xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.DISCONNECT

.


  5 AMQ broker log
 5.1 Exception on Stomp message

Exception appears to be generated on *every* stomp message whether enqueuing
at the broker is successful or not.

java.net.SocketException: Connection reset
  at java.net.SocketInputStream.read(SocketInputStream.java:168)
  at org.apache.activemq.transport.tcp.TcpBufferedInputStream.fill(TcpBufferedInputStream.java:50)
  at org.apache.activemq.transport.tcp.TcpTransport$2.fill(TcpTransport.java:527)
  at org.apache.activemq.transport.tcp.TcpBufferedInputStream.read(TcpBufferedInputStream.java:58)
  at org.apache.activemq.transport.tcp.TcpTransport$2.read(TcpTransport.java:512)
  at java.io.DataInputStream.readByte(DataInputStream.java:248)
  at org.apache.activemq.transport.stomp.StompWireFormat.unmarshal(StompWireFormat.java:157)
  at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:211)
  at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
  at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
  at java.lang.Thread.run(Thread.java:619)


Author: Matthew Ryall
<matt.ryall at net-a-porter.com><matt.ryall at net-a-porter.com>

Date: Day 3 of week 44 of 2010


-- 
Chisel
e: chisel at chizography.net
w: http://chizography.net

More information about the london.pm mailing list