Bug 529069 - qpidd+store encounters connection framing error 'error Unexpected exception: Attempted size underflow on dequeue(86): size: max=104857600, current=0; count: unlimited; type=reject (qpid/broker/QueuePolicy.cpp:51)' after txtest recovery check
Summary: qpidd+store encounters connection framing error 'error Unexpected exception: ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: Development
Hardware: All
OS: Linux
medium
high
Target Milestone: 1.2
: ---
Assignee: messaging-bugs
QA Contact: Frantisek Reznicek
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-10-14 20:15 UTC by Frantisek Reznicek
Modified: 2015-11-16 01:11 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2010-03-16 14:31:53 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Frantisek Reznicek 2009-10-14 20:15:01 UTC
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)

Comment 1 Frantisek Reznicek 2009-10-14 20:17:15 UTC
The problem observed on standalone broker config.

Comment 2 Gordon Sim 2009-10-18 16:33:43 UTC
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

Comment 3 Frantisek Reznicek 2009-10-22 06:50:14 UTC
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

Comment 4 Jeff Needle 2010-03-16 14:31:53 UTC
The fix for this bug was included in the MRG 1.2 release.

Comment 5 Jeff Needle 2010-03-16 14:35:41 UTC
The fix for this bug was included in the MRG 1.2 release.


Note You need to log in before you can comment on or make changes to this bug.