Bug 514686 - Flow to disk on replicated queues can crash broker
Summary: Flow to disk on replicated queues can crash broker
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: 1.1.2
Hardware: All
OS: Linux
urgent
medium
Target Milestone: 1.2
: ---
Assignee: Carl Trieloff
QA Contact: Jan Sarenik
URL:
Whiteboard:
Depends On:
Blocks: 527551
TreeView+ depends on / blocked
 
Reported: 2009-07-30 08:02 UTC by Gordon Sim
Modified: 2009-12-03 09:17 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Messaging bug fix C: flow to disk and replication are both enabled on the same queue C: The broker would crash. F: The flow-to-disk is now delayed until the QueueEvent has been processed. R: The broker no longer crashes. When flow-to-disk and replication were both enabled on the same queue, the broker would occasionally crash. The flow-to-disk is now delayed until the QueueEvent has been processed, preventing the broker from crashing.
Clone Of:
Environment:
Last Closed: 2009-12-03 09:17:00 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
patch for issue (5.14 KB, patch)
2009-08-03 19:34 UTC, Carl Trieloff
no flags Details | Diff
patch re-attched (5.07 KB, patch)
2009-08-03 19:36 UTC, Carl Trieloff
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2009:1633 0 normal SHIPPED_LIVE Red Hat Enterprise MRG Messaging and Grid Version 1.2 2009-12-03 09:15:33 UTC

Description Gordon Sim 2009-07-30 08:02:41 UTC
Description of problem:

If flow to disk and replication are both enabled on the same queue, the broker can crash.

Version-Release number of selected component (if applicable):

qpidd-0.5.752581-26.el5 (but believed to be present since 1.1.1)

How reproducible:

100%

Steps to Reproduce:
1. start two brokers with replication enabled between them
   e.g. I used 5672 as source, 5673 as backup,
   (a) specify --create-replication-queue --replication-queue  REPLICATION_QUEUE when starting source broker, then
   (b) qpid-config -a localhost:5673 add exchange replication REPLICATION_EXCHANGE
   (c) qpid-route queue add localhost:5673 localhost:5672 REPLICATION_EXCHANGE REPLICATION_QUEUE
2. run: for i in `seq 1 5`; do qpid-config add queue latency-test-$i --durable--max-queue-count 5 --generate-queue-events 2 --limit-policy flow-to-disk; qpid-config -a localhost:5673 add queue latency-test-$i; done
3. run: latencytest --rate 500 --durable true --queues 5
  
Actual results:

E.g. terminate called after throwing an instance of 'qpid::Exception'
  what():  Queue latency-test-4: loadContent() failed: jexception 0x0901 rmgr::read() threw JERR_RMGR_RIDMISMATCH: RID mismatch between current record and dtok RID (rid=0x0000000000000085; dtok_rid=0000000000000085; dtok_id=0x0000000d) (MessageStoreImpl.cpp:1289)
Aborted (core dumped)

Actual error can differ

Expected results:

No crash; no errors.

Additional info:

Comment 1 Gordon Sim 2009-07-30 08:04:38 UTC
Some other errors possible:

terminate called after throwing an instance of 'qpid::Exception'
  what():  Queue latency-test-3: loadContent() failed: jexception 0x0108 JournalImpl::loadMsgContent() threw JERR__UNEXPRESPONSE: Unexpected response to call or event. (read_data_record() returned RHM_IORES_EMPTY) (MessageStoreImpl.cpp:1289)
Aborted (core dumped)

terminate called after throwing an instance of 'qpid::Exception'
  what():  Queue latency-test-3: loadContent() failed: jexception 0x0701 jrec::chk_tail() threw JERR_JREC_BADRECTAIL: Invalid data record tail. (magic: rid=0x0: expected=0x9ab2b7ad read=0x9ab2b7ad) (MessageStoreImpl.cpp:1289)
Aborted (core dumped)

Comment 2 Carl Trieloff 2009-08-03 19:34:30 UTC
Created attachment 356073 [details]
patch for issue

The patch corrects the core issue, but delaying the flow-to-disk until the QueueEvent has been processed.

Comment 3 Carl Trieloff 2009-08-03 19:36:59 UTC
Created attachment 356074 [details]
patch re-attched

Comment 4 Carl Trieloff 2009-08-03 19:41:15 UTC

Testing:

./qpidd --auth no --load-module .libs/replication_exchange.so --port 5673 --no-data-dir 

./qpidd --auth no --load-module .libs/replicating_listener.so --no-data-dir --replication-queue replication-queue --create-replication-queue true --load-module ~/mrg/trunk/cpp/lib/.libs/msgstore.so


