7 Replies Latest reply on Feb 23, 2010 9:51 AM by jmesnil

    Stomp transport - "Connection closed" when sending at high speed

    mjustin

      Hello,

       

      with the current trunk release, I have sucessfully tested sending and receiving of one million messages (producer and consumer running in parallel, on the same Windows Vista system as HornetQ). The producer and consumer console application logs all sent / received messages, which slows down the processing a little.

       

      If I switch off the console log output to test the maximum speed for this configuration, warning messages and stack traces appear in the HornetQ console window. It looks like the broker has lost the connection to the consumer, the stack trace indicates that the exception was thrown in the onSend() method of StompProtocolManager.


      The risk of getting this problem depends on the message count sent in one batch. For example if I send 500 messages (with 500 byte each), sending and receiving works fine (and is very fast, up to 5 messages per millisecond). But for higher message count, the warning occurs very frequently and a high percentage of the messages is lost.

       

      This is the log window output (for every undeliverable message):

       

      [org.hornetq.core.protocol.stomp.StompProtocolManager]  Connection closed org.ho
      rnetq.core.protocol.stomp.StompConnection@df824a
      org.hornetq.core.protocol.stomp.StompException: Not connected
              at org.hornetq.core.protocol.stomp.StompProtocolManager.checkConnected(S
      tompProtocolManager.java:412)
              at org.hornetq.core.protocol.stomp.StompProtocolManager.onSend(StompProt
      ocolManager.java:472)
              at org.hornetq.core.protocol.stomp.StompProtocolManager.doHandleBuffer(S
      tompProtocolManager.java:174)
              at org.hornetq.core.protocol.stomp.StompProtocolManager.access$000(Stomp
      ProtocolManager.java:51)
              at org.hornetq.core.protocol.stomp.StompProtocolManager$1.run(StompProto
      colManager.java:139)
              at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(Ordere
      dExecutorFactory.java:96)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source
      )
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
              at java.lang.Thread.run(Unknown Source)
      [Thread-3 (group:HornetQ-server-threads21726407-16408563)] 17:02:41,404 WARNING
      [org.hornetq.core.protocol.stomp.StompProtocolManager]  Connection closed org.ho
      rnetq.core.protocol.stomp.StompConnection@df824a

       

       

      If time permits I will try to write a test application with the Stomp Java code in HornetQ and on Linux and Windows XP. Maybe it is be a timing problem in the Vista TCP/IP stack. The two Delphi network libraries I am using work in blocking mode and show the same problem.

       

      Regards,

      Michael

        • 1. Re: Stomp transport - "Connection closed" when sending at high speed
          mjustin

          Hello,

           

          here is a JUnit test which shows the problem. It sends 1000 messages in a loop, and the output window will show many 'not connected' warnings unless the Threap.sleep(1) is used. I have attached the full StompTest.java source, which includes the code for message listener.

           


          Update: tests with HornetQ running on Ubunto 9.10 and client on Vista show the same problem.

           

           

           

          Regards,

          Michael Justin

           

           

              public void testSendManyMessages() throws Exception {
                 MessageConsumer consumer = session.createConsumer(queue);

           

                 String frame =
                         "CONNECT\n" +
                                 "login: brianm\n" +
                                 "passcode: wombats\n\n" +
                                 Stomp.NULL;
                 sendFrame(frame);
                 frame = receiveFrame(10000);
                
                 Assert.assertTrue(frame.startsWith("CONNECTED"));   
                
                 consumer.setMessageListener(this);
                
                 frame =
                         "SEND\n" +
                                 "destination:" + getQueuePrefix() + getQueueName() + "\n\n" +
                                 "Hello World" +
                                 Stomp.NULL;   
                 for (int i=1; i <= 1000; i++) {
                    // Thread.sleep(1);
                    sendFrame(frame);
                 }
                 
              }

           

          Nachricht geändert durch Michael Justin

          • 2. Re: Stomp transport - "Connection closed" when sending at high speed
            jmesnil

            Hi Michal,

             

            I've substantially refactored the Stomp code in the trunk based on your feedback.

            Could you give it another go and tell me if you have other issues?

             

            Regarding your test, I've added a modified version to our test suite

            where I have a latch waiting for all messages to be consumed.

            It's disabled by default but you can run it by removing the trailing _.

             

            Thanks for your help,

            jeff

            • 3. Re: Stomp transport - "Connection closed" when sending at high speed
              mjustin

              Hi Jeff,

               

              many thanks for adding the test, I will try if I can get the error again but currently I have no luck receiving messages from the broker with the Delphi client. Sending works fine (the content length header is now always present in the outgoing frames), but no message are visible in JMX console for ExampleQueue. If I run the JUnit tests they run ok, and as I can see there are no changes in the frame layout. So I guess there is something in the environment or the HornetQ core which has changed. Has there been a change which requires some configuration now? I will check again tomorrow morning.

               

              Regards,

              Michael

              • 4. Re: Stomp transport - "Connection closed" when sending at high speed
                mjustin

                Hello,

                 

                it  looks like the StompFrameDecoder is broken. The following Stomp test sends one message to the broker. I have added log lines to the StompFrameDecoder class (see attachment). The broker does not recognize the SEND frame. The broker logs command.length() many times so it looks like there is a loop in the calling code which does not find usable data.

                 

                Michael

                 

                Connecting to URL: stomp://localhost:61613
                Publishing a Message with size 255 to queue: ExampleQueue
                Using non-persistent messages
                Sleeping between publish 0 ms
                send:
                CONNECT

                 

                 

                 

                received:
                CONNECTED
                session:13328393

                 


                Sending message: Message: 0 sent at: 23.02.2010 12:14:13           ...
                send:
                SEND
                destination:jms.queue.ExampleQueue

                 

                Message: 0 sent at: 23.02.2010 12:14:13

                 

                 

                 


                send:
                DISCONNECT

                 

                 

                 

                Done.

                 

                 

                The log:

                 

                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: no contentLength
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: Received CONNECT
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: no contentLength
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: Received CONNECT
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: sending CONNECTED
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: command.length() == 0
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: command.length() == 0
                23.02.2010 12:15:31 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: command.length() == 0
                23.02.2010 12:15:32 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: command.length() == 0
                23.02.2010 12:15:32 org.hornetq.core.logging.impl.JULLogDelegate info
                INFO: command.length() == 0

                • 5. Re: Stomp transport - "Connection closed" when sending at high speed
                  jmesnil

                  I found the issue: the frame decoder was expecting the frame to start with a line containing the command.

                  However if there was empty lines, they were not skipped and the decoded repeatedly refuse to decode the frame.

                   

                  I fixed it by allowing empty lines before the frame's command but you should also check on your side

                  if your client (or your tests) is sending additional empty lines.

                  It's fixed now in the trunk.

                   

                  Regarding the stomp frame decoder, it will be called repeatedly every time netty has received more bytes.

                  If the decoder has enough bytes to decode the whole Stomp frame, it will return the frame. Otherwise, it will

                  return null, telling to netty "call me back later, I need more bytes to decode the frame".

                  • 6. Re: Stomp transport - "Connection closed" when sending at high speed
                    mjustin

                    Thank you for the quick fix! The frames do not contain additional headers, the content sent to the server is just what is shown in my last posting. Maybe it is the trailing newline character at the end of the frames which caused the error?

                     

                    Regarding content-length: is it now defined to include the content-length header in all frames in both directions? I think this was discussed (asking to be sure about the final result). I wiill adapt my sources now to refect this change and include an application-managed content-type header to indicate text or byte content.

                     

                    Michael

                    • 7. Re: Stomp transport - "Connection closed" when sending at high speed
                      jmesnil

                      mjustin wrote:

                       

                      Thank you for the quick fix! The frames do not contain additional headers, the content sent to the server is just what is shown in my last posting. Maybe it is the trailing newline character at the end of the frames which caused the error?

                      I think that was it. The CONNECT frame was correctly decoded but the trailing newline was considered part of the next Stomp frame (SEND) which

                      prevented to decode it properly.

                       

                      mjustin wrote:

                       

                      Regarding content-length: is it now defined to include the content-length header in all frames in both directions? I think this was discussed (asking to be sure about the final result). I wiill adapt my sources now to refect this change and include an application-managed content-type header to indicate text or byte content.

                      You do not need to define the content-length in the SEND frame unless the body contains NULL bytes. In that case, you MUST set the

                      content-length AND finish the frame by a NULL byte too.

                      The MESSAGE frames sent by HornetQ will now always contain the content-length header.

                      You're right: you should better use a user-define header to manage the body type.