qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

classic Classic list List threaded Threaded
31 messages Options
12
Reply | Threaded
Open this post in threaded view
|

qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Team,

We are getting "Suspected deadlocked threads" error in PROD environment. We
are trying to find out root cause of this issue.

Could you please give us any clue regarding below error, so we can proceed
further.

Logs -
Suspected deadlocked threads: JmsSession
[ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:10] delivery dispatcher
Id=41620240 is in BLOCKED on lock=org.mule.servicebus.SbusConnector@58e4b68c    
is owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7]
delivery dispatcher Id=41620237 | JmsSession
[ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7] delivery dispatcher
Id=41620237 is in WAITING on
lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:5] delivery
dispatcher Id=41620235 | JmsSession
[ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:5] delivery dispatcher
Id=41620235 is in BLOCKED on lock=org.mule.servicebus.SbusConnector@58e4b68c    
is owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7]
delivery dispatcher Id=41620237 |


Regards,
Abhishek Kumar



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
This seems likely to be similar to the situation we discussed in May
[1]. You have the delivery thread from one session, which necessarily
holds its own session delivery lock while dispatching, in a situation
it is also holding application-level lock(s), while then trying to
perform operations on another connection/session that requires holding
its session delivery lock too, which that session is already
necessarily holding by its own message delivery thread during
delivery, which is in turn waiting on getting the same application
lock(s) held by the other session thread earlier, and so your
application has created a cross-session-inter-application block upon
itself.

There was a nuance to the earlier thread, in that one of the threads
involved was actually running the connection ExceptionListener at the
time due to an issue attempting delivery of the messages (which you
traced to happening with messages you did certain management
operations on), and was still holding the session delivery lock while
it was doing that. Though this wasn't a client bug, it was something
we could improve without issue by unlocking the delivery lock before
doing that, and we did this in the 0.52.0 release early in June.
Perhaps you should try using one of the newer releases instead of the
same older version as before.

There will also be another client release soon (perhaps next week),
0.55.0, after the next proton-j release is available, which will
contain a very nuanced buffer/string-decoding related fix to string
that could perhaps even have also been in play in your original issue.

[1] https://lists.apache.org/thread.html/r93536c9040b79931f1eee99ba4f721335f5d7b8991ac3dfc50bd7d55%40%3Cusers.qpid.apache.org%3E



On Thu, 12 Nov 2020 at 17:14, akabhishek1
<[hidden email]> wrote:

>
> Hi Team,
>
> We are getting "Suspected deadlocked threads" error in PROD environment. We
> are trying to find out root cause of this issue.
>
> Could you please give us any clue regarding below error, so we can proceed
> further.
>
> Logs -
> Suspected deadlocked threads: JmsSession
> [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:10] delivery dispatcher
> Id=41620240 is in BLOCKED on lock=org.mule.servicebus.SbusConnector@58e4b68c
> is owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7]
> delivery dispatcher Id=41620237 | JmsSession
> [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7] delivery dispatcher
> Id=41620237 is in WAITING on
> lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
> owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:5] delivery
> dispatcher Id=41620235 | JmsSession
> [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:5] delivery dispatcher
> Id=41620235 is in BLOCKED on lock=org.mule.servicebus.SbusConnector@58e4b68c
> is owned by JmsSession [ID:de300758-71f8-4fff-9d51-0a3e6dc01b88:9:7]
> delivery dispatcher Id=41620237 |
>
>
> Regards,
> Abhishek Kumar
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hey Robbie,

Thanks a lot for quick reply.

We are using JmsSession for below purposes
1. Creating JMS messages
2. Creating producers for sending message
3. Creating consumers for receiving message

Thread name "delivery dispatcher" suggests that there is an issue in
consumer JmsSession. Could you please confirm this ?

If you think there could be an issue in other processor like JmsMessage
creation or publishing then please let me know. So I can try to find
blocking thread.

Regards,
Abhishek Kumar




--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
The 'dispatcher thread' is the session thread used to deliver messages
from receiver onMessage callbacks, 1 thread per session as mandated by
JMS. When a session is delivering to onMessage, that blocks certain
other operations on the session/connection from completing since a
delivery is in progress, as mandated by JMS. This is accomplished with
a lock.

You are essentially blocking these delivery threads upon both
additional locks in your application and to extent upon each other, in
a circle'ish sequence, by having dispatcher thread acquire a lock
inside your application, then performing operations with the thread
upon different connection/session that require that other sessions
delivery lock, which you can't get because the other session is also
trying to do a similar thing at the same time, but is unable to get
the lock in your application as the first session has it, resulting in
each waiting on the other to finish, which they then obviously can't.
That is not an issue in JmsSession but in your general use of the
client.

As I have said a couple of times, we did identify one thing in 0.45.0
back in May where the session thread would continue to hold this
delivery lock while the thread was firing the connection exception
listener during certain types of delivery failure. We improved that so
it stopped holding the lock here in early June. Thus upgrading your
client would resolve the specific issue you reported in May. That may
or may not be the very same issue you are reporting now since you are
still using the older client, or it may actually be two onMessage
calls performing the similar thread dance, which there is nothing the
client can do about.

