[
https://issues.apache.org/jira/browse/QPID-5439?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13857167#comment-13857167
]
Ulrich Romahn commented on QPID-5439:
-------------------------------------
I ran the qpid-cpp broker with protocol tracing enabled and found the following
sequence when writing to a queue from the JMS client:
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
<- AMQP
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
-> AMQP
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 <- @open(16) [container-id="uromahn-vm-linuxmint15.corp.ebay.com(7563):1",
hostname="YY.YY.YY.YY", max-frame-size=65536, channel-max=255]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @open(16) [container-id="f60a5acf-ac8a-4a4e-9b43-c9efd0f20f3a"]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 <- @begin(17) [next-outgoing-id=0, incoming-window=2048,
outgoing-window=2048, handle-max=4294967295]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @begin(17) [remote-channel=0, next-outgoing-id=0,
incoming-window=2147483647, outgoing-window=0]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 <- @attach(18) [name="gce.queue<-34f8a965-f134-43ef-ba7a-0851c113a908",
handle=0, role=false, snd-settle-mode=0, rcv-settle-mode=0, source=@source(40)
[address="34f8a965-f134-43ef-ba7a-0851c113a908", default-outcome=@accepted(36)
[], outcomes=@PN_SYMBOL[:"amqp:accepted:list", :"amqp:rejected:list"]],
target=@target(41) [address="gce.queue"], initial-delivery-count=0]
2013-12-26 23:23:04 [Protocol] debug qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435
link 0x7f99e400d520 attached on 0x7f99e4024010
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @attach(18) [name="gce.queue<-34f8a965-f134-43ef-ba7a-0851c113a908",
handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40)
[durable=0, timeout=0, dynamic=false], target=@target(41) [address="gce.queue",
durable=0, timeout=0, dynamic=false], initial-delivery-count=0]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @flow(19) [next-incoming-id=0, incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0,
link-credit=100, drain=false]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 <- @transfer(20) [handle=0, delivery-id=0, delivery-tag=b"0",
message-format=0, settled=false] (161)
"\x00Sp\xc0\x04\x02AP\x04\x00Sr\xc1\x17\x02\xa3\x0dx-opt-to-type\xa1\x05queue\x00Ss\xc0B\x0a\xa0$90af4656-3202-48df-8dcf-9d0b06bb1f72@\xa1\x09gce.queue@@@@@@\x83\x00\x00\x01C19\xb8\xef\x00St\xc1\x01\x00\x00Sw\xa1$0e68286c-794b-4e79-8d66-a57a279c17f7\x00Sx\xc1\x01\x00"
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @flow(19) [next-incoming-id=1, incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=1,
link-credit=100, drain=false]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 -> @disposition(21) [role=true, first=0, last=0, settled=true,
state=@accepted(36) []]
2013-12-26 23:23:04 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43435]:
0 <- @detach(22) [handle=0]
And there it was "hanging".
For comparison, the following shows the trace for a communication using
Proton-j Messenger (v0.5):
2013-12-26 23:21:29 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
-> AMQP
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
<- AMQP
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 <- @open(16) [container-id="8c290e33-9174-436c-a63b-ffa08694e803",
hostname="YY.YY.YY.YY"]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 <- @begin(17) [next-outgoing-id=1, incoming-window=0, outgoing-window=0,
handle-max=1024]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 <- @attach(18) [name="gce.queue", handle=0, role=false, snd-settle-mode=2,
rcv-settle-mode=0, source=@source(40) [address="gce.queue"], target=@target(41)
[address="gce.queue"], incomplete-unsettled=false, initial-delivery-count=0]
2013-12-26 23:21:30 [Protocol] debug qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049
link 0x7f90b4019d50 attached on 0x7f90b401cda0
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @open(16) [container-id="2c47bf3d-c9fd-4b0f-8e19-fd572d8282b7"]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @begin(17) [remote-channel=0, next-outgoing-id=0,
incoming-window=2147483647, outgoing-window=0]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @attach(18) [name="gce.queue", handle=0, role=true, snd-settle-mode=2,
rcv-settle-mode=0, source=@source(40) [durable=0, timeout=0, dynamic=false],
target=@target(41) [address="gce.queue", durable=0, timeout=0, dynamic=false],
initial-delivery-count=0]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @flow(19) [next-incoming-id=1, incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0,
link-credit=100, drain=false]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 <- @transfer(20) [handle=0, delivery-id=0, delivery-tag=b"1",
message-format=0] (63)
"\x00Ss\xc0'\x03@@\xa1"amqp://YY.YY.YY.YY:5672/gce.queue\x00Sw\xa1\x0eTestMessage123"
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @flow(19) [next-incoming-id=2, incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=1,
link-credit=100, drain=false]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @disposition(21) [role=true, first=0, last=0, settled=true,
state=@accepted(36) []]
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 <- @close(24) []
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
<- EOS
2013-12-26 23:21:30 [Protocol] trace [qpid.YY.YY.YY.YY:5672-XX.XX.XX.XX:43049]:
0 -> @close(24) []
As one can see, here a "proper" close gets issued which properly disconnects
the client. However, in contrast, there is no detach from the session, which I
assume is implicit since we are closing the entire connection anyways.
Looks like the JMS client library is in a dead-lock while trying to close the
connection.
> [AMQP 1.0 JMS client] Client hangs during connection.close()
> ------------------------------------------------------------
>
> Key: QPID-5439
> URL: https://issues.apache.org/jira/browse/QPID-5439
> Project: Qpid
> Issue Type: Bug
> Components: Java Client
> Affects Versions: 0.27
> Environment: qpid-cpp 0.27 (latest trunk), amqp-1-0-client-jms
> 0.28-SNAPSHOT (latest trunk).
> Reporter: Ulrich Romahn
> Priority: Blocker
>
> I am connecting to a cpp broker via the amqp-1-0-client-jms client and send
> 1000 simple text messages to a queue on the broker. After that, I am opening
> a second session to receive those 1000 messages.
> When trying to close the connection (calling connection.close()), the client
> "hangs". When I look at the broker (qpid-tool, list connection) I am still
> seeing this connection open.
> Debugging through the code, shows that there is a lock in the class
> org.apache.qpid.amqp_1_0.client.Sender at the following code in method
> close():
> ...
> _session.removeSender(this);
> _endpoint.setSource(null);
> _endpoint.detach();
> _closed = true;
> synchronized(_endpoint.getLock())
> {
> while(!_endpoint.isDetached())
> {
> try
> {
> _endpoint.getLock().wait();
> }
> catch (InterruptedException e)
> {
> throw new SenderClosingException(e);
> }
> }
> }
> It actually seems to hang at the line " _endpoint.getLock().wait(); "
> NOTE: the exact same code works when running against a Java broker 0.24.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
