5 Replies Latest reply on Jun 7, 2012 7:57 PM by clebert.suconic

    Unexpected exception in high rate producer

    into_java

      Hi i am seeing this error in the hornetq module when i try to  send events using a producer at max possible rate ....I suddenly see this exception in my code and have no idea what is causing this...as at the consumer i get all my messages passed on to the producer.

      If any one has any idea let me know

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.1/27]: Caught unexpected exception

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.2/27]: java.lang.NullPointerException

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.3/27]:         at org.hornetq.core.server.impl.ServerSessionIm

      pl.send(ServerSessionImpl.java:992)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.4/27]:         at org.hornetq.core.protocol.core.ServerSession

      PacketHandler.handlePacket(ServerSessionPacketHandler.java:461)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.5/27]:         at org.hornetq.core.protocol.core.impl.ChannelI

      mpl.handlePacket(ChannelImpl.java:471)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.6/27]:         at org.hornetq.core.protocol.core.impl.Remoting

      ConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:451)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.7/27]:         at org.hornetq.core.protocol.core.impl.Remoting

      ConnectionImpl.bufferReceived(RemotingConnectionImpl.java:412)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.8/27]:         at org.hornetq.core.remoting.server.impl.Remoti

      ngServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:459)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.9/27]:         at org.hornetq.core.remoting.impl.netty.HornetQ

      ChannelHandler.messageReceived(HornetQChannelHandler.java:67)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.10/27]:         at org.jboss.netty.channel.SimpleChannelHandle

      r.handleUpstream(SimpleChannelHandler.java:100)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.11/27]:         at org.jboss.netty.channel.StaticChannelPipeli

      ne.sendUpstream(StaticChannelPipeline.java:362)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.12/27]:         at org.jboss.netty.channel.StaticChannelPipeli

      ne$StaticChannelHandlerContext.sendUpstream(StaticChannelPipeline.java:514)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.13/27]:         at org.jboss.netty.channel.Channels.fireMessag

      eReceived(Channels.java:287)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.14/27]:         at org.hornetq.core.remoting.impl.netty.Hornet

      QFrameDecoder2.decode(HornetQFrameDecoder2.java:169)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.15/27]:         at org.hornetq.core.remoting.impl.netty.Hornet

      QFrameDecoder2.messageReceived(HornetQFrameDecoder2.java:134)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.16/27]:         at org.jboss.netty.channel.SimpleChannelUpstre

      amHandler.handleUpstream(SimpleChannelUpstreamHandler.java:80)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.17/27]:         at org.jboss.netty.channel.StaticChannelPipeli

      ne.sendUpstream(StaticChannelPipeline.java:362)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.18/27]:         at org.jboss.netty.channel.StaticChannelPipeli

      ne.sendUpstream(StaticChannelPipeline.java:357)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.19/27]:         at org.jboss.netty.channel.Channels.fireMessag

      eReceived(Channels.java:274)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.20/27]:         at org.jboss.netty.channel.Channels.fireMessag

      eReceived(Channels.java:261)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.21/27]:         at org.jboss.netty.channel.socket.oio.OioWorke

      r.run(OioWorker.java:90)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.22/27]:         at org.jboss.netty.util.ThreadRenamingRunnable

      .run(ThreadRenamingRunnable.java:108)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.23/27]:         at org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.24/27]:         at org.jboss.netty.util.VirtualExecutorService$ChildExecutorRunnable.run(VirtualExecutorService.java:181)

      Jul 28 2011 01:19:48.770 %[ch=ServerSessionPacketHandler][tid=Old I/O server worker (parentId: 845283709, channelId: 1435877627, null => /0.0.0.0:5445)][part=1043.25/27]:         at java.util.concurrent.ThreadPoolExecutor$Wor:

        • 1. Re: Unexpected exception in high rate producer
          clebert.suconic

          What version?

           

          Any logging indicating what happened? I don't have much information here to guess what happened

          • 2. Re: Unexpected exception in high rate producer
            safetytrick

            I'm seeing this same error, sometimes GB of logs in a day. The only way i can clear it up is to delete all of the logs (data and tmp directories in jboss as 7) and restart. I'm using HornetQ bundled with JBoss as 7.1.2

            • 3. Re: Unexpected exception in high rate producer
              clebert.suconic

              @Michael: I had asked "java into" for what version he was using and he never answered, so I couldn't check the exception against any version unless I guessed based on the stack traces.

               

              Can you paste one of these exceptions?

               

              Can you replicate it with a dumb test?

              • 4. Re: Unexpected exception in high rate producer
                safetytrick

                I haven't been able to replicate it with a test.

                 

                There is no stack trace associated with the message, only the line after line of the Old IO Worker message. This can occur while the server is active but most often occurs on server startup. Restarting the server prints out the same set of messages. In some cases the only way to fix the problem has been to delete the journaling files.

                 

                04:57:22,348 WARN  [org.hornetq.core.postoffice.impl.BindingsImpl] (Old I/O server worker (parentId: 801652105, [id: 0x2fc83d89, app02.sb01.ut.us.attask.com/10.42.103.112:5445])) Couldn't find binding with id=4295059667 on routeFromCluster for message=ServerMessage[messageID=4295235231,priority=4, bodySize=1552,expiration=0, durable=true, address=jms.topic.topic/toplinkSynchronization,properties=TypedProperties[{}]]@934126048 binding = BindingsImpl [name=jms.topic.topic/toplinkSynchronization]

                04:57:22,348 WARN  [org.hornetq.core.postoffice.impl.BindingsImpl] (Old I/O server worker (parentId: 801652105, [id: 0x2fc83d89, app02.sb01.ut.us.attask.com/10.42.103.112:5445])) Couldn't find binding with id=4295059667 on routeFromCluster for message=ServerMessage[messageID=4295235234,priority=4, bodySize=1552,expiration=0, durable=true, address=jms.topic.topic/toplinkSynchronization,properties=TypedProperties[{}]]@1751029166 binding = BindingsImpl [name=jms.topic.topic/toplinkSynchronization]

                04:57:22,350 WARN  [org.hornetq.core.postoffice.impl.BindingsImpl] (Old I/O server worker (parentId: 801652105, [id: 0x2fc83d89, app02.sb01.ut.us.attask.com/10.42.103.112:5445])) Couldn't find binding with id=4295059667 on routeFromCluster for message=ServerMessage[messageID=4295235237,priority=4, bodySize=1552,expiration=0, durable=true, address=jms.topic.topic/toplinkSynchronization,properties=TypedProperties[{}]]@431294474 binding = BindingsImpl [name=jms.topic.topic/toplinkSynchronization]

                04:57:22,351 WARN  [org.hornetq.core.postoffice.impl.BindingsImpl] (Old I/O server worker (parentId: 801652105, [id: 0x2fc83d89, app02.sb01.ut.us.attask.com/10.42.103.112:5445])) Couldn't find binding with id=4295059667 on routeFromCluster for message=ServerMessage[messageID=4295235240,priority=4, bodySize=1552,expiration=0, durable=true, address=jms.topic.topic/toplinkSynchronization,properties=TypedProperties[{}]]@1008915893 binding = BindingsImpl [name=jms.topic.topic/toplinkSynchronization]

                04:57:22,352 WARN  [org.hornetq.core.postoffice.impl.BindingsImpl] (Old I/O server worker (parentId: 801652105, [id: 0x2fc83d89, app02.sb01.ut.us.attask.com/10.42.103.112:5445])) Couldn't find binding with id=4295059667 on routeFromCluster for message=ServerMessage[messageID=4295235243,priority=4, bodySize=1552,expiration=0, durable=true, address=jms.topic.topic/toplinkSynchronization,properties=TypedProperties[{}]]@318536939 binding = BindingsImpl [name=jms.topic.topic/toplinkSynchronization]

                • 5. Re: Unexpected exception in high rate producer
                  clebert.suconic

                  It seems that the topic subscription was gone and the server has had still some messages to be sent.

                   

                   

                  I haven't seen this issue before...   (and it doesn't seem related to the issue at the first post here). I would need more information about it.

                   

                   

                  First thing is it would be nice if you could replace hornetq by 2.2.18:

                   

                   

                  using git:

                   

                  git clone git://github.com/hornetq/hornetq.git

                  cd hornetq

                  git checkout HornetQ_2_2_18_AS7_Final

                  ./build.sh

                   

                  and replace the JARs on the application server.

                   

                   

                  (At least that will give us a good baseline).

                   

                   

                  2.2.18 should be production ready.. it's not applied to JBoss 7.1.3 (next) yet as it needs some adaptation in some of their tests, but it's been tested on EAP and it's one of our latest patches.

                   

                   

                   

                  I would need more infomration on how to replay your scenario. A testcase would be great.