Error Frame received errors

[2potatocakes]

Hi guys,

I ran into some probs today on a VM I've got running. I have a backend service manager which I wrote in ruby. Since updating 1 of my VM's from version 1.1.10 to the latest 1.2.2 gem I've been receiving loads of Error messages like these:

27-04-2012 17:21:03 #2860 INFO --: Processing request for service font, worker 1 27-04-2012 17:21:06 #2860 INFO --: Finished processing request for service font, worker 1 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"content-length bytes were read and there was no trailing null byte"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [Arial\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [BatangChe\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [GungsuhChe\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [DaunPenh\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [Estrangelo Edessa\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [Gautami\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [Gulim\r]"} 27-04-2012 17:21:07 #2860 ERROR --: ERROR frame received: {"message"=>"Unable to parser header line [Dotum\r]"} 27-04-2012 17:21:08 #2860 INFO --: Processing request for service font, worker 1 27-04-2012 17:21:10 #2860 INFO --: Finished processing request for service font, worker 1 27-04-2012 17:21:10 #2860 ERROR --: ERROR frame received: {"message"=>"Unexpected ACK received for message-id [ID:uk-towton-01-59246-1335543450997-2:31:-1:1:1]"}

This error occurs when trying to send a response back to ActiveMQ.

If I revert to the older 1.1.10 gem the problem goes away. I've stepped through it on my service manager's end and I can't see anywhere that is "ACK"ing back inappropriately, also I've tried modifying my service manager to ensure the 'content-length' header has been set properly on my end and it is from what I can tell.

As far as I can tell it looks like something's been introduced into one of the latest gem versions? I don't mind taking a look at the stomp gem, I just thought I'd check with you guys first if you've seen this before or if it's already been dealt with recently?

Lucas

[gmallard]

Lucas - We have not seen anything like that. 1.2.2 is known to be running without problems in some fairly large environments.

Do you have a small sample that reproduces this? If so, can you post it?

Question 1: you are using which of:

Stomp::Client
Stomp::Connection

Question 2: Do you have "\r" values embedded in header keys or values anywhere?

Question 3: If you are using a Stomp::Connection, do your 'subscribe' calls use the subscription ID (3rd parameter)?

I suggest you use the optional logging facility to get a better idea of what is happening. See the examples directory, files:

• slogger.rb
• logexamp.rb

Perhaps implement the:

on_subscribe
on_publish
on_receive

methods and dump any available data to a log. In 'on_subscribe' dump the headers. In 'on_publish' dump the entire message.

Unfortunately we do not have a logging callback for 'ack' at present.

If you have time, I would also like to know if the error occurs with 1.2.0 or 1.2.1 gems.

Those "\r" characters are ...... a bit disconcerting.

[gmallard]

Those error messages are definitely from AMQ. See:

https://bitbucket.org/mirror/activemq/src/a35fdd13fb9b/activemq-core/src/main/java/org/apache/activemq/transport/stomp/StompWireFormat.java

Line number 207.

AMQ is not liking something about the headers. I need to see all headers put on to and received from the wire.

Question: what version of AMQ ?

Regarding "\r" characters embedded in headers;

a) This gem can send headers like that b) This gem cannot receive headers like that (even in 1.1.10) c) General info, "\r" is forbidden in STOMP 1.1

[gmallard]

This message:

Unexpected ACK received for message-id 

is easily reproduced by sending ACKs to the broker out of sequence.

Possible?

[2potatocakes]

Hi guy, sorry thought you'd be asleep, I've been playing with it for a couple of hours.. Here's what I've found..

I'm using ActiveMQ 5.5.1 (When running AMQ on windows I cannot replicate this issue) When using ActiveMQ on a CentOS box I do see this issue.

I'm currently using Ruby 1.8.7 and am sending and receiving from a windows machine.

Also this bug was reported to me through someone using my service_manager in the US, but I was able to replicate it here locally as well so it's not just my machine.

I cannot replicate the issue in stomp version 1.1.10, but I can replicate it using 1.2.0, 1.2.1 and 1.2.2

I'm absolutely certain that there are no "\r" characters in the headers as I also parse them in my own code and make sure they're removed.

It's a pain in the butt of a bug because it's not consistently replicable. It occurs occasionally which makes me think it maybe a mutex/thread issue?

[2potatocakes]

You were dead on the money with your AMQ bitbucket link as well. This is what I got when I added your slogger class to a test I was running.. .The java stack trace that came back in the body references the line you found: org.apache.activemq.transport.stomp.StompWireFormat.unmarshal(StompWireFormat.java:109)

Also included my test files..

https://gist.github.com/2565253

[gmallard]

