Re: Fwd: Deadlock caused by ActiveMQMessageConsumer.dispatch() due to onEvent invocation

[Facundo Darío Velazquez Santillán <fa...@gmail.com>]

Hi guys.
I send a new message to this topic since in Mule ESB, we are suffering a
deadlock again regarding to the same root cause.
I am attaching the stacktrace so you can analyze this.
The previous time, I applied the Tim Bain suggestion and removed a logger
that called the connection.toString() method causing the issue.
However, now with a different execution chain, this deadlock is being
reproduced again.
I quoted my previous opinion regarding to a definitive solution for this
problem:

I think the root problem is the invocation of the external implemented
> method onMessage().
> Calling the external implemented onMessage() in the synchronized lock can
> cause an unpredictable behavior in lock ordering causing deadlock issues.
> It could be resolved if the lock is released before invoking onMessage().


I am referring to this code line
<https://github.com/apache/activemq/blob/master/activemq-client/src/main/java/org/apache/activemq/ActiveMQMessageConsumer.java#L1404>
.
As you can see, in this line external code is invoking (in this case, mule
code) without releasing the acquired locks.
would it possible to call this method after releasing the lock?

Regards.



2017-03-14 9:02 GMT-03:00 Facundo Darío Velazquez Santillán <
facundovelazquezsantillan@gmail.com>:

> Excuse me, if I referenced a wrong method.
> In SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(),
> when the toString method is called, through inflection is invoked
> getConnection() method. You can see it here.
> getConnection() method takes the monitor lock that is participating in the
> deadlock. You can see it here.
> I'm agree you, I think the faster way to solve the problem, it's avoiding
> this toString() method in our logs. I'll take this way.
> I also could report to Spring, That They are locking a resource to do a
> toString, although I suspect the idea is to not log a null connection.
> Finally, It would be great, if you could give a solution regarding to the
> external onMessage() invocation without releasing the log, to avoid future
> deadlocks.
>
> Thanks for all.
> Cheers.
> Facundo.
>
> 2017-03-13 15:35 GMT-03:00 Tim Bain <tb...@alumni.duke.edu>:
>
>> This is definitely a bug, the question is whose bug it is (whose code
>> should change): ActiveMQ, Mule, Spring, or some combination of the three.
>>
>> I looked in http://grepcode.com/file/repo1.maven.org/maven2/org.
>> springframework/spring-jms/3.0.0.RELEASE/org/springframework
>> /jms/connection/
>> SingleConnectionFactory.java and I don't see the
>> org.springframework.Single
>> ConnectionFactory.getConnection() method you referenced. What version of
>> Spring are you using?
>>
>> You referenced a toString() method; where is that code? My initial
>> reaction
>> based on what you've written is that although calling external code while
>> holding a lock isn't great (and we might want to change the code to not do
>> that), the most egregious problem is the fact that a toString() method is
>> doing something that involves acquiring a lock, and that's my first
>> thought
>> for the best way to solve this immediate problem.
>>
>> Tim
>>
>> On Mar 10, 2017 4:11 PM, "Facundo Darío Velazquez Santillán" <
>> facundovelazquezsantillan@gmail.com> wrote:
>>
>> Hi.
>> In Mule ESB,
>> I have detected a deadlock caused by the interaction between Spring and
>> ActiveMQ.
>> Basically, there are two execution chains that are causing the deadlock:
>>
>> First Chain: when a Message arrives to the JMS Queue:
>>
>> 1) ActiveMQMessageConsumer.dispatch() gets the lock of
>> FifoMessageDispatchChannel.mutex.
>> 2) ActiveMQMessageConsumer.dispatch() calls the onMessage() method
>> without
>> releasing the lock.
>> 3) onMessage Mule Implementation calls org.springframework.
>> SingleConnectionFactory$SharedConnectionInvocationHandler.invoke()
>> because
>> It needs a toString of the used resource (in this case the connection) to
>> logging purposes.
>> 3) in ToString() method,
>> org.springframework.SingleConnectionFactory.getConnection()
>> method is called and It takes the org.springframework.Single
>> ConnectionFactory.connectionMonitor lock to access to connection (that's
>> a
>> shared resource).
>>
>> Lock ordering in this chain:
>>
>> FifoMessageDispatchChannel.mutex lock -> org.springframework.SingleC
>> onnectionFactory.connectionMonitor lock
>>
>> Second Chain: when A reconnection-strategy is applied:
>>
>> 1) Mule stops the current connection calling org.springframework.Sin
>> gleConnectionFactory.localStop()
>> 2) LocalStop takes the org.springframework.SingleConnectionFactory
>> .connectionMonitor lock.
>> 3) After a chain of calls: FifoMessageDispatchChannel.stop() is called.
>> 4) FifoMessageDispatchChannel.stop() takes the
>> FifoMessageDispatchChannel.mutex lock.
>>
>> Lock Ordering in this case:
>>
>> org.springframework.SingleConnectionFactory.connectionMonitor lock ->
>> FifoMessageDispatchChannel.mutex lock
>>
>> As you can see, The chains don't take care about lock ordering, and It's
>> causing a deadlock.
>>
>> I think the root problem is the invocation of the external implemented
>> method onEvent().
>> Calling the external implemented onEvent() method in the synchronized lock
>> can cause an unpredictable behaviour in lock ordering causing deadlock
>> issues.
>> I think It could be resolved if the lock is released before invoking
>> onEvent().
>> I would like to know their opinions about this case to report an issue if
>> It is necessary.
>>
>> Thanks.
>> Cheers.
>>
>
>