Separately, we identified an issue in proton-j, which can lead to the
very style of delivery failure from your original report (though you
also identified your particular usage of Service Bus tooling resulted
in that behaviour, so it may also be unrelated). The proton-j 0.33.8
release fixing that is now available, and we will do a Qpid JMS 0.55.0
release using it soon (though you can manually update to use 0.33.8
with the existing 0.54.0 release already if so desired).

Robbie

On Tue, 17 Nov 2020 at 16:41, akabhishek1
<[hidden email]> wrote:

>
> Hey Robbie,
>
> Thanks a lot for quick reply.
>
> We are using JmsSession for below purposes
> 1. Creating JMS messages
> 2. Creating producers for sending message
> 3. Creating consumers for receiving message
>
> Thread name "delivery dispatcher" suggests that there is an issue in
> consumer JmsSession. Could you please confirm this ?
>
> If you think there could be an issue in other processor like JmsMessage
> creation or publishing then please let me know. So I can try to find
> blocking thread.
>
> Regards,
> Abhishek Kumar
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Thanks a lot for details reply.

We have added story in our backlog to upgrade project with 0.55.0 client. As
we have to do a lot of performance testing, so we will use latest version
for testing which will save our time.

As you are targeting to release this week, so we will wait for release and
then plan to upgrade accordingly.

Thanks again.

Regards,
Abhishek Kumar



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
In reply to this post by Robbie Gemmell
Hi Robbie,

We are trying to replicate this issue from our end, so we can confidently
apply fix and roll out to all. We need some your input/help to replicate
this issue.  It could be be some issue from my end, So I am trying to find
trouble code as well. Sorry for many questions.

In May, we had this issue due to bad Message which was published with .Net,
but now we got issue due to normal messages as well.

We are having this issue while restarting of ServiceBus connector restart
(due to ServiceBus connectivity loss). I follow below steps for restart -
-------------------------------------------
1. Closing and Nullifying JMS Objects

a. Connection.close(),
    Connection = null,

b. MessageConsumer.setMessageListener(null); --> I think i am doing wrong
here. I don't need to set null here, as i am closing on next step. What's
your opinion?
    MessageConsumer.close();
    MessageConsumer=null;

c. Session.close();
   Session = null
------------------------------------------
2. Creating JMS Objects
    a. Create Connection
    b. Create Session
    c. Create Consumer
------------------------------------------
Q1. ) Could you please suggest if I am doing anything wrong while restarting
of JMS Objects ?

Q2. ) If we got any exception while closing Connection, Session, Consumer
and Producer, then how can we make sure that Connection, Session, Consumer
and Producer closed and clear successfully from system?
Is it good practise set Null to JMS Objects after closing to make sure that
JMS Objects are cleaned up properly?
I want to make sure that JMS object and threads are clear from system
properly before creating new connection, so it will not cause any issue
while starting of JMS connection, Session, etc.
Overall I feel that, this could be an issue with clearance/disposing of
existing JMS Objects.

Could you please suggest your opinion to handle gracefully for exception
scenario while closing JMS Objects?


Q3. ) We got  "Illegal invocation from MessageListener callback" error while
closing Connection & Session, and then we started having "Suspected
deadlocked threads" error.

Could you please suggest any idea to generate "Illegal invocation from
MessageListener callback" error ? It could be one of reason for deadlocked.
If I am able to generate this error then I could generate deadlock error.

It will be great help if you provide your opinion on above queries.

Please find below error logs.

