Bug 692880

Summary: qpid python client reliably aborts with timeout during transmission of messages
Product: Red Hat Enterprise MRG Reporter: Frantisek Reznicek <freznice>
Component: python-qpidAssignee: messaging-bugs <messaging-bugs>
Status: CLOSED NOTABUG QA Contact: MRG Quality Engineering <mrgqe-bugs>
Severity: high Docs Contact:
Priority: unspecified    
Version: DevelopmentCC: esammons, gsim
Target Milestone: 2.0   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-04-04 08:00:42 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Qpid low-level API python client showing the issue none

Description Frantisek Reznicek 2011-04-01 13:55:52 UTC
Description of problem:
qpid python low-level API client reliably aborts with qpid.exceptions.Timeout exception during consecutive session.message_transfer() calls.

Let's have following code:

props = session.delivery_properties(routing_key=routing_key_ndur_name)
for i in range(queue_ndur_count):
  print i,
  session.message_transfer(destination=exchange_name,
                           message=Message(props,"message " + str(i)))


This is working well with 1.3.2, but on 2.0 ir aborts with:
..accessing non-durable queue - phase A (msg queue count: 100)
0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81
Traceback (most recent call last):
  File "./bz452141.py", line 200, in ?
    session.message_transfer(destination=exchange_name, message=Message(props,"message " + str(i)))
  File "/usr/lib/python2.3/site-packages/qpid/generator.py", line 25, in <lambda>
    method = lambda self, *args, **kwargs: self.invoke(op, args, kwargs)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 138, in invoke
    return self.do_invoke(op, args, kwargs)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 183, in do_invoke
    self.sync(self.timeout)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 101, in sync
    raise Timeout()
qpid.exceptions.Timeout


This behavior seems to be bug, otherwise customers need to be guided to change their programs...
The issue is observed on RHEL4/5/6 i386 / x86_64.

Version-Release number of selected component (if applicable):
[root@mrg-qe-03 qpid_queue_policy_bz452141_bz456667]# rpm -qa | egrep '(qpid|sesame|qmf)' | grep -v rh-tests | sort
python-qpid-0.10-1.el4.noarch
python-qpid-qmf-0.10-2.el4.x86_64
qpid-cpp-client-0.10-2.el4.x86_64
qpid-cpp-client-devel-0.10-2.el4.x86_64
qpid-cpp-client-devel-docs-0.10-2.el4.x86_64
qpid-cpp-client-ssl-0.10-2.el4.x86_64
qpid-cpp-mrg-debuginfo-0.10-2.el4.x86_64
qpid-cpp-server-0.10-2.el4.x86_64
qpid-cpp-server-devel-0.10-2.el4.x86_64
qpid-cpp-server-ssl-0.10-2.el4.x86_64
qpid-cpp-server-store-0.10-2.el4.x86_64
qpid-cpp-server-xml-0.10-2.el4.x86_64
qpid-dotnet-0.4.738274-2.el4.x86_64
qpid-java-client-0.10-1.el4.noarch
qpid-java-common-0.10-1.el4.noarch
qpid-java-example-0.10-1.el4.noarch
qpid-qmf-0.10-2.el4.x86_64
qpid-qmf-debuginfo-0.10-2.el4.x86_64
qpid-qmf-devel-0.10-2.el4.x86_64
qpid-tests-0.9.1073306-1.el4.noarch
qpid-tools-0.10-1.el4.noarch
rh-qpid-cpp-tests-0.10-2.el4.x86_64
sesame-0.10-1.el4.x86_64
sesame-debuginfo-0.10-1.el4.x86_64


How reproducible:
99%

Steps to Reproduce:
1. qpidd --truncate yes --data-dir /tmp/dd  --log-enable debug+ &> /tmp/qpidd.log
2. python ./bz452141.py
3. echo $?
  
Actual results:
Batched message sent via low level API using session.message_transfer() timeouts.

Expected results:
Batched message sent via low level API using session.message_transfer() should not timeout.

Additional info:
[root@mrg-qe-03 qpid_queue_policy_bz452141_bz456667]# qpidd --truncate yes --data-dir /tmp/dd  --log-enable debug+ &> /tmp/qpidd.log

[1]+  Stopped                 qpidd --truncate yes --data-dir /tmp/dd --log-enable debug+ >&/tmp/qpidd.log
[root@mrg-qe-03 qpid_queue_policy_bz452141_bz456667]# bg
[1]+ qpidd --truncate yes --data-dir /tmp/dd --log-enable debug+ >&/tmp/qpidd.log &
[root@mrg-qe-03 qpid_queue_policy_bz452141_bz456667]# wc -l /tmp/qpidd.log
77 /tmp/qpidd.log
[root@mrg-qe-03 qpid_queue_policy_bz452141_bz456667]# python ./bz452141.py
.qpid-config to set create queue exchange with given policy
Queue 'my_durable_queue'
    bind [my_durable_queue] => ''
    bind [routing_key2] => amq.direct
Queue 'my_durable_queue2'
    bind [my_durable_queue2] => ''
    bind [routing_key22] => amq.direct
Queue 'my_ndurable_queue'
    bind [my_ndurable_queue] => ''
    bind [routing_key1] => amq.direct
Queue 'qmfagent-c84ed64b-6b26-4867-841f-3657e19a9792'
    bind [qmfagent-c84ed64b-6b26-4867-841f-3657e19a9792] => ''
    bind [qmfagent-c84ed64b-6b26-4867-841f-3657e19a9792] => amq.direct
    bind [redhat.com:sesame:16adff47-be53-4740-a1a3-6d5863f208b6] => qmf.default.direct
    bind [console.#] => qmf.default.topic
Queue 'qmfc-v2-hb-mrg-qe-03.lab.eng.brq.redhat.com.5544.1'
    bind [qmfc-v2-hb-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => ''
    bind [agent.ind.heartbeat.#] => qmf.default.topic
Queue 'qmfc-v2-mrg-qe-03.lab.eng.brq.redhat.com.5544.1'
    bind [qmfc-v2-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => ''
    bind [qmfc-v2-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => qmf.default.direct
Queue 'qmfc-v2-ui-mrg-qe-03.lab.eng.brq.redhat.com.5544.1'
    bind [qmfc-v2-ui-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => ''
Queue 'reply-mrg-qe-03.lab.eng.brq.redhat.com.5544.1'
    bind [reply-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => ''
    bind [reply-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => amq.direct
Queue 'topic-mrg-qe-03.lab.eng.brq.redhat.com.5544.1'
    bind [topic-mrg-qe-03.lab.eng.brq.redhat.com.5544.1] => ''
    bind [console.event.*.*.org.apache.qpid.broker.agent] => qpid.management
    bind [console.obj.*.*.org.apache.qpid.broker.agent] => qpid.management
    bind [schema.#] => qpid.management
..queues declared and bind ok
.qpidd connection
.running the core test
..accessing non-durable queue - phase A (msg queue count: 100)
0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81
Traceback (most recent call last):
  File "./bz452141.py", line 200, in ?
    session.message_transfer(destination=exchange_name, message=Message(props,"message " + str(i)))
  File "/usr/lib/python2.3/site-packages/qpid/generator.py", line 25, in <lambda>
    method = lambda self, *args, **kwargs: self.invoke(op, args, kwargs)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 138, in invoke
    return self.do_invoke(op, args, kwargs)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 183, in do_invoke
    self.sync(self.timeout)
  File "/usr/lib/python2.3/site-packages/qpid/session.py", line 101, in sync
    raise Timeout()
qpid.exceptions.Timeout

Comment 1 Frantisek Reznicek 2011-04-01 13:57:38 UTC
Created attachment 489413 [details]
Qpid low-level API python client showing the issue

Comment 2 Gordon Sim 2011-04-01 14:06:37 UTC
My guess is that this is related to the current flow control solution? Is there a size limit on the queue? Does turning that off resolve the issue?

Comment 3 Frantisek Reznicek 2011-04-04 08:00:42 UTC
Indeed this the timeout exception is raised due to activated producer flow control.

-> Marking as CLOSED / NOT-A-BUG