Re: Fwd: Deadlock caused by ActiveMQMessageConsumer.dispatch() due to onEvent invocation

[Facundo Darío Velazquez Santillán <fa...@gmail.com>]

Hi Tim.
Thanks for your valuable help.
I have commented the issue with the requested information.
If you need anymore, please let me know.
Regards.

2017-07-20 3:21 GMT-03:00 Tim Bain <tb...@alumni.duke.edu>:

> I've submitted https://issues.apache.org/jira/browse/AMQ-6773 to capture
> the deadlocks you encountered and your proposal that we invoke that
> onMessage() method without holding the lock.
>
> Can you please update it to provide the version of ActiveMQ you were using,
> as well as any additional information you think would be useful to whoever
> takes on this fix?
>
> Also, can you please share details about the new code path that resulted in
> the deadlock? It would be good to know about what the second lock is, as
> well as what the code path is that resulted in us calling one of the three
> methods protected by our lock while holding that external lock.
>
> Thanks,
> Tim
>
> P.S. I apologize for not replying to your first response, but the mailing
> list only just delivered it to me (via email, which is how I access the
> list). I suspect it spent the time between May 14 and now in a "waiting to
> be accepted by the mailing list" state, for whatever reason.
>
> On Tue, Jul 18, 2017 at 6:58 PM, Facundo Darío Velazquez Santillán <
> facundovelazquezsantillan@gmail.com> wrote:
>
> > Hi guys.
> > I send a new message to this topic since in Mule ESB, we are suffering a
> > deadlock again regarding to the same root cause.
> > I am attaching the stacktrace so you can analyze this.
> > The previous time, I applied the Tim Bain suggestion and removed a logger
> > that called the connection.toString() method causing the issue.
> > However, now with a different execution chain, this deadlock is being
> > reproduced again.
> > I quoted my previous opinion regarding to a definitive solution for this
> > problem:
> >
> > I think the root problem is the invocation of the external implemented
> >> method onMessage().
> >> Calling the external implemented onMessage() in the synchronized lock
> can
> >> cause an unpredictable behavior in lock ordering causing deadlock
> issues.
> >> It could be resolved if the lock is released before invoking
> onMessage().
> >
> >
> > I am referring to this code line
> > <https://github.com/apache/activemq/blob/master/activemq-
> client/src/main/java/org/apache/activemq/ActiveMQMessageConsumer.java#
> L1404>
> > .
> > As you can see, in this line external code is invoking (in this case,
> mule
> > code) without releasing the acquired locks.
> > would it possible to call this method after releasing the lock?
> >
> > Regards.
> >
> >
> >
> > 2017-03-14 9:02 GMT-03:00 Facundo Darío Velazquez Santillán <
> > facundovelazquezsantillan@gmail.com>:
> >
> >> Excuse me, if I referenced a wrong method.
> >> In SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(),
> >> when the toString method is called, through inflection is invoked
> >> getConnection() method. You can see it here.
> >> getConnection() method takes the monitor lock that is participating in
> >> the deadlock. You can see it here.
> >> I'm agree you, I think the faster way to solve the problem, it's
> avoiding
> >> this toString() method in our logs. I'll take this way.
> >> I also could report to Spring, That They are locking a resource to do a
> >> toString, although I suspect the idea is to not log a null connection.
> >> Finally, It would be great, if you could give a solution regarding to
> the
> >> external onMessage() invocation without releasing the log, to avoid
> future
> >> deadlocks.
> >>
> >> Thanks for all.
> >> Cheers.
> >> Facundo.
> >>
> >> 2017-03-13 15:35 GMT-03:00 Tim Bain <tb...@alumni.duke.edu>:
> >>
> >>> This is definitely a bug, the question is whose bug it is (whose code
> >>> should change): ActiveMQ, Mule, Spring, or some combination of the
> three.
> >>>
> >>> I looked in http://grepcode.com/file/repo1.maven.org/maven2/org.
> >>> springframework/spring-jms/3.0.0.RELEASE/org/springframework
> >>> /jms/connection/
> >>> SingleConnectionFactory.java and I don't see the
> >>> org.springframework.Single
> >>> ConnectionFactory.getConnection() method you referenced. What version
> of
> >>> Spring are you using?
> >>>
> >>> You referenced a toString() method; where is that code? My initial
> >>> reaction
> >>> based on what you've written is that although calling external code
> while
> >>> holding a lock isn't great (and we might want to change the code to not
> >>> do
> >>> that), the most egregious problem is the fact that a toString() method
> is
> >>> doing something that involves acquiring a lock, and that's my first
> >>> thought
> >>> for the best way to solve this immediate problem.
> >>>
> >>> Tim
> >>>
> >>> On Mar 10, 2017 4:11 PM, "Facundo Darío Velazquez Santillán" <
> >>> facundovelazquezsantillan@gmail.com> wrote:
> >>>
> >>> Hi.
> >>> In Mule ESB,
> >>> I have detected a deadlock caused by the interaction between Spring and
> >>> ActiveMQ.
> >>> Basically, there are two execution chains that are causing the
> deadlock:
> >>>
> >>> First Chain: when a Message arrives to the JMS Queue:
> >>>
> >>> 1) ActiveMQMessageConsumer.dispatch() gets the lock of
> >>> FifoMessageDispatchChannel.mutex.
> >>> 2) ActiveMQMessageConsumer.dispatch() calls the onMessage() method
> >>> without
> >>> releasing the lock.
> >>> 3) onMessage Mule Implementation calls org.springframework.
> >>> SingleConnectionFactory$SharedConnectionInvocationHandler.invoke()
> >>> because
> >>> It needs a toString of the used resource (in this case the connection)
> to
> >>> logging purposes.
> >>> 3) in ToString() method,
> >>> org.springframework.SingleConnectionFactory.getConnection()
> >>> method is called and It takes the org.springframework.Single
> >>> ConnectionFactory.connectionMonitor lock to access to connection
> >>> (that's a
> >>> shared resource).
> >>>
> >>> Lock ordering in this chain:
> >>>
> >>> FifoMessageDispatchChannel.mutex lock -> org.springframework.SingleC
> >>> onnectionFactory.connectionMonitor lock
> >>>
> >>> Second Chain: when A reconnection-strategy is applied:
> >>>
> >>> 1) Mule stops the current connection calling org.springframework.Sin
> >>> gleConnectionFactory.localStop()
> >>> 2) LocalStop takes the org.springframework.SingleConnectionFactory
> >>> .connectionMonitor lock.
> >>> 3) After a chain of calls: FifoMessageDispatchChannel.stop() is
> called.
> >>> 4) FifoMessageDispatchChannel.stop() takes the
> >>> FifoMessageDispatchChannel.mutex lock.
> >>>
> >>> Lock Ordering in this case:
> >>>
> >>> org.springframework.SingleConnectionFactory.connectionMonitor lock ->
> >>> FifoMessageDispatchChannel.mutex lock
> >>>
> >>> As you can see, The chains don't take care about lock ordering, and
> It's
> >>> causing a deadlock.
> >>>
> >>> I think the root problem is the invocation of the external implemented
> >>> method onEvent().
> >>> Calling the external implemented onEvent() method in the synchronized
> >>> lock
> >>> can cause an unpredictable behaviour in lock ordering causing deadlock
> >>> issues.
> >>> I think It could be resolved if the lock is released before invoking
> >>> onEvent().
> >>> I would like to know their opinions about this case to report an issue
> if
> >>> It is necessary.
> >>>
> >>> Thanks.
> >>> Cheers.
> >>>
> >>
> >>
> >
>