Error Pattern 1 -
"Failed to close connection - 'Illegal invocation from MessageListener
callback'"
"Stopping: 'null'. Object is: ServicebusMessageReceiver"
"Failed to reset message listener on endpoint
'servicebus://topic:***/subscriptions/***' - 'The MessageConsumer was closed
due to an unrecoverable error.' - 'class javax.jms.IllegalStateException'"
"Suspected deadlocked threads: JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
Id=41620240 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
delivery dispatcher Id=51620937 is in WAITING on
lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
dispatcher Id=41620235 | JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
Id=41620235 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | "
"Suspected deadlocked threads: JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
Id=41620240 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
delivery dispatcher Id=51620937 is in WAITING on
lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
dispatcher Id=41620235 | JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
Id=41620235 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | "
"Suspected deadlocked threads: JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
Id=41620240 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
delivery dispatcher Id=51620937 is in WAITING on
lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
dispatcher Id=41620235 | JmsSession
[ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
Id=41620235 is in BLOCKED on
lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
Id=51620937 | "

Error Sample 2
"Failed to close connection - 'Illegal invocation from MessageListener
callback'"
"Failed to close session - 'Illegal invocation from MessageListener
callback'"

Regards,
Abhishek Kumar



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
The "Illegal invocation from MessageListener callback" issue looks to
be a distinct bug in the client. A MessageListener isnt normally
allowed to call close() on its session or connection, however the way
this restriction is implemented in the client means it is currently
also being applied incorrectly during the ExceptionListener callback
caused by these unusual failures during async dispatch. Essentially,
if your application didnt deadlock upon itself across different
sessions/connections in somewhat of a circle as youve seen, then it
could have instead hit this bug.

I have raised https://issues.apache.org/jira/browse/QPIDJMS-521 and
pushed an initial change with a test exposing the issue and an initial
fix resolving it. You can try it out by building yourself from
https://github.com/apache/qpid-jms or using a snapshot from
http://repository.apache.org/content/groups/snapshots/.

The order of your connection/consumer/session closures doesnt make
sense. If you close the connection as you do first, then the sessions
and their consumers/producers are implicity shut down and marked
closed. You can just close the connection in that case.

No, you needn't call setMessageListener(null) first if you do close a
consumer. You can just close the consumer, or its session, or
connection. The overall effect isnt much different - all routes would
wait on the delivery lock if needed before proceeding.

Setting the fields to null wont really affect cleanup beyond basic GC.
If there is a failure to cleanup and there are threads still running
they may keep doing so regardless. That mostly shouldnt be a
problem(besides obviously the associated resources) since the
connections would be largely independent outwith your application. One
thing to perhaps look at may be the way you create/use the
ExceptionListeners. It might be good to try and ensure each listener
can only reference specific objects it was created for, and cant for
example reference different objects created later over time, which are
perhaps being served by another listener also created later, such that
they cant cross-interact that way.

The original issue occurred due to unexpected failure during the work
surrounding onMessage callback, leading to the ExceptionListener being
fired. In the older client, this was done while holding the session
delivery lock, leading to interaction with your applications own lock
and connection/session usage as I've previously explained, or failing
that issue arising then instead it could then hit QPIDJMS-521. One
simple way the unexpected failure might occur was for message arriving
with a Data body section and having content-type indicating it
contained text, but the payload not decoding as such. This seemed to
be what you were saw originally. Another simple way presented recently
by PROTON-2097 was for an entirely valid UTF-8 encoded string type
containing multi-byte character encodings, to be received across
multiple transfer sections, such that a single multi-byte character
was split across different internal buffer sections. Simplest way for
the client to hit this, is likely to receive a > 2MB TextMessage (with
amqp-value body section containing string type) with body composed
entirely of multi-byte unicode characters, ensuring it breaches the
clients default maxFrameSize and will be in multiple chunks. There is
still an element of variability where it could work though, depending
on the other properties etc in the message shifting the relative
position of the body content such that a character isn't split across
different chunks.

Robbie

On Thu, 26 Nov 2020 at 17:13, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> We are trying to replicate this issue from our end, so we can confidently
> apply fix and roll out to all. We need some your input/help to replicate
> this issue.  It could be be some issue from my end, So I am trying to find
> trouble code as well. Sorry for many questions.
>
> In May, we had this issue due to bad Message which was published with .Net,
> but now we got issue due to normal messages as well.
>
> We are having this issue while restarting of ServiceBus connector restart
> (due to ServiceBus connectivity loss). I follow below steps for restart -
> -------------------------------------------
> 1. Closing and Nullifying JMS Objects
>
> a. Connection.close(),
>     Connection = null,
>
> b. MessageConsumer.setMessageListener(null); --> I think i am doing wrong
> here. I don't need to set null here, as i am closing on next step. What's
> your opinion?
>     MessageConsumer.close();
>     MessageConsumer=null;
>
> c. Session.close();
>    Session = null
> ------------------------------------------
> 2. Creating JMS Objects
>     a. Create Connection
>     b. Create Session
>     c. Create Consumer
> ------------------------------------------
> Q1. ) Could you please suggest if I am doing anything wrong while restarting
> of JMS Objects ?
>
> Q2. ) If we got any exception while closing Connection, Session, Consumer
> and Producer, then how can we make sure that Connection, Session, Consumer
> and Producer closed and clear successfully from system?
> Is it good practise set Null to JMS Objects after closing to make sure that
> JMS Objects are cleaned up properly?
> I want to make sure that JMS object and threads are clear from system
> properly before creating new connection, so it will not cause any issue
> while starting of JMS connection, Session, etc.
> Overall I feel that, this could be an issue with clearance/disposing of
> existing JMS Objects.
>
> Could you please suggest your opinion to handle gracefully for exception
> scenario while closing JMS Objects?
>
>
> Q3. ) We got  "Illegal invocation from MessageListener callback" error while
> closing Connection & Session, and then we started having "Suspected
> deadlocked threads" error.
>
> Could you please suggest any idea to generate "Illegal invocation from
> MessageListener callback" error ? It could be one of reason for deadlocked.
> If I am able to generate this error then I could generate deadlock error.
>
> It will be great help if you provide your opinion on above queries.
>
> Please find below error logs.
>
> Error Pattern 1 -
> "Failed to close connection - 'Illegal invocation from MessageListener
> callback'"
> "Stopping: 'null'. Object is: ServicebusMessageReceiver"
> "Failed to reset message listener on endpoint
> 'servicebus://topic:***/subscriptions/***' - 'The MessageConsumer was closed
> due to an unrecoverable error.' - 'class javax.jms.IllegalStateException'"
> "Suspected deadlocked threads: JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
> Id=41620240 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
> delivery dispatcher Id=51620937 is in WAITING on
> lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
> owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
> dispatcher Id=41620235 | JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
> Id=41620235 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | "
> "Suspected deadlocked threads: JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
> Id=41620240 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
> delivery dispatcher Id=51620937 is in WAITING on
> lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
> owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
> dispatcher Id=41620235 | JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
> Id=41620235 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | "
> "Suspected deadlocked threads: JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:10] delivery dispatcher
> Id=41620240 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7]
> delivery dispatcher Id=51620937 is in WAITING on
> lock=java.util.concurrent.locks.ReentrantLock$NonfairSync@26cc0a98     is
> owned by JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery
> dispatcher Id=41620235 | JmsSession
> [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:5] delivery dispatcher
> Id=41620235 is in BLOCKED on
> lock=org.mule.transport.servicebus.SbusConnector@58e4b68c     is owned by
> JmsSession [ID:ge300959-71f8-8fff-9d61-0a3e6dc02b98:9:7] delivery dispatcher
> Id=51620937 | "
>
> Error Sample 2
> "Failed to close connection - 'Illegal invocation from MessageListener
> callback'"
> "Failed to close session - 'Illegal invocation from MessageListener
> callback'"
>
> Regards,
> Abhishek Kumar
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Robbie,

