[ARTEMIS-2707] last payload is sent indicating message incomplete, then empty final transfer sent to complete it

• Type: Sub-task
• Status: Resolved
• Priority: Major
• Resolution: Done
• Affects Version/s: 2.12.0
• Component/s: AMQP
• Assignee: Unassigned
• Reporter: Robbie Gemmell
• Created: 13/Apr/20 15:43
• Updated: 15/Apr/20 11:24
• Resolved: 15/Apr/20 11:24

Description

As first noted on ARTEMIS-2659, when sending larger AMQP messages using multiple frames the broker can be seen to send the final message payload while still indicating the message is not complete, and then send another empty (i.e no payload) transfer frame to indicate the message delivery is actually already complete.

A prior example was shown in ARTEMIS-2659. A fresh example below shows a 'full' frame (itself unexpectedly small with 1024 payload bytes, see ARTEMIS-2706) holding the penultimate payload, then a frame with the final payload content but still indicating more=true incorrectly, then a last transfer with no payload and indicating more=false.

[417713843:1] <- Transfer{handle=1, deliveryId=0, deliveryTag=\x00, messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null, resume=false, aborted=false, batchable=false} (1024) "\xa3L&\x8eq3\xa7\x83\x87]\xc8\xb92N\xa1\xb4\xe2wg\x94"'\xb6\x8c\xd6\x93\x90\x1a\x9aB%j\xcb\x13\xef\x05\xa8I\xe5\xd5\x06\xc5\x9fH\x86\xa7\x17\xd4\xbd\xf16\xd2J\xdd\xf3\xc8\xa5z\xe6\xbf\x90\xbe\x89\x0e#\x98\xdd\xadY\x09\xaa\xb6BeA\x98J\xf5\xec\x81\xf0\xfa\xaf\xbfE\xcb~\xb9G\xa2!Z\xb9\xa2\x0d\xf2{P\x98\x90\xee\xf5r\xd9d.\x95\xfeg\xf6:\x1a\xef\xfb\xbaD\xb1\x07q\x15R\x9f\x83\x89\x0a\x0cC\xa2\x9bG\x05\xa7\xd6\xfe%R\xea\x18\x15\xa6BG"\x9e\xe5{\x0f\x92ge\xfbr\xdd\xfd\xad!\xd0rp\xd1\xaa\x8a\x08\xb7\x96.\xe2\xfb\x90\xeb\xe9>CV\x01kDT\x03\xdf(<\xe7\x17\xe0\xeb\x8dA\x1f\xb0G\x06\x8fJ\x00\x10\xa9\x97\xd9\xd5\xd5\xedU\x9f\xca\xbdT\x04\x97\xe3ZGL\xabr\xfd\x81\x00\xff\xb3\xf1\xca\x9d\xa5\xd38\x94\xa7\xaf\x17\xc7\xcf\x9f\xd8\x1d\xf6\x14\x80\xd9n\x11\xb0\xa4H\x0a\xeb\xfc\x85\xad\x8e\x82\x02q\xd0\x94\xbe{\x9b9\x17`Vw\x7f}\xb3@\xf0\x8a\xbea\x9eU\x12\x97b\xc6%\x0dX\x9d\x1d\xa4\xd5\xecq\xb46`\x9b\x06\x04\xd9\x97\xe8X\xfd\x08\x9fg\xffC\xd6r\xffF\xf5W\xee[)\x03\xacv\x83\x11\xfb\xb4~\xb8\x8aOGT\xa7\xd0w\xbe\xab\xe6\x08\x0cZ\x84\xf9"...(truncated)
[417713843:1] <- Transfer{handle=1, deliveryId=0, deliveryTag=\x00, messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null, resume=false, aborted=false, batchable=false} (176) "_=\xfe\xd6p%0Z\x98?\x86\x07iZNfU\x1f\x9b\x11\x93\xca\xf7\xb1\xbd9\xbf$Q\xc5\xbd:\x00\xe9T\xe8T\xf1\xab\x03\x1a\x05\x1dza[u\x84\xd2\x9e0WT\x8e\x95\xc7\x5c8=\x80\xad\x02\x5c\xb0\x9f \x0a\xaf}u\xe3\xd6\xaa'\x1a\x14\x94\xf3\x7f2\xb1\xc0\xf6L}\xb0\xf3h\xbf\x0e\xben>\xfeb\xcf\x881\xdc\xc1\xce,5\x81\xce\xd2\x94\x8c\xfaJ\xc0\x9d^\xc0s\x97\xa7u\xb0\x8e\x07$\x1bf~cY\xbb\xdc\xb6\x01\x12\xa0\xb8Y'\xa67#la\xea\xb4\xae\xa7:\x8f\xa5\xed-\xc23\xeah\xbe l<\xe5\xe6\x9a \x8d\xf2t\xac\xd3\xe4ss\x90\xd2\x8f\xce\xc7\xe3"
[417713843:1] <- Transfer{handle=1, deliveryId=0, deliveryTag=\x00, messageFormat=0, settled=false, more=false, rcvSettleMode=null, state=null, resume=false, aborted=false, batchable=false}
[417713843:1] -> Disposition{role=RECEIVER, first=0, last=0, settled=true, state=Accepted{}, batchable=false}

It is a legal protocol trace, but it should never really happen in a broker.

It suggests that the delivery send isnt being completed at the point the last payload has been added, with the transport output then generated, and only later is the delivery being indicated completed and further transport output generated that sends the final transfer.

Issue Links

• relates to: ARTEMIS-2659 AMQP integration test instabilities, failure to deliver messages, etc
• relates to: ARTEMIS-2706 outgoing AMQP messages split into an unexpectedly large number of transfer frames