Bug 724968

Summary: iWARP configuration qpid-perftest hangs "Connection closed" when --qt arg is supplied
Product: Red Hat Enterprise MRG Reporter: ppecka <ppecka>
Component: qpid-cppAssignee: messaging-bugs <messaging-bugs>
Status: NEW --- QA Contact: MRG Quality Engineering <mrgqe-bugs>
Severity: unspecified Docs Contact:
Priority: medium    
Version: 1.3CC: jross
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 700156    

Description ppecka 2011-07-22 13:08:43 UTC 
Description of problem:
Attempt to verify Bug #700156 on RHEL 5.7 (x86_64) with Chelsio iWARP failed.
This seem to have different symptomps than Bug #674011

Reason
[root@mrg5 ~]# qpid-perftest -Prdma -b192.168.1.4 --count 10 --size 8 --npubs 1 --nsubs 1 --qt 13

2011-07-22 08:34:32 warning Connection  closed

Connection  closed



(see Additional info for qpid-perftest trace+ log)

#gdb -q - $(pidof qpid-perftest)

(gdb) info threads 
  8 Thread 0x42115940 (LWP 4973)  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
  7 Thread 0x40ea5940 (LWP 4974)  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
  6 Thread 0x42b16940 (LWP 4975)  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  5 Thread 0x43517940 (LWP 4976)  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  4 Thread 0x43f18940 (LWP 4977)  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
  3 Thread 0x44919940 (LWP 4978)  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  2 Thread 0x4531a940 (LWP 4979)  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
* 1 Thread 0x2b677ca8f4a0 (LWP 4972)  0x0000003d18a07b35 in pthread_join ()
   from /lib64/libpthread.so.0
(gdb) thread apply all bt

Thread 8 (Thread 0x42115940 (LWP 4973)):
#0  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
#1  0x00002b677beb3511 in qpid::sys::Poller::wait(qpid::sys::Duration) ()
   from /usr/lib64/libqpidcommon.so.4
#2  0x00002b677beb3fa7 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.4
#3  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#4  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#5  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x40ea5940 (LWP 4974)):
#0  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
#1  0x00002b677beb3511 in qpid::sys::Poller::wait(qpid::sys::Duration) ()
   from /usr/lib64/libqpidcommon.so.4
#2  0x00002b677beb3fa7 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.4
#3  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#4  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#5  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x42b16940 (LWP 4975)):
#0  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00002b677bb3321b in qpid::client::LocalQueueImpl::get(qpid::client::Message&, qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.4
#2  0x00002b677bb33a89 in qpid::client::LocalQueueImpl::get(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#3  0x00002b677bb33c29 in qpid::client::LocalQueueImpl::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#4  0x00002b677bb30c3c in qpid::client::LocalQueue::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#5  0x000000000041c564 in ?? ()
#6  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#7  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x43517940 (LWP 4976)):
---Type <return> to continue, or q <return> to quit---
#0  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00002b677bb3321b in qpid::client::LocalQueueImpl::get(qpid::client::Message&, qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.4
#2  0x00002b677bb33a89 in qpid::client::LocalQueueImpl::get(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#3  0x00002b677bb33c29 in qpid::client::LocalQueueImpl::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#4  0x00002b677bb30c3c in qpid::client::LocalQueue::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#5  0x000000000041b0f2 in ?? ()
#6  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#7  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x43f18940 (LWP 4977)):
#0  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
#1  0x00002b677beb3511 in qpid::sys::Poller::wait(qpid::sys::Duration) ()
   from /usr/lib64/libqpidcommon.so.4
#2  0x00002b677beb3fa7 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.4
#3  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#4  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#5  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x44919940 (LWP 4978)):
#0  0x0000003d18a0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00002b677bb3321b in qpid::client::LocalQueueImpl::get(qpid::client::Message&, qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.4
#2  0x00002b677bb33a89 in qpid::client::LocalQueueImpl::get(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#3  0x00002b677bb33c29 in qpid::client::LocalQueueImpl::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#4  0x00002b677bb30c3c in qpid::client::LocalQueue::pop(qpid::sys::Duration) ()
   from /usr/lib64/libqpidclient.so.4