Thanks a lot for detail reply. We have started testing with
"0.56.0-SNAPSHOT" .

Do we have any high level timeline to release "0.56.0" ? So we can plan
accordigly.

Regards,
Abhishek Kumar



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
Not really, no. Having just done 0.55.0 (+ various other releases)
very recently I wasn't actually looking to do another imminently. I'll
probably just do it at some point it suits in the next couple of
weeks.

I might also wait for you to report back on your testing unless
something else more pressing comes up. Had you tried things out after
the improvement made ~6 months ago due to your initial report, or
again after your recent re-report before 0.55.0 was released, this
'new' (~4 years old probably) issue would have been found and fixed
already without need of yet another/specific release.

On Wed, 2 Dec 2020 at 15:08, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> Thanks a lot for detail reply. We have started testing with
> "0.56.0-SNAPSHOT" .
>
> Do we have any high level timeline to release "0.56.0" ? So we can plan
> accordigly.
>
> Regards,
> Abhishek Kumar
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Robbie,

Sure, I will be happy to provide you testing feedback.

I was doing testing with "qpid-jms-client-0.56.0-SNAPSHOT" and
"proton-j-0.33.8". So far I managed to found three issues.
These issues are intermittent, however we can regenerate this issue in
couple of retries. I manage to capture error with Qpid Traces. Please find
below details.

Infrastructure Details --> Created 2 JMS connection instance for testing.
First JMS connection.
 * 1 endpoint topic-subscription
 * 4 consumer/listener
 
Second JMS connection.
 * 1 endpoint Queue
 * 4 consumer/listener
 
Steps to reproduce this issue -
1. Start the application, which should start listening on both endpoints
with separate JMS connections
2. DO NOT publish any message for consumption
3. Keep Application idle for 5m or sometimes 20m. If you didn't get this
issue then please restart the application couple of times

**** Issue Details *****
1. Both JMS connection have one active listener, but still getting this
error - 'The connection was inactive for more than the allowed 120000
milliseconds and is closed by container
'7A2E0A0515A9427F82D1ACF7F25A024D_G12'. [condition =
amqp:connection:forced]' - 'class javax.jms.JMSException'
   
 We shouldn't get this error as we have 1 active listener on both JMS
connection. Please refer "Receiver_Timeout_120000_ms.txt" log file for more
details.

2. Inconsistent JMS connection status while getting timeout error.
    a) Connection Active for Receiver TimeOut -  If we are getting timeout
error due to receiver then we can see that connection is active at time of
exception. Refer "Receiver_Timeout_120000_ms.txt"

   b) Connection InActive for No Session/Producer/Consumer -  Create a JMS
connection which does not have any session/producer/consumer and keep
application running.  We will get 60000ms idle timeout error after some
time. Please refer below logs.
We are using "JmsConnection.getClientID" to check connection status. Please
refer below sample method 'isConnectionActive'.
               
