Bug 795440

Summary: Low level API durable distributed transaction client (qpid-txtest) with heartbeat sometimes hangs when ran against clustered node
Product: Red Hat Enterprise MRG Reporter: Frantisek Reznicek <freznice>
Component: qpid-cppAssignee: Ken Giusti <kgiusti>
Status: CLOSED WONTFIX QA Contact: MRG Quality Engineering <mrgqe-bugs>
Severity: medium Docs Contact:
Priority: medium    
Version: DevelopmentCC: esammons, jross
Target Milestone: 3.0   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-23 01:32:08 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
Hang analysis from 2012-03-07
none
hang analysis from 2012-08-15 (el5) none

Description Frantisek Reznicek 2012-02-20 14:46:47 UTC
Description of problem:

Low level API durable distributed transaction client (qpid-txtest) with heartbeat sometimes hangs when ran against clustered node.

There are already two observations of hanging qpid-txtest client on rhel6.2 4 node cluster.

One of the distributed transaction test repeats following pattern:
  [10:44:20] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.178', result:0, dur.:0.14
  [10:44:22] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.181', result:0, dur.:2.22
  [10:44:23] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.179', result:0, dur.:0.19


Problem was found when durability and heartbeat was enabled:
  ...
  [10:45:21] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.208', result:0, dur.:0.17
  [10:45:24] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.178', result:0, dur.:2.73
  [10:45:27] ERROR:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.178', result:2, dur.:2.07
  [10:45:27] DEBUG:stdout:
    Connection  closed
  [10:45:27] DEBUG:stderr:
    2012-02-19 04:45:28 warning Connect failed: Connection timedout
    2012-02-19 04:45:28 warning Connection  closed
  [10:45:27] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1  --durable yes --size 1024 --broker=10.34.37.181', result:0, dur.:0.20
  
  <hang at:> dhcp-37-178: qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1 --durable yes --size 1024 --broker=10.34.37.208


Cluster was functional after client hang, tested by qpid-cluster/qpid-stat/qpid-perftest clients.

Client should get disconnected when heartbeat is specified, which is not the case.

Version-Release number of selected component (if applicable):
  corosync-1.4.1-4.el6.x86_64
  corosynclib-1.4.1-4.el6.x86_64
  python-qpid-0.14-3.el6.noarch
  python-qpid-qmf-0.14-4.el6.x86_64
  python-saslwrapper-0.10-2.el6.x86_64
  qpid-cpp-client-0.14-6.el6.x86_64
  qpid-cpp-client-devel-0.14-6.el6.x86_64
  qpid-cpp-client-devel-docs-0.14-6.el6.noarch
  qpid-cpp-client-rdma-0.14-6.el6.x86_64
  qpid-cpp-client-ssl-0.14-6.el6.x86_64
  qpid-cpp-debuginfo-0.14-6.el6.x86_64
  qpid-cpp-server-0.14-6.el6.x86_64
  qpid-cpp-server-cluster-0.14-6.el6.x86_64
  qpid-cpp-server-devel-0.14-6.el6.x86_64
  qpid-cpp-server-rdma-0.14-6.el6.x86_64
  qpid-cpp-server-ssl-0.14-6.el6.x86_64
  qpid-cpp-server-store-0.14-6.el6.x86_64
  qpid-cpp-server-xml-0.14-6.el6.x86_64
  qpid-java-client-0.14-1.el6.noarch
  qpid-java-common-0.14-1.el6.noarch
  qpid-java-example-0.14-1.el6.noarch
  qpid-qmf-0.14-4.el6.x86_64
  qpid-qmf-debuginfo-0.14-4.el6.x86_64
  qpid-qmf-devel-0.14-4.el6.x86_64
  qpid-tests-0.14-1.el6.noarch
  qpid-tools-0.14-1.el6.noarch
  rh-qpid-cpp-tests-0.14-6.el6.x86_64
  ruby-qpid-qmf-0.14-4.el6.x86_64
  ruby-saslwrapper-0.10-2.el6.x86_64
  saslwrapper-0.10-2.el6.x86_64
  saslwrapper-debuginfo-0.10-2.el6.x86_64
  saslwrapper-devel-0.10-2.el6.x86_64
  sesame-1.0-2.el6.x86_64
  sesame-debuginfo-1.0-2.el6.x86_64


How reproducible:
<2%

Steps to Reproduce:
1. cluster_test run test_cluster_dtx_phased_nonlocal test in the loop
   or eventually
1. start 4 node cluster
2. run in loop following dtx clients:
   on node-B:
   qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1  --durable yes --size 1024 --broker=<brk-A>
   on node-C:
   qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1  --durable yes --size 1024 --broker=<brk-B>
   on node-A:
   qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1  --durable yes --size 1024 --broker=<brk-C>
3. expect ecodes of 0
  
Actual results:
qpid-txtest hangs.

Expected results:
qpid-txtest should not hang.

