Robbie Gemmell created QPID-6947:
------------------------------------
Summary: [Java Broker] deliverycount advanced outside a previous
drain attempt that used all credit
Key: QPID-6947
URL: https://issues.apache.org/jira/browse/QPID-6947
Project: Qpid
Issue Type: Bug
Components: Java Broker
Affects Versions: qpid-java-6.0
Reporter: Robbie Gemmell
While investigating QPIDJMS-139 I noticed the broker seeming to advance the
delivery count outside of an earlier drain attempt (for which the credit was
either already used by in flight messages, or completely used by messages upon
the drain arrival meaning no 'drain response' flow was sent).
(It also shows the behaviour at the end which PROTON-1077 was raised for, which
causes the client to end up thinking it has credit that it does not)
Robbie
{noformat}
# Consumer grants new credit:
2015-12-09 19:37:17,063 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 granting
additional credit: 1000
2015-12-09 19:37:17,128 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=9361,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=15546, linkCredit=1000, available=null, drain=false, echo=false,
properties=null}
# Broker sends the consumer a flow (I believe after we accepted a message):
2015-12-09 19:37:17,214 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=9361, outgoingWindow=2048, handle=0,
deliveryCount=15546, linkCredit=1000, available=0, drain=false, echo=false,
properties=null}
2015-12-09 19:37:17,214 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 flow
update recieved, current local credit = 1000, queued = 0, remote credit = 1000
# Consumer drains having got no new messages yet:
2015-12-09 19:37:17,259 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Pull on consumer ID:WorkMac-62323-1449707737437-22:5:1:1
with timeout = 0
2015-12-09 19:37:17,259 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 draining,
current local credit = 1000, queued = 0, remote credit = 1000
2015-12-09 19:37:17,259 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=9361,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=15546, linkCredit=1000, available=null, drain=true, echo=false,
properties=null}
# Consumer grants new credit, having got 10361-9361=1000 transfers (/messages
in this case) either already in flight or sent because of the drain:
2015-12-09 19:37:17,278 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 granting
additional credit: 1000
2015-12-09 19:37:17,428 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=10361,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=16546, linkCredit=1000, available=null, drain=false, echo=false,
properties=null}
# Consumer tops up credit to 1000 again, having got another 11072-10361=711
messages:
2015-12-09 19:37:17,627 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 granting
additional credit: 711
2015-12-09 19:37:17,638 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=11072,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=17257, linkCredit=1000, available=null, drain=false, echo=false,
properties=null}
# Broker sends a lot of flows, seemingly as client accepts messages, indicating
link credit is 0.
# Another 11340-11072=268 apparently sent since (/already in flight before)
clients last top-up, which the broker hasnt seen when these were sent.
# Delivery count has reached 17546, while earlier (after the clients drain
attempt got 1000 messages) it was 16546 with 1000 credits and no drain, but
only 11340-10361=979 messages have been sent since then, so the delivery count
seems to have been advanced even after the earlier drain attempt used all the
credit.
2015-12-09 19:37:17,722 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=11340, outgoingWindow=2048, handle=0,
deliveryCount=17546, linkCredit=0, available=0, drain=false, echo=false,
properties=null}
...hundreds more the same...
2015-12-09 19:37:18,231 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=11340, outgoingWindow=2048, handle=0,
deliveryCount=17546, linkCredit=0, available=0, drain=false, echo=false,
properties=null}
# Broker sends a new flow with link credit now reflecting the additional 711
credit the client granted earlier:
2015-12-09 19:37:18,231 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=11340, outgoingWindow=2048, handle=0,
deliveryCount=17546, linkCredit=711, available=0, drain=false, echo=false,
properties=null}
2015-12-09 19:37:18,231 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 flow
update recieved, current local credit = 711, queued = 0, remote credit = 711
# Consumer receives 711 more messages, tops up credit supposedly to 1000, but
the Proton transport incorrectly thought the credit was -711 at this point (a
bug..) and only actually sends out 289 as the value:
2015-12-09 19:37:18,240 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 granting
additional credit: 1000
2015-12-09 19:37:18,240 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=12051,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=18257, linkCredit=289, available=null, drain=false, echo=false,
properties=null}
# Broker uses that credit, so client runs out of messages and then drains the
credit it thinks it has (but doesnt actually), leading to proton issuing a
drain with 0 credit instead.
2015-12-09 19:37:18,304 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=12051, outgoingWindow=2048, handle=0,
deliveryCount=18257, linkCredit=0, available=0, drain=false, echo=false,
properties=null}
2015-12-09 19:37:18,407 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Handled flow frame on channel 1: Flow{nextIncomingId=1,
incomingWindow=2048, nextOutgoingId=12051, outgoingWindow=2048, handle=0,
deliveryCount=18257, linkCredit=289, available=0, drain=false, echo=false,
properties=null}
2015-12-09 19:37:18,435 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 flow
update recieved, current local credit = 1000, queued = 0, remote credit = 1000
2015-12-09 19:37:18,678 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Pull on consumer ID:WorkMac-62323-1449707737437-22:5:1:1
with timeout = 0
2015-12-09 19:37:18,679 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.j.p.a.A.CREDIT Consumer ID:WorkMac-62323-1449707737437-22:5:1:1 draining,
current local credit = 711, queued = 0, remote credit = 711
2015-12-09 19:37:18,682 TRACE [AmqpProvider:(97):[amqp://localhost:5672/]]
o.a.q.p.e.i.T.CREDIT Wrote flow frame on channel 1: Flow{nextIncomingId=12340,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0,
deliveryCount=18546, linkCredit=0, available=null, drain=true, echo=false,
properties=null}
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