Problem - At receiver time out (a) connection is active, But at second
scenario (b) connection is inactive.
I think at both scenario connection should be inactive.
       
        ***Logs**
        TRACE 2020-12-03 12:40:05,354 [AmqpProvider
:(3):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] RECV:
Close{error=Error{condition=amqp:connection:forced, description='The
connection was inactive for more than the allowed 60000 milliseconds and is
closed by container 'LinkTracker'.
TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5,
Timestamp:2020-12-03T12:40:05', info=null}}
TRACE 2020-12-03 12:40:05,364 [AmqpProvider
:(3):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] SENT:
Close{error=null}
ERROR 2020-12-03 12:40:05,370 [QpidJMS Connection Executor:
ID:a6cf63d9-4608-4643-8955-eee32e604674:1]
org.mule.servicebus.SbusConnector: Connection exception, Reason 'The
connection was inactive for more than the allowed 60000 milliseconds and is
closed by container 'LinkTracker'.
TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5,
Timestamp:2020-12-03T12:40:05 [condition = amqp:connection:forced]' - 'class
org.apache.qpid.jms.JmsConnectionRemotelyClosedException',
isConnectionActive 'false'

****Sample Code ***
protected boolean isConnectionActive() {
        boolean connectionStatus = false;
        try {
            String clientID = getConnection().getClientID();
            connectionStatus = true;
        } catch (Exception e) {
            connectionStatus = false;
        }
        return connectionStatus;
    }

3. Use Case - We have 1 JMS connection, which will be used for publishing
message.
        We know that ServiceBus detach active connection link, if we don't have any
active Producer/Consumer.
        For avoiding this issue, we registered a timer which will periodically
create/reset temporary Session+Producer instead of JMS connection. This
solution help us to keep JMS connection live, so we don't need to reset JMS
connection again and again. We haven't faced any issue so far with old
client 0.45.0 jar.
       
        After upgrading the JAR, we are facing intermittent issue while resetting
Producer. Error Log - "Failed to reset temp producer -
javax.jms.JMSException: The service was unable to process the request;"
        Please refer "3rd_issue_Failed_To_Reset_Producer_Error.txt" for more
details.
       

NOTE - We haven't faced above 3 issues with Old client 0.45.0 jar.

Could you please advise us on above 3 issues. Please feel free to let me
know for any other information.

Receiver_Timeout_120000_ms.txt
<http://qpid.2158936.n2.nabble.com/file/t396358/Receiver_Timeout_120000_ms.txt>  
3rd_issue_Failed_To_Reset_Producer_Error.txt
<http://qpid.2158936.n2.nabble.com/file/t396358/3rd_issue_Failed_To_Reset_Producer_Error.txt>  



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
To be clear I meant testing of the issue in question, rather than
debugging your application / use of Service Bus.

On Thu, 3 Dec 2020 at 13:32, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> Sure, I will be happy to provide you testing feedback.
>
> I was doing testing with "qpid-jms-client-0.56.0-SNAPSHOT" and
> "proton-j-0.33.8". So far I managed to found three issues.
> These issues are intermittent, however we can regenerate this issue in
> couple of retries. I manage to capture error with Qpid Traces. Please find
> below details.
>
> Infrastructure Details --> Created 2 JMS connection instance for testing.
> First JMS connection.
>  * 1 endpoint topic-subscription
>  * 4 consumer/listener
>
> Second JMS connection.
>  * 1 endpoint Queue
>  * 4 consumer/listener
>
> Steps to reproduce this issue -
> 1. Start the application, which should start listening on both endpoints
> with separate JMS connections
> 2. DO NOT publish any message for consumption
> 3. Keep Application idle for 5m or sometimes 20m. If you didn't get this
> issue then please restart the application couple of times
>
> **** Issue Details *****
> 1. Both JMS connection have one active listener, but still getting this
> error - 'The connection was inactive for more than the allowed 120000
> milliseconds and is closed by container
> '7A2E0A0515A9427F82D1ACF7F25A024D_G12'. [condition =
> amqp:connection:forced]' - 'class javax.jms.JMSException'
>
>  We shouldn't get this error as we have 1 active listener on both JMS
> connection. Please refer "Receiver_Timeout_120000_ms.txt" log file for more
> details.
>

Your logs show there was a consumer and Service Bus closed it, with a
rather misleading error description that "The connection was inactive
for more than the allowed 120000 milliseconds and is closed...". The
connection was not closed (and as a whole wasnt inactive for 120sec
either way), the receiver was.

ServiceBus has its own unique definitions and enforcements of being
idle. ServiceBus closing the consumer link because you aren't using it
is not a client issue.

> 2. Inconsistent JMS connection status while getting timeout error.
>     a) Connection Active for Receiver TimeOut -  If we are getting timeout
> error due to receiver then we can see that connection is active at time of
> exception. Refer "Receiver_Timeout_120000_ms.txt"
>
>    b) Connection InActive for No Session/Producer/Consumer -  Create a JMS
> connection which does not have any session/producer/consumer and keep
> application running.  We will get 60000ms idle timeout error after some
> time. Please refer below logs.
> We are using "JmsConnection.getClientID" to check connection status. Please
> refer below sample method 'isConnectionActive'.
>
> Problem - At receiver time out (a) connection is active, But at second
> scenario (b) connection is inactive.
> I think at both scenario connection should be inactive.
>

No, they shouldn't. In the first case, the connection was still open
as I noted above, hence it didn't behave like it isn't. In the latter
case, the connection as a whole got closed, and so reacted
accordingly.

