You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Tommy Lindgren (Commented) (JIRA)" <ji...@apache.org> on 2011/12/12 13:52:30 UTC
[jira] [Commented] (AMQ-3605) NullPointerException in
TransportConnection
[ https://issues.apache.org/jira/browse/AMQ-3605?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13167478#comment-13167478 ]
Tommy Lindgren commented on AMQ-3605:
-------------------------------------
I've done some testing against 5.6-SNAPSHOT (as of 2011-11-23). I don't see the NPE anymore but clients closing the socket in an unclean fashion seems to still be a problem.
It looks like my affected client now hangs on the SEND call. I can reproduce this problem within minutes by stressing my clients while a script repeatedly forks, connects to AMQ, subscribes to a topic and then calls _exit() (to make sure the socket isn't closed by the garbage collector).
The resulting AMQ log is 200MB+ and may contain sensitive information, so I can't attach it as it is. Just before the client hangs I see (log excerpts slightly edited):
{noformat}
2011-12-12 10:56:21,776 | TRACE | Received:
SEND
[...]
2011-12-12 10:56:21,776 | DEBUG | message is ActiveMQTextMessage {commandId = 2262, responseRequired = false, messageId = ID:dev01-54928-1323379526715-4:15980:-1:1:
2254, originalDestination = null, originalTransactionId = null, producerId = ID:dev01-54928-1323379526715-4:15980:-1:1, destination = topic://change.TRANSFER, trans
actionId = null, expiration = 0, timestamp = 1323683781775, arrival = 0, brokerInTime = 1323683781775, brokerOutTime = 1323683781775, correlationId = null, replyTo = n
ull, persistent = false, type = EVENT.ResourceChangeEvent, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null,
content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 1507, properties = {[...]}, readOnlyProperties = true, readO
nlyBody = true, droppable = false, text = <?xml version="1.0" encoding="UTF-8"?>
<atom:...atom:entry>
}
2011-12-12 10:56:21,776 | DEBUG | Message available, but continuation is already resumed. Buffer for next time.
2011-12-12 10:56:21,776 | DEBUG | Transport failed: java.io.EOFException
java.io.EOFException
at java.io.DataInputStream.readByte(DataInputStream.java:250)
at org.apache.activemq.transport.stomp.StompWireFormat.readHeaderLine(StompWireFormat.java:155)
at org.apache.activemq.transport.stomp.StompWireFormat.readLine(StompWireFormat.java:148)
at org.apache.activemq.transport.stomp.StompWireFormat.parseAction(StompWireFormat.java:170)
at org.apache.activemq.transport.stomp.StompWireFormat.unmarshal(StompWireFormat.java:98)
at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
at java.lang.Thread.run(Thread.java:662)
2011-12-12 10:56:21,776 | DEBUG | message for ActiveMQMessageConsumer { value=ID:dev01-54928-1323379526715-8:58:1:1, started=true } continuation=org.eclipse.jetty.s
erver.AsyncContinuation@e9b412d@IDLE,initial
2011-12-12 10:56:21,776 | DEBUG | message for ActiveMQMessageConsumer { value=ID:dev01-54928-1323379526715-8:57:1:1, started=true } continuation=org.eclipse.jetty.s
erver.AsyncContinuation@50afeae@IDLE,initial
2011-12-12 10:56:21,776 | TRACE | org.apache.activemq.broker.region.cursors.QueueStorePrefetch@73a2335d:daemon.archived,batchResetNeeded=false,storeHasMessages=true,si
ze=0,cacheEnabled=true - fillBatch
2011-12-12 10:56:21,777 | TRACE | ID:dev01-54928-1323379526715-8:58:1:1 received message: MessageDispatch {commandId = 391, responseRequired = false, consumerId = I
D:dev01-54928-1323379526715-8:58:1:1, destination = topic://change.TRANSFER, message = ActiveMQTextMessage {commandId = 2262, responseRequired = false, messageId =
ID:dev01-54928-1323379526715-4:15980:-1:1:2254, originalDestination = null, originalTransactionId = null, producerId = ID:dev01-54928-1323379526715-4:15980:-1:1,
destination = topic://change.TRANSFER, transactionId = null, expiration = 0, timestamp = 1323683781775, arrival = 0, brokerInTime = 1323683781775, brokerOutTime = 132
3683781775, correlationId = null, replyTo = null, persistent = false, type = EVENT.ResourceChangeEvent, priority = 4, groupID = null, groupSequence = 0, targetConsumer
Id = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 1507, properties = {[...]},
readOnlyProperties = true, readOnlyBody = true, droppable = false, text = <?xml version="1.0" encoding="UTF-8"?>
<atom:...atom:entry>
}, redeliveryCounter = 0}
2011-12-12 10:56:21,776 | DEBUG | Transport failed: java.net.SocketException: Broken pipe
java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
at java.io.DataOutputStream.flush(DataOutputStream.java:106)
at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:184)
at org.apache.activemq.transport.stomp.StompTransportFilter.sendToStomp(StompTransportFilter.java:97)
at org.apache.activemq.transport.stomp.StompSubscription.onMessageDispatch(StompSubscription.java:99)
at org.apache.activemq.transport.stomp.ProtocolConverter.onActiveMQCommand(ProtocolConverter.java:746)
at org.apache.activemq.transport.stomp.StompTransportFilter.oneway(StompTransportFilter.java:64)
at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:262)
at org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:244)
at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1281)
at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:830)
at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:866)
at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
{noformat}
The "Received: SEND" message is from my affected client. I see a bunch of such messages after the SocketException before the client hangs two seconds later. I assume the client hangs because some buffer at some level is full. I can't see anything obvious explaining why AMQ stops processing the client's messages.
Occasionally I also see the following exception:
{noformat}
java.lang.IllegalStateException: Cannot lookup a producer from a connection that had not been registered: ID:dev01-54928-1323379526715-4:59
at org.apache.activemq.broker.SingleTransportConnectionStateRegister.lookupConnectionState(SingleTransportConnectionStateRegister.java:93)
at org.apache.activemq.broker.TransportConnection.lookupConnectionState(TransportConnection.java:1438)
at org.apache.activemq.broker.TransportConnection.getProducerBrokerExchange(TransportConnection.java:1314)
at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:468)
at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:318)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:181)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:45)
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
at org.apache.activemq.transport.stomp.StompTransportFilter.sendToActiveMQ(StompTransportFilter.java:87)
at org.apache.activemq.transport.stomp.ProtocolConverter.sendToActiveMQ(ProtocolConverter.java:166)
at org.apache.activemq.transport.stomp.ProtocolConverter.onStompSend(ProtocolConverter.java:292)
at org.apache.activemq.transport.stomp.ProtocolConverter.onStompCommand(ProtocolConverter.java:204)
at org.apache.activemq.transport.stomp.StompTransportFilter.onCommand(StompTransportFilter.java:76)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
{noformat}
Not sure how useful these log excerpts are. I haven't tested the attached patch yet. If you think it will help I can try to build AMQ myself.
> NullPointerException in TransportConnection
> -------------------------------------------
>
> Key: AMQ-3605
> URL: https://issues.apache.org/jira/browse/AMQ-3605
> Project: ActiveMQ
> Issue Type: Bug
> Components: Transport
> Affects Versions: 5.5.0
> Environment: SLES 11 SP1
> java version "1.6.0_23"
> perl 5.10.0 + Net::Stomp 0.38_99
> Reporter: Tommy Lindgren
> Priority: Critical
> Labels: stomp
> Attachments: AMQ-3605-Patch.txt, StompDedicatedTaskRunnerTests.java, StompDedicatedTaskRunnerTests.java
>
>
> I'm running ActiveMQ 5.5.0 and clients using Net::Stomp 0.38_99 and I'm seeing infrequent NullPointerExceptions in TransportConnection:
> {noformat}
> Exception in thread "ActiveMQ Connection Dispatcher: /172.31.201.11:50607" java.lang.NullPointerException
> at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:327)
> at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:179)
> at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:69)
> at org.apache.activemq.transport.stomp.StompTransportFilter.sendToActiveMQ(StompTransportFilter.java:81)
> at org.apache.activemq.transport.stomp.StompSubscription.onMessageDispatch(StompSubscription.java:79)
> at org.apache.activemq.transport.stomp.ProtocolConverter.onActiveMQCommand(ProtocolConverter.java:596)
> at org.apache.activemq.transport.stomp.StompTransportFilter.oneway(StompTransportFilter.java:58)
> at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:40)
> at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1270)
> at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:815)
> at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:851)
> at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
> at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
> {noformat}
> This seems to happen 1-2 times per month or so but the result is dire: new messages aren't delivered to the affected client (you can see the number of pending messages increasing in the admin web interface) until the client or ActiveMQ is restarted.
> Relevant code snippet from TransportConnection.java,
> {noformat}
> 326 if (context != null) {
> 327 if (context.isDontSendReponse()) {
> {noformat}
> implies that we are dealing with a race condition. I'm not familiar with the ActiveMQ code base but it looks like it grabs a lock (serviceLock) before entering that function, so not sure what's going on.
> Since there's no timestamp associated with the stack trace I'm not completly sure what's going on on the client side. I've tried to reproduce it by writing a small script that uses Net::Stomp in a similar way to my real clients, but no luck so far.
> No idea if it's relevant, but my affected clients have been both consuming and producing, and sending/receiving on both topics and queues.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira