Description of problem: Having a scenario with a slow producer and a consumer periodically running Receiver::fetch() method (for timeout lesser than forever), the consumer gets just first N messages where N is the size of prefetch / capacity, and then nothing - despite there are new messages on the broker. Version-Release number of selected component (if applicable): qpid-cpp-client*-0.18-14 How reproducible: 100% Steps to Reproduce: 1. Unpack attached tarball 2. make 3. in one terminal, create queue and start producer (that waits 15 seconds to kick-off consumer first): ./setup 4. in another terminal, start consumer: ./read Actual results: When producer starts to produce messages, the consumer gets just first 10 messages (or whatever is set in receiver.setCapacity()). Later on, despite there are new messages in the queue, receiver does not get any. Expected results: Receiver gets further messages when some occurr on the broker. Additional info: See next update for in-depth analysis.
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