qpid-config -a localhost:5673 add exchange replication replication-exchange
qpid-route --ack 50 queue add localhost:5673 localhost replication-exchange replication-queue
for i in `seq 1 5`; do qpid-config add queue latency-test-$i --durable --max-queue-count 5 --generate-queue-events 2 --limit-policy flow-to-disk; qpid-config -a localhost:5673 add queue latency-test-$i; done
 
./latencytest --rate 500 --durable true --concurrentTests 5

expected results: no core, no errors.
also, check that queue depth greater than the policy limit of 5, using qpid-tool for example to make sure this fix is being exercised.

Comment 5 Carl Trieloff 2009-08-04 02:30:30 UTC
Issues here:

a.) release content before message is cloned by replication event
b.) dequeue of message before message is cloned?

lt-qpidd: qpid/broker/SessionState.cpp:346: virtual void qpid::broker::SessionState::deliver(qpid::broker::DeliveryRecord&, bool): Assertion `senderGetCommandPoint() == SessionPoint(commandId+1, 0)' failed.
Aborted (core dumped)


Thread 5 (process 6329):
#0  0x0000003fe66a7f81 in nanosleep () from /lib64/libc.so.6
#1  0x0000003fe66df264 in usleep () from /lib64/libc.so.6
#2  0x00007f02d4e61d15 in mrg::msgstore::JournalImpl::loadMsgContent (this=0x1288f80, rid=1820810, data=@0x7f02cc875230, length=65523, offset=0)
    at JournalImpl.cpp:300
#3  0x00007f02d4e80a83 in mrg::msgstore::MessageStoreImpl::loadContent (this=0x1261280, queue=@0x1287ad0, msg=<value optimized out>, data=@0x7f02cc875230, 
    offset=0, length=4294967295) at MessageStoreImpl.cpp:1357
#4  0x00007f02d5f273fb in qpid::broker::MessageStoreModule::loadContent (this=<value optimized out>, queue=@0x0, msg=@0x0, data=@0xffffffffffffffff, 
    offset=19437104, length=0) at qpid/broker/MessageStoreModule.cpp:117
#5  0x00007f02d5f2383c in qpid::broker::Message::getContentFrame (this=0x7f02cf456e40, queue=@0x1287ad0, frame=@0x7fff636e07b0, maxContentSize=65523, 
    offset=0) at qpid/broker/Message.cpp:231
#6  0x00007f02d5f23fe8 in qpid::broker::Message::sendContent (this=0x7f02cf456e40, queue=@0x1287ad0, out=@0x141cf08, maxFrameSize=<value optimized out>)
    at qpid/broker/Message.cpp:256
#7  0x00007f02d5eec688 in qpid::broker::DeliveryRecord::deliver (this=0x7fff636e0990, h=@0x141cf08, deliveryId=<value optimized out>, framesize=65535)
    at qpid/broker/DeliveryRecord.cpp:84
#8  0x00007f02d5f6f708 in qpid::broker::SessionState::deliver (this=0x134fb90, msg=@0x7fff636e0990, sync=false) at qpid/broker/SessionState.cpp:345
#9  0x00007f02d5f4fd81 in qpid::broker::SemanticState::ConsumerImpl::deliver (this=0x1289fd0, msg=@0x7fff636e09f0) at qpid/broker/SemanticState.cpp:275
#10 0x00007f02d5f37232 in qpid::broker::Queue::dispatch (this=<value optimized out>, c=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
) at qpid/broker/Queue.cpp:413
#11 0x00007f02d5f54f6e in qpid::broker::SemanticState::ConsumerImpl::doOutput (this=0x1289fd0) at qpid/broker/SemanticState.cpp:604
#12 0x00007f02d5b44b70 in qpid::sys::AggregateOutput::doOutput (this=0x141ef30) at qpid/sys/AggregateOutput.cpp:62
#13 0x00007f02d5ee251f in qpid::broker::Connection::doOutput (this=0x141eec0) at qpid/broker/Connection.cpp:276
#14 0x00007f02d5ec3f1e in qpid::amqp_0_10::Connection::encode (this=0x13393d0, buffer=<value optimized out>, size=<value optimized out>)
    at qpid/amqp_0_10/Connection.cpp:94
#15 0x00007f02d5b47001 in qpid::sys::AsynchIOHandler::idle (this=0x141a7a0) at qpid/sys/AsynchIOHandler.cpp:206
#16 0x00007f02d5a93e77 in boost::function1<void, qpid::sys::AsynchIO&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#17 0x00007f02d5a91017 in qpid::sys::posix::AsynchIO::writeable (this=0x141dc20, h=@0x141dc28) at qpid/sys/posix/AsynchIO.cpp:566
#18 0x00007f02d5b4c767 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#19 0x00007f02d5b4b362 in qpid::sys::DispatchHandle::processEvent (this=0x141dc28, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:285
#20 0x00007f02d5a9f228 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#21 qpid::sys::Poller::run (this=0x125b9b0) at qpid/sys/epoll/EpollPoller.cpp:476
#22 0x00007f02d5ecee92 in qpid::broker::Broker::run (this=0x0) at qpid/broker/Broker.cpp:319
#23 0x00000000004093ba in QpiddBroker::execute (this=<value optimized out>, options=0x125ae80) at posix/QpiddBroker.cpp:166
#24 0x0000000000406394 in main (argc=11, argv=0x7fff636e22a8) at qpidd.cpp:77
---Type <return> to continue, or q <return> to quit--- 

Thread 4 (process 6345):
#0  0x0000003fe720b58d in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f02d5b51092 in qpid::sys::Condition::wait () at ../include/qpid/sys/posix/Condition.h:69
#2  qpid::sys::Monitor::wait () at ../include/qpid/sys/Monitor.h:45
#3  qpid::sys::Timer::run (this=0x125f0d0) at qpid/sys/Timer.cpp:129
#4  0x00007f02d5a95eba in runRunnable (p=0x125f104) at qpid/sys/posix/Thread.cpp:35
#5  0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#6  0x0000003fe66e62bd in clone () from /lib64/libc.so.6

Thread 3 (process 6348):
#0  AMQFrame () at ./qpid/framing/AMQFrame.h:37
#1  __gnu_cxx::new_allocator<qpid::framing::AMQFrame>::construct ()
    at /usr/lib/gcc/x86_64-redhat-linux/4.3.2/../../../../include/c++/4.3.2/ext/new_allocator.h:108
#2  std::vector<qpid::framing::AMQFrame, qpid::InlineAllocator<std::allocator<qpid::framing::AMQFrame>, 4ul> >::push_back ()
    at /usr/lib/gcc/x86_64-redhat-linux/4.3.2/../../../../include/c++/4.3.2/bits/stl_vector.h:690
#3  qpid::framing::FrameSet::append (this=0x7f02c7c9dad8, part=@0x7f02d1ec96d0) at qpid/framing/FrameSet.cpp:35
#4  0x00007f02d5118c16 in qpid::replication::AppendingHandler::handle (f=<value optimized out>, this=<value optimized out>)
    at qpid/replication/ReplicatingEventListener.cpp:120
#5  qpid::replication::ReplicatingEventListener::cloneMessage (this=<value optimized out>, queue=@0x1269eb0, original=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
)
    at qpid/replication/ReplicatingEventListener.cpp:138
#6  0x00007f02d51191fe in qpid::replication::ReplicatingEventListener::deliverEnqueueMessage (this=0x7f02d53200c0, enqueued=@0x7f02d1ec9ae8)
    at qpid/replication/ReplicatingEventListener.cpp:71
#7  0x00007f02d5119b38 in qpid::replication::ReplicatingEventListener::handle (this=0x7f02c7c9dad8, event=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
)
    at qpid/replication/ReplicatingEventListener.cpp:42
#8  0x00007f02d511b144 in boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>::operator() ()
    at /usr/include/boost/bind/mem_fn_template.hpp:162
#9  operator()<boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>, boost::_bi::list1<qpid::broker::QueueEvents::Event&> > () at /usr/include/boost/bind.hpp:288
#10 operator()<qpid::broker::QueueEvents::Event> () at /usr/include/boost/bind/bind_template.hpp:32
#11 boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>, boost::_bi::list2<boost::_bi::value<qpid::replication::ReplicatingEventListener*>, boost::arg<1> (*)()> >, void, qpid::broker::QueueEvents::Event>::invoke (function_obj_ptr=@0x7f02d1ec96d0, a0=<value optimized out>) at /usr/include/boost/function/function_template.hpp:155
#12 0x00007f02d5f3d5d8 in boost::function1<void, qpid::broker::QueueEvents::Event, std::allocator<void> >::operator() (this=<value optimized out>, 
    a0=<value optimized out>) at /usr/include/boost/function/function_template.hpp:692
#13 0x00007f02d5f3b1d6 in qpid::broker::QueueEvents::handle (this=0x125f660, events=@0x125f728) at qpid/broker/QueueEvents.cpp:77
---Type <return> to continue, or q <return> to quit---
#14 0x00007f02d5f3cfa9 in boost::_mfi::mf1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>::operator() () at /usr/include/boost/bind/mem_fn_template.hpp:162
#15 operator()<__gnu_cxx::__normal_iterator<const qpid::broker::QueueEvents::Event*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, boost::_mfi::mf1<__gnu_cxx::__normal_iterator<const qpid::broker::QueueEvents::Event*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, const std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> >&>, boost::_bi::list1<const std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> >&> >
    () at /usr/include/boost/bind.hpp:278
#16 operator()<std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > > ()
    at /usr/include/boost/bind/bind_template.hpp:47
#17 boost::detail::function::function_obj_invoker1<boost::_bi::bind_t<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, boost::_mfi::mf1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>, boost::_bi::list2<boost::_bi::value<qpid::broker::QueueEvents*>, boost::arg<1> (*)()> >, __gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>::invoke (
    function_obj_ptr=<value optimized out>, a0=@0x7f02c7c9daf8) at /usr/include/boost/function/function_template.hpp:134
#18 0x00007f02d5f3f093 in boost::function1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&, std::allocator<void> >::operator() () at /usr/include/boost/function/function_template.hpp:692
#19 qpid::sys::PollableQueue<qpid::broker::QueueEvents::Event>::process (this=0x125f660) at ./qpid/sys/PollableQueue.h:151
#20 0x00007f02d5f3f3da in qpid::sys::PollableQueue<qpid::broker::QueueEvents::Event>::dispatch (this=0x125f660, cond=@0x125f6d8)
    at ./qpid/sys/PollableQueue.h:137
#21 0x00007f02d5a9bf67 in boost::function1<void, qpid::sys::PollableCondition&, std::allocator<boost::function_base> >::operator() (
    this=<value optimized out>, a0=@0x7f02c7c9daf8) at /usr/include/boost/function/function_template.hpp:692
#22 0x00007f02d5b4c767 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x7f02c7c9daf8) at /usr/include/boost/function/function_template.hpp:692
#23 0x00007f02d5b4b4d5 in qpid::sys::DispatchHandle::processEvent (this=0x125f810, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:278
#24 0x00007f02d5a9f228 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#25 qpid::sys::Poller::run (this=0x125b9b0) at qpid/sys/epoll/EpollPoller.cpp:476
#26 0x00007f02d5a95eba in runRunnable (p=0x7f02c7c9dad8) at qpid/sys/posix/Thread.cpp:35
#27 0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#28 0x0000003fe66e62bd in clone () from /lib64/libc.so.6

Thread 2 (process 6346):
#0  0x0000003fe720b58d in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#1  0x00007f02d5f780cf in qpid::sys::Condition::wait (this=0xffffffffffffff92, mutex=@0x1268838, absoluteTime=<value optimized out>)
    at ../include/qpid/sys/posix/Condition.h:69
#2  0x00007f02d5f766dd in qpid::sys::Monitor::wait () at ../include/qpid/sys/Monitor.h:45
#3  qpid::broker::Timer::run (this=0x1268830) at qpid/broker/Timer.cpp:83
#4  0x00007f02d5a95eba in runRunnable (p=0x1268864) at qpid/sys/posix/Thread.cpp:35
#5  0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#6  0x0000003fe66e62bd in clone () from /lib64/libc.so.6

Thread 1 (process 6347):
#0  0x00007f02d5f23f08 in qpid::framing::TypeFilter<(unsigned char)3>::operator() (f=<value optimized out>) at ./qpid/framing/TypeFilter.h:38
#1  map_if<qpid::framing::SendContent, qpid::framing::TypeFilter<3u> > () at ./qpid/framing/FrameSet.h:103
#2  qpid::broker::Message::sendContent (this=0x7f02cc6cfca0, queue=@0x1269eb0, out=@0x13d47c8, maxFrameSize=<value optimized out>)
    at qpid/broker/Message.cpp:264
#3  0x00007f02d5eec688 in qpid::broker::DeliveryRecord::deliver (this=0x7f02d28ca780, h=@0x13d47c8, deliveryId=<value optimized out>, framesize=65535)
    at qpid/broker/DeliveryRecord.cpp:84
#4  0x00007f02d5f6f708 in qpid::broker::SessionState::deliver (this=0x141c000, msg=@0x7f02d28ca780, sync=false) at qpid/broker/SessionState.cpp:345
#5  0x00007f02d5f4fd81 in qpid::broker::SemanticState::ConsumerImpl::deliver (this=0x1333510, msg=@0x7f02d28ca7e0) at qpid/broker/SemanticState.cpp:275
#6  0x00007f02d5f37232 in qpid::broker::Queue::dispatch (this=<value optimized out>, c=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
) at qpid/broker/Queue.cpp:413
#7  0x00007f02d5f54f6e in qpid::broker::SemanticState::ConsumerImpl::doOutput (this=0x1333510) at qpid/broker/SemanticState.cpp:604
#8  0x00007f02d5b44b70 in qpid::sys::AggregateOutput::doOutput (this=0x145c6a0) at qpid/sys/AggregateOutput.cpp:62
#9  0x00007f02d5ee251f in qpid::broker::Connection::doOutput (this=0x145c630) at qpid/broker/Connection.cpp:276
#10 0x00007f02d5ec28b2 in qpid::amqp_0_10::Connection::canEncode (this=0x1305100) at qpid/amqp_0_10/Connection.cpp:64
#11 0x00007f02d5b46fcb in qpid::sys::AsynchIOHandler::idle (this=0x7f02cc004160) at qpid/sys/AsynchIOHandler.cpp:202
#12 0x00007f02d5a93e77 in boost::function1<void, qpid::sys::AsynchIO&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#13 0x00007f02d5a91017 in qpid::sys::posix::AsynchIO::writeable (this=0x7f02cc046cf0, h=@0x7f02cc046cf8) at qpid/sys/posix/AsynchIO.cpp:566
#14 0x00007f02d5b4c767 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#15 0x00007f02d5b4b362 in qpid::sys::DispatchHandle::processEvent (this=0x7f02cc046cf8, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:285
#16 0x00007f02d5a9f228 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#17 qpid::sys::Poller::run (this=0x125b9b0) at qpid/sys/epoll/EpollPoller.cpp:476
#18 0x00007f02d5a95eba in runRunnable (p=0x0) at qpid/sys/posix/Thread.cpp:35
#19 0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#20 0x0000003fe66e62bd in clone () from /lib64/libc.so.6
(gdb)

Comment 6 Carl Trieloff 2009-08-04 17:59:22 UTC
as of 

URL: https://svn.jboss.org/repos/rhmessaging/store/trunk/cpp
Repository Root: https://svn.jboss.org/repos/rhmessaging
Repository UUID: 06e15bec-b515-0410-bef0-cc27a458cf48
Revision: 3537
Node Kind: directory
Schedule: normal
Last Changed Author: kpvdr
Last Changed Rev: 3537
Last Changed Date: 2009-08-04 10:11:24 -0400 (Tue, 04 Aug 2009)


The assert above is not reproducing.

Comment 7 Carl Trieloff 2009-08-04 18:11:11 UTC
Will reproduce for durable flow to disk, but not with transient messages.

Comment 8 Carl Trieloff 2009-08-04 20:54:19 UTC
Thread 5 (process 7634):
#0  0x0000003fe66a7f81 in nanosleep () from /lib64/libc.so.6
#1  0x0000003fe66df264 in usleep () from /lib64/libc.so.6
#2  0x00007f3224a41715 in mrg::msgstore::JournalImpl::loadMsgContent (this=0x19041e0, rid=535875, data=@0x7f321da46660, length=65523, offset=0)
    at JournalImpl.cpp:300
#3  0x00007f3224a60483 in mrg::msgstore::MessageStoreImpl::loadContent (this=0x144e280, queue=@0x19035c0, msg=<value optimized out>, data=@0x7f321da46660, 
    offset=0, length=4294967295) at MessageStoreImpl.cpp:1357
#4  0x00007f322590233b in qpid::broker::MessageStoreModule::loadContent (this=<value optimized out>, queue=@0x0, msg=@0x0, data=@0xffffffffffffffff, 
    offset=26232976, length=0) at qpid/broker/MessageStoreModule.cpp:117
#5  0x00007f32258fe23a in qpid::broker::Message::getContentFrame (this=0x54134b0, queue=@0x19035c0, frame=@0x7f32224bd5a0, maxContentSize=65523, offset=0)
    at qpid/broker/Message.cpp:234
#6  0x00007f32258fe7b2 in qpid::broker::Message::sendContent (this=0x54134b0, queue=@0x19035c0, out=@0x7f321444b968, maxFrameSize=<value optimized out>)
    at qpid/broker/Message.cpp:263
#7  0x00007f32258c7688 in qpid::broker::DeliveryRecord::deliver (this=0x7f32224bd780, h=@0x7f321444b968, deliveryId=<value optimized out>, framesize=65535)
    at qpid/broker/DeliveryRecord.cpp:84
#8  0x00007f322594a6d8 in qpid::broker::SessionState::deliver (this=0x7f32154b2500, msg=@0x7f32224bd780, sync=false) at qpid/broker/SessionState.cpp:345
#9  0x00007f322592ad51 in qpid::broker::SemanticState::ConsumerImpl::deliver (this=0x2d0c0d0, msg=@0x7f32224bd7e0) at qpid/broker/SemanticState.cpp:275
#10 0x00007f3225912202 in qpid::broker::Queue::dispatch (this=<value optimized out>, c=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
) at qpid/broker/Queue.cpp:413
#11 0x00007f322592ff3e in qpid::broker::SemanticState::ConsumerImpl::doOutput (this=0x2d0c0d0) at qpid/broker/SemanticState.cpp:604
#12 0x00007f322551fb50 in qpid::sys::AggregateOutput::doOutput (this=0x7f3214ec1040) at qpid/sys/AggregateOutput.cpp:62
#13 0x00007f32258bd51f in qpid::broker::Connection::doOutput (this=0x7f3214ec0fd0) at qpid/broker/Connection.cpp:276
#14 0x00007f322589d8b2 in qpid::amqp_0_10::Connection::canEncode (this=0x7f3214e2c400) at qpid/amqp_0_10/Connection.cpp:64
#15 0x00007f3225521fab in qpid::sys::AsynchIOHandler::idle (this=0x7f3214f1e7e0) at qpid/sys/AsynchIOHandler.cpp:202
#16 0x00007f322546ee57 in boost::function1<void, qpid::sys::AsynchIO&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#17 0x00007f322546bff7 in qpid::sys::posix::AsynchIO::writeable (this=0x7f3214405e90, h=@0x7f3214405e98) at qpid/sys/posix/AsynchIO.cpp:566
#18 0x00007f3225527837 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#19 0x00007f3225526822 in qpid::sys::DispatchHandle::processEvent (this=0x7f3214405e98, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:285
#20 0x00007f322547a208 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#21 qpid::sys::Poller::run (this=0x14489b0) at qpid/sys/epoll/EpollPoller.cpp:476
#22 0x00007f3225470e9a in runRunnable (p=0x7f32224bc790) at qpid/sys/posix/Thread.cpp:35
#23 0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#24 0x0000003fe66e62bd in clone () from /lib64/libc.so.6

---Type <return> to continue, or q <return> to quit---
Thread 4 (process 7631):
#0  0x0000003fe720b58d in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f322552c162 in qpid::sys::Condition::wait () at ../include/qpid/sys/posix/Condition.h:69
#2  qpid::sys::Monitor::wait () at ../include/qpid/sys/Monitor.h:45
#3  qpid::sys::Timer::run (this=0x144c0d0) at qpid/sys/Timer.cpp:129
#4  0x00007f3225470e9a in runRunnable (p=0x144c104) at qpid/sys/posix/Thread.cpp:35
#5  0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#6  0x0000003fe66e62bd in clone () from /lib64/libc.so.6

Thread 3 (process 7615):
#0  0x00007f322545ad68 in std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > > >::_M_insert_ () from /home/cctrieloff/apache/qpid1/cpp/src/.libs/libqpidcommon.so.2
#1  0x00007f322550f837 in std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > > >::_M_insert_unique_ (this=0x7f321d8e9590, __position={_M_node = 0x7f321f42e620}, __v=@0x7fff6f96d4d0)
    at /usr/lib/gcc/x86_64-redhat-linux/4.3.2/../../../../include/c++/4.3.2/bits/stl_tree.h:1204
#2  0x00007f322550fa2b in std::map<std::string, boost::shared_ptr<qpid::framing::FieldValue>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > > >::insert () at /usr/lib/gcc/x86_64-redhat-linux/4.3.2/../../../../include/c++/4.3.2/bits/stl_map.h:496
#3  std::map<std::string, boost::shared_ptr<qpid::framing::FieldValue>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<qpid::framing::FieldValue> > > >::operator[] (this=0x7f321d8e9590, __k=@0x7f3224eff098)
    at /usr/lib/gcc/x86_64-redhat-linux/4.3.2/../../../../include/c++/4.3.2/bits/stl_map.h:419
#4  0x00007f322550d7f5 in qpid::framing::FieldTable::setInt (this=0x7f321d8e9590, name=@0x7f3224eff098, value=53675) at qpid/framing/FieldTable.cpp:104
#5  0x00007f3224cf8286 in qpid::replication::ReplicatingEventListener::deliverEnqueueMessage (this=0x7f3224eff0c0, enqueued=@0x7fff6f96d8e8)
    at qpid/replication/ReplicatingEventListener.cpp:75
#6  0x00007f3224cf8b38 in qpid::replication::ReplicatingEventListener::handle (this=0x7f321d8e9590, event=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
)
    at qpid/replication/ReplicatingEventListener.cpp:42
#7  0x00007f3224cfa144 in boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>::operator() ()
    at /usr/include/boost/bind/mem_fn_template.hpp:162
#8  operator()<boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>, boost::_bi::list1<qpid::broker::QueueEvents::Event&> > () at /usr/include/boost/bind.hpp:288
#9  operator()<qpid::broker::QueueEvents::Event> () at /usr/include/boost/bind/bind_template.hpp:32
#10 boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, qpid::replication::ReplicatingEventListener, qpid::broker::QueueEvents::Event>, boost::_bi::list2<boost::_bi::value<qpid::replication::ReplicatingEventListener*>, boost::arg<1> (*)()> >, void, qpid::broker::QueueEvents::Event>::invoke (function_obj_ptr=@0x7fff6f96d4d0, a0=<value optimized out>) at /usr/include/boost/function/function_template.hpp:155
#11 0x00007f32259185a8 in boost::function1<void, qpid::broker::QueueEvents::Event, std::allocator<void> >::operator() (this=<value optimized out>, 
---Type <return> to continue, or q <return> to quit---
    a0=<value optimized out>) at /usr/include/boost/function/function_template.hpp:692
#12 0x00007f32259161a6 in qpid::broker::QueueEvents::handle (this=0x144c660, events=@0x144c728) at qpid/broker/QueueEvents.cpp:77
#13 0x00007f3225917f79 in boost::_mfi::mf1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>::operator() () at /usr/include/boost/bind/mem_fn_template.hpp:162
#14 operator()<__gnu_cxx::__normal_iterator<const qpid::broker::QueueEvents::Event*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, boost::_mfi::mf1<__gnu_cxx::__normal_iterator<const qpid::broker::QueueEvents::Event*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, const std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> >&>, boost::_bi::list1<const std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> >&> >
    () at /usr/include/boost/bind.hpp:278
#15 operator()<std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > > ()
    at /usr/include/boost/bind/bind_template.hpp:47
#16 boost::detail::function::function_obj_invoker1<boost::_bi::bind_t<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, boost::_mfi::mf1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, qpid::broker::QueueEvents, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>, boost::_bi::list2<boost::_bi::value<qpid::broker::QueueEvents*>, boost::arg<1> (*)()> >, __gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&>::invoke (
    function_obj_ptr=<value optimized out>, a0=@0x7f321f42e620) at /usr/include/boost/function/function_template.hpp:134
#17 0x00007f322591a063 in boost::function1<__gnu_cxx::__normal_iterator<qpid::broker::QueueEvents::Event const*, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > >, std::vector<qpid::broker::QueueEvents::Event, std::allocator<qpid::broker::QueueEvents::Event> > const&, std::allocator<void> >::operator() () at /usr/include/boost/function/function_template.hpp:692
#18 qpid::sys::PollableQueue<qpid::broker::QueueEvents::Event>::process (this=0x144c660) at ./qpid/sys/PollableQueue.h:151
#19 0x00007f322591a3aa in qpid::sys::PollableQueue<qpid::broker::QueueEvents::Event>::dispatch (this=0x144c660, cond=@0x144c6d8)
    at ./qpid/sys/PollableQueue.h:137
#20 0x00007f3225476f47 in boost::function1<void, qpid::sys::PollableCondition&, std::allocator<boost::function_base> >::operator() (
    this=<value optimized out>, a0=@0x7f321f42e620) at /usr/include/boost/function/function_template.hpp:692
#21 0x00007f3225527837 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x7f321f42e620) at /usr/include/boost/function/function_template.hpp:692
#22 0x00007f3225526995 in qpid::sys::DispatchHandle::processEvent (this=0x144c810, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:278
#23 0x00007f322547a208 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#24 qpid::sys::Poller::run (this=0x14489b0) at qpid/sys/epoll/EpollPoller.cpp:476
#25 0x00007f32258a9e92 in qpid::broker::Broker::run (this=0x0) at qpid/broker/Broker.cpp:319
#26 0x00000000004093ba in QpiddBroker::execute (this=<value optimized out>, options=0x1447e80) at posix/QpiddBroker.cpp:166
#27 0x0000000000406394 in main (argc=11, argv=0x7fff6f96e888) at qpidd.cpp:77

---Type <return> to continue, or q <return> to quit---
Thread 2 (process 7632):
#0  0x0000003fe720b58d in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f322595309f in qpid::sys::Condition::wait (this=0xffffffffffffff92, mutex=@0x1456738, absoluteTime=<value optimized out>)
    at ../include/qpid/sys/posix/Condition.h:69
#2  0x00007f32259516ad in qpid::sys::Monitor::wait () at ../include/qpid/sys/Monitor.h:45
#3  qpid::broker::Timer::run (this=0x1456730) at qpid/broker/Timer.cpp:83
#4  0x00007f3225470e9a in runRunnable (p=0x1456764) at qpid/sys/posix/Thread.cpp:35
#5  0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#6  0x0000003fe66e62bd in clone () from /lib64/libc.so.6

Thread 1 (process 7633):
#0  0x00007f32258fbe17 in qpid::framing::TypeFilter2<(unsigned char)2, (unsigned char)3>::operator() () at ./qpid/framing/TypeFilter.h:45
#1  map_if<qpid::framing::SumBodySize, qpid::framing::TypeFilter2<2u, 3u> > () at ./qpid/framing/FrameSet.h:103
#2  qpid::broker::Message::getRequiredCredit (this=0x7f321f4ef4c0) at qpid/broker/Message.cpp:116
#3  0x00007f32258c71c2 in DeliveryRecord (this=0x7f3222ebe780, _msg=<value optimized out>, _queue=<value optimized out>, _tag=<value optimized out>, 
    _acquired=true, accepted=false, _windowing=32, _credit=0) at qpid/broker/DeliveryRecord.cpp:48
#4  0x00007f322592ad1c in qpid::broker::SemanticState::ConsumerImpl::deliver (this=0x7f321cbece70, msg=@0x7f3222ebe7e0) at qpid/broker/SemanticState.cpp:272
#5  0x00007f3225912202 in qpid::broker::Queue::dispatch (this=<value optimized out>, c=DWARF-2 expression error: DW_OP_reg operations must be used either alone or in conjuction with DW_OP_piece.
) at qpid/broker/Queue.cpp:413
#6  0x00007f322592ff3e in qpid::broker::SemanticState::ConsumerImpl::doOutput (this=0x7f321cbece70) at qpid/broker/SemanticState.cpp:604
#7  0x00007f322551fb50 in qpid::sys::AggregateOutput::doOutput (this=0x54ada60) at qpid/sys/AggregateOutput.cpp:62
#8  0x00007f32258bd51f in qpid::broker::Connection::doOutput (this=0x54ad9f0) at qpid/broker/Connection.cpp:276
#9  0x00007f322589d8b2 in qpid::amqp_0_10::Connection::canEncode (this=0x43dd790) at qpid/amqp_0_10/Connection.cpp:64
#10 0x00007f3225521fab in qpid::sys::AsynchIOHandler::idle (this=0x22a2f60) at qpid/sys/AsynchIOHandler.cpp:202
#11 0x00007f322546ee57 in boost::function1<void, qpid::sys::AsynchIO&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#12 0x00007f322546bff7 in qpid::sys::posix::AsynchIO::writeable (this=0x19074a0, h=@0x19074a8) at qpid/sys/posix/AsynchIO.cpp:566
#13 0x00007f3225527837 in boost::function1<void, qpid::sys::DispatchHandle&, std::allocator<boost::function_base> >::operator() (this=<value optimized out>, 
    a0=@0x0) at /usr/include/boost/function/function_template.hpp:692
#14 0x00007f3225526822 in qpid::sys::DispatchHandle::processEvent (this=0x19074a8, type=<value optimized out>) at qpid/sys/DispatchHandle.cpp:285
#15 0x00007f322547a208 in qpid::sys::Poller::Event::process () at ./qpid/sys/Poller.h:123
#16 qpid::sys::Poller::run (this=0x14489b0) at qpid/sys/epoll/EpollPoller.cpp:476
#17 0x00007f3225470e9a in runRunnable (p=0x0) at qpid/sys/posix/Thread.cpp:35
#18 0x0000003fe72073da in start_thread () from /lib64/libpthread.so.0
#19 0x0000003fe66e62bd in clone () from /lib64/libc.so.6
(gdb)

Comment 12 Carl Trieloff 2009-08-31 18:36:31 UTC
Moving the copy onto the originating thread resolves the final trace.

Comment 13 Carl Trieloff 2009-09-23 20:36:23 UTC
fixed 817742..

needs backport

Comment 14 Carl Trieloff 2009-09-23 20:37:44 UTC
fixed svn 818244 and requires 817742

Comment 15 Jan Sarenik 2009-10-16 08:11:15 UTC
Reproduced on RHEL5, i386 on MRG 1.1.6 packages.

Verified on RHEL 4 and 5, i386 and x86_64:
  rhm-0.5.3206-14.el5 (and .el4)
  qpidd-0.5.752581-28.el5 (and .el4)

Comment 16 Irina Boverman 2009-10-22 17:39:26 UTC
Release note added. If any revisions are required, please set the 
"requires_release_notes" flag to "?" and edit the "Release Notes" field accordingly.
All revisions will be proofread by the Engineering Content Services team.

New Contents:
The broker is no longer crashing when flow to disk and replication are both enabled on the same queue (514686)

Comment 17 Lana Brindley 2009-11-26 21:17:22 UTC
Release note updated. If any revisions are required, please set the 
"requires_release_notes"  flag to "?" and edit the "Release Notes" field accordingly.
All revisions will be proofread by the Engineering Content Services team.

Diffed Contents:
@@ -1 +1,9 @@
-The broker is no longer crashing when flow to disk and replication are both enabled on the same queue (514686)+Messaging bug fix
+
+C: flow to disk and replication are both enabled on the same queue
+C: The broker would crash.
+F: The flow-to-disk is now delayed until the
+QueueEvent has been processed.  
+R: The broker no longer crashes.
+
+When flow-to-disk and replication were both enabled on the same queue, the broker would occasionally crash. The flow-to-disk is now delayed until the QueueEvent has been processed, preventing the broker from crashing.

Comment 19 errata-xmlrpc 2009-12-03 09:17:00 UTC
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHEA-2009-1633.html


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