Re: Fwd: Deadlock caused by ActiveMQMessageConsumer.dispatch() due to onEvent invocation

[Tim Bain <tb...@alumni.duke.edu>]

I've submitted https://issues.apache.org/jira/browse/AMQ-6773 to capture
the deadlocks you encountered and your proposal that we invoke that
onMessage() method without holding the lock.

Can you please update it to provide the version of ActiveMQ you were using,
as well as any additional information you think would be useful to whoever
takes on this fix?

Also, can you please share details about the new code path that resulted in
the deadlock? It would be good to know about what the second lock is, as
well as what the code path is that resulted in us calling one of the three
methods protected by our lock while holding that external lock.

Thanks,
Tim

P.S. I apologize for not replying to your first response, but the mailing
list only just delivered it to me (via email, which is how I access the
list). I suspect it spent the time between May 14 and now in a "waiting to
be accepted by the mailing list" state, for whatever reason.

On Tue, Jul 18, 2017 at 6:58 PM, Facundo Darío Velazquez Santillán <
facundovelazquezsantillan@gmail.com> wrote:

> Hi guys.
> I send a new message to this topic since in Mule ESB, we are suffering a
> deadlock again regarding to the same root cause.
> I am attaching the stacktrace so you can analyze this.
> The previous time, I applied the Tim Bain suggestion and removed a logger
> that called the connection.toString() method causing the issue.
> However, now with a different execution chain, this deadlock is being
> reproduced again.
> I quoted my previous opinion regarding to a definitive solution for this
> problem:
>
> I think the root problem is the invocation of the external implemented
>> method onMessage().
>> Calling the external implemented onMessage() in the synchronized lock can
>> cause an unpredictable behavior in lock ordering causing deadlock issues.
>> It could be resolved if the lock is released before invoking onMessage().
>
>
> I am referring to this code line
> <https://github.com/apache/activemq/blob/master/activemq-client/src/main/java/org/apache/activemq/ActiveMQMessageConsumer.java#L1404>
> .
> As you can see, in this line external code is invoking (in this case, mule
> code) without releasing the acquired locks.
> would it possible to call this method after releasing the lock?
>
> Regards.
>
>
>
> 2017-03-14 9:02 GMT-03:00 Facundo Darío Velazquez Santillán <
> facundovelazquezsantillan@gmail.com>:
>
>> Excuse me, if I referenced a wrong method.
>> In SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(),
>> when the toString method is called, through inflection is invoked
>> getConnection() method. You can see it here.
>> getConnection() method takes the monitor lock that is participating in
>> the deadlock. You can see it here.
>> I'm agree you, I think the faster way to solve the problem, it's avoiding
>> this toString() method in our logs. I'll take this way.
>> I also could report to Spring, That They are locking a resource to do a
>> toString, although I suspect the idea is to not log a null connection.
>> Finally, It would be great, if you could give a solution regarding to the
>> external onMessage() invocation without releasing the log, to avoid future
>> deadlocks.
>>
>> Thanks for all.
>> Cheers.
>> Facundo.
>>
>> 2017-03-13 15:35 GMT-03:00 Tim Bain <tb...@alumni.duke.edu>:
>>
>>> This is definitely a bug, the question is whose bug it is (whose code
>>> should change): ActiveMQ, Mule, Spring, or some combination of the three.
>>>
>>> I looked in http://grepcode.com/file/repo1.maven.org/maven2/org.
>>> springframework/spring-jms/3.0.0.RELEASE/org/springframework
>>> /jms/connection/
>>> SingleConnectionFactory.java and I don't see the
>>> org.springframework.Single
>>> ConnectionFactory.getConnection() method you referenced. What version of
>>> Spring are you using?
>>>
>>> You referenced a toString() method; where is that code? My initial
>>> reaction
>>> based on what you've written is that although calling external code while
>>> holding a lock isn't great (and we might want to change the code to not
>>> do
>>> that), the most egregious problem is the fact that a toString() method is
>>> doing something that involves acquiring a lock, and that's my first
>>> thought
>>> for the best way to solve this immediate problem.
>>>
>>> Tim
>>>
>>> On Mar 10, 2017 4:11 PM, "Facundo Darío Velazquez Santillán" <
>>> facundovelazquezsantillan@gmail.com> wrote:
>>>
>>> Hi.
>>> In Mule ESB,
>>> I have detected a deadlock caused by the interaction between Spring and
>>> ActiveMQ.
>>> Basically, there are two execution chains that are causing the deadlock:
>>>
>>> First Chain: when a Message arrives to the JMS Queue:
>>>
>>> 1) ActiveMQMessageConsumer.dispatch() gets the lock of
>>> FifoMessageDispatchChannel.mutex.
>>> 2) ActiveMQMessageConsumer.dispatch() calls the onMessage() method
>>> without
>>> releasing the lock.
>>> 3) onMessage Mule Implementation calls org.springframework.
>>> SingleConnectionFactory$SharedConnectionInvocationHandler.invoke()
>>> because
>>> It needs a toString of the used resource (in this case the connection) to
>>> logging purposes.
>>> 3) in ToString() method,
>>> org.springframework.SingleConnectionFactory.getConnection()
>>> method is called and It takes the org.springframework.Single
>>> ConnectionFactory.connectionMonitor lock to access to connection
>>> (that's a
>>> shared resource).
>>>
>>> Lock ordering in this chain:
>>>
>>> FifoMessageDispatchChannel.mutex lock -> org.springframework.SingleC
>>> onnectionFactory.connectionMonitor lock
>>>
>>> Second Chain: when A reconnection-strategy is applied:
>>>
>>> 1) Mule stops the current connection calling org.springframework.Sin
>>> gleConnectionFactory.localStop()
>>> 2) LocalStop takes the org.springframework.SingleConnectionFactory
>>> .connectionMonitor lock.
>>> 3) After a chain of calls: FifoMessageDispatchChannel.stop() is called.
>>> 4) FifoMessageDispatchChannel.stop() takes the
>>> FifoMessageDispatchChannel.mutex lock.
>>>
>>> Lock Ordering in this case:
>>>
>>> org.springframework.SingleConnectionFactory.connectionMonitor lock ->
>>> FifoMessageDispatchChannel.mutex lock
>>>
>>> As you can see, The chains don't take care about lock ordering, and It's
>>> causing a deadlock.
>>>
>>> I think the root problem is the invocation of the external implemented
>>> method onEvent().
>>> Calling the external implemented onEvent() method in the synchronized
>>> lock
>>> can cause an unpredictable behaviour in lock ordering causing deadlock
>>> issues.
>>> I think It could be resolved if the lock is released before invoking
>>> onEvent().
>>> I would like to know their opinions about this case to report an issue if
>>> It is necessary.
>>>
>>> Thanks.
>>> Cheers.
>>>
>>
>>
>