Nice test files, they are excellent. I wish everyone would supply sample code like that.

I have confirmed:

• I can almost totally recreate with Ruby 1.8.7
• I get a variety of other similar failures for various Rubies 1.8.x, 1.9.x, and 2.0.0dev
• Dropping back to gem 1.1.10 indeed appears to work - no exceptions - however I am not yet convinced that all is correct even at that level. Even there, queue display in the AMQ admin console do not look right.

I recreated totally on an Ubuntu box, 11.10. No need for me to even boot a Win VM for testing.

Line # 96 of receiver.rb - I do not know what 'StopServer' is, but it is not defined.

Yep, we are in wildly different time zones ...... I will play with this as the day progresses here.

[gmallard]

There is a clue (I think) on line number 7 of the log file in your docs:

D, [2012-05-01T11:53:03.502290 #3624] DEBUG -- : Subscribe Headers destination/queue/font_requestackclient

That header display should show me a well formed Ruby Hash. I think I am looking at a single String.

Update:

This is a false lead. The example logger code does:

@log.debug "Subscribe Headers #{headers}"

When it should do:

@log.debug "Subscribe Headers #{headers.inspect}"

[gmallard]

Lucas - Possible quick fix / get around - in your senders, do not do:

body = "\x00"

Instead do:

body = ""

Let me know if that clears up any or perhaps all of these issues.

I can and will get around this in the gem but changing your sender(s) might be easier if you are in a hurry. Let me know your thoughts.

If you want to apply a temp patch to the gem, then:

diff --git a/lib/stomp/connection.rb b/lib/stomp/connection.rb
index 84bde52..81beec8 100644
--- a/lib/stomp/connection.rb
+++ b/lib/stomp/connection.rb
@@ -611,7 +611,7 @@ module Stomp
         end
         @transmit_semaphore.synchronize do
           # Handle nil body
-          body = '' if body.nil?
+          body = '' if body.nil? || body == "\x00"
           # The content-length should be expressed in bytes.
           # Ruby 1.8: String#length => # of bytes; Ruby 1.9: String#length => #
           # With Unicode strings, # of bytes != # of characters.  So, use Strin

I truthfully think this result is an AMQ bug exposed by the current gem. Apollo in Stomp 1.0 mode handles your original example fine.

[gmallard]

Notes about the above suggestion:

• it may work in your particular case
• use it with caution, because I do not believe the single byte body of "\x00" is the root cause
• I can recreate this with a single byte body of "Z" or even "ZZTOP" and recreate this problem with your sample code

It seems to be related to the 'response' message ....... at this point.

I will keep looking at this as time permits.

[gmallard]

OoooooK. I think I understand this. All of the above is Guy aiming clay mores at a problem. Ignore it.

Please do this:

• Run a fresh install of 1.2.2
• Apply the patch shown below
• Retest everything and provide feedback

The patch:

diff --git a/lib/stomp/connection.rb b/lib/stomp/connection.rb
index adf59b2..804bbda 100644
--- a/lib/stomp/connection.rb
+++ b/lib/stomp/connection.rb
@@ -596,8 +596,8 @@ module Stomp
           # and ActiveMQ will interpret the message as a TextMessage.
           # For more information refer to http://juretta.com/log/2009/05/24/act
           # Lets send this header in the message, so it can maintain state when
-          headers['content-length'] = "#{body_length_bytes}" unless headers[:su
-          headers['content-type'] = "text/plain; charset=UTF-8" unless headers[
+          headers[:'content-length'] = "#{body_length_bytes}" unless headers[:s
+          headers[:'content-type'] = "text/plain; charset=UTF-8" unless headers
           used_socket.puts command
           headers.each do |k,v|
             if v.is_a?(Array)

[2potatocakes]

I just sat down at my desk.. Looks like you've been busy.. Thanks for your help on this. :)

I'll apply your patch now and give it a go. 2 mins.. just booting everything up

[2potatocakes]

Looks like that's done the trick mate, nice spot! I looked over that method yesterday and didn't notice the unsymbolized keys.. Am glad you spotted it. Have just ran it through a few dozen times and I can't see the issue anymore.

Massively appreciate your help on this! Hope it didn't take up too much of your time. If you ever need anything tested on Windows/CentOS/RedHat/AMQ feel free to drop me a line and I'll see if I can return the favour. Kind Regards, Lucas

[gmallard]

Argh. Just realized that patch is truncated on the right. Thanks for figuring that out.

This will be included in 1.2.3. Keep the patch in the meantime.

Thanks for the offer on testing, will keep that in mind.

I am going to close this issue. Reopen it, or open another if necessary.

Regards, Guy