#5  0x000000000041c564 in ?? ()
#6  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
---Type <return> to continue, or q <return> to quit---
#7  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#8  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x4531a940 (LWP 4979)):
#0  0x0000003d17ed48a8 in epoll_wait () from /lib64/libc.so.6
#1  0x00002b677beb3511 in qpid::sys::Poller::wait(qpid::sys::Duration) ()
   from /usr/lib64/libqpidcommon.so.4
#2  0x00002b677beb3fa7 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.4
#3  0x00002b677beaa1fa in ?? () from /usr/lib64/libqpidcommon.so.4
#4  0x0000003d18a0673d in start_thread () from /lib64/libpthread.so.0
#5  0x0000003d17ed44bd in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x2b677ca8f4a0 (LWP 4972)):
#0  0x0000003d18a07b35 in pthread_join () from /lib64/libpthread.so.0
#1  0x00002b677beaa74d in qpid::sys::Thread::join() () from /usr/lib64/libqpidcommon.so.4
#2  0x000000000040cf49 in std::ios_base::Init::~Init() ()
#3  0x0000003d17e1d994 in __libc_start_main () from /lib64/libc.so.6
#4  0x000000000040aa89 in std::ios_base::Init::~Init() ()
#5  0x00007fffd0bae7f8 in ?? ()
#6  0x0000000000000000 in ?? ()

Version-Release number of selected component (if applicable):
# rpm -qa | grep qpid | sort -u
python-qpid-0.7.946106-15.el5
qpid-cpp-client-0.7.946106-33.el5
qpid-cpp-client-devel-0.7.946106-33.el5
qpid-cpp-client-devel-docs-0.7.946106-33.el5
qpid-cpp-client-rdma-0.7.946106-33.el5
qpid-cpp-client-ssl-0.7.946106-33.el5
qpid-cpp-server-0.7.946106-33.el5
qpid-cpp-server-cluster-0.7.946106-33.el5
qpid-cpp-server-devel-0.7.946106-33.el5
qpid-cpp-server-rdma-0.7.946106-33.el5
qpid-cpp-server-ssl-0.7.946106-33.el5
qpid-cpp-server-store-0.7.946106-33.el5
qpid-cpp-server-xml-0.7.946106-33.el5
qpid-java-client-0.10-6.el5
qpid-java-common-0.10-6.el5
qpid-java-example-0.10-6.el5
qpid-tests-0.7.946106-1.el5
qpid-tools-0.7.946106-12.el5
rh-qpid-cpp-tests-0.7.946106-33.el5


How reproducible:
100% on testbed

Steps to Reproduce:
1./usr/sbin/qpidd -d --port 5672 --mgmt-enable no --mgmt-qmf2 no \
--log-enable trace+ --log-to-file /tmp/qpidd.log --auth no --data-dir $(mktemp -td )
2. qpid-perftest -Prdma -b192.168.1.4 --count 10 --size 8 --npubs 1 --nsubs 1 --qt 13
  
Actual results:
# qpid-perftest -Prdma -b192.168.1.4 --count 10 --size 8 --npubs 1 --nsubs 1 --qt 13
2011-07-22 08:56:57 warning Connection  closed

Connection  closed


Expected results:
qpid-perftest graceful exit with statistics report



Additional info:
qpid-perftest "trace log"