Additional info:

  [10:44:00] DEBUG:TEST 'test_cluster_dtx_phased_nonlocal' loop 1/1 started. [tst_cnt:61188, err_cnt:2, dur.:147830 (41.1h)]
  [10:44:02] DEBUG:Cluster state: 4 of 4 up and running
  [10:44:13] INFO:localhost:'cluster topology change (ecode: True exp. True)', result:True, dur.:-1.00
  [10:44:15] DEBUG:Cluster state: 4 of 4 up and running
  [10:44:19] INFO:localhost:'Cluster should be fully up (4 of 4 up)', result:True, dur.:-1.00
  [10:44:20] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.178', result:0, dur.:0.14
  [10:44:22] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.181', result:0, dur.:2.22
  [10:44:23] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=13 --messages-per-tx=10 --tx-count=17 --total-messages=999   --durable no  --broker=10.34.37.179', result:0, dur.:0.19
  [10:44:23] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=13 --messages-per-tx=9 --tx-count=10 --total-messages=955   --durable no --size 16 --broker=10.34.37.208', result:0, dur.:0.12
  [10:44:26] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=13 --messages-per-tx=9 --tx-count=10 --total-messages=955   --durable no --size 16 --broker=10.34.37.208', result:0, dur.:2.22
  [10:44:26] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=13 --messages-per-tx=9 --tx-count=10 --total-messages=955   --durable no --size 16 --broker=10.34.37.178', result:0, dur.:0.20
  [10:44:27] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=18 --messages-per-tx=7 --tx-count=18 --total-messages=920   --durable no --size 1024 --broker=10.34.37.179', result:0, dur.:0.19
  [10:44:31] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=18 --messages-per-tx=7 --tx-count=18 --total-messages=920   --durable no --size 1024 --broker=10.34.37.178', result:0, dur.:3.20
  [10:44:31] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=18 --messages-per-tx=7 --tx-count=18 --total-messages=920   --durable no --size 1024 --broker=10.34.37.181', result:0, dur.:0.24
  [10:44:32] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=19 --messages-per-tx=5 --tx-count=16 --total-messages=953   --durable yes  --broker=10.34.37.181', result:0, dur.:0.18
  [10:44:35] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=19 --messages-per-tx=5 --tx-count=16 --total-messages=953   --durable yes  --broker=10.34.37.208', result:0, dur.:2.91
  [10:44:36] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=19 --messages-per-tx=5 --tx-count=16 --total-messages=953   --durable yes  --broker=10.34.37.208', result:0, dur.:0.21
  [10:44:36] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=16 --messages-per-tx=9 --tx-count=18 --total-messages=916   --durable yes --size 16 --broker=10.34.37.181', result:0, dur.:0.15
  [10:44:40] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=16 --messages-per-tx=9 --tx-count=18 --total-messages=916   --durable yes --size 16 --broker=10.34.37.178', result:0, dur.:3.51
  [10:44:41] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=16 --messages-per-tx=9 --tx-count=18 --total-messages=916   --durable yes --size 16 --broker=10.34.37.178', result:0, dur.:0.20
  [10:44:42] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=17 --messages-per-tx=8 --tx-count=10 --total-messages=871   --durable yes --size 1024 --broker=10.34.37.178', result:0, dur.:0.22
  [10:44:44] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=17 --messages-per-tx=8 --tx-count=10 --total-messages=871   --durable yes --size 1024 --broker=10.34.37.178', result:0, dur.:1.79
  [10:44:44] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=17 --messages-per-tx=8 --tx-count=10 --total-messages=871   --durable yes --size 1024 --broker=10.34.37.208', result:0, dur.:0.28
  [10:44:45] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=18 --messages-per-tx=8 --tx-count=12 --total-messages=875  --tcp-nodelay --durable no  --broker=10.34.37.208', result:0, dur.:0.20
  [10:44:47] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=18 --messages-per-tx=8 --tx-count=12 --total-messages=875  --tcp-nodelay --durable no  --broker=10.34.37.178', result:0, dur.:1.97
  [10:44:48] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=18 --messages-per-tx=8 --tx-count=12 --total-messages=875  --tcp-nodelay --durable no  --broker=10.34.37.208', result:0, dur.:0.23
  [10:44:48] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=12 --messages-per-tx=6 --tx-count=19 --total-messages=898  --tcp-nodelay --durable no --size 16 --broker=10.34.37.179', result:0, dur.:0.13
  [10:44:52] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=12 --messages-per-tx=6 --tx-count=19 --total-messages=898  --tcp-nodelay --durable no --size 16 --broker=10.34.37.178', result:0, dur.:2.70
  [10:44:52] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=12 --messages-per-tx=6 --tx-count=19 --total-messages=898  --tcp-nodelay --durable no --size 16 --broker=10.34.37.181', result:0, dur.:0.22
  [10:44:53] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=15 --messages-per-tx=6 --tx-count=11 --total-messages=931  --tcp-nodelay --durable no --size 1024 --broker=10.34.37.178', result:0, dur.:0.23
  [10:44:55] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=15 --messages-per-tx=6 --tx-count=11 --total-messages=931  --tcp-nodelay --durable no --size 1024 --broker=10.34.37.179', result:0, dur.:1.39
  [10:44:55] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=15 --messages-per-tx=6 --tx-count=11 --total-messages=931  --tcp-nodelay --durable no --size 1024 --broker=10.34.37.179', result:0, dur.:0.22
  [10:44:56] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=20 --messages-per-tx=6 --tx-count=13 --total-messages=818  --tcp-nodelay --durable yes  --broker=10.34.37.179', result:0, dur.:0.16
  [10:44:58] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=20 --messages-per-tx=6 --tx-count=13 --total-messages=818  --tcp-nodelay --durable yes  --broker=10.34.37.178', result:0, dur.:2.01
  [10:44:59] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=20 --messages-per-tx=6 --tx-count=13 --total-messages=818  --tcp-nodelay --durable yes  --broker=10.34.37.208', result:0, dur.:0.25
  [10:44:59] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=14 --messages-per-tx=9 --tx-count=11 --total-messages=997  --tcp-nodelay --durable yes --size 16 --broker=10.34.37.208', result:0, dur.:0.15
  [10:45:01] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=14 --messages-per-tx=9 --tx-count=11 --total-messages=997  --tcp-nodelay --durable yes --size 16 --broker=10.34.37.179', result:0, dur.:1.39
  [10:45:01] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=14 --messages-per-tx=9 --tx-count=11 --total-messages=997  --tcp-nodelay --durable yes --size 16 --broker=10.34.37.179', result:0, dur.:0.20
  [10:45:02] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=14 --messages-per-tx=8 --tx-count=15 --total-messages=969  --tcp-nodelay --durable yes --size 1024 --broker=10.34.37.208', result:0, dur.:0.20
  [10:45:05] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=14 --messages-per-tx=8 --tx-count=15 --total-messages=969  --tcp-nodelay --durable yes --size 1024 --broker=10.34.37.208', result:0, dur.:2.21
  [10:45:05] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=14 --messages-per-tx=8 --tx-count=15 --total-messages=969  --tcp-nodelay --durable yes --size 1024 --broker=10.34.37.178', result:0, dur.:0.20
  [10:45:06] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=16 --messages-per-tx=9 --tx-count=11 --total-messages=929 --heartbeat 1  --durable no  --broker=10.34.37.181', result:0, dur.:0.18
  [10:45:08] ERROR:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=16 --messages-per-tx=9 --tx-count=11 --total-messages=929 --heartbeat 1  --durable no  --broker=10.34.37.178', result:2, dur.:2.15
  [10:45:08] DEBUG:stdout:
    Transfering from tx-test-1 to tx-test-2
    Transfering from tx-test-2 to tx-test-3
    Transfering from tx-test-3 to tx-test-4
    Transfering from tx-test-4 to tx-test-5
    Transfering from tx-test-5 to tx-test-6
    Transfering from tx-test-6 to tx-test-7
    Transfering from tx-test-7 to tx-test-8
    Connection  closed
  [10:45:08] DEBUG:stderr:
    2012-02-19 04:45:09 warning Connect failed: Connection timedout
    2012-02-19 04:45:09 warning Connection  closed
  [10:45:09] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=16 --messages-per-tx=9 --tx-count=11 --total-messages=929 --heartbeat 1  --durable no  --broker=10.34.37.181', result:0, dur.:0.20
  [10:45:09] INFO:10.34.37.178:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=17 --messages-per-tx=5 --tx-count=20 --total-messages=923 --heartbeat 1  --durable no --size 16 --broker=10.34.37.208', result:0, dur.:0.18
  [10:45:14] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=17 --messages-per-tx=5 --tx-count=20 --total-messages=923 --heartbeat 1  --durable no --size 16 --broker=10.34.37.208', result:0, dur.:4.09
  [10:45:14] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=17 --messages-per-tx=5 --tx-count=20 --total-messages=923 --heartbeat 1  --durable no --size 16 --broker=10.34.37.178', result:0, dur.:0.19
  [10:45:15] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=11 --messages-per-tx=6 --tx-count=13 --total-messages=927 --heartbeat 1  --durable no --size 1024 --broker=10.34.37.178', result:0, dur.:0.21
  [10:45:17] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=11 --messages-per-tx=6 --tx-count=13 --total-messages=927 --heartbeat 1  --durable no --size 1024 --broker=10.34.37.178', result:0, dur.:1.50
  [10:45:17] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=11 --messages-per-tx=6 --tx-count=13 --total-messages=927 --heartbeat 1  --durable no --size 1024 --broker=10.34.37.179', result:0, dur.:0.22
  [10:45:18] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=16 --messages-per-tx=8 --tx-count=10 --total-messages=979 --heartbeat 1  --durable yes  --broker=10.34.37.208', result:0, dur.:0.17
  [10:45:20] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=16 --messages-per-tx=8 --tx-count=10 --total-messages=979 --heartbeat 1  --durable yes  --broker=10.34.37.208', result:0, dur.:1.95
  [10:45:21] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=16 --messages-per-tx=8 --tx-count=10 --total-messages=979 --heartbeat 1  --durable yes  --broker=10.34.37.179', result:0, dur.:0.20
  [10:45:21] INFO:10.34.37.181:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.208', result:0, dur.:0.17
  [10:45:24] INFO:10.34.37.179:'qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.178', result:0, dur.:2.73
  [10:45:27] ERROR:10.34.37.208:'qpid-txtest --dtx yes --init 0 --transfer 0 --check 1 --queues=19 --messages-per-tx=10 --tx-count=12 --total-messages=902 --heartbeat 1  --durable yes --size 16 --broker=10.34.37.178', result:2, dur.:2.07
  [10:45:27] DEBUG:stdout:
    Connection  closed
  [10:45:27] DEBUG:stderr:
    2012-02-19 04:45:28 warning Connect failed: Connection timedout
    2012-02-19 04:45:28 warning Connection  closed
  [10:45:27] INFO:10.34.37.208:'qpid-txtest --dtx yes --init 1 --transfer 0 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1  --durable yes --size 1024 --broker=10.34.37.181', result:0, dur.:0.20
  
  <hang in:> dhcp-37-178: qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1 --durable yes --size 1024 --broker=10.34.37.208
  
  
  
  [root@dhcp-37-178 _dump]# !ps
  ps auxw | grep qpid
  qpidd    18354  0.9 30.7 1291944 631196 ?      Ssl  Feb18  27:06 /usr/sbin/qpidd --data-dir /var/lib/qpidd --daemon
  root     21706  0.0  0.9 1800480 18560 ?       Ssl  Feb19   0:04 qpid-txtest --dtx yes --init 0 --transfer 1 --check 0 --queues=20 --messages-per-tx=9 --tx-count=18 --total-messages=830 --heartbeat 1 --durable yes --size 1024 --broker=10.34.37.208
  root     26373  0.0  0.0 103300   820 pts/1    S+   09:06   0:00 grep qpid
  [root@dhcp-37-178 _dump]# pstree -ap 21706
  qpid-txtest,21706 --dtx yes --init 0 --transfer 1 --check 0 ...
    ├─{qpid-txtest},21715
    ├─{qpid-txtest},21716
    ├─{qpid-txtest},21717
    ├─{qpid-txtest},21719
    ├─{qpid-txtest},21720
    ├─{qpid-txtest},21721
    ├─{qpid-txtest},21722
    ├─{qpid-txtest},21723
    ├─{qpid-txtest},21724
    ├─{qpid-txtest},21725
    ├─{qpid-txtest},21726
    ├─{qpid-txtest},21727
    ├─{qpid-txtest},21728
    ├─{qpid-txtest},21729
    ├─{qpid-txtest},21730
    ├─{qpid-txtest},21731
    ├─{qpid-txtest},21732
    ├─{qpid-txtest},21733
    ├─{qpid-txtest},21734
    ├─{qpid-txtest},21735
    ├─{qpid-txtest},21736
    ├─{qpid-txtest},21737
    └─{qpid-txtest},21738
  
  [root@dhcp-37-178 _dump]# strace -p 21706
  Process 21706 attached - interrupt to quit
  futex(0x7f0c3abfd9d0, FUTEX_WAIT, 21720, NULL^C <unfinished ...>
  Process 21706 detached
  
  
  (*): Shared library is missing debugging information.
  (gdb)   24 Thread 0x7f0c42c37700 (LWP 21715)  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
    23 Thread 0x7f0c42236700 (LWP 21716)  0x0000003216e0b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    22 Thread 0x7f0c3bfff700 (LWP 21717)  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
    21 Thread 0x7f0c33fff700 (LWP 21719)  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
    20 Thread 0x7f0c3abfd700 (LWP 21720)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    19 Thread 0x7f0c3a1fc700 (LWP 21721)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    18 Thread 0x7f0c397fb700 (LWP 21722)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    17 Thread 0x7f0c38dfa700 (LWP 21723)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    16 Thread 0x7f0c335fe700 (LWP 21724)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    15 Thread 0x7f0c32bfd700 (LWP 21725)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    14 Thread 0x7f0c321fc700 (LWP 21726)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    13 Thread 0x7f0c317fb700 (LWP 21727)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    12 Thread 0x7f0c30dfa700 (LWP 21728)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    11 Thread 0x7f0c07fff700 (LWP 21729)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    10 Thread 0x7f0c075fe700 (LWP 21730)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    9 Thread 0x7f0c06bfd700 (LWP 21731)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    8 Thread 0x7f0c061fc700 (LWP 21732)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    7 Thread 0x7f0c057fb700 (LWP 21733)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    6 Thread 0x7f0c04dfa700 (LWP 21734)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    5 Thread 0x7f0beffff700 (LWP 21735)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    4 Thread 0x7f0bef5fe700 (LWP 21736)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    3 Thread 0x7f0beebfd700 (LWP 21737)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    2 Thread 0x7f0bee1fc700 (LWP 21738)  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  * 1 Thread 0x7f0c439067a0 (LWP 21706)  0x0000003216e0804d in pthread_join () from /lib64/libpthread.so.0
  (gdb) 
  Thread 24 (Thread 0x7f0c42c37700 (LWP 21715)):
  #0  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x0000003452f4867a in qpid::sys::Poller::wait (this=0x2835490, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x0000003452f48d27 in qpid::sys::Poller::run (this=0x2835490) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 23 (Thread 0x7f0c42236700 (LWP 21716)):
  #0  0x0000003216e0b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x000000345300e132 in wait (this=0x34536bf560) at ../include/qpid/sys/posix/Condition.h:69
  #2  wait (this=0x34536bf560) at ../include/qpid/sys/Monitor.h:45
  #3  qpid::sys::Timer::run (this=0x34536bf560) at qpid/sys/Timer.cpp:159
  #4  0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #5  0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #6  0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 22 (Thread 0x7f0c3bfff700 (LWP 21717)):
  #0  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x0000003452f4867a in qpid::sys::Poller::wait (this=0x2835490, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x0000003452f48d27 in qpid::sys::Poller::run (this=0x2835490) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 21 (Thread 0x7f0c33fff700 (LWP 21719)):
  #0  0x00000032166e5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x0000003452f4867a in qpid::sys::Poller::wait (this=0x2835490, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x0000003452f48d27 in qpid::sys::Poller::run (this=0x2835490) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 20 (Thread 0x7f0c3abfd700 (LWP 21720)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c2c000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c2c000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c2c000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c2c000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c2c000a60, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x283b490) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 19 (Thread 0x7f0c3a1fc700 (LWP 21721)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c20000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c20000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c20000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c20000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c20000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x283d270) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 18 (Thread 0x7f0c397fb700 (LWP 21722)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c24000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c24000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c24000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c24000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c24000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x283ea10) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 17 (Thread 0x7f0c38dfa700 (LWP 21723)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c18000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c18000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c18000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c18000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c18000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2840300) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 16 (Thread 0x7f0c335fe700 (LWP 21724)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c1c000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c1c000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c1c000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c1c000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c1c000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2841a70) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 15 (Thread 0x7f0c32bfd700 (LWP 21725)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c10000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c10000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c10000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c10000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c10000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2843330) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 14 (Thread 0x7f0c321fc700 (LWP 21726)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c14000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c14000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c14000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c14000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c14000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2843fd0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 13 (Thread 0x7f0c317fb700 (LWP 21727)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c08000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c08000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c08000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c08000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c08000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2846300) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 12 (Thread 0x7f0c30dfa700 (LWP 21728)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c0c000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c0c000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c0c000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c0c000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c0c000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2846fe0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 11 (Thread 0x7f0c07fff700 (LWP 21729)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0c00000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0c00000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0c00000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0c00000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0c00000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2848970) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 10 (Thread 0x7f0c075fe700 (LWP 21730)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bf8000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bf8000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bf8000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bf8000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bf8000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x284a090) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 9 (Thread 0x7f0c06bfd700 (LWP 21731)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bfc000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bfc000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bfc000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bfc000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bfc000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x284b990) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 8 (Thread 0x7f0c061fc700 (LWP 21732)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bf0000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bf0000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bf0000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bf0000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bf0000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x284d1c0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 7 (Thread 0x7f0c057fb700 (LWP 21733)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bf4000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bf4000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bf4000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bf4000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bf4000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x284f610) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 6 (Thread 0x7f0c04dfa700 (LWP 21734)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0be8000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0be8000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0be8000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0be8000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0be8000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x28501f0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 5 (Thread 0x7f0beffff700 (LWP 21735)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0be4000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0be4000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0be4000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0be4000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0be4000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2852530) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 4 (Thread 0x7f0bef5fe700 (LWP 21736)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bdc000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bdc000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bdc000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bdc000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bdc000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x28533a0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 3 (Thread 0x7f0beebfd700 (LWP 21737)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0be0000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0be0000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0be0000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0be0000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0be0000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x28554e0) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 2 (Thread 0x7f0bee1fc700 (LWP 21738)):
  #0  0x0000003216e0b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x0000003453476c3b in wait (this=0x7f0bd4000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f0bd4000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f0bd4000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f0bd4000c10, result=..., timeout=...) at qpid/sys/BlockingQueue.h:55
  #5  0x000000345347e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000345347f297 in qpid::client::LocalQueueImpl::get (this=0x7f0bd4000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000345347f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000345347db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>) at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x2856440) at qpid-txtest.cpp:161
  #10 0x0000003452f4066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x0000003216e077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000032166e592d in clone () from /lib64/libc.so.6
  
  Thread 1 (Thread 0x7f0c439067a0 (LWP 21706)):
  #0  0x0000003216e0804d in pthread_join () from /lib64/libpthread.so.0
  #1  0x0000003452f40867 in qpid::sys::Thread::join (this=<value optimized out>) at qpid/sys/posix/Thread.cpp:71
  #2  0x000000000041362c in qpid::tests::Controller::transfer (this=0x7fff8e2524e0) at qpid-txtest.cpp:238
  #3  0x000000000040d5dd in main (argc=<value optimized out>, argv=<value optimized out>) at qpid-txtest.cpp:333
  (gdb) Detaching from program: /usr/bin/qpid-txtest, process 21706
  (gdb) quit

Comment 1 Frantisek Reznicek 2012-03-06 10:04:44 UTC
Raising reproducibility to 30%

Happen again on RHEL6.2x 4 node VM cluster...
Current behavior confirms that gdb attach; bt;detach unblock the program as shown on ssh command at 10:52:34 below:

Test log:
~~~~~~~~

  [11:44:25] INFO:10.34.37.181:'date', result:0, dur.:0.05
  [11:44:25] DEBUG:stdout:
    Fri Mar  2 05:44:25 EST 2012
  ...
  [20:54:47] INFO:10.34.37.181:'qpid-txtest --queues=14 --messages-per-tx=7 --tx-count=7 --total-messages=801 --heartbeat 1  --durable no --size 10
  24 --dtx yes ', result:0, dur.:9.70
  [10:52:34] ERROR:10.34.37.181:'qpid-txtest --queues=19 --messages-per-tx=7 --tx-count=10 --total-messages=868 --heartbeat 1  --durable yes  --dtx
  yes ', result:2, dur.:223066.31
  [10:52:34] DEBUG:stdout:
    Transfering from tx-test-1 to tx-test-2
    Transfering from tx-test-2 to tx-test-3
    Transfering from tx-test-3 to tx-test-4
    Transfering from tx-test-4 to tx-test-5
    Transfering from tx-test-5 to tx-test-6
    Transfering from tx-test-6 to tx-test-7
    Transfering from tx-test-7 to tx-test-8
    Transfering from tx-test-8 to tx-test-9
    Transfering from tx-test-9 to tx-test-10
    Transfering from tx-test-10 to tx-test-11
    Transfering from tx-test-11 to tx-test-12
    Transfering from tx-test-12 to tx-test-13
    Transfering from tx-test-13 to tx-test-14
    Transfering from tx-test-14 to tx-test-15
    Transfering from tx-test-15 to tx-test-16
    Transfering from tx-test-16 to tx-test-17
    Transfering from tx-test-17 to tx-test-18
    Transfering from tx-test-18 to tx-test-19
    Transfering from tx-test-19 to tx-test-1
    Transfer interrupted: Connection [[::1]:54969-localhost:5672] closed
    Transfer interrupted: Connection [[::1]:54970-localhost:5672] closed
    Transfer interrupted: Connection [[::1]:54967-localhost:5672] closed
    Transfer interrupted: Connection [[::1]:54968-localhost:5672] closed
    Connection [[::1]:54951-localhost:5672] closed
  [10:52:34] DEBUG:stderr:
    2012-03-03 14:54:58 warning Connection [[::1]:54969-localhost:5672] closed
    2012-03-03 14:54:58 warning Connection [[::1]:54951-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54952-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54953-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54954-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54955-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54956-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54970-localhost:5672] closed
    2012-03-03 14:54:59 warning Connection [[::1]:54967-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54957-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54958-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54959-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54960-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54962-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54963-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54964-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54965-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54966-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54968-localhost:5672] closed
    2012-03-06 04:52:35 warning Connection [[::1]:54961-localhost:5672] closed


Broker log stripe:
~~~~~~~~~~~~~~~~~
  ...
  2012-03-03 14:53:47 info JournalInactive:test_cluster_toggle_load_w_sesame-70 task late and overran 1 times: late 58ms, overran 40ms (taking 2665
  ns) on average.
  2012-03-03 14:54:58 error Connection [::1]:5672-[::1]:54969 timed out: closing
  2012-03-03 14:54:58 error Connection [::1]:5672-[::1]:54951 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54952 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54953 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54954 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54955 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54956 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54970 timed out: closing
  2012-03-03 14:54:59 error Connection [::1]:5672-[::1]:54967 timed out: closing
  2012-03-03 20:42:26 info ConnectionHeartbeat task late and overran 1 times: late 5ms, overran 2ms (taking 38792ns) on average.
  ...

Debugging session:
~~~~~~~~~~~~~~~~~

  [root@dhcp-37-181 ~]# ps auxw | grep qpid
  qpidd    12898  0.4  3.9 814792 80572 ?        Ssl  Mar03  18:54 /usr/sbin/qpidd --data-dir /var/lib/qpidd --daemon
  root     16902  0.0  0.6 1659340 12832 ?       Ssl  Mar03   0:01 qpid-txtest --queues=19 --messages-per-tx=7 --tx-count=10 --total-messages=868 --heartbeat 1 --durable yes --dtx yes
  root     26844  0.0  0.0   6436   640 pts/0    S+   04:51   0:00 grep qpid
  [root@dhcp-37-181 ~]# pstack 16902
  Thread 6 (Thread 0x7f9c72006700 (LWP 16911)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait(qpid::sys::Duration) () from /usr/lib64/libqpidcommon.so.5
  #2  0x000000313a348d27 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.5
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable(void*) () from /usr/lib64/libqpidcommon.so.5
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  Thread 5 (Thread 0x7f9c713f7700 (LWP 16912)):
  #0  0x00000034f860b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x000000313a40da42 in qpid::sys::Timer::run() () from /usr/lib64/libqpidcommon.so.5
  #2  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable(void*) () from /usr/lib64/libqpidcommon.so.5
  #3  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #4  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  Thread 4 (Thread 0x7f9c6b24d700 (LWP 16913)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait(qpid::sys::Duration) () from /usr/lib64/libqpidcommon.so.5
  #2  0x000000313a348d27 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.5
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable(void*) () from /usr/lib64/libqpidcommon.so.5
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  Thread 3 (Thread 0x7f9c69e4b700 (LWP 16915)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait(qpid::sys::Duration) () from /usr/lib64/libqpidcommon.so.5
  #2  0x000000313a348d27 in qpid::sys::Poller::run() () from /usr/lib64/libqpidcommon.so.5
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable(void*) () from /usr/lib64/libqpidcommon.so.5
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  Thread 2 (Thread 0x7f9c1f5fe700 (LWP 16931)):
  #0  0x00000034f860b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x000000313ac76c3b in qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop(boost::shared_ptr<qpid::framing::FrameSet>&, qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.5
  #2  0x000000313ac7e4c5 in qpid::client::LocalQueueImpl::get(qpid::client::Message&, qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.5
  #3  0x000000313ac7f297 in qpid::client::LocalQueueImpl::get(qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.5
  #4  0x000000313ac7f409 in qpid::client::LocalQueueImpl::pop(qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.5
  #5  0x000000313ac7db9c in qpid::client::LocalQueue::pop(qpid::sys::Duration) () from /usr/lib64/libqpidclient.so.5
  #6  0x0000000000414e34 in qpid::tests::Transfer::run() ()
  #7  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable(void*) () from /usr/lib64/libqpidcommon.so.5
  #8  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #9  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  Thread 1 (Thread 0x7f9c734fa7a0 (LWP 16902)):
  #0  0x00000034f860804d in pthread_join () from /lib64/libpthread.so.0
  #1  0x000000313a340867 in qpid::sys::Thread::join() () from /usr/lib64/libqpidcommon.so.5
  #2  0x000000000041362c in qpid::tests::Controller::transfer() ()
  #3  0x000000000040d5dd in main ()
  [root@dhcp-37-181 ~]#
  [root@dhcp-37-181 ~]# gdb
  GNU gdb (GDB) Red Hat Enterprise Linux (7.2-50.el6)
  Copyright (C) 2010 Free Software Foundation, Inc.
  License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
  This is free software: you are free to change and redistribute it.
  There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
  and "show warranty" for details.
  This GDB was configured as "x86_64-redhat-linux-gnu".
  For bug reporting instructions, please see:
  <http://www.gnu.org/software/gdb/bugs/>.
  (gdb) attach 16902
  Attaching to process 16902
  ...
  Loaded symbols for /lib64/libdb-4.7.so
  0x00000034f860804d in pthread_join () from /lib64/libpthread.so.0
  Missing separate debuginfos, use: debuginfo-install boost-filesystem-1.41.0-11.el6_1.2.x86_64 boost-program-options-1.41.0-11.el6_1.2.x86_64 boost-system-1.41.0-11.el6_1.2.x86_64 cyrus-sasl-gssapi-2.1.23-13.el6.x86_64 cyrus-sasl-lib-2.1.23-13.el6.x86_64 cyrus-sasl-md5-2.1.23-13.el6.x86_64 cyrus-sasl-plain-2.1.23-13.el6.x86_64 db4-4.7.25-16.el6.x86_64 glibc-2.12-1.47.el6_2.5.x86_64 keyutils-libs-1.4-3.el6.x86_64 krb5-libs-1.9-22.el6_2.1.x86_64 libcom_err-1.41.12-11.el6.x86_64 libgcc-4.4.6-3.el6.x86_64 libibverbs-1.1.5-3.el6.x86_64 librdmacm-1.0.14.1-3.el6.x86_64 libselinux-2.0.94-5.2.el6.x86_64 libstdc++-4.4.6-3.el6.x86_64 libuuid-2.17.2-12.4.el6.x86_64 nspr-4.8.9-3.el6_2.x86_64 nss-3.13.1-7.el6_2.x86_64 nss-softokn-freebl-3.12.9-11.el6.x86_64 nss-util-3.13.1-3.el6_2.x86_64 openssl-1.0.0-20.el6_2.1.x86_64 zlib-1.2.3-27.el6.x86_64
  (gdb) info threads
    6 Thread 0x7f9c72006700 (LWP 16911)  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
    5 Thread 0x7f9c713f7700 (LWP 16912)  0x00000034f860b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
    4 Thread 0x7f9c6b24d700 (LWP 16913)  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
    3 Thread 0x7f9c69e4b700 (LWP 16915)  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
    2 Thread 0x7f9c1f5fe700 (LWP 16931)  0x00000034f860b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  * 1 Thread 0x7f9c734fa7a0 (LWP 16902)  0x00000034f860804d in pthread_join () from /lib64/libpthread.so.0
  (gdb) thread apply all bt
  
  Thread 6 (Thread 0x7f9c72006700 (LWP 16911)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait (this=0x8f44d0, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x000000313a348d27 in qpid::sys::Poller::run (this=0x8f44d0) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  
  Thread 5 (Thread 0x7f9c713f7700 (LWP 16912)):
  #0  0x00000034f860b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x000000313a40da42 in wait (this=0x313aebf560) at ../include/qpid/sys/posix/Condition.h:69
  #2  wait (this=0x313aebf560) at ../include/qpid/sys/Monitor.h:45
  #3  qpid::sys::Timer::run (this=0x313aebf560) at qpid/sys/Timer.cpp:159
  #4  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #5  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #6  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  
  Thread 4 (Thread 0x7f9c6b24d700 (LWP 16913)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait (this=0x8f44d0, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x000000313a348d27 in qpid::sys::Poller::run (this=0x8f44d0) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  
  Thread 3 (Thread 0x7f9c69e4b700 (LWP 16915)):
  #0  0x00000034f7ee5f23 in epoll_wait () from /lib64/libc.so.6
  #1  0x000000313a34867a in qpid::sys::Poller::wait (this=0x8f44d0, timeout=...) at qpid/sys/epoll/EpollPoller.cpp:568
  #2  0x000000313a348d27 in qpid::sys::Poller::run (this=0x8f44d0) at qpid/sys/epoll/EpollPoller.cpp:520
  #3  0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #4  0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #5  0x00000034f7ee592d in clone () from /lib64/libc.so.6
  
  Thread 2 (Thread 0x7f9c1f5fe700 (LWP 16931)):
  #0  0x00000034f860b3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  #1  0x000000313ac76c3b in wait (this=0x7f9c0c000c10, result=..., timeout=...) at ../include/qpid/sys/posix/Condition.h:63
  #2  wait (this=0x7f9c0c000c10, result=..., timeout=...) at ../include/qpid/sys/Monitor.h:41
  #3  wait (this=0x7f9c0c000c10, result=..., timeout=...) at qpid/sys/Waitable.h:91
  #4  qpid::sys::BlockingQueue<boost::shared_ptr<qpid::framing::FrameSet> >::pop (this=0x7f9c0c000c10, result=..., timeout=...)
      at qpid/sys/BlockingQueue.h:55
  #5  0x000000313ac7e4c5 in qpid::client::LocalQueueImpl::get (this=<value optimized out>, result=..., timeout=<value optimized out>)
      at qpid/client/LocalQueueImpl.cpp:49
  #6  0x000000313ac7f297 in qpid::client::LocalQueueImpl::get (this=0x7f9c0c000ab0, timeout=...) at qpid/client/LocalQueueImpl.cpp:40
  #7  0x000000313ac7f409 in qpid::client::LocalQueueImpl::pop (this=<value optimized out>, timeout=<value optimized out>)
      at qpid/client/LocalQueueImpl.cpp:36
  #8  0x000000313ac7db9c in qpid::client::LocalQueue::pop (this=<value optimized out>, timeout=<value optimized out>)
      at qpid/client/LocalQueue.cpp:43
  #9  0x0000000000414e34 in qpid::tests::Transfer::run (this=0x90ec70) at qpid-txtest.cpp:161
  #10 0x000000313a34066a in qpid::sys::(anonymous namespace)::runRunnable (p=<value optimized out>) at qpid/sys/posix/Thread.cpp:35
  #11 0x00000034f86077f1 in start_thread () from /lib64/libpthread.so.0
  #12 0x00000034f7ee592d in clone () from /lib64/libc.so.6
  
  Thread 1 (Thread 0x7f9c734fa7a0 (LWP 16902)):
  #0  0x00000034f860804d in pthread_join () from /lib64/libpthread.so.0
  #1  0x000000313a340867 in qpid::sys::Thread::join (this=<value optimized out>) at qpid/sys/posix/Thread.cpp:71
  #2  0x000000000041362c in qpid::tests::Controller::transfer (this=0x7fffd9ee3dc0) at qpid-txtest.cpp:238
  #3  0x000000000040d5dd in main (argc=<value optimized out>, argv=<value optimized out>) at qpid-txtest.cpp:333
  (gdb) detach
  Detaching from program: /usr/bin/qpid-txtest, process 16902
  (gdb) quit
  
  # PROCESS gone after gdb attach - detach
  [root@dhcp-37-181 ~]# ps 16902 ; echo $?
    PID TTY      STAT   TIME COMMAND
  1
  [root@dhcp-37-181 ~]# ps auxw | grep qpid
  qpidd    12898  0.4  3.9 814792 80568 ?        Ssl  Mar03  18:55 /usr/sbin/qpidd --data-dir /var/lib/qpidd --daemon
  root     26866  0.0  0.7 1575284 14584 ?       Ssl  04:52   0:00 qpid-txtest --queues=17 --messages-per-tx=8 --tx-count=7 --total-messages=831 --heartbeat 1 --durable yes --size 16 --dtx yes
  root     26911  0.0  0.0   6436   644 pts/0    S+   04:59   0:00 grep qpid

Comment 2 Frantisek Reznicek 2012-03-07 10:14:30 UTC
Created attachment 568225 [details]
Hang analysis from 2012-03-07

Raising reproducibility to 40%

Happen again on RHEL6.2x 4 node VM cluster...
Hang details attached.

Comment 3 Frantisek Reznicek 2012-08-15 08:49:06 UTC
Created attachment 604552 [details]
hang analysis from 2012-08-15 (el5)

Issue seen on both rhel5.8 / 6.3 x86_64.
Raising reproducibility to 60%

Happen again on RHEL5.8ixxx RHEL6.3ixxx 4 node VM cluster...

It is proved that hanged process starts to continue when process is analysed by gdb (attach, info threads, t a a bt, detach). After gdb's detach process exits as shows chapter d] in attached hang analysis.

Comment 4 Frantisek Reznicek 2013-02-05 16:48:20 UTC
Still reproducible even on qpid-0.18-14.

Comment 5 Justin Ross 2013-02-23 01:32:08 UTC
Take notice: the low level api is deprecated.  -> wontfix