stomp payload causes java.lang.NegativeArraySizeException

[drkirwin]

Folks--

Working with 2.1.2.Final and the Stomp protocol (and with a checkout of trunk):

I've got a Scala app which is receiving messages (using Core) and a client (python) sending messages. When I attempt to read the message that gets delivered, I get the following:

     [java] java.lang.NegativeArraySizeException

     [java]      at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readSimpleStringInternal(ChannelBufferWrapper.java:83)

     [java]      at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readStringInternal(ChannelBufferWrapper.java:112)

     [java]      at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readString(ChannelBufferWrapper.java:90)

     [java]      at emme.lib.hornetq.HornetQ$Handler.onMessage(Hornet.scala:213)

     [java]      at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:822)

     [java]      at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:46)

     [java]      at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:940)

     [java]      at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)

     [java]      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

     [java]      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

     [java]      at java.lang.Thread.run(Thread.java:619)

     [java] java.lang.NegativeArraySizeException

     [java] at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readSimpleStringInternal(ChannelBufferWrapper.java:83)

     [java] at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readStringInternal(ChannelBufferWrapper.java:112)

     [java] at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readString(ChannelBufferWrapper.java:90)

     [java] at emme.lib.hornetq.HornetQ$Handler.onMessage(Hornet.scala:213)

     [java] at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:822)

     [java] at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:46)

     [java] at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:940)

     [java] at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)

     [java] at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

     [java] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

     [java] at java.lang.Thread.run(Thread.java:619)

I can get at the data doing something like:

private def mkString(buffer: HornetQBuffer): String =

        new String(buffer.toByteBuffer().asCharBuffer().toString())

When I print out that string, I notice that the first few characters are negative numbers or some sort of prefix to the string itself. It's as if the object that gets passed in is in some sort of serialized format (with most of the format being the actual string). The first character of the string is clipped.

Here's some output from when I used the above charBuffer method to get the string, then printed out the first 10 characters by called toInt on each char in the string and printing it in hex:

     [java] 2010-10-14 17:22:30,079 DEBUG hornetq.HornetQ$Handler -  -- getting msg body

     [java] 2010-10-14 17:22:30,081 DEBUG hornetq.HornetQ$Handler - 100

     [java] 2010-10-14 17:22:30,081 DEBUG hornetq.HornetQ$Handler - 0

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 5431

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 32

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 33

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 34

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 35

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 36

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 39

     [java] 2010-10-14 17:22:30,082 DEBUG hornetq.HornetQ$Handler - 38

     [java] 2010-10-14 17:22:30,082 INFO  hornetq.HornetQ$Handler - size of body 44

     [java] 2010-10-14 17:22:30,082 INFO  hornetq.HornetQ$Handler -  -- creating properties map

     [java] 2010-10-14 17:22:30,083 DEBUG hornetq.HornetQ$Handler -  -- looping through props

     [java] 2010-10-14 17:22:30,095 DEBUG hornetq.HornetQ$Handler -  -- calling handler

     [java] 2010-10-14 17:22:30,097 INFO  actors.ScreenUpdateActor$ - --------------------------------

     [java] 2010-10-14 17:22:30,097 INFO  actors.ScreenUpdateActor$ - RECEIVE:

     [java] 2010-10-14 17:22:30,097 INFO  actors.ScreenUpdateActor$ -  + body: [Ā吱2345698093480598345

     [java] 092309482039842342

     [java] ]

The original data sent was "1234...." etc. So you can see that the first "1" was stuck to the end of the 54 in the fourth line above.

This happens regardless of whether or not I'm using Python's stompy client, or just using telnet. Using telnet (or python), I'm running from a terminal with the following:

LANG=en_US.utf8

Regardless, that NegativeArraySizeException is worrying.

Any tips?

Keith

PS. With 2.2 trunk I was unable to get a telnet session working. Seemed to be unable to deal with me typing in CONNECT<ret>. Threw an exception.

[clebert.suconic]

I thought you would provide a test as we talked over IRC. Anthing you could produce with some instructions and how to run it?