>         ***Logs**
>         TRACE 2020-12-03 12:40:05,354 [AmqpProvider
> :(3):[amqps://***.servicebus.windows.net:-1]]
> org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] RECV:
> Close{error=Error{condition=amqp:connection:forced, description='The
> connection was inactive for more than the allowed 60000 milliseconds and is
> closed by container 'LinkTracker'.
> TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5,
> Timestamp:2020-12-03T12:40:05', info=null}}
> TRACE 2020-12-03 12:40:05,364 [AmqpProvider
> :(3):[amqps://***.servicebus.windows.net:-1]]
> org.apache.qpid.jms.provider.amqp.FRAMES: [1314740929:0] SENT:
> Close{error=null}
> ERROR 2020-12-03 12:40:05,370 [QpidJMS Connection Executor:
> ID:a6cf63d9-4608-4643-8955-eee32e604674:1]
> org.mule.servicebus.SbusConnector: Connection exception, Reason 'The
> connection was inactive for more than the allowed 60000 milliseconds and is
> closed by container 'LinkTracker'.
> TrackingId:8ac03af7d6794026ab3948b199e58a35_G5, SystemTracker:gateway5,
> Timestamp:2020-12-03T12:40:05 [condition = amqp:connection:forced]' - 'class
> org.apache.qpid.jms.JmsConnectionRemotelyClosedException',
> isConnectionActive 'false'
>
> ****Sample Code ***
> protected boolean isConnectionActive() {
>         boolean connectionStatus = false;
>         try {
>             String clientID = getConnection().getClientID();
>             connectionStatus = true;
>         } catch (Exception e) {
>             connectionStatus = false;
>         }
>         return connectionStatus;
>     }
>
> 3. Use Case - We have 1 JMS connection, which will be used for publishing
> message.
>         We know that ServiceBus detach active connection link, if we don't have any
> active Producer/Consumer.
>         For avoiding this issue, we registered a timer which will periodically
> create/reset temporary Session+Producer instead of JMS connection. This
> solution help us to keep JMS connection live, so we don't need to reset JMS
> connection again and again. We haven't faced any issue so far with old
> client 0.45.0 jar.
>
>         After upgrading the JAR, we are facing intermittent issue while resetting
> Producer. Error Log - "Failed to reset temp producer -
> javax.jms.JMSException: The service was unable to process the request;"
>         Please refer "3rd_issue_Failed_To_Reset_Producer_Error.txt" for more
> details.
>

The server refused the producers link attach, with error indicating an
internal-error and description saying it wasnt able to process the
request and to try again. I dont see anything wrong in what the client
says its doing (which matches what it did previously), and the server
gives no useful reason why it failed. This seems like a transient
server failure of some kind.

>
> NOTE - We haven't faced above 3 issues with Old client 0.45.0 jar.
>
> Could you please advise us on above 3 issues. Please feel free to let me
> know for any other information.
>
> Receiver_Timeout_120000_ms.txt
> <http://qpid.2158936.n2.nabble.com/file/t396358/Receiver_Timeout_120000_ms.txt>
> 3rd_issue_Failed_To_Reset_Producer_Error.txt
> <http://qpid.2158936.n2.nabble.com/file/t396358/3rd_issue_Failed_To_Reset_Producer_Error.txt>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Robbie,

Thanks for quick reply. I referenced your test case and tried to generate
"Illegal invocation from MessageListener callback" error.
At this moment, I am not able to generate this error neither "Suspected
deadlocked threads" error.

So, I can't confirm that this fix is working or not.

Please find attached sample test class  ConnectionTest.java
<http://qpid.2158936.n2.nabble.com/file/t396358/ConnectionTest.java>  . I
tested with both library "45.0" and "0.56.0-SNAPSHOT", And test cases are
failing for both jar versions.
So definitely, I am missing something .

Is that possible for you to suggest correction in attached
"ConnectionTest.java" ? So I can generate error and proceed further for
testing.

Regarding last reported 3 issues - I will try to replicate these issues in
independent project and share details with you.
As we are upgrading library, so we want to make sure that existing(0.45.0)
positive functionalities should match with latest jar (0.56.SNAPSHOT).


Regards,
Abhishek Kumar




--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
On Thu, 3 Dec 2020 at 18:36, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> Thanks for quick reply. I referenced your test case and tried to generate
> "Illegal invocation from MessageListener callback" error.
> At this moment, I am not able to generate this error neither "Suspected
> deadlocked threads" error.
>
> So, I can't confirm that this fix is working or not.
>
> Please find attached sample test class  ConnectionTest.java
> <http://qpid.2158936.n2.nabble.com/file/t396358/ConnectionTest.java>  . I
> tested with both library "45.0" and "0.56.0-SNAPSHOT", And test cases are
> failing for both jar versions.
> So definitely, I am missing something .

A few things.

You are trying to use the same invalid-payload my test uses, but you
are in fact sending something that is very different and perfectly
valid, so it presumably won't generate the TextMessage decode failure,
and be successfully received, failing the test. When you send a
BytesMessage with the client it is annotated as such, and will always
be treated as a BytesMessage on receipt, so that payload is perfectly
valid then. The client cant generate the exact payload I used in my
test. You might be able to directly replace the body Section on the
text message facade with some reflection to get closer to the same
payload.

You could also do what I said in my earlier mail and use larger
multi-frame messages with unicode characters. You could even reduce
the connections maxFrameSize to lower the threshold for multiple
frames being required to receive a message, causing more frames and
increasing the chance of the cross-frame decode issue in the old
client. The newer proton-j used in the new client wont throw that
failure though and so wont cause the delivery failure, you would have
to use dependency management to downgrade the new client to use e.g
0.33.7.

You look to be trying to perform essentially exactly the same test I
did. If you succeed it should of course give the same result. I was
expecting you to test what you are doing when you see the error,
having encountered two different ways of doing so.

You will certainly never reproduce the deadlock with the test as it
only has 1 connection/session rather than 2+ needed, and has no
application-level lock for them to compete over before trying to close
the others and form the block.

(It won't matter here, but I also noticed you have a somewhat amusing
and contradictory set of URI options:
"&jms.forceSyncSend=true&jms.forceAsyncSend=true"...sync wins due to
the impl).

>
> Is that possible for you to suggest correction in attached
> "ConnectionTest.java" ? So I can generate error and proceed further for
> testing.
>
> Regarding last reported 3 issues - I will try to replicate these issues in
> independent project and share details with you.

I dont see a need. The second of your points isn't an issue at all and
your expectation was simply wrong, again likely in large part due to
the misleading error description used by Service Bus. The others are
server side behaviours.

> As we are upgrading library, so we want to make sure that existing(0.45.0)
> positive functionalities should match with latest jar (0.56.SNAPSHOT).
>
>
> Regards,
> Abhishek Kumar
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Robbie,

Thanks a lot for details insight and correction. Test case is working fine
now with 0.56-SNAPSHOT.
I am able to generate invalid message which continously throw 'Cannot decode
String in UTF-8' error.

The good thing is - I am able to generate "Suspected deadlocked threads"
error repeatedly with Old(0.45.o) jar. I used invalid message .

Steps to generate error - I need to do enable/disable queue and WiFI ON/OFF
couple of times to get this error. I have not found consistent pattern yet,
but couple of retries helps to generate this error.

I did similar testing with New "0.56.0-SNAPSHOT" jar. Unfortunatelly I am
getting same "Suspected deadlocked threads" error with new jar.

Can you please check attached thread dump
"ThreadDumps_Deadlock_56-SNAPSHOT.txt", if you find anything from your side.

ThreadDumps_Deadlock_56-SNAPSHOT.txt
<http://qpid.2158936.n2.nabble.com/file/t396358/ThreadDumps_Deadlock_56-SNAPSHOT.txt>  

I am also trying to find root cause from my side.

Regrads,
Abhishek Kumar




--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
On Wed, 9 Dec 2020 at 16:37, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> Thanks a lot for details insight and correction. Test case is working fine
> now with 0.56-SNAPSHOT.
> I am able to generate invalid message which continously throw 'Cannot decode
> String in UTF-8' error.
>
> The good thing is - I am able to generate "Suspected deadlocked threads"
> error repeatedly with Old(0.45.o) jar. I used invalid message .
>
> Steps to generate error - I need to do enable/disable queue and WiFI ON/OFF
> couple of times to get this error. I have not found consistent pattern yet,
> but couple of retries helps to generate this error.
>
> I did similar testing with New "0.56.0-SNAPSHOT" jar. Unfortunatelly I am
> getting same "Suspected deadlocked threads" error with new jar.
>

No, you are actually getting a fairly different scenario this time.
Previously the deadlock involved locks in your application and a
delivery lock within the client, which was being held when firing the
exception listener, and is also needed to close things down. We
removed that client lock from being in play here, which your result
shows is the case; your new result only involves locks outside the
client, within your application, but now being acquired in different
orders. By pairing the invalid message causing failure before
onMessage (which is really quite unexpected) with disconnecting the
actual connection in full, I think you managed to get multiple calls
to the exception listener. In those your handling then acquires these
application locks in different orders and thus upon which it can then
deadlock.

If your reaction to the ExceptionListener firing is always to close
the connection and reconnect, I would suggest that you use an
AtomicBoolean as a gate within your handler (which per previous mail,
should ensure it only operates on a single connection) such that only
a single attempt can be made to clear up and reconnect, thereby
removing the chance for your locks to be acquired in different orders,
e.g:

if (exceptionFired.compareAndSet(false, true)) {
  // Do cleanup work
}


> Can you please check attached thread dump
> "ThreadDumps_Deadlock_56-SNAPSHOT.txt", if you find anything from your side.
>
> ThreadDumps_Deadlock_56-SNAPSHOT.txt
> <http://qpid.2158936.n2.nabble.com/file/t396358/ThreadDumps_Deadlock_56-SNAPSHOT.txt>
>
> I am also trying to find root cause from my side.
>
> Regrads,
> Abhishek Kumar
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hey Robbie,

Thanks a lot for your suggestion. I am still working on exception listener,
will let you know for any issue.

While testing with 0.56.0-SNAPSHOT, I found one distinct issue - consumer
closed for wrong receiver. Please find below details

JMS Infra details -
a) JMS Connection - 1
   receiver endpoint - 2
   Consumer on every receiver - 4 (Total 8)
   Separate session for every consumer - Total 8
b) JMS Connection - 1
   receiver endpoint - 2
   Consumer on every receiver - 4 (Total 8)
   Separate session for every consumer - Total 8
   
Steps to reproduce this issue -
1. Start attached MultipleConsumerTest.java class
2. disable only one receiver endpoint (only one subscription - sub1)
3. Wait for connection exception
4. We can see that two receivers are failing to consume messages which was
registered on same JMS connection.
As we have disabled only one subscription, so consumer should be close for
only one receiver instead of two.
   
Please find attached sample test class  MultipleConsumerTest.java
<http://qpid.2158936.n2.nabble.com/file/t396358/MultipleConsumerTest.java>  
and error log  consumer_closed_for_wrong_receiver.txt
<http://qpid.2158936.n2.nabble.com/file/t396358/consumer_closed_for_wrong_receiver.txt>
. Please take a look on this issue and let us know your
opinion.


Regards,
Abhishek Kumar




--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
If I understand your description and code correctly, you create 4
consumers (each on their own session) per 'Service Bus subscription',
using 2 connections, each of which are used for 2 different subs. You
then did something on the server side for a single sub and expected
its related 4 consumers to close, but actually consumers for both subs
in use on the connection were closed.

The logs very clearly show (snippets below) Service Bus remotely
initiating closure of all 8 consumers on the connection in quick
succession, for both sub 3 and sub 4 on connection 2 (rather than sub
1 on connection 1 as mentioned in your description). If that isn't
what you expected based on what you did you will need to raise that
with Microsoft, it's again not a client issue but server-initiated
behaviour.

TRACE 2020-12-10 20:20:41,753 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:5] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790524:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:5:1:test2/subscriptions/sub4'
is force detached. Code: consumer(link10371). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00080ab0000028835fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub4, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,759 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:1] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790494:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:1:1:test2/subscriptions/sub3'
is force detached. Code: consumer(link10359). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00050ab0000028775fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub3, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,761 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:2] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790505:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:2:1:test2/subscriptions/sub3'
is force detached. Code: consumer(link10362). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00050ab00000287a5fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub3, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,762 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:6] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790529:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:6:1:test2/subscriptions/sub4'
is force detached. Code: consumer(link10374). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00080ab0000028865fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub4, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,764 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:3] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790510:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:3:1:test2/subscriptions/sub3'
is force detached. Code: consumer(link10365). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00050ab00000287d5fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub3, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,765 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:7] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790534:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:7:1:test2/subscriptions/sub4'
is force detached. Code: consumer(link10377). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00080ab0000028895fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub4, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,766 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:4] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790515:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:4:1:test2/subscriptions/sub3'
is force detached. Code: consumer(link10368). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00050ab0000028805fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub3, Timestamp:2020-12-10T20:20:41',
info=null}}
TRACE 2020-12-10 20:20:41,766 [AmqpProvider
:(2):[amqps://***.servicebus.windows.net:-1]]
org.apache.qpid.jms.provider.amqp.FRAMES: [1943855334:8] RECV:
Detach{handle=0, closed=true,
error=Error{condition=amqp:link:detach-forced, description='The link
'G7:1790539:qpid-jms:receiver:ID:25209b36-d040-48af-a4a1-3e21f090b3d0:1:8:1:test2/subscriptions/sub4'
is force detached. Code: consumer(link10380). Details:
InnerMessageReceiver was closed.
TrackingId:b77a844b00080ab00000288c5fd2830c_G7_B23,
SystemTracker:***:Topic:test2|sub4, Timestamp:2020-12-10T20:20:41',
info=null}}


On Thu, 10 Dec 2020 at 20:45, akabhishek1
<[hidden email]> wrote:

>
> Hey Robbie,
>
> Thanks a lot for your suggestion. I am still working on exception listener,
> will let you know for any issue.
>
> While testing with 0.56.0-SNAPSHOT, I found one distinct issue - consumer
> closed for wrong receiver. Please find below details
>
> JMS Infra details -
> a) JMS Connection - 1
>    receiver endpoint - 2
>    Consumer on every receiver - 4 (Total 8)
>    Separate session for every consumer - Total 8
> b) JMS Connection - 1
>    receiver endpoint - 2
>    Consumer on every receiver - 4 (Total 8)
>    Separate session for every consumer - Total 8
>
> Steps to reproduce this issue -
> 1. Start attached MultipleConsumerTest.java class
> 2. disable only one receiver endpoint (only one subscription - sub1)
> 3. Wait for connection exception
> 4. We can see that two receivers are failing to consume messages which was
> registered on same JMS connection.
> As we have disabled only one subscription, so consumer should be close for
> only one receiver instead of two.
>
> Please find attached sample test class  MultipleConsumerTest.java
> <http://qpid.2158936.n2.nabble.com/file/t396358/MultipleConsumerTest.java>
> and error log  consumer_closed_for_wrong_receiver.txt
> <http://qpid.2158936.n2.nabble.com/file/t396358/consumer_closed_for_wrong_receiver.txt>
> . Please take a look on this issue and let us know your
> opinion.
>
>
> Regards,
> Abhishek Kumar
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
HI Robbie,

