You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by craig mcmillan <cr...@trampolinesystems.com> on 2009/07/21 14:30:16 UTC
NPE in broker => inoperative broker
hi,
i'm seeing an NPE in my broker, after which the broker is inoperable
without a restart. below is the amq related logging upto the first
occurence of the NPE. there's no obvious cause, and prior to the NPE
the broker had been working fine for 19 hours or so, logging pretty
much nothing, and had processed a few hundred thousand messages
ring any bells with anyone ?
thanks
craig
-------------------------------->
20 Jul 2009 14:01:21,134 INFO [BrokerService] (main:) - Using
Persistence Adapter: AMQPersistenceAdapter(/home/sonar/sonar/
local_storage/production_devcrunch01-reeep/amq)
20 Jul 2009 14:01:21,219 INFO [KahaStore] (main:) - Kaha Store using
data directory /home/sonar/sonar/local_storage/production_devcrunch01-
reeep/amq/kr-store/state
20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - ActiveMQ
5.2.0 JMS Message Broker (sonar-production-devcrunch01-reeep) is
starting
20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - For help or
more information please see: http://activemq.apache.org/
20 Jul 2009 14:01:21,527 INFO [KahaStore] (main:) - Kaha Store using
data directory /home/sonar/sonar/local_storage/production_devcrunch01-
reeep/amq/kr-store/data
20 Jul 2009 14:01:21,595 INFO [TransportServerThreadSupport] (main:)
- Listening for connections at: tcp://devcrunch01:50639
20 Jul 2009 14:01:21,667 INFO [TransportConnector] (main:) -
Connector openwire Started
20 Jul 2009 14:01:21,668 INFO [BrokerService] (main:) - ActiveMQ JMS
Message Broker (sonar-production-devcrunch01-reeep,
ID:devcrunch01-55590-1248098481379-0:0) started
20 Jul 2009 14:02:19,904 INFO [DiscoveryTransport] (Multicast
Discovery Agent Notifier:) - Adding new broker connection URL: tcp://
devcrunch01:50639
20 Jul 2009 14:02:19,934 INFO [FailoverTransport] (ActiveMQ Task:) -
Successfully connected to tcp://devcrunch01:50639
20 Jul 2009 14:36:24,989 INFO [DiscoveryTransport] (Multicast
Discovery Agent Notifier:) - Adding new broker connection URL: tcp://
devcrunch01:50639
20 Jul 2009 19:53:24,757 INFO [DiscoveryTransport] (Multicast
Discovery Agent Notifier:) - Adding new broker connection URL: tcp://
devcrunch01:50639
20 Jul 2009 19:53:25,249 WARN [FailoverTransport] (ActiveMQ
Transport: tcp://localhost/127.0.0.1:50639:) - Transport failed to
tcp://devcrunch01:50639 , attempting to automatically reconnect due
to: java.net.SocketException: Connection reset
20 Jul 2009 19:53:25,322 INFO [FailoverTransport] (ActiveMQ Task:) -
Successfully reconnected to tcp://devcrunch01:50639
21 Jul 2009 09:03:59,091 INFO [DiscoveryTransport] (Multicast
Discovery Agent Notifier:) - Adding new broker connection URL: tcp://
devcrunch01:50639
21 Jul 2009 09:03:59,341 INFO [FailoverTransport] (ActiveMQ Task:) -
Successfully reconnected to tcp://devcrunch01:50639
21 Jul 2009 09:03:59,362 WARN [FailoverTransport] (InactivityMonitor
Async Task: java.util.concurrent.ThreadPoolExecutor$Worker@719bd84b:)
- Transport failed to tcp://devcrunch01:50639 , attempting to
automatically reconnect due to:
org.apache.activemq.transport.InactivityIOException: Channel was
inactive for too long: localhost/127.0.0.1:50639
21 Jul 2009 09:04:14,136 ERROR [Service] (ActiveMQ Transport: tcp:///
127.0.0.1:55870:) - Async error occurred: java.lang.NullPointerException
java.lang.NullPointerException
at org.apache.activemq.broker.region.Queue.send(Queue.java:328)
at
org
.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:
350)
at
org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:
437)
at
org
.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:
224)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)
at
org
.apache
.activemq
.broker
.CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
at
org
.apache
.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:133)
at
org
.apache
.activemq
.broker.TransportConnection.processMessage(TransportConnection.java:450)
at
org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:
639)
at
org
.apache
.activemq.broker.TransportConnection.service(TransportConnection.java:
305)
at org.apache.activemq.broker.TransportConnection
$1.onCommand(TransportConnection.java:179)
at
org
.apache
.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at
org
.apache
.activemq
.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:143)
at
org
.apache
.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:
206)
at
org
.apache
.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:
203)
at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:
185)
at java.lang.Thread.run(Thread.java:619)
Re: NPE in broker => inoperative broker
Posted by craig mcmillan <cr...@trampolinesystems.com>.
thanks gary,
here's the jira : https://issues.apache.org/activemq/browse/AMQ-2329
tcp:///127.0.0.1:55870 is a client connection : there were two client
connections, both tcp, one from in-vm, producing only, and the other
from another vm on the same machine, both producing and consuming
i don't currently have enough information to isolate a test scenario.
i've only seen this issue intermittently : after a broker has been
running fine for quite a while, and there is no apparent clue to what
is the cause. if anything else comes up i'll see what i can do
craig
On 21 Jul 2009, at 14:08, Gary Tully wrote:
> This has cropped up once or twice in the past few months. I did a
> quick inspection between the current trunk and the 5.2 tag and it
> looks like not much has changed in this logic around setting up the
> internal producerInfo (which appears to be null). For this reason I
> suspect that the issue still exists on trunk.
>
> Could you raise a jira issue for this and attach what you have so that
> we can start to track this down. The key would be having a
> reproducible scenario description or test case.
>
> Do you know of the connection on tcp:///127.0.0.1:55870 is from a
> client or from another networked broker?
>
> previous reference from the user list:
> http://www.nabble.com/What-can-be-the-reason---td21750762.html#a21750762
>
>
> 2009/7/21 craig mcmillan <cr...@trampolinesystems.com>:
>> hi,
>>
>> i'm seeing an NPE in my broker, after which the broker is
>> inoperable without
>> a restart. below is the amq related logging upto the first
>> occurence of the
>> NPE. there's no obvious cause, and prior to the NPE the broker had
>> been
>> working fine for 19 hours or so, logging pretty much nothing, and had
>> processed a few hundred thousand messages
>>
>> ring any bells with anyone ?
>>
>> thanks
>>
>> craig
>>
>> -------------------------------->
>>
>> 20 Jul 2009 14:01:21,134 INFO [BrokerService] (main:) - Using
>> Persistence
>> Adapter:
>> AMQPersistenceAdapter(/home/sonar/sonar/local_storage/
>> production_devcrunch01-reeep/amq)
>> 20 Jul 2009 14:01:21,219 INFO [KahaStore] (main:) - Kaha Store
>> using data
>> directory
>> /home/sonar/sonar/local_storage/production_devcrunch01-reeep/amq/kr-
>> store/state
>> 20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - ActiveMQ
>> 5.2.0 JMS
>> Message Broker (sonar-production-devcrunch01-reeep) is starting
>> 20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - For help
>> or more
>> information please see: http://activemq.apache.org/
>> 20 Jul 2009 14:01:21,527 INFO [KahaStore] (main:) - Kaha Store
>> using data
>> directory
>> /home/sonar/sonar/local_storage/production_devcrunch01-reeep/amq/kr-
>> store/data
>> 20 Jul 2009 14:01:21,595 INFO [TransportServerThreadSupport]
>> (main:) -
>> Listening for connections at: tcp://devcrunch01:50639
>> 20 Jul 2009 14:01:21,667 INFO [TransportConnector] (main:) -
>> Connector
>> openwire Started
>> 20 Jul 2009 14:01:21,668 INFO [BrokerService] (main:) - ActiveMQ JMS
>> Message Broker (sonar-production-devcrunch01-reeep,
>> ID:devcrunch01-55590-1248098481379-0:0) started
>> 20 Jul 2009 14:02:19,904 INFO [DiscoveryTransport] (Multicast
>> Discovery
>> Agent Notifier:) - Adding new broker connection URL: tcp://
>> devcrunch01:50639
>> 20 Jul 2009 14:02:19,934 INFO [FailoverTransport] (ActiveMQ Task:) -
>> Successfully connected to tcp://devcrunch01:50639
>> 20 Jul 2009 14:36:24,989 INFO [DiscoveryTransport] (Multicast
>> Discovery
>> Agent Notifier:) - Adding new broker connection URL: tcp://
>> devcrunch01:50639
>> 20 Jul 2009 19:53:24,757 INFO [DiscoveryTransport] (Multicast
>> Discovery
>> Agent Notifier:) - Adding new broker connection URL: tcp://
>> devcrunch01:50639
>> 20 Jul 2009 19:53:25,249 WARN [FailoverTransport] (ActiveMQ
>> Transport:
>> tcp://localhost/127.0.0.1:50639:) - Transport failed to
>> tcp://devcrunch01:50639 , attempting to automatically reconnect due
>> to:
>> java.net.SocketException: Connection reset
>> 20 Jul 2009 19:53:25,322 INFO [FailoverTransport] (ActiveMQ Task:) -
>> Successfully reconnected to tcp://devcrunch01:50639
>> 21 Jul 2009 09:03:59,091 INFO [DiscoveryTransport] (Multicast
>> Discovery
>> Agent Notifier:) - Adding new broker connection URL: tcp://
>> devcrunch01:50639
>> 21 Jul 2009 09:03:59,341 INFO [FailoverTransport] (ActiveMQ Task:) -
>> Successfully reconnected to tcp://devcrunch01:50639
>> 21 Jul 2009 09:03:59,362 WARN [FailoverTransport]
>> (InactivityMonitor Async
>> Task: java.util.concurrent.ThreadPoolExecutor$Worker@719bd84b:) -
>> Transport
>> failed to tcp://devcrunch01:50639 , attempting to automatically
>> reconnect
>> due to: org.apache.activemq.transport.InactivityIOException:
>> Channel was
>> inactive for too long: localhost/127.0.0.1:50639
>> 21 Jul 2009 09:04:14,136 ERROR [Service] (ActiveMQ Transport:
>> tcp:///127.0.0.1:55870:) - Async error occurred:
>> java.lang.NullPointerException
>> java.lang.NullPointerException
>> at org.apache.activemq.broker.region.Queue.send(Queue.java:
>> 328)
>> at
>> org
>> .apache
>> .activemq.broker.region.AbstractRegion.send(AbstractRegion.java:350)
>> at
>> org
>> .apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:
>> 437)
>> at
>> org
>> .apache
>> .activemq.broker.TransactionBroker.send(TransactionBroker.java:224)
>> at
>> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)
>> at
>> org
>> .apache
>> .activemq
>> .broker
>> .CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
>> at
>> org
>> .apache
>> .activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:
>> 133)
>> at
>> org
>> .apache
>> .activemq
>> .broker.TransportConnection.processMessage(TransportConnection.java:
>> 450)
>> at
>> org
>> .apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:
>> 639)
>> at
>> org
>> .apache
>> .activemq
>> .broker.TransportConnection.service(TransportConnection.java:305)
>> at
>> org.apache.activemq.broker.TransportConnection
>> $1.onCommand(TransportConnection.java:179)
>> at
>> org
>> .apache
>> .activemq.transport.TransportFilter.onCommand(TransportFilter.java:
>> 68)
>> at
>> org
>> .apache
>> .activemq
>> .transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:
>> 143)
>> at
>> org
>> .apache
>> .activemq
>> .transport.InactivityMonitor.onCommand(InactivityMonitor.java:206)
>> at
>> org
>> .apache
>> .activemq
>> .transport.TransportSupport.doConsume(TransportSupport.java:84)
>> at
>> org
>> .apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:
>> 203)
>> at
>> org
>> .apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:
>> 185)
>> at java.lang.Thread.run(Thread.java:619)
>>
>>
>
>
>
> --
> http://blog.garytully.com
>
> Open Source Integration
> http://fusesource.com
Re: NPE in broker => inoperative broker
Posted by Gary Tully <ga...@gmail.com>.
This has cropped up once or twice in the past few months. I did a
quick inspection between the current trunk and the 5.2 tag and it
looks like not much has changed in this logic around setting up the
internal producerInfo (which appears to be null). For this reason I
suspect that the issue still exists on trunk.
Could you raise a jira issue for this and attach what you have so that
we can start to track this down. The key would be having a
reproducible scenario description or test case.
Do you know of the connection on tcp:///127.0.0.1:55870 is from a
client or from another networked broker?
previous reference from the user list:
http://www.nabble.com/What-can-be-the-reason---td21750762.html#a21750762
2009/7/21 craig mcmillan <cr...@trampolinesystems.com>:
> hi,
>
> i'm seeing an NPE in my broker, after which the broker is inoperable without
> a restart. below is the amq related logging upto the first occurence of the
> NPE. there's no obvious cause, and prior to the NPE the broker had been
> working fine for 19 hours or so, logging pretty much nothing, and had
> processed a few hundred thousand messages
>
> ring any bells with anyone ?
>
> thanks
>
> craig
>
> -------------------------------->
>
> 20 Jul 2009 14:01:21,134 INFO [BrokerService] (main:) - Using Persistence
> Adapter:
> AMQPersistenceAdapter(/home/sonar/sonar/local_storage/production_devcrunch01-reeep/amq)
> 20 Jul 2009 14:01:21,219 INFO [KahaStore] (main:) - Kaha Store using data
> directory
> /home/sonar/sonar/local_storage/production_devcrunch01-reeep/amq/kr-store/state
> 20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - ActiveMQ 5.2.0 JMS
> Message Broker (sonar-production-devcrunch01-reeep) is starting
> 20 Jul 2009 14:01:21,348 INFO [BrokerService] (main:) - For help or more
> information please see: http://activemq.apache.org/
> 20 Jul 2009 14:01:21,527 INFO [KahaStore] (main:) - Kaha Store using data
> directory
> /home/sonar/sonar/local_storage/production_devcrunch01-reeep/amq/kr-store/data
> 20 Jul 2009 14:01:21,595 INFO [TransportServerThreadSupport] (main:) -
> Listening for connections at: tcp://devcrunch01:50639
> 20 Jul 2009 14:01:21,667 INFO [TransportConnector] (main:) - Connector
> openwire Started
> 20 Jul 2009 14:01:21,668 INFO [BrokerService] (main:) - ActiveMQ JMS
> Message Broker (sonar-production-devcrunch01-reeep,
> ID:devcrunch01-55590-1248098481379-0:0) started
> 20 Jul 2009 14:02:19,904 INFO [DiscoveryTransport] (Multicast Discovery
> Agent Notifier:) - Adding new broker connection URL: tcp://devcrunch01:50639
> 20 Jul 2009 14:02:19,934 INFO [FailoverTransport] (ActiveMQ Task:) -
> Successfully connected to tcp://devcrunch01:50639
> 20 Jul 2009 14:36:24,989 INFO [DiscoveryTransport] (Multicast Discovery
> Agent Notifier:) - Adding new broker connection URL: tcp://devcrunch01:50639
> 20 Jul 2009 19:53:24,757 INFO [DiscoveryTransport] (Multicast Discovery
> Agent Notifier:) - Adding new broker connection URL: tcp://devcrunch01:50639
> 20 Jul 2009 19:53:25,249 WARN [FailoverTransport] (ActiveMQ Transport:
> tcp://localhost/127.0.0.1:50639:) - Transport failed to
> tcp://devcrunch01:50639 , attempting to automatically reconnect due to:
> java.net.SocketException: Connection reset
> 20 Jul 2009 19:53:25,322 INFO [FailoverTransport] (ActiveMQ Task:) -
> Successfully reconnected to tcp://devcrunch01:50639
> 21 Jul 2009 09:03:59,091 INFO [DiscoveryTransport] (Multicast Discovery
> Agent Notifier:) - Adding new broker connection URL: tcp://devcrunch01:50639
> 21 Jul 2009 09:03:59,341 INFO [FailoverTransport] (ActiveMQ Task:) -
> Successfully reconnected to tcp://devcrunch01:50639
> 21 Jul 2009 09:03:59,362 WARN [FailoverTransport] (InactivityMonitor Async
> Task: java.util.concurrent.ThreadPoolExecutor$Worker@719bd84b:) - Transport
> failed to tcp://devcrunch01:50639 , attempting to automatically reconnect
> due to: org.apache.activemq.transport.InactivityIOException: Channel was
> inactive for too long: localhost/127.0.0.1:50639
> 21 Jul 2009 09:04:14,136 ERROR [Service] (ActiveMQ Transport:
> tcp:///127.0.0.1:55870:) - Async error occurred:
> java.lang.NullPointerException
> java.lang.NullPointerException
> at org.apache.activemq.broker.region.Queue.send(Queue.java:328)
> at
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:350)
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:437)
> at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:224)
> at
> org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)
> at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
> at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:133)
> at
> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:450)
> at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:639)
> at
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:305)
> at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:179)
> at
> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
> at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:143)
> at
> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:206)
> at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
> at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
> at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:185)
> at java.lang.Thread.run(Thread.java:619)
>
>
--
http://blog.garytully.com
Open Source Integration
http://fusesource.com