Description of problem: The transaction integrity test which uses txtest and killing broker to make sure we do not loose any messages. The last build (qpidc...-28, rhm-...-14) show rarely following error which brings down the connected client: Exception constructed: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) Version-Release number of selected component (if applicable): 1.2 candidate: qpidd-0.5.752581-28.el5 qpidd-acl-0.5.752581-28.el5 qpidd-cluster-0.5.752581-28.el5 qpidd-devel-0.5.752581-28.el5 qpidd-rdma-0.5.752581-28.el5 qpidd-ssl-0.5.752581-28.el5 qpidd-xml-0.5.752581-28.el5 rhm-0.5.3206-14.el5 rhm-docs-0.5.756148-1.el5 Seen on the rhel5.4 and also rhel 4.8. How reproducible: very rarely ~ 5 % of the cases Steps to Reproduce: 1. start broker /usr/sbin/qpidd -p 5672 --auth no --log-enable debug+ --data-dir /root/MRG/Messaging/qpid_test_transaction_integrity/rhts_qpidd/20091014_150934/broker.9683 2. start txtest /usr/bin/txtest -p 5672 --log-enable info+ --messages-per-tx 176 --tx-count 149380 --total-messages 13389 --size 86 --queues 8 --init yes --transfer yes --dtx yes --queue-base-name G4R 3. kill broker 4. restart broker from the same data-dir 5. restart txtest with --check yes /usr/bin/txtest -p 5672 --messages-per-tx 176 --tx-count 149380 --total-messages 13389 --size 86 --queues 8 --check yes --init no --transfer no --dtx yes --queue-base-name G4R -> txtest exits with exit code of 2 and both broker and client (txtest) display following error: Recovering DTX in-doubt transaction(s): * committing {Xid: format=1279348295; global-id=59efb462-1de7-4cd3-92bb-25f3cf6dc9f4; branch-id=G4R-6; } Drained 11101 messages from G4R-1 Drained 880 messages from G4R-2 Drained 352 messages from G4R-3 Drained 352 messages from G4R-4 Drained 0 messages from G4R-5 2009-oct-14 15:12:09 warning Broker closed connection: 501, Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) framing-error: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) framing-error: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) Actual results: Client (txtest) exit with above framing-errors/exceptions, txtest exits with and error. Expected results: No framing-erors/exceptions should be seen, txtest should end fine. Additional info: rough log: ~~~~~~~~~ [15:11:11] run(A) 2/75--------------------------[err_cnt:0] [15:11:21] .starting qpidd - 1] [15:11:21] .waiting for qpidd start - 2] . [15:11:23] ..qpidd just started [15:11:25] ..qpidd started on port 5672, parent lock file exists [15:11:25] ..qpidd process detected (29502 ) [15:11:25] .running txtest - 3] [15:11:25] ..config:[msg_per_tx:176, tx_cnt:149380, msg_cnt:13389, msg_size:86, q_cnt:8, --dtx yes] . [15:11:29] ..txtest just started (and transfering) [15:11:29] ..qpidd & txtest up and running [15:11:29] .wait some rand time & kill the qpidd (now waiting 6sec) - 4] [15:11:35] mrg_kill_process_name: process (/usr/sbin/qpidd-29502 ) killed ./qpidd_runner.sh: line 27: 29502 Killed ${QPIDD_WRAPPER} ${QPIDD_DIR}/qpidd ${RUNNER_QPIDD_PARAMS} >> ${QPIDD_TRANSCRIPT} 2>&1 [15:11:45] .pack the journal (before qpidd tries to recover) - 5] [15:11:59] ..qpidd journal saved in qpidd_journal_a0002.tar.bz2 [15:11:59] .journal lock left untouched, db_recover run disabled - 6] [15:12:04] ..qpidd & txtest and not running at the moment [15:12:04] .re-start qpidd for journal recovery - 7] [15:12:04] .wait for qpidd journal recovery settles - 8] . [15:12:07] ..qpidd just started [15:12:07] ..qpidd started on port 5672, lock is present [15:12:07] .re-running txtest - 9] [15:12:14] ..ERROR:txtest failed (ecode=2) [15:12:14] ..ERROR:txtest logfile indicates failure that not all messages were rx'd (nr.lines:12 txtest.transcript.log): > [15:12:07] begin (run(A) 2/75 @step9] ) > [15:12:07] Command: /usr/bin/txtest -p 5672 --messages-per-tx 176 --tx-count 149380 --total-messages 13389 --size 86 --queues 8 --check yes --init no --transfer no --dtx yes --queue-base-name G4R > Recovering DTX in-doubt transaction(s): > * committing {Xid: format=1279348295; global-id=59efb462-1de7-4cd3-92bb-25f3cf6dc9f4; branch-id=G4R-6; } > Drained 11101 messages from G4R-1 > Drained 880 messages from G4R-2 > Drained 352 messages from G4R-3 > Drained 352 messages from G4R-4 > Drained 0 messages from G4R-5 > 2009-oct-14 15:12:09 warning Broker closed connection: 501, Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) [15:12:19] .stop qpidd/txtest (if needed) - 10] [15:12:19] ..killing /usr/sbin/qpidd (PID:29602 ) [15:12:19] mrg_kill_process_id: process 29602 killed ./qpidd_runner.sh: line 27: 29602 Killed ${QPIDD_WRAPPER} ${QPIDD_DIR}/qpidd ${RUNNER_QPIDD_PARAMS} >> ${QPIDD_TRANSCRIPT} 2>&1 [15:12:31] run(A) 3/75--------------------------[err_cnt:2] ... part of fine log: ~~~~~~~~~~~~~~~~ 2009-oct-14 15:12:09 debug DeliveryRecord::setEnded() id=12861 2009-oct-14 15:12:09 debug Credit available for 'G4R-6' on 0x8ce3010 bytes: 4294967295 msgs: 4294967295 2009-oct-14 15:12:09 debug Credit allocated for 'G4R-6' on 0x8ce3010, was bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295 2009-oct-14 15:12:09 debug DeliveryRecord::setEnded() id=12862 2009-oct-14 15:12:09 debug Credit available for 'G4R-6' on 0x8ce3010 bytes: 4294967295 msgs: 4294967295 2009-oct-14 15:12:09 debug Credit allocated for 'G4R-6' on 0x8ce3010, was bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295 2009-oct-14 15:12:09 debug DeliveryRecord::setEnded() id=12863 2009-oct-14 15:12:09 debug Exception constructed: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) 2009-oct-14 15:12:09 error Unexpected exception: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) 2009-oct-14 15:12:09 error Connection 127.0.0.1:44470 closed by error: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51)(501) 2009-oct-14 15:12:09 debug Exception constructed: Channel 2 is not attached (qpid/amqp_0_10/SessionHandler.cpp:40) 2009-oct-14 15:12:09 error Channel exception: not-attached: Channel 2 is not attached (qpid/amqp_0_10/SessionHandler.cpp:40) [15:12:19] here goes txtest.transcript.log transcript ( ) [15:12:07] begin (run(A) 2/75 @step9] ) [15:12:07] Command: /usr/bin/txtest -p 5672 --messages-per-tx 176 --tx-count 149380 --total-messages 13389 --size 86 --queues 8 --check yes --init no --transfer no --dtx yes --queue-base-name G4R Recovering DTX in-doubt transaction(s): * committing {Xid: format=1279348295; global-id=59efb462-1de7-4cd3-92bb-25f3cf6dc9f4; branch-id=G4R-6; } Drained 11101 messages from G4R-1 Drained 880 messages from G4R-2 Drained 352 messages from G4R-3 Drained 352 messages from G4R-4 Drained 0 messages from G4R-5 2009-oct-14 15:12:09 warning Broker closed connection: 501, Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) framing-error: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51) framing-error: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51)
The problem observed on standalone broker config.
Committed to trunk as r826460 and to MRG release branch as http://git.et.redhat.com/git/qpid.git/?p=qpid.git;a=commitdiff;h=8ec49a359a0f8d23eb69f5cef7694343b8951945
The issue has been fixed, validated on RHEL 4.8 / 5.4 i386 / x86_64 on packages: qpid*-0.5.752581-29.el5 rhm-0.5.3206-16.el5 ->VERIFIED
The fix for this bug was included in the MRG 1.2 release.