2011-07-22 08:48:41 debug Created IO thread: 0
2011-07-22 08:48:41 debug RdmaConnector created for 0-10
2011-07-22 08:48:41 debug RDMA: ci=0x137aadd0: Creating ConnectionManager
2011-07-22 08:48:41 info Connection  connected to rdma:192.168.1.4:5672
2011-07-22 08:48:41 debug RDMA: qp=0x137acc50: Called for data, but got none: xmitCredit=63
2011-07-22 08:48:41 debug RECV [192.168.1.5:45702 192.168.1.4:5672] INIT(0-10)
2011-07-22 08:48:41 trace RECV [192.168.1.5:45702 192.168.1.4:5672]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federation_tag:V2:36:str16(30a28a92-8728-4dd1-a1d0-5278ba3c7393)}; mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)}; locales=str16{V2:5:str16(en_US)}; }]
2011-07-22 08:48:41 debug CyrusSasl::start(ANONYMOUS PLAIN)
2011-07-22 08:48:41 debug min_ssf: 0, max_ssf: 256
2011-07-22 08:48:41 debug CyrusSasl::start(ANONYMOUS PLAIN): selected ANONYMOUS response: 'anonymous.bos.redhat.com'
2011-07-22 08:48:41 trace SENT [192.168.1.5:45702 192.168.1.4:5672]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties={qpid.client_pid:F4:int32(5024),qpid.client_ppid:F4:int32(3436),qpid.client_process:V2:13:str16(qpid-perftest),qpid.session_flow:F4:int32(1)}; mechanism=ANONYMOUS; response=xxxxxx; locale=en_US; }]
2011-07-22 08:48:41 debug RDMA: qp=0x137acc50: Called for data, but got none: xmitCredit=63
2011-07-22 08:48:41 debug RDMA: qp=0x137acc50: Called for data, but got none: xmitCredit=63
2011-07-22 08:48:41 trace RECV [192.168.1.5:45702 192.168.1.4:5672]: Frame[BEbe; channel=0; {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; }]
2011-07-22 08:48:41 trace SENT [192.168.1.5:45702 192.168.1.4:5672]: Frame[BEbe; channel=0; {ConnectionTuneOkBody: channel-max=32767; max-frame-size=65535; heartbeat=0; }]


[cut]....[cut]


2011-07-22 08:48:42 debug RDMA: ci=0x14fd1dd0: Creating ConnectionManager
2011-07-22 08:48:42 info Connection  connected to rdma:192.168.1.4:5672
2011-07-22 08:48:42 trace SENT [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {MessageSubscribeBody: queue=qpid-perftest_pub_start; destination=qpid-perftest_pub_start; accept-mode=0; acquire-mode=0; resume-id=; resume-ttl=0; arguments={}; }]
2011-07-22 08:48:42 debug RDMA: qp=0x147c9d40: Called for data, but got none: xmitCredit=63
2011-07-22 08:48:42 trace SENT [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {MessageSetFlowModeBody: destination=qpid-perftest_pub_start; flow-mode=1; }]
2011-07-22 08:48:42 trace SENT [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {MessageFlowBody: destination=qpid-perftest_pub_start; unit=0; value=1; }]
2011-07-22 08:48:42 trace SENT [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {MessageFlowBody: destination=qpid-perftest_pub_start; unit=1; value=4294967295; }]
2011-07-22 08:48:42 trace SENT [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
2011-07-22 08:48:42 debug RDMA: qp=0x147c9d40: Called for data, but got none: xmitCredit=62
2011-07-22 08:48:42 debug RDMA: qp=0x147c9d40: Called for data, but got none: xmitCredit=62
2011-07-22 08:48:42 trace RECV [192.168.1.5:60315 192.168.1.4:5672]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [0,4] }; }]
2011-07-22 08:48:42 debug RDMA: qp=0x147c9d40: Called for data, but got none: xmitCredit=64
2011-07-22 08:48:42 debug Connection Rejected : 0
2011-07-22 08:48:42 debug RdmaConnector::connectionStopped 
2011-07-22 08:48:42 debug RDMA: ci=0x14fd1dd0: Deleting ConnectionManager
2011-07-22 08:48:42 warning Connection  closed
2011-07-22 08:48:42 debug Exception constructed: Connection  closed
2011-07-22 08:48:42 debug ~RdmaConnector 

Connection  closed