[drkirwin]

Here's the python script:

#!/usr/bin/env python

from stompy.simple import Client
import time

topic="device.screen-update"

screen_msg="""This is a test"""

print "sending message of length", len(screen_msg)
stomp = Client()
stomp.connect(username="guest", password="guest")
stomp.put(screen_msg, destination=topic)

time.sleep(2)
stomp.disconnect()

I'm not sure how to extract my Scala code from the framework in which it's embedded. I'll see what I can do.

To run this on Ubuntu, just:

sudo apt-get install python-stompy

Then you should be able to ./send.py.

[drkirwin]

I've attached a scala test.

This requires Scala 2.8, and can be invoked as:

scala -cp hornetq-core-client.jar:netty.jar ScalaTest.scala

The test will wait for a message sent via the Python script.

[jmesnil]

Keith Irwin wrote:

I can get at the data doing something like:

private def mkString(buffer: HornetQBuffer): String =

        new String(buffer.toByteBuffer().asCharBuffer().toString())

A STOMP message with a text body is stored as a *nullable simple string* inside the HornetQ Core message that you will receive.

To get the String from it, try instead something like:

      private def mkString(buffer: HornetQBuffer): String = buffer.readNullableSimpleString().toString()

      private def mkString(buffer: HornetQBuffer): String = buffer.readNullableSimpleString().toString()

PS. With 2.2 trunk I was unable to get a telnet session working. Seemed to be unable to deal with me typing in CONNECT<ret>. Threw an exception.

What exception did you get?

I checked that the stomp example was working fine in the trunk and I can connect using telnet without any pb.

[drkirwin]

Jeff---

Using the readNullableSimpleString() seems to have solved the problem. Thanks! I suppose my other tests were with the 2.0.0 GA release, and didn't use stomp. Just java apps communicating. Somehow that must have worked. ;)

And now I can move on!

Keith

[drkirwin]

Jeff--

The problem I'm getting with using Stomp via telnet with yesterday's trunk build is the folllowing:

[Old I/O server worker (parentId: 13055716, channelId: 172748, null => localhost/127.0.0.1:61613)] 09:38:36,868 SEVERE [org.hornetq.core.protocol.stomp.StompProtocolManager]  Failed to decode

,\n,hornetq.core.protocol.stomp.StompException: Invalid STOMP frame: C,O,N,N,E,C,T,

at org.hornetq.core.protocol.stomp.StompDecoder.throwInvalid(StompDecoder.java:494)

at org.hornetq.core.protocol.stomp.StompDecoder.decode(StompDecoder.java:305)

at org.hornetq.core.protocol.stomp.StompProtocolManager.handleBuffer(StompProtocolManager.java:160)

at org.hornetq.core.protocol.stomp.StompConnection.bufferReceived(StompConnection.java:260)

at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:459)

at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.messageReceived(HornetQChannelHandler.java:73)

at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:100)

at org.jboss.netty.channel.StaticChannelPipeline.sendUpstream(StaticChannelPipeline.java:362)

at org.jboss.netty.channel.StaticChannelPipeline.sendUpstream(StaticChannelPipeline.java:357)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)

at org.jboss.netty.channel.socket.oio.OioWorker.run(OioWorker.java:90)

at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

at org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)

at org.jboss.netty.util.VirtualExecutorService$ChildExecutorRunnable.run(VirtualExecutorService.java:181)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at java.lang.Thread.run(Thread.java:619)

[Old I/O server worker (parentId: 13055716, channelId: 172748, null => localhost/127.0.0.1:61613)] 09:38:36,868 SEVERE [org.hornetq.core.protocol.stomp.StompProtocolManager]  Failed to decode

,\n,hornetq.core.protocol.stomp.StompException: Invalid STOMP frame: C,O,N,N,E,C,T,

at org.hornetq.core.protocol.stomp.StompDecoder.throwInvalid(StompDecoder.java:494)

at org.hornetq.core.protocol.stomp.StompDecoder.decode(StompDecoder.java:305)

