activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Gabriel Gerhardsson (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (AMQ-4022) SEND directly after SUBSCRIBE causes bad state -> no DISCONNECT receipt
Date Tue, 11 Sep 2012 13:39:07 GMT

    [ https://issues.apache.org/jira/browse/AMQ-4022?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13453013#comment-13453013
] 

Gabriel Gerhardsson commented on AMQ-4022:
------------------------------------------

jstack output (partial) from when the problem had been reproduced:

{noformat}
"ActiveMQ Transport: tcp:///127.0.0.1:59675" daemon prio=10 tid=0x00000000402bf000 nid=0x1bf0
waiting for monitor entry [0x00007fffcc787000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.activemq.broker.TransportConnection.removeConsumerBrokerExchange(TransportConnection.java:1473)
    - waiting to lock <0x00000000c3cf2838> (a java.util.HashMap)
    at org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:684)
    at org.apache.activemq.broker.TransportConnection.processRemoveSession(TransportConnection.java:721)
    at org.apache.activemq.broker.TransportConnection.processRemoveConnection(TransportConnection.java:840)
    - locked <0x00000000c3ce8e98> (a org.apache.activemq.broker.jmx.ManagedTransportConnection)
    at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:77)
    at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:336)
    at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:189)
    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.ProtocolConverter.sendToActiveMQ(ProtocolConverter.java:166)
    at org.apache.activemq.transport.stomp.ProtocolConverter.onStompDisconnect(ProtocolConverter.java:586)
    at org.apache.activemq.transport.stomp.ProtocolConverter.onStompCommand(ProtocolConverter.java:220)
    at org.apache.activemq.transport.stomp.StompTransportFilter.onCommand(StompTransportFilter.java:70)
    at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
    at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:232)
    at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
    at java.lang.Thread.run(Thread.java:662)

"ActiveMQ Connection Dispatcher: /127.0.0.1:59675" daemon prio=10 tid=0x00000000402be000 nid=0x1bef
waiting for monitor entry [0x00007fffcae6e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.activemq.broker.TransportConnection.lookupConnectionState(TransportConnection.java:1537)
    - waiting to lock <0x00000000c3ce8e98> (a org.apache.activemq.broker.jmx.ManagedTransportConnection)
    at org.apache.activemq.broker.TransportConnection.getConsumerBrokerExchange(TransportConnection.java:1451)
    - locked <0x00000000c3cf2838> (a java.util.HashMap)
    at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:572)
    at org.apache.activemq.command.MessageAck.visit(MessageAck.java:229)
    at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:336)
    at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:189)
    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:636)
    at org.apache.activemq.transport.stomp.StompTransportFilter.oneway(StompTransportFilter.java:58)
    at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:40)
    - locked <0x00000000c3cf1f10> (a java.lang.Object)
    at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1384)
    at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:929)
    at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:965)
    at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
    at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
{noformat}

{noformat}
Found one Java-level deadlock:
=============================
"ActiveMQ Transport: tcp:///127.0.0.1:59675":
  waiting to lock monitor 0x0000000040ad8440 (object 0x00000000c3cf2838, a java.util.HashMap),
  which is held by "ActiveMQ Connection Dispatcher: /127.0.0.1:59675"
"ActiveMQ Connection Dispatcher: /127.0.0.1:59675":
  waiting to lock monitor 0x00000000403568a8 (object 0x00000000c3ce8e98, a org.apache.activemq.broker.jmx.ManagedTransportConnection),
  which is held by "ActiveMQ Transport: tcp:///127.0.0.1:59675"
{noformat}

This method (in broker/TransportConnection.java) is one of the culprits, and feels like a
good place to break the deadlock:
{noformat}
    private ConsumerBrokerExchange getConsumerBrokerExchange(ConsumerId id) {
        ConsumerBrokerExchange result = consumerExchanges.get(id);
        if (result == null) {
            synchronized (consumerExchanges) {
                result = new ConsumerBrokerExchange();
                TransportConnectionState state = lookupConnectionState(id);
                context = state.getContext();
                result.setConnectionContext(context);
                SessionState ss = state.getSessionState(id.getParentId());
                if (ss != null) { 
                    ConsumerState cs = ss.getConsumerState(id);
                    if (cs != null) {
                        ConsumerInfo info = cs.getInfo();
                        if (info != null) { 
                            if (info.getDestination() != null && info.getDestination().isPattern())
{
                                result.setWildcard(true);
                            }   
                        }   
                    }   
                }   
                consumerExchanges.put(id, result);
            }   
        }   
        return result;
    }   
{noformat}

