Bug 913448

Created attachment 700414 [details]
Reproducer

In-depth analysis:

Client library does not send session.completed when expected so. As default flow mode - window - is used, to acknowledge received messages (or compelte their delivery), session.complete has to be sent by the client. Quoting AMQP spec and Command: message.set-flow-mode:

"(for Window based flow control) Completion of the transfer command with session.completed is the only way credit is implicitly updated".

While the client never sends session.completed method, just only these (qpid client trace logs):

2013-02-21 09:46:47 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {MessageAcceptBody: transfers={ [4,4] }; }]
2013-02-21 09:46:47 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }]
2013-02-21 09:46:47 [Network] trace RECV [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [47,51] }; timely-reply=1; }]
2013-02-21 09:46:47 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ [47,51] }; }]
2013-02-21 09:46:49 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {MessageFlushBody: destination=ToApp; }]
2013-02-21 09:46:49 [Network] trace RECV [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [52,52] }; }]
No messages pending in queue 
2013-02-21 09:46:49 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {MessageSetFlowModeBody: destination=ToApp; flow-mode=1; }]
2013-02-21 09:46:49 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {MessageFlowBody: destination=ToApp; unit=0; value=10; }]
2013-02-21 09:46:49 [Network] trace SENT [[[::1]:49334-localhost:5672]]: Frame[BEbe; channel=1; {MessageFlowBody: destination=ToApp; unit=1; value=4294967295; }]
2013-02-21 09:46:50 [Network] trace RECV [[[::1]:49334-localhost:5672]]: Frame[Bbe; channel=1; {MessageTransferBody: destination=ToApp; accept-mode=0; acquire-mode=0; }]
2013-02-21 09:46:50 [Network] trace RECV [[[::1]:49334-localhost:5672]]: Frame[be; channel=1; header (31 bytes); properties={{MessageProperties: content-length=3; }{DeliveryProperties: exchange=App.Ex; }}]
2013-02-21 09:46:50 [Network] trace RECV [[[::1]:49334-localhost:5672]]: Frame[Ebe; channel=1; content (3 bytes) xxx]
2013-02-21 09:46:50 [Client] debug Delivered {MessageTransferBody: destination=ToApp; accept-mode=0; acquire-mode=0; } header (31 bytes); properties={{MessageProperties: content-length=3; }{DeliveryProperties: exchange=App.Ex; }}

See the client sends just:
message.accept
session.flush
session.known-completed
message.set-flow-mode
message.flow

Reading this: why the client sends message.accept as that does not really complete the message delivery? (comparing with qpid-receive trace, qpid-receive sends session.completed after N/2 messages received for N=prefetch, nothing else). Is not the client behaving rather than in credit flow mode (while setting window mode in message.set-flow-mode)?

Curiously, changing fetch timeout to FOREVER in read.cpp, the client is getting all messages as expected and invokes session.completed as expected (after N/2 msgs received).

Created attachment 701038 [details]
Patch proposal

Root cause of the bug: see qpid::client::amqp0_10::ReceiverImpl::fetchImpl method:

After sending message.flush, the consumer's credit is zero so it re-sets it by calling startFlow(ScopedLock) method. BUT session.complete command is not sent to really update the credit.

Invoking that requires received(message); method call. To perform the call properly, startFlow can't update window - thats why startFlow has a new bool parameter.

IMHO no problem adding the customer to Cc here - that is usually done and this BZ has nothing sensitive (and I assume it wont have anything so).

Dan, ask the customer for bugzilla login (email address) and add the email to Cc.

Gordon Sim resolved QPID-4595 in 0.21 (Fixed by http://svn.apache.org/viewvc?view=revision&revision=1455630)

Tested on both RHEL5.9 and RHEL6.4 (i386 and x86_64). This issue has been fixed.

Packages used for testing:

RHEL6.4:
python-qpid-0.22-3.el6
python-qpid-qmf-0.22-3.el6
qpid-cpp-client-0.22-4.el6
qpid-cpp-client-devel-0.22-4.el6
qpid-cpp-client-devel-docs-0.22-4.el6
qpid-cpp-server-0.22-4.el6
qpid-cpp-server-devel-0.22-4.el6
qpid-cpp-server-store-0.22-4.el6
qpid-cpp-server-xml-0.22-4.el6
qpid-java-client-0.22-3.el6
qpid-java-common-0.22-3.el6
qpid-java-example-0.22-3.el6
qpid-jca-0.18-8.el6
qpid-jca-xarecovery-0.18-8.el6
qpid-proton-c-0.4-2.2.el6
qpid-qmf-0.22-3.el6
qpid-tools-0.22-3.el6

RHEL5.9:
python-qpid-0.22-2.el5
python-qpid-qmf-0.22-2.el5
qpid-cpp-client-0.22-4.el5
qpid-cpp-client-devel-0.22-4.el5
qpid-cpp-client-devel-docs-0.22-4.el5
qpid-cpp-client-ssl-0.22-4.el5
qpid-cpp-server-0.22-4.el5
qpid-cpp-server-devel-0.22-4.el5
qpid-cpp-server-ha-0.22-4.el5
qpid-cpp-server-ssl-0.22-4.el5
qpid-cpp-server-store-0.22-4.el5
qpid-cpp-server-xml-0.22-4.el5
qpid-java-client-0.22-2.el5
qpid-java-common-0.22-2.el5
qpid-java-example-0.22-2.el5
qpid-jca-0.18-8.el5
qpid-jca-xarecovery-0.18-8.el5
qpid-proton-c-0.4-2.2.el5
qpid-qmf-0.22-2.el5
qpid-qmf-devel-0.22-2.el5
qpid-tools-0.22-2.el5

-> VERIFIED

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHEA-2014-1296.html