5 Replies Latest reply: Jun 7, 2012 7:57 PM by Clebert Suconic RSS

Unexpected exception in high rate producer

java into Newbie

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 Master

    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
    Michael Nielson Newbie

    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 Master

    @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
    Michael Nielson Newbie

    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 Master

    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.