It holds the consumerExchanges lock, calls lookupConnectionState, which is 'synchronized',
while another thread is within another 'synchronized' method and calls removeConsumerBrokerExchange,
which tries to take consumerExchanges.

Something like this instead would solve it, basically minimizing the locking to only the get
(which wasn't protected at all previously) and the put. The only possible problem is if two
callers enter getConsumerBrokerExchange at the same time, both enter the "if (result == null)"
block and then 'put' the result, causing one to overwrite the result of the other. Without
knowing the code it's a bit hard to say, but I'd say that it looks likely that the double-put
race condition isn't a problem in this case. It wouldn't do any harm, as far as I can see.
What do you think?
{noformat}
    private ConsumerBrokerExchange getConsumerBrokerExchange(ConsumerId id) {
        ConsumerBrokerExchange result;
        synchronized (consumerExchanges) {
            result = consumerExchanges.get(id);
        }
        if (result == null) {
            result = new ConsumerBrokerExchange();
            TransportConnectionState state = lookupConnectionState(id);
            context = state.getContext();
            result.setConnectionContext(context);
            SessionState ss = state.getSessionState(id.getParentId());
            if (ss != null) {
                ConsumerState cs = ss.getConsumerState(id);
                if (cs != null) {
                    ConsumerInfo info = cs.getInfo();
                    if (info != null) {
                        if (info.getDestination() != null && info.getDestination().isPattern())
{
                            result.setWildcard(true);
                        }
                    }
                }
            }
            synchronized (consumerExchanges) {
                consumerExchanges.put(id, result);
            }
        }
        return result;
    }
{noformat}

I'll attach a patch.
                
> SEND directly after SUBSCRIBE causes bad state -> no DISCONNECT receipt
> -----------------------------------------------------------------------
>
>                 Key: AMQ-4022
>                 URL: https://issues.apache.org/jira/browse/AMQ-4022
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: stomp
>    Affects Versions: 5.5.1
>         Environment: SLES11-SP1 x86_64
>            Reporter: Gabriel Gerhardsson
>         Attachments: amqtest.pl, Net_Stomp.pm.diff
>
>
> Executive summary
> ---
> A message is lost, the connection ends up in a strange state, and then when the client
sends DISCONNECT it gets no receipt.
> Details
> ---
> Steps to reproduce:
> 1) Using STOMP
> 2) Send a SUBSCRIBE message with destination=/topic/foo, without asking for a receipt.
No other options sent in message.
> 3) Send a message to /topic/foo, without asking for a receipt.
> 4) Wait 10ms for message
> 5) Go right ahead and send DISCONNECT message, asking for a receipt.
> 5.1) About 20% of the time, no DISCONNECT receipt is received, however long the client
waits. This seems to coincide with the case when the message doesn't arrive in #4.
> 5.2) It does look like ActiveMQ gets the DISCONNECT message tho since it unsubscribes
the client from /topic/foo at that timestamp.
> The DISCONNECT receipt getting lost is clearly a bug. Waiting for the receipt is important
since I've seen cases where the client isn't unregistered properly in ActiveMQ if the client
just sends DISCONNECT and then closes the socket.
> Test script
> ---
> Apply the small patch to the perl library Net/Stomp.pm
> It's a naive minimal patch to make it wait for a receipt for the DISCONNECT message.
It will actually just wait for any frame to arrive and won't check what it is, but it's enough
for this test.
> Run amqtest.pl a few times. A non-buggy run completes almost immediately. A buggy run
hangs the script during disconnect.
> Workaround
> ---
> -When sending the SUBSCRIBE with receipt requested, and waiting for the receipt before
sending the SEND, I was unable to reproduce the issue, even after running the script 100000
times.-
> No, it turns out that the workaround suggested above does not completely eliminate the
problem. It probably just introduces a large enough delay to almost always avoid the race
condition. After 30000 additional test runs with the script the error occured again.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message