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 <[email protected]><[email protected]> Date: Day 3 of week 44 of 2010 -- Chisel e: [email protected] w: http://chizography.net