at org.hornetq.core.protocol.stomp.StompProtocolManager.handleBuffer(StompProtocolManager.java:160)

at org.hornetq.core.protocol.stomp.StompConnection.bufferReceived(StompConnection.java:260)

at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:459)

at org.hornetq.core.remoting.impl.netty.HornetQChannelHandler.messageReceived(HornetQChannelHandler.java:73)

at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:100)

at org.jboss.netty.channel.StaticChannelPipeline.sendUpstream(StaticChannelPipeline.java:362)

at org.jboss.netty.channel.StaticChannelPipeline.sendUpstream(StaticChannelPipeline.java:357)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)

at org.jboss.netty.channel.socket.oio.OioWorker.run(OioWorker.java:90)

at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

at org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)

at org.jboss.netty.util.VirtualExecutorService$ChildExecutorRunnable.run(VirtualExecutorService.java:181)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at java.lang.Thread.run(Thread.java:619)

I've attached a screenshot showing what I typed in, and what the result was.

It's as if it's trying to process the frame before I get to the ^@ terminator.

Keith

[jmesnil]

hi keith,

Stomp decoding code was recently rewritten and it is a bit too restrictive.

It does not support additional new lines that are sent from a telnet client between STOMP frames: https://jira.jboss.org/browse/HORNETQ-552

afaik, this should affect only telnet and not other STOMP clients.

[drkirwin]

Jeff--

Yes, the stomp stuff seems to be working fine using 3rd party libs like the one that comes with Python (on the 2.2 snapshot of trunk that I have). Version 2.1.X seems to work fine with telnet.

Keith

[timfox]

Strictly it's invalid to just add extra new lines between STOMP frames and expect them to be ignored, so the server is correct to reject these frames.

Apart from telnet, some STOMP clients, e.g. the PHP client terminates frames with NUL followed by newline, this is also incorrect (should just be NUL).

This results in the next frame having new lines at the beginning of it.

We already have code in place to be permissive around a single new line to allow for the PHP client, but this won't cope with multiple new lines.

If you really want to allow people to hit newline in telnet as many times as they want (not sure this is a good idea), then this could easily be incorporated by modifying the current code slightly:

if (workingBuffer[0] == NEW_LINE)
         {
            // Yuck, some badly behaved STOMP clients add a \n *after* the terminating NUL char at the end of the
            // STOMP
            // frame this can manifest as an extra \n at the beginning when the next STOMP frame is read - we need to
            // deal
            // with this
            offset = 1;
         }
         else
         {
            offset = 0;
         }

Simply allow more than one leading \n and increment the offset appropriately.

[timfox]

Looking at your telnet session you're hitting enter twice between each frame. Simple workaround would be to only hit enter once.

[drkirwin]

Tim--

For the screenshot I supplied, I only hit return once, right after I typed the word CONNECT. The error (which you can see in the log tail session) was generated at that point. Perhaps telnet sent along something before I typed the initial letter C?

Anyway, I guess I don't really care if telnet doesn't work easily with HornetQ STOMP. It's nice to be able to use it to debug, but it's not totally necessary. If fixing this messes up the code or adds in performance probs, it's hardly worth it.

I was mainly interested in alerting you if it was indeed unexpected behavior.

Keith

[timfox]

Keith Irwin wrote:

Tim--

For the screenshot I supplied, I only hit return once, right after I typed the word CONNECT. The error (which you can see in the log tail session) was generated at that point. Perhaps telnet sent along something before I typed the initial letter C?

Anyway, I guess I don't really care if telnet doesn't work easily with HornetQ STOMP. It's nice to be able to use it to debug, but it's not totally necessary. If fixing this messes up the code or adds in performance probs, it's hardly worth it.

I was mainly interested in alerting you if it was indeed unexpected behavior.

Keith

Yeah, perhaps telnet is sending some strange stuff. Am supposed to be on hols but this is a 5 min thing - I added some better logging on invalid frames in TRUNK, if you try again from there it should dump exactly what it got on the server.