Thanks a lot for quick feedback. I will raise this with Microsoft.

Regards,
Abhi



--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

akabhishek1
Hi Robbie,

I applied the changes in exception listener which will make sure to cleanup
once instead of multiple times. After changes, I tested multiple times and
it is working fine so far.

As you mentioned before - "By pairing the invalid message causing failure
before
onMessage (which is really quite unexpected) with disconnecting the actual
connection in full"

Do we need to worry about this?

I saw your release notification for 0.56, I am hoping you will release this
within 1-2 days. So i will use released version.

Regards,
Abhishek Kumar




--
Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid-jms-client-0.45 --> Suspected deadlocked threads - owned by JmsSession delivery dispatcher

Robbie Gemmell
Administrator
On Mon, 14 Dec 2020 at 19:42, akabhishek1
<[hidden email]> wrote:

>
> Hi Robbie,
>
> I applied the changes in exception listener which will make sure to cleanup
> once instead of multiple times. After changes, I tested multiple times and
> it is working fine so far.
>
> As you mentioned before - "By pairing the invalid message causing failure
> before
> onMessage (which is really quite unexpected) with disconnecting the actual
> connection in full"
>
> Do we need to worry about this?
>

No, as it typically won't happen, and the change to your handling I
suggested means it also isn't an issue if it were to, as your testing
showed.

> I saw your release notification for 0.56, I am hoping you will release this
> within 1-2 days. So i will use released version.
>

It will be released once a vote is successfully completed. Votes take
at least 3 days, so currently it might emerge early on Thursday
evening (in Europe) if all goes well.


> Regards,
> Abhishek Kumar
>
>
>
>
> --
> Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

12