[QPID-6947] [Java Broker] deliverycount advanced outside a previous drain attempt that used all credit

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: qpid-java-6.0
• Component/s: Broker-J
• Assignee: Unassigned
• Reporter: Robbie Gemmell
• Created: 14/Dec/15 12:23
• Updated: 18/Dec/15 15:37

Description

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

# 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}

Issue Links

• is related to: QPID-6863 AMQP 1.0 message flow to consumers stops
• relates to: PROTON-1077 receiver link and transport view of credit can become disjoint when sending link sends flow frames
• relates to: QPIDJMS-139 Message flow to synchronous consumer from Qpid Java broker unexpectedly ceases