You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@qpid.apache.org by Matt Broadstone <mb...@gmail.com> on 2016/01/11 18:37:23 UTC
spurious ABRT in qpidd
I'm having trouble tracking down the root cause of a thrown SIGABRT in
qpidd, and was wondering for some advice from the list. Specifically, it
seems to be after a period of little to no activity, a large burst of
traffic hits the broker and the only information we're seeing in the logs
is:
Jan 11 15:58:33 test-box kernel: [ 652.903997] init: qpidd main process
(2239) killed by ABRT signal
Jan 11 15:58:33 test-box kernel: [ 652.911661] init: qpidd main process
ended, respawning
We're running ubuntu 14.04 (trusty) on this machine, with the packages off
the official qpid PPA. I tried running the services with trace logging
enabled to no avail (there were no strange packets, and no error messages
about bad assertions). Attaching gdb to the process also resulted in no
relevant information, so I'm running out of ideas of what to try next.
AFAICT the only `abort()` present in the codebase is in the assertion code,
which would print something about around the assertion failure.
Any thoughts on what I might try to help resolve this issue?
Regards,
Matt
Re: spurious ABRT in qpidd
Posted by Gordon Sim <gs...@redhat.com>.
On 01/21/2016 03:30 AM, Matt Broadstone wrote:
> It looks like that was the problem after all, I had a bug in my code that
> was sending back disposition frames for every object contained in a bulk
> message. This seems to solve the problem on my end, but I think this is
> probably still a bug in qpidd.
Yes, I agree. I've raised a JIRA[1] and will have a look at this (it's
possible it is also a proton-c bug, but will need to dig deeper to
tell). Thanks very much for all your work in reproducing and analysing this!
[1] https://issues.apache.org/jira/browse/QPID-7010
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Wed, Jan 20, 2016 at 9:58 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Wed, Jan 20, 2016 at 8:31 PM, Matt Broadstone <mb...@gmail.com>
> wrote:
>
>> On Wed, Jan 20, 2016 at 6:52 PM, Matt Broadstone <mb...@gmail.com>
>> wrote:
>>
>>> On Wed, Jan 20, 2016 at 6:10 PM, Matt Broadstone <mb...@gmail.com>
>>> wrote:
>>>
>>>> On Tue, Jan 12, 2016 at 8:39 AM, Matt Broadstone <mb...@gmail.com>
>>>> wrote:
>>>>
>>>>> On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
>>>>>
>>>>>> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>>>>>>
>>>>>>> Looks like I did just get a valid assertion, but I'm not even clear
>>>>>>> anymore
>>>>>>> whether this is related to the initially reported bug (since we're
>>>>>>> trying
>>>>>>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>>>>>>
>>>>>>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head
>>>>>>> is now 0
>>>>>>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1
>>>>>>> :56687
>>>>>>> handling outgoing delivery for 0x7f3fdc262590 on session
>>>>>>> 0x7f3fdc111650
>>>>>>> qpidd:
>>>>>>>
>>>>>>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>>>>>>> virtual void
>>>>>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>>>>>>> Assertion `r.delivery == delivery' failed.
>>>>>>>
>>>>>>
>>>>>> Do you have the core for that? If so can you check the values of
>>>>>> 'delivery' and 'r.delivery'? Is either of them 0?
>>>>>>
>>>>>>
>>>>>>
>>>>> Hi Gordon,
>>>>> I unfortunately don't have access to the box at the moment (and won't
>>>>> for a few hours, if its even still in a reproducible state), but I'll try
>>>>> to get a core next time. In the meantime, do you have any ideas for values
>>>>> I should check on the sending side that might cause this? I can certainly
>>>>> look through all of that code and see if I can make a smaller case that
>>>>> exhibits this behavior.
>>>>>
>>>>> Matt
>>>>>
>>>>>
>>>>
>>>> Hi Gordon,
>>>> Just got this again, and I'm (sort of) able to reproduce it. I have a
>>>> core file for you, if you'd like me to mail it directly to you? Do you have
>>>> any thoughts on what could cause the problem in the first place? This is
>>>> really hanging us up over here unfortunately..
>>>>
>>>> Regards,
>>>> Matt
>>>>
>>>>
>>>>
>>>
>>> Gordon,
>>>
>>> Here is the full backtrace:
>>>
>>> (gdb) bt full
>>> #0 0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
>>> ../nptl/sysdeps/unix/sysv/linux/raise.c:56
>>> resultvar = 0
>>> pid = 18195
>>> selftid = 18207
>>> #1 0x00007ffff64c60d8 in __GI_abort () at abort.c:89
>>> save_stage = 2
>>> act = {__sigaction_handler = {sa_handler = 0x7fffffffe8e0,
>>> sa_sigaction = 0x7fffffffe8e0}, sa_mask = {__val = {140737326910748,
>>> 140737289582424, 115, 140737168167888,
>>> 140737325552867, 4294967296, 140737168167840, 3974779888,
>>> 140737289033565, 140737155069744, 0, 0, 0, 21474836480, 140737354080256,
>>> 140737326925872}}, sa_flags = -198772828,
>>> sa_restorer = 0x7ffff4270020
>>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>}
>>> sigs = {__val = {32, 0 <repeats 15 times>}}
>>> #2 0x00007ffff64bbb86 in __assert_fail_base (fmt=0x7ffff660c830
>>> "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7ffff426f7a4
>>> "r.delivery == delivery",
>>> file=file@entry=0x7ffff426f758
>>> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
>>> line=line@entry=115,
>>> function=function@entry=0x7ffff4270020
>>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
>>> "virtual void
>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
>>> assert.c:92
>>> str = 0x7fffc80c0d90 ""
>>> total = 4096
>>> #3 0x00007ffff64bbc32 in __GI___assert_fail (assertion=0x7ffff426f7a4
>>> "r.delivery == delivery",
>>> file=0x7ffff426f758
>>> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
>>> line=115,
>>> function=0x7ffff4270020
>>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
>>> "virtual void
>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
>>> assert.c:101
>>> No locals.
>>> #4 0x00007ffff4226e73 in qpid::broker::amqp::OutgoingFromQueue::handle
>>> (this=0x7fffc8029160, delivery=0x7fffdc000fe0)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:115
>>> txn = {first = 0x0, second = 0}
>>> i = 14
>>> r = @0x7fffec227718: {cursor = {type = qpid::broker::CONSUMER,
>>> position = 0, version = 0, valid = false, context = {px = 0x0, pn = {pi_ =
>>> 0x0}}}, msg = {sharedState = {px = 0x0},
>>> persistentContext = {px = 0x0}, deliveryCount = -1,
>>> alreadyAcquired = false, annotations = {value = {px = 0x0}}, state =
>>> (unknown: 3690991584),
>>> sequence =
>>> {<boost::equality_comparable<qpid::framing::SequenceNumber,
>>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>> =
>>> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
>>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t> >> =
>>> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>> =
>>> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
>>> {<boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
>>> {<boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
>>> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
>>> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
>>> fields>}, <No data fields>}, <No data fields>}, value = 0},
>>> replicationId =
>>> {<boost::equality_comparable<qpid::framing::SequenceNumber,
>>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>> =
>>> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
>>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t> >> =
>>> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::Se---Type <return> to continue, or q
>>> <return> to quit---
>>> quenceNumber, boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>>> boost::detail::true_t>> =
>>> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
>>> boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
>>> {<boost::incrementable<qpid::framing::SequenceNumber,
>>> boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
>>> {<boost::decrementable<qpid::framing::SequenceNumber,
>>> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
>>> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
>>> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
>>> fields>}, <No data fields>}, <No data fields>}, value = 0},
>>> isReplicationIdSet = false}, delivery = 0x0, disposition =
>>> 0, index = 14, tag = {size = 4, start = 0x7fffec227790 ""}, static
>>> TAG_WIDTH = 4, tagData = "\000\000\000\016"}
>>> __PRETTY_FUNCTION__ = "virtual void
>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)"
>>> #5 0x00007ffff423d358 in qpid::broker::amqp::Session::writable
>>> (this=0x7fffc8006bf0, link=0x7fffc80239a0, delivery=0x7fffdc000fe0)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Session.cpp:723
>>> sender = {_M_node = 0x7fffc80296a0}
>>> __PRETTY_FUNCTION__ = "void
>>> qpid::broker::amqp::Session::writable(pn_link_t*, pn_delivery_t*)"
>>> #6 0x00007ffff41e7667 in
>>> qpid::broker::amqp::Connection::doDeliveryUpdated (this=0x7fffc80047a8,
>>> delivery=0x7fffdc000fe0)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:665
>>> i = {_M_node = 0x7fffc8013b90}
>>> link = 0x7fffc80239a0
>>> __PRETTY_FUNCTION__ = "void
>>> qpid::broker::amqp::Connection::doDeliveryUpdated(pn_delivery_t*)"
>>> #7 0x00007ffff41e5863 in qpid::broker::amqp::Connection::process
>>> (this=0x7fffc80047a8) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:458
>>> __PRETTY_FUNCTION__ = "virtual void
>>> qpid::broker::amqp::Connection::process()"
>>> event = 0x7fffc8009680
>>> #8 0x00007ffff41e2ed4 in qpid::broker::amqp::Connection::decode
>>> (this=0x7fffc80047a8, buffer=0x7ffff7e27010 "", size=83)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:199
>>> now = 140737168171232
>>> __PRETTY_FUNCTION__ = "virtual size_t
>>> qpid::broker::amqp::Connection::decode(const char*, size_t)"
>>> n = 83
>>> #9 0x00007ffff42319ca in qpid::broker::amqp::Sasl::decode
>>> (this=0x7fffc8004740, buffer=0x7ffff7e27010 "", size=83)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Sasl.cpp:52
>>> decoded = 0
>>> total = 0
>>> __PRETTY_FUNCTION__ = "virtual size_t
>>> qpid::broker::amqp::Sasl::decode(const char*, size_t)"
>>> #10 0x00007ffff7233255 in qpid::sys::AsynchIOHandler::readbuff
>>> (this=0x7fffc8000b40, buff=0x7fffc8001960) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/AsynchIOHandler.cpp:138
>>> decoded = 0
>>> __PRETTY_FUNCTION__ = "void
>>> qpid::sys::AsynchIOHandler::readbuff(qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIO::BufferBase*)"
>>> #11 0x00007ffff7a6a3a8 in boost::_mfi::mf2<void,
>>> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000ce0,
>>> p=0x7fffc8000b40,
>>> a1=..., a2=0x7fffc8001960) at
>>> /usr/include/boost/bind/mem_fn_template.hpp:280
>>> No locals.
>>> #12 0x00007ffff7a691ac in
>>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>>> boost::arg<1>, boost::arg<2> >::operator()<boost::_mfi::mf2<void,
>>> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>, boost::_bi::list2<qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*&> > (this=0x7fffc8000cf0, f=..., a=...)
>>> at /usr/include/boost/bind/bind.hpp:392
>>> No locals.
>>> #13 0x00007ffff7a686ca in boost::_bi::bind_t<void,
>>> boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>,
>>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>>> boost::arg<1>, boost::arg<2> > >::operator()<qpid::sys::AsynchIO,
>>> qpid::sys::AsynchIOBufferBase*> (this=0x7fffc8000ce0, a1=...,
>>> a2=@0x7fffecea6708: 0x7fffc8001960) at
>>> /usr/include/boost/bind/bind_template.hpp:61
>>> ---Type <return> to continue, or q <return> to quit---
>>> a = {<boost::_bi::storage2<qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*&>> =
>>> {<boost::_bi::storage1<qpid::sys::AsynchIO&>> = {a1_ = @0x7fffc8000b80},
>>> a2_ = @0x7fffecea6708}, <No data fields>}
>>> #14 0x00007ffff7a67a58 in
>>> boost::detail::function::void_function_obj_invoker2<boost::_bi::bind_t<void,
>>> boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>,
>>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>>> boost::arg<1>, boost::arg<2> > >, void, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>::invoke (
>>> function_obj_ptr=..., a0=..., a1=0x7fffc8001960) at
>>> /usr/include/boost/function/function_template.hpp:153
>>> f = 0x7fffc8000ce0
>>> #15 0x00007ffff7196a2c in boost::function2<void, qpid::sys::AsynchIO&,
>>> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000cd8, a0=...,
>>> a1=0x7fffc8001960)
>>> at /usr/include/boost/function/function_template.hpp:767
>>> No locals.
>>> #16 0x00007ffff7193bef in qpid::sys::posix::AsynchIO::readable
>>> (this=0x7fffc8000b80, h=...) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/AsynchIO.cpp:453
>>> duration = 1
>>> buff = 0x7fffc8001960
>>> readCount = 65536
>>> rc = 83
>>> readStartTime = {timepoint = 110113377219333}
>>> total = 83
>>> readCalls = 1
>>> __PRETTY_FUNCTION__ = "void
>>> qpid::sys::posix::AsynchIO::readable(qpid::sys::DispatchHandle&)"
>>> #17 0x00007ffff719b858 in boost::_mfi::mf1<void,
>>> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>::operator()
>>> (this=0x7fffc8000ba0, p=0x7fffc8000b80, a1=...)
>>> at /usr/include/boost/bind/mem_fn_template.hpp:165
>>> No locals.
>>> #18 0x00007ffff719abe1 in
>>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>>> boost::arg<1> >::operator()<boost::_mfi::mf1<void,
>>> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
>>> boost::_bi::list1<qpid::sys::DispatchHandle&> > (this=0x7fffc8000bb0,
>>> f=..., a=...) at /usr/include/boost/bind/bind.hpp:313
>>> No locals.
>>> #19 0x00007ffff7199ec0 in boost::_bi::bind_t<void,
>>> boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
>>> qpid::sys::DispatchHandle&>,
>>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>>> boost::arg<1> > >::operator()<qpid::sys::DispatchHandle>
>>> (this=0x7fffc8000ba0, a1=...) at
>>> /usr/include/boost/bind/bind_template.hpp:32
>>> a = {<boost::_bi::storage1<qpid::sys::DispatchHandle&>> = {a1_ =
>>> @0x7fffc8000b88}, <No data fields>}
>>> #20 0x00007ffff7198ed4 in
>>> boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void,
>>> boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
>>> qpid::sys::DispatchHandle&>,
>>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>>> boost::arg<1> > >, void, qpid::sys::DispatchHandle&>::invoke
>>> (function_obj_ptr=..., a0=...)
>>> at /usr/include/boost/function/function_template.hpp:153
>>> f = 0x7fffc8000ba0
>>> #21 0x00007ffff7236fe3 in boost::function1<void,
>>> qpid::sys::DispatchHandle&>::operator() (this=0x7fffc8000b98, a0=...) at
>>> /usr/include/boost/function/function_template.hpp:767
>>> No locals.
>>> #22 0x00007ffff7236641 in qpid::sys::DispatchHandle::processEvent
>>> (this=0x7fffc8000b88, type=qpid::sys::Poller::READABLE)
>>> at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/DispatchHandle.cpp:280
>>> __PRETTY_FUNCTION__ = "virtual void
>>> qpid::sys::DispatchHandle::processEvent(qpid::sys::Poller::EventType)"
>>> #23 0x00007ffff71bd280 in qpid::sys::Poller::Event::process
>>> (this=0x7fffecea6c90) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Poller.h:131
>>> No locals.
>>> #24 0x00007ffff71bc5c6 in qpid::sys::Poller::run (this=0x680640) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/epoll/EpollPoller.cpp:522
>>> event = {handle = 0x7fffc8000b88, type =
>>> qpid::sys::Poller::READABLE}
>>> ss = {__val = {18446744067267100671, 18446744073709551615
>>> <repeats 15 times>}}
>>> __PRETTY_FUNCTION__ = "virtual void qpid::sys::Poller::run()"
>>> ---Type <return> to continue, or q <return> to quit---
>>> #25 0x00007ffff723537b in qpid::sys::Dispatcher::run
>>> (this=0x7fffffffdd10) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Dispatcher.cpp:37
>>> No locals.
>>> #26 0x00007ffff71b0b8d in qpid::sys::(anonymous namespace)::runRunnable
>>> (p=0x7fffffffdd10) at
>>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/Thread.cpp:35
>>> No locals.
>>> #27 0x00007ffff6859182 in start_thread (arg=0x7fffecea7700) at
>>> pthread_create.c:312
>>> __res = <optimized out>
>>> pd = 0x7fffecea7700
>>> now = <optimized out>
>>> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737168176896,
>>> 9029394154174007709, 1, 0, 140737168177600, 140737168176896,
>>> -9029431446891673187, -9029375100312499811},
>>> mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0},
>>> data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
>>> not_first_call = <optimized out>
>>> pagesize_m1 = <optimized out>
>>> sp = <optimized out>
>>> freesize = <optimized out>
>>> __PRETTY_FUNCTION__ = "start_thread"
>>> #28 0x00007ffff658647d in clone () at
>>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
>>> No locals.
>>>
>>>
>>>
>>>
>> Gordon,
>>
>> So as you can see above the record's delivery is indeed zero, as you had
>> suspected. I've done a little bit of digging around locally, printing out
>> the incoming delivery tags as well as the record chosen for the incoming
>> tag and am seeing that this crash occurs when there are two `handle` calls
>> in a row with the same index/delivery_tag:
>>
>> incoming delivery tag: 565, record delivery tag: 565
>> incoming delivery tag: 565, record delivery tag: 565
>> qpidd:
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:117:
>> virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>> Assertion `r.delivery == delivery' failed.
>>
>> Hope this helps, I'll keep looking around to see if I can figure out why
>> this happens in the first place.
>>
>> Matt
>>
>>
>>
> Last update for the night! The following trace log seems to indicate that
> four disposition frames are being sent for the same message. Am I right in
> reading this? That would certainly be an issue (though I believe the spec
> indicates that these should be ignored after the first one).
>
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @flow(19) [next-incoming-id=76,
> incoming-window=104, next-outgoing-id=38, outgoing-window=63, handle=2,
> link-credit=10, available=0, drain=false, echo=false, properties={}]
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @disposition(21) [role=true,
> first=75, last=75, settled=true, state=@accepted(36) [], batchable=false]
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @flow(19) [next-incoming-id=76,
> incoming-window=105, next-outgoing-id=38, outgoing-window=63, handle=3,
> link-credit=64, available=0, drain=false, echo=false, properties={}]
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @disposition(21) [role=true,
> first=75, last=75, settled=true, state=@accepted(36) [], batchable=false]
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @disposition(21) [role=true,
> first=75, last=75, settled=true, state=@accepted(36) [], batchable=false]
> 2016-01-21 02:51:48 [Protocol] trace
> [qpid.127.0.0.1:5672-127.0.0.1:43203]: 1 <- @disposition(21) [role=true,
> first=75, last=75, settled=true, state=@accepted(36) [], batchable=false]
> 2016-01-21 02:51:48 [Network] debug qpid.127.0.0.1:5672-127.0.0.1:43203
> decoded 166 bytes from 166
> 2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
> process()
> 2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
> handling outgoing delivery for 0x7fffd4055010 on session 0x7fffd4044a30
> 2016-01-21 02:51:48 [Broker] debug clean(): 0 messages remain; head is now
> 0
> 2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
> handling outgoing delivery for 0x7fffd4055010 on session 0x7fffd4044a30
>
> qpidd:
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:117:
> virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
> Assertion `r.delivery == delivery' failed.
>
> Program received signal SIGABRT, Aborted.
> 0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:56
> 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> (gdb)
>
>
It looks like that was the problem after all, I had a bug in my code that
was sending back disposition frames for every object contained in a bulk
message. This seems to solve the problem on my end, but I think this is
probably still a bug in qpidd. Sorry for the (ton of) noise!
> Matt
>
>
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Wed, Jan 20, 2016 at 8:31 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Wed, Jan 20, 2016 at 6:52 PM, Matt Broadstone <mb...@gmail.com>
> wrote:
>
>> On Wed, Jan 20, 2016 at 6:10 PM, Matt Broadstone <mb...@gmail.com>
>> wrote:
>>
>>> On Tue, Jan 12, 2016 at 8:39 AM, Matt Broadstone <mb...@gmail.com>
>>> wrote:
>>>
>>>> On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
>>>>
>>>>> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>>>>>
>>>>>> Looks like I did just get a valid assertion, but I'm not even clear
>>>>>> anymore
>>>>>> whether this is related to the initially reported bug (since we're
>>>>>> trying
>>>>>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>>>>>
>>>>>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head
>>>>>> is now 0
>>>>>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1
>>>>>> :56687
>>>>>> handling outgoing delivery for 0x7f3fdc262590 on session
>>>>>> 0x7f3fdc111650
>>>>>> qpidd:
>>>>>>
>>>>>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>>>>>> virtual void
>>>>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>>>>>> Assertion `r.delivery == delivery' failed.
>>>>>>
>>>>>
>>>>> Do you have the core for that? If so can you check the values of
>>>>> 'delivery' and 'r.delivery'? Is either of them 0?
>>>>>
>>>>>
>>>>>
>>>> Hi Gordon,
>>>> I unfortunately don't have access to the box at the moment (and won't
>>>> for a few hours, if its even still in a reproducible state), but I'll try
>>>> to get a core next time. In the meantime, do you have any ideas for values
>>>> I should check on the sending side that might cause this? I can certainly
>>>> look through all of that code and see if I can make a smaller case that
>>>> exhibits this behavior.
>>>>
>>>> Matt
>>>>
>>>>
>>>
>>> Hi Gordon,
>>> Just got this again, and I'm (sort of) able to reproduce it. I have a
>>> core file for you, if you'd like me to mail it directly to you? Do you have
>>> any thoughts on what could cause the problem in the first place? This is
>>> really hanging us up over here unfortunately..
>>>
>>> Regards,
>>> Matt
>>>
>>>
>>>
>>
>> Gordon,
>>
>> Here is the full backtrace:
>>
>> (gdb) bt full
>> #0 0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
>> ../nptl/sysdeps/unix/sysv/linux/raise.c:56
>> resultvar = 0
>> pid = 18195
>> selftid = 18207
>> #1 0x00007ffff64c60d8 in __GI_abort () at abort.c:89
>> save_stage = 2
>> act = {__sigaction_handler = {sa_handler = 0x7fffffffe8e0,
>> sa_sigaction = 0x7fffffffe8e0}, sa_mask = {__val = {140737326910748,
>> 140737289582424, 115, 140737168167888,
>> 140737325552867, 4294967296, 140737168167840, 3974779888,
>> 140737289033565, 140737155069744, 0, 0, 0, 21474836480, 140737354080256,
>> 140737326925872}}, sa_flags = -198772828,
>> sa_restorer = 0x7ffff4270020
>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>}
>> sigs = {__val = {32, 0 <repeats 15 times>}}
>> #2 0x00007ffff64bbb86 in __assert_fail_base (fmt=0x7ffff660c830
>> "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7ffff426f7a4
>> "r.delivery == delivery",
>> file=file@entry=0x7ffff426f758
>> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
>> line=line@entry=115,
>> function=function@entry=0x7ffff4270020
>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
>> "virtual void
>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
>> assert.c:92
>> str = 0x7fffc80c0d90 ""
>> total = 4096
>> #3 0x00007ffff64bbc32 in __GI___assert_fail (assertion=0x7ffff426f7a4
>> "r.delivery == delivery",
>> file=0x7ffff426f758
>> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
>> line=115,
>> function=0x7ffff4270020
>> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
>> "virtual void
>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
>> assert.c:101
>> No locals.
>> #4 0x00007ffff4226e73 in qpid::broker::amqp::OutgoingFromQueue::handle
>> (this=0x7fffc8029160, delivery=0x7fffdc000fe0)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:115
>> txn = {first = 0x0, second = 0}
>> i = 14
>> r = @0x7fffec227718: {cursor = {type = qpid::broker::CONSUMER,
>> position = 0, version = 0, valid = false, context = {px = 0x0, pn = {pi_ =
>> 0x0}}}, msg = {sharedState = {px = 0x0},
>> persistentContext = {px = 0x0}, deliveryCount = -1,
>> alreadyAcquired = false, annotations = {value = {px = 0x0}}, state =
>> (unknown: 3690991584),
>> sequence =
>> {<boost::equality_comparable<qpid::framing::SequenceNumber,
>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>> =
>> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t> >> =
>> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>> =
>> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
>> {<boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
>> {<boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
>> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
>> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
>> fields>}, <No data fields>}, <No data fields>}, value = 0},
>> replicationId =
>> {<boost::equality_comparable<qpid::framing::SequenceNumber,
>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>> =
>> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
>> boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t> >> =
>> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::Se---Type <return> to continue, or q
>> <return> to quit---
>> quenceNumber, boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
>> boost::detail::empty_base<qpid::framing::SequenceNumber>,
>> boost::detail::true_t>> =
>> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
>> boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
>> {<boost::incrementable<qpid::framing::SequenceNumber,
>> boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
>> {<boost::decrementable<qpid::framing::SequenceNumber,
>> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
>> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
>> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
>> fields>}, <No data fields>}, <No data fields>}, value = 0},
>> isReplicationIdSet = false}, delivery = 0x0, disposition = 0,
>> index = 14, tag = {size = 4, start = 0x7fffec227790 ""}, static TAG_WIDTH =
>> 4, tagData = "\000\000\000\016"}
>> __PRETTY_FUNCTION__ = "virtual void
>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)"
>> #5 0x00007ffff423d358 in qpid::broker::amqp::Session::writable
>> (this=0x7fffc8006bf0, link=0x7fffc80239a0, delivery=0x7fffdc000fe0)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Session.cpp:723
>> sender = {_M_node = 0x7fffc80296a0}
>> __PRETTY_FUNCTION__ = "void
>> qpid::broker::amqp::Session::writable(pn_link_t*, pn_delivery_t*)"
>> #6 0x00007ffff41e7667 in
>> qpid::broker::amqp::Connection::doDeliveryUpdated (this=0x7fffc80047a8,
>> delivery=0x7fffdc000fe0)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:665
>> i = {_M_node = 0x7fffc8013b90}
>> link = 0x7fffc80239a0
>> __PRETTY_FUNCTION__ = "void
>> qpid::broker::amqp::Connection::doDeliveryUpdated(pn_delivery_t*)"
>> #7 0x00007ffff41e5863 in qpid::broker::amqp::Connection::process
>> (this=0x7fffc80047a8) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:458
>> __PRETTY_FUNCTION__ = "virtual void
>> qpid::broker::amqp::Connection::process()"
>> event = 0x7fffc8009680
>> #8 0x00007ffff41e2ed4 in qpid::broker::amqp::Connection::decode
>> (this=0x7fffc80047a8, buffer=0x7ffff7e27010 "", size=83)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:199
>> now = 140737168171232
>> __PRETTY_FUNCTION__ = "virtual size_t
>> qpid::broker::amqp::Connection::decode(const char*, size_t)"
>> n = 83
>> #9 0x00007ffff42319ca in qpid::broker::amqp::Sasl::decode
>> (this=0x7fffc8004740, buffer=0x7ffff7e27010 "", size=83)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Sasl.cpp:52
>> decoded = 0
>> total = 0
>> __PRETTY_FUNCTION__ = "virtual size_t
>> qpid::broker::amqp::Sasl::decode(const char*, size_t)"
>> #10 0x00007ffff7233255 in qpid::sys::AsynchIOHandler::readbuff
>> (this=0x7fffc8000b40, buff=0x7fffc8001960) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/AsynchIOHandler.cpp:138
>> decoded = 0
>> __PRETTY_FUNCTION__ = "void
>> qpid::sys::AsynchIOHandler::readbuff(qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIO::BufferBase*)"
>> #11 0x00007ffff7a6a3a8 in boost::_mfi::mf2<void,
>> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000ce0,
>> p=0x7fffc8000b40,
>> a1=..., a2=0x7fffc8001960) at
>> /usr/include/boost/bind/mem_fn_template.hpp:280
>> No locals.
>> #12 0x00007ffff7a691ac in
>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>> boost::arg<1>, boost::arg<2> >::operator()<boost::_mfi::mf2<void,
>> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>, boost::_bi::list2<qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*&> > (this=0x7fffc8000cf0, f=..., a=...)
>> at /usr/include/boost/bind/bind.hpp:392
>> No locals.
>> #13 0x00007ffff7a686ca in boost::_bi::bind_t<void, boost::_mfi::mf2<void,
>> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>,
>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>> boost::arg<1>, boost::arg<2> > >::operator()<qpid::sys::AsynchIO,
>> qpid::sys::AsynchIOBufferBase*> (this=0x7fffc8000ce0, a1=...,
>> a2=@0x7fffecea6708: 0x7fffc8001960) at
>> /usr/include/boost/bind/bind_template.hpp:61
>> ---Type <return> to continue, or q <return> to quit---
>> a = {<boost::_bi::storage2<qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*&>> =
>> {<boost::_bi::storage1<qpid::sys::AsynchIO&>> = {a1_ = @0x7fffc8000b80},
>> a2_ = @0x7fffecea6708}, <No data fields>}
>> #14 0x00007ffff7a67a58 in
>> boost::detail::function::void_function_obj_invoker2<boost::_bi::bind_t<void,
>> boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>,
>> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
>> boost::arg<1>, boost::arg<2> > >, void, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>::invoke (
>> function_obj_ptr=..., a0=..., a1=0x7fffc8001960) at
>> /usr/include/boost/function/function_template.hpp:153
>> f = 0x7fffc8000ce0
>> #15 0x00007ffff7196a2c in boost::function2<void, qpid::sys::AsynchIO&,
>> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000cd8, a0=...,
>> a1=0x7fffc8001960)
>> at /usr/include/boost/function/function_template.hpp:767
>> No locals.
>> #16 0x00007ffff7193bef in qpid::sys::posix::AsynchIO::readable
>> (this=0x7fffc8000b80, h=...) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/AsynchIO.cpp:453
>> duration = 1
>> buff = 0x7fffc8001960
>> readCount = 65536
>> rc = 83
>> readStartTime = {timepoint = 110113377219333}
>> total = 83
>> readCalls = 1
>> __PRETTY_FUNCTION__ = "void
>> qpid::sys::posix::AsynchIO::readable(qpid::sys::DispatchHandle&)"
>> #17 0x00007ffff719b858 in boost::_mfi::mf1<void,
>> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>::operator()
>> (this=0x7fffc8000ba0, p=0x7fffc8000b80, a1=...)
>> at /usr/include/boost/bind/mem_fn_template.hpp:165
>> No locals.
>> #18 0x00007ffff719abe1 in
>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>> boost::arg<1> >::operator()<boost::_mfi::mf1<void,
>> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
>> boost::_bi::list1<qpid::sys::DispatchHandle&> > (this=0x7fffc8000bb0,
>> f=..., a=...) at /usr/include/boost/bind/bind.hpp:313
>> No locals.
>> #19 0x00007ffff7199ec0 in boost::_bi::bind_t<void, boost::_mfi::mf1<void,
>> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>> boost::arg<1> > >::operator()<qpid::sys::DispatchHandle>
>> (this=0x7fffc8000ba0, a1=...) at
>> /usr/include/boost/bind/bind_template.hpp:32
>> a = {<boost::_bi::storage1<qpid::sys::DispatchHandle&>> = {a1_ =
>> @0x7fffc8000b88}, <No data fields>}
>> #20 0x00007ffff7198ed4 in
>> boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void,
>> boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
>> qpid::sys::DispatchHandle&>,
>> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
>> boost::arg<1> > >, void, qpid::sys::DispatchHandle&>::invoke
>> (function_obj_ptr=..., a0=...)
>> at /usr/include/boost/function/function_template.hpp:153
>> f = 0x7fffc8000ba0
>> #21 0x00007ffff7236fe3 in boost::function1<void,
>> qpid::sys::DispatchHandle&>::operator() (this=0x7fffc8000b98, a0=...) at
>> /usr/include/boost/function/function_template.hpp:767
>> No locals.
>> #22 0x00007ffff7236641 in qpid::sys::DispatchHandle::processEvent
>> (this=0x7fffc8000b88, type=qpid::sys::Poller::READABLE)
>> at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/DispatchHandle.cpp:280
>> __PRETTY_FUNCTION__ = "virtual void
>> qpid::sys::DispatchHandle::processEvent(qpid::sys::Poller::EventType)"
>> #23 0x00007ffff71bd280 in qpid::sys::Poller::Event::process
>> (this=0x7fffecea6c90) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Poller.h:131
>> No locals.
>> #24 0x00007ffff71bc5c6 in qpid::sys::Poller::run (this=0x680640) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/epoll/EpollPoller.cpp:522
>> event = {handle = 0x7fffc8000b88, type =
>> qpid::sys::Poller::READABLE}
>> ss = {__val = {18446744067267100671, 18446744073709551615
>> <repeats 15 times>}}
>> __PRETTY_FUNCTION__ = "virtual void qpid::sys::Poller::run()"
>> ---Type <return> to continue, or q <return> to quit---
>> #25 0x00007ffff723537b in qpid::sys::Dispatcher::run
>> (this=0x7fffffffdd10) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Dispatcher.cpp:37
>> No locals.
>> #26 0x00007ffff71b0b8d in qpid::sys::(anonymous namespace)::runRunnable
>> (p=0x7fffffffdd10) at
>> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/Thread.cpp:35
>> No locals.
>> #27 0x00007ffff6859182 in start_thread (arg=0x7fffecea7700) at
>> pthread_create.c:312
>> __res = <optimized out>
>> pd = 0x7fffecea7700
>> now = <optimized out>
>> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737168176896,
>> 9029394154174007709, 1, 0, 140737168177600, 140737168176896,
>> -9029431446891673187, -9029375100312499811},
>> mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0},
>> data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
>> not_first_call = <optimized out>
>> pagesize_m1 = <optimized out>
>> sp = <optimized out>
>> freesize = <optimized out>
>> __PRETTY_FUNCTION__ = "start_thread"
>> #28 0x00007ffff658647d in clone () at
>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
>> No locals.
>>
>>
>>
>>
> Gordon,
>
> So as you can see above the record's delivery is indeed zero, as you had
> suspected. I've done a little bit of digging around locally, printing out
> the incoming delivery tags as well as the record chosen for the incoming
> tag and am seeing that this crash occurs when there are two `handle` calls
> in a row with the same index/delivery_tag:
>
> incoming delivery tag: 565, record delivery tag: 565
> incoming delivery tag: 565, record delivery tag: 565
> qpidd:
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:117:
> virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
> Assertion `r.delivery == delivery' failed.
>
> Hope this helps, I'll keep looking around to see if I can figure out why
> this happens in the first place.
>
> Matt
>
>
>
Last update for the night! The following trace log seems to indicate that
four disposition frames are being sent for the same message. Am I right in
reading this? That would certainly be an issue (though I believe the spec
indicates that these should be ignored after the first one).
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @flow(19) [next-incoming-id=76, incoming-window=104,
next-outgoing-id=38, outgoing-window=63, handle=2, link-credit=10,
available=0, drain=false, echo=false, properties={}]
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @disposition(21) [role=true, first=75, last=75, settled=true,
state=@accepted(36) [], batchable=false]
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @flow(19) [next-incoming-id=76, incoming-window=105,
next-outgoing-id=38, outgoing-window=63, handle=3, link-credit=64,
available=0, drain=false, echo=false, properties={}]
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @disposition(21) [role=true, first=75, last=75, settled=true,
state=@accepted(36) [], batchable=false]
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @disposition(21) [role=true, first=75, last=75, settled=true,
state=@accepted(36) [], batchable=false]
2016-01-21 02:51:48 [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:43203]:
1 <- @disposition(21) [role=true, first=75, last=75, settled=true,
state=@accepted(36) [], batchable=false]
2016-01-21 02:51:48 [Network] debug qpid.127.0.0.1:5672-127.0.0.1:43203
decoded 166 bytes from 166
2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
process()
2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
handling outgoing delivery for 0x7fffd4055010 on session 0x7fffd4044a30
2016-01-21 02:51:48 [Broker] debug clean(): 0 messages remain; head is now 0
2016-01-21 02:51:48 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:43203
handling outgoing delivery for 0x7fffd4055010 on session 0x7fffd4044a30
qpidd:
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:117:
virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
Assertion `r.delivery == delivery' failed.
Program received signal SIGABRT, Aborted.
0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:56
56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb)
Matt
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Wed, Jan 20, 2016 at 6:52 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Wed, Jan 20, 2016 at 6:10 PM, Matt Broadstone <mb...@gmail.com>
> wrote:
>
>> On Tue, Jan 12, 2016 at 8:39 AM, Matt Broadstone <mb...@gmail.com>
>> wrote:
>>
>>> On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
>>>
>>>> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>>>>
>>>>> Looks like I did just get a valid assertion, but I'm not even clear
>>>>> anymore
>>>>> whether this is related to the initially reported bug (since we're
>>>>> trying
>>>>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>>>>
>>>>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is
>>>>> now 0
>>>>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
>>>>> handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
>>>>> qpidd:
>>>>>
>>>>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>>>>> virtual void
>>>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>>>>> Assertion `r.delivery == delivery' failed.
>>>>>
>>>>
>>>> Do you have the core for that? If so can you check the values of
>>>> 'delivery' and 'r.delivery'? Is either of them 0?
>>>>
>>>>
>>>>
>>> Hi Gordon,
>>> I unfortunately don't have access to the box at the moment (and won't
>>> for a few hours, if its even still in a reproducible state), but I'll try
>>> to get a core next time. In the meantime, do you have any ideas for values
>>> I should check on the sending side that might cause this? I can certainly
>>> look through all of that code and see if I can make a smaller case that
>>> exhibits this behavior.
>>>
>>> Matt
>>>
>>>
>>
>> Hi Gordon,
>> Just got this again, and I'm (sort of) able to reproduce it. I have a
>> core file for you, if you'd like me to mail it directly to you? Do you have
>> any thoughts on what could cause the problem in the first place? This is
>> really hanging us up over here unfortunately..
>>
>> Regards,
>> Matt
>>
>>
>>
>
> Gordon,
>
> Here is the full backtrace:
>
> (gdb) bt full
> #0 0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:56
> resultvar = 0
> pid = 18195
> selftid = 18207
> #1 0x00007ffff64c60d8 in __GI_abort () at abort.c:89
> save_stage = 2
> act = {__sigaction_handler = {sa_handler = 0x7fffffffe8e0,
> sa_sigaction = 0x7fffffffe8e0}, sa_mask = {__val = {140737326910748,
> 140737289582424, 115, 140737168167888,
> 140737325552867, 4294967296, 140737168167840, 3974779888,
> 140737289033565, 140737155069744, 0, 0, 0, 21474836480, 140737354080256,
> 140737326925872}}, sa_flags = -198772828,
> sa_restorer = 0x7ffff4270020
> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>}
> sigs = {__val = {32, 0 <repeats 15 times>}}
> #2 0x00007ffff64bbb86 in __assert_fail_base (fmt=0x7ffff660c830
> "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7ffff426f7a4
> "r.delivery == delivery",
> file=file@entry=0x7ffff426f758
> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
> line=line@entry=115,
> function=function@entry=0x7ffff4270020
> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
> "virtual void
> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
> assert.c:92
> str = 0x7fffc80c0d90 ""
> total = 4096
> #3 0x00007ffff64bbc32 in __GI___assert_fail (assertion=0x7ffff426f7a4
> "r.delivery == delivery",
> file=0x7ffff426f758
> "/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
> line=115,
> function=0x7ffff4270020
> <qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
> "virtual void
> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
> assert.c:101
> No locals.
> #4 0x00007ffff4226e73 in qpid::broker::amqp::OutgoingFromQueue::handle
> (this=0x7fffc8029160, delivery=0x7fffdc000fe0)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:115
> txn = {first = 0x0, second = 0}
> i = 14
> r = @0x7fffec227718: {cursor = {type = qpid::broker::CONSUMER,
> position = 0, version = 0, valid = false, context = {px = 0x0, pn = {pi_ =
> 0x0}}}, msg = {sharedState = {px = 0x0},
> persistentContext = {px = 0x0}, deliveryCount = -1,
> alreadyAcquired = false, annotations = {value = {px = 0x0}}, state =
> (unknown: 3690991584),
> sequence =
> {<boost::equality_comparable<qpid::framing::SequenceNumber,
> boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>> =
> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
> boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t> >> =
> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>> =
> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
> {<boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
> {<boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
> fields>}, <No data fields>}, <No data fields>}, value = 0},
> replicationId =
> {<boost::equality_comparable<qpid::framing::SequenceNumber,
> boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>> =
> {<boost::equality_comparable1<qpid::framing::SequenceNumber,
> boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t> >> =
> {<boost::less_than_comparable<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::Se---Type <return> to continue, or q
> <return> to quit---
> quenceNumber, boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
> boost::detail::empty_base<qpid::framing::SequenceNumber>,
> boost::detail::true_t>> =
> {<boost::less_than_comparable1<qpid::framing::SequenceNumber,
> boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
> {<boost::incrementable<qpid::framing::SequenceNumber,
> boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
> {<boost::decrementable<qpid::framing::SequenceNumber,
> boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
> {<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
> fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
> fields>}, <No data fields>}, <No data fields>}, value = 0},
> isReplicationIdSet = false}, delivery = 0x0, disposition = 0,
> index = 14, tag = {size = 4, start = 0x7fffec227790 ""}, static TAG_WIDTH =
> 4, tagData = "\000\000\000\016"}
> __PRETTY_FUNCTION__ = "virtual void
> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)"
> #5 0x00007ffff423d358 in qpid::broker::amqp::Session::writable
> (this=0x7fffc8006bf0, link=0x7fffc80239a0, delivery=0x7fffdc000fe0)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Session.cpp:723
> sender = {_M_node = 0x7fffc80296a0}
> __PRETTY_FUNCTION__ = "void
> qpid::broker::amqp::Session::writable(pn_link_t*, pn_delivery_t*)"
> #6 0x00007ffff41e7667 in
> qpid::broker::amqp::Connection::doDeliveryUpdated (this=0x7fffc80047a8,
> delivery=0x7fffdc000fe0)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:665
> i = {_M_node = 0x7fffc8013b90}
> link = 0x7fffc80239a0
> __PRETTY_FUNCTION__ = "void
> qpid::broker::amqp::Connection::doDeliveryUpdated(pn_delivery_t*)"
> #7 0x00007ffff41e5863 in qpid::broker::amqp::Connection::process
> (this=0x7fffc80047a8) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:458
> __PRETTY_FUNCTION__ = "virtual void
> qpid::broker::amqp::Connection::process()"
> event = 0x7fffc8009680
> #8 0x00007ffff41e2ed4 in qpid::broker::amqp::Connection::decode
> (this=0x7fffc80047a8, buffer=0x7ffff7e27010 "", size=83)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:199
> now = 140737168171232
> __PRETTY_FUNCTION__ = "virtual size_t
> qpid::broker::amqp::Connection::decode(const char*, size_t)"
> n = 83
> #9 0x00007ffff42319ca in qpid::broker::amqp::Sasl::decode
> (this=0x7fffc8004740, buffer=0x7ffff7e27010 "", size=83)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Sasl.cpp:52
> decoded = 0
> total = 0
> __PRETTY_FUNCTION__ = "virtual size_t
> qpid::broker::amqp::Sasl::decode(const char*, size_t)"
> #10 0x00007ffff7233255 in qpid::sys::AsynchIOHandler::readbuff
> (this=0x7fffc8000b40, buff=0x7fffc8001960) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/AsynchIOHandler.cpp:138
> decoded = 0
> __PRETTY_FUNCTION__ = "void
> qpid::sys::AsynchIOHandler::readbuff(qpid::sys::AsynchIO&,
> qpid::sys::AsynchIO::BufferBase*)"
> #11 0x00007ffff7a6a3a8 in boost::_mfi::mf2<void,
> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000ce0,
> p=0x7fffc8000b40,
> a1=..., a2=0x7fffc8001960) at
> /usr/include/boost/bind/mem_fn_template.hpp:280
> No locals.
> #12 0x00007ffff7a691ac in
> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
> boost::arg<1>, boost::arg<2> >::operator()<boost::_mfi::mf2<void,
> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>, boost::_bi::list2<qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*&> > (this=0x7fffc8000cf0, f=..., a=...)
> at /usr/include/boost/bind/bind.hpp:392
> No locals.
> #13 0x00007ffff7a686ca in boost::_bi::bind_t<void, boost::_mfi::mf2<void,
> qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>,
> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
> boost::arg<1>, boost::arg<2> > >::operator()<qpid::sys::AsynchIO,
> qpid::sys::AsynchIOBufferBase*> (this=0x7fffc8000ce0, a1=...,
> a2=@0x7fffecea6708: 0x7fffc8001960) at
> /usr/include/boost/bind/bind_template.hpp:61
> ---Type <return> to continue, or q <return> to quit---
> a = {<boost::_bi::storage2<qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*&>> =
> {<boost::_bi::storage1<qpid::sys::AsynchIO&>> = {a1_ = @0x7fffc8000b80},
> a2_ = @0x7fffecea6708}, <No data fields>}
> #14 0x00007ffff7a67a58 in
> boost::detail::function::void_function_obj_invoker2<boost::_bi::bind_t<void,
> boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>,
> boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
> boost::arg<1>, boost::arg<2> > >, void, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>::invoke (
> function_obj_ptr=..., a0=..., a1=0x7fffc8001960) at
> /usr/include/boost/function/function_template.hpp:153
> f = 0x7fffc8000ce0
> #15 0x00007ffff7196a2c in boost::function2<void, qpid::sys::AsynchIO&,
> qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000cd8, a0=...,
> a1=0x7fffc8001960)
> at /usr/include/boost/function/function_template.hpp:767
> No locals.
> #16 0x00007ffff7193bef in qpid::sys::posix::AsynchIO::readable
> (this=0x7fffc8000b80, h=...) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/AsynchIO.cpp:453
> duration = 1
> buff = 0x7fffc8001960
> readCount = 65536
> rc = 83
> readStartTime = {timepoint = 110113377219333}
> total = 83
> readCalls = 1
> __PRETTY_FUNCTION__ = "void
> qpid::sys::posix::AsynchIO::readable(qpid::sys::DispatchHandle&)"
> #17 0x00007ffff719b858 in boost::_mfi::mf1<void,
> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>::operator()
> (this=0x7fffc8000ba0, p=0x7fffc8000b80, a1=...)
> at /usr/include/boost/bind/mem_fn_template.hpp:165
> No locals.
> #18 0x00007ffff719abe1 in
> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
> boost::arg<1> >::operator()<boost::_mfi::mf1<void,
> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
> boost::_bi::list1<qpid::sys::DispatchHandle&> > (this=0x7fffc8000bb0,
> f=..., a=...) at /usr/include/boost/bind/bind.hpp:313
> No locals.
> #19 0x00007ffff7199ec0 in boost::_bi::bind_t<void, boost::_mfi::mf1<void,
> qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
> boost::arg<1> > >::operator()<qpid::sys::DispatchHandle>
> (this=0x7fffc8000ba0, a1=...) at
> /usr/include/boost/bind/bind_template.hpp:32
> a = {<boost::_bi::storage1<qpid::sys::DispatchHandle&>> = {a1_ =
> @0x7fffc8000b88}, <No data fields>}
> #20 0x00007ffff7198ed4 in
> boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void,
> boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
> qpid::sys::DispatchHandle&>,
> boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
> boost::arg<1> > >, void, qpid::sys::DispatchHandle&>::invoke
> (function_obj_ptr=..., a0=...)
> at /usr/include/boost/function/function_template.hpp:153
> f = 0x7fffc8000ba0
> #21 0x00007ffff7236fe3 in boost::function1<void,
> qpid::sys::DispatchHandle&>::operator() (this=0x7fffc8000b98, a0=...) at
> /usr/include/boost/function/function_template.hpp:767
> No locals.
> #22 0x00007ffff7236641 in qpid::sys::DispatchHandle::processEvent
> (this=0x7fffc8000b88, type=qpid::sys::Poller::READABLE)
> at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/DispatchHandle.cpp:280
> __PRETTY_FUNCTION__ = "virtual void
> qpid::sys::DispatchHandle::processEvent(qpid::sys::Poller::EventType)"
> #23 0x00007ffff71bd280 in qpid::sys::Poller::Event::process
> (this=0x7fffecea6c90) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Poller.h:131
> No locals.
> #24 0x00007ffff71bc5c6 in qpid::sys::Poller::run (this=0x680640) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/epoll/EpollPoller.cpp:522
> event = {handle = 0x7fffc8000b88, type =
> qpid::sys::Poller::READABLE}
> ss = {__val = {18446744067267100671, 18446744073709551615 <repeats
> 15 times>}}
> __PRETTY_FUNCTION__ = "virtual void qpid::sys::Poller::run()"
> ---Type <return> to continue, or q <return> to quit---
> #25 0x00007ffff723537b in qpid::sys::Dispatcher::run (this=0x7fffffffdd10)
> at /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Dispatcher.cpp:37
> No locals.
> #26 0x00007ffff71b0b8d in qpid::sys::(anonymous namespace)::runRunnable
> (p=0x7fffffffdd10) at
> /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/Thread.cpp:35
> No locals.
> #27 0x00007ffff6859182 in start_thread (arg=0x7fffecea7700) at
> pthread_create.c:312
> __res = <optimized out>
> pd = 0x7fffecea7700
> now = <optimized out>
> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737168176896,
> 9029394154174007709, 1, 0, 140737168177600, 140737168176896,
> -9029431446891673187, -9029375100312499811},
> mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0},
> data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
> not_first_call = <optimized out>
> pagesize_m1 = <optimized out>
> sp = <optimized out>
> freesize = <optimized out>
> __PRETTY_FUNCTION__ = "start_thread"
> #28 0x00007ffff658647d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
> No locals.
>
>
>
>
Gordon,
So as you can see above the record's delivery is indeed zero, as you had
suspected. I've done a little bit of digging around locally, printing out
the incoming delivery tags as well as the record chosen for the incoming
tag and am seeing that this crash occurs when there are two `handle` calls
in a row with the same index/delivery_tag:
incoming delivery tag: 565, record delivery tag: 565
incoming delivery tag: 565, record delivery tag: 565
qpidd:
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:117:
virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
Assertion `r.delivery == delivery' failed.
Hope this helps, I'll keep looking around to see if I can figure out why
this happens in the first place.
Matt
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Wed, Jan 20, 2016 at 6:10 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Tue, Jan 12, 2016 at 8:39 AM, Matt Broadstone <mb...@gmail.com>
> wrote:
>
>> On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
>>
>>> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>>>
>>>> Looks like I did just get a valid assertion, but I'm not even clear
>>>> anymore
>>>> whether this is related to the initially reported bug (since we're
>>>> trying
>>>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>>>
>>>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is
>>>> now 0
>>>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
>>>> handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
>>>> qpidd:
>>>>
>>>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>>>> virtual void
>>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>>>> Assertion `r.delivery == delivery' failed.
>>>>
>>>
>>> Do you have the core for that? If so can you check the values of
>>> 'delivery' and 'r.delivery'? Is either of them 0?
>>>
>>>
>>>
>> Hi Gordon,
>> I unfortunately don't have access to the box at the moment (and won't for
>> a few hours, if its even still in a reproducible state), but I'll try to
>> get a core next time. In the meantime, do you have any ideas for values I
>> should check on the sending side that might cause this? I can certainly
>> look through all of that code and see if I can make a smaller case that
>> exhibits this behavior.
>>
>> Matt
>>
>>
>
> Hi Gordon,
> Just got this again, and I'm (sort of) able to reproduce it. I have a core
> file for you, if you'd like me to mail it directly to you? Do you have any
> thoughts on what could cause the problem in the first place? This is really
> hanging us up over here unfortunately..
>
> Regards,
> Matt
>
>
>
Gordon,
Here is the full backtrace:
(gdb) bt full
#0 0x00007ffff64c2cc9 in __GI_raise (sig=sig@entry=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:56
resultvar = 0
pid = 18195
selftid = 18207
#1 0x00007ffff64c60d8 in __GI_abort () at abort.c:89
save_stage = 2
act = {__sigaction_handler = {sa_handler = 0x7fffffffe8e0,
sa_sigaction = 0x7fffffffe8e0}, sa_mask = {__val = {140737326910748,
140737289582424, 115, 140737168167888,
140737325552867, 4294967296, 140737168167840, 3974779888,
140737289033565, 140737155069744, 0, 0, 0, 21474836480, 140737354080256,
140737326925872}}, sa_flags = -198772828,
sa_restorer = 0x7ffff4270020
<qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007ffff64bbb86 in __assert_fail_base (fmt=0x7ffff660c830
"%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
assertion=assertion@entry=0x7ffff426f7a4
"r.delivery == delivery",
file=file@entry=0x7ffff426f758
"/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
line=line@entry=115,
function=function@entry=0x7ffff4270020
<qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
"virtual void
qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
assert.c:92
str = 0x7fffc80c0d90 ""
total = 4096
#3 0x00007ffff64bbc32 in __GI___assert_fail (assertion=0x7ffff426f7a4
"r.delivery == delivery",
file=0x7ffff426f758
"/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp",
line=115,
function=0x7ffff4270020
<qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)::__PRETTY_FUNCTION__>
"virtual void
qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)") at
assert.c:101
No locals.
#4 0x00007ffff4226e73 in qpid::broker::amqp::OutgoingFromQueue::handle
(this=0x7fffc8029160, delivery=0x7fffdc000fe0)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Outgoing.cpp:115
txn = {first = 0x0, second = 0}
i = 14
r = @0x7fffec227718: {cursor = {type = qpid::broker::CONSUMER,
position = 0, version = 0, valid = false, context = {px = 0x0, pn = {pi_ =
0x0}}}, msg = {sharedState = {px = 0x0},
persistentContext = {px = 0x0}, deliveryCount = -1,
alreadyAcquired = false, annotations = {value = {px = 0x0}}, state =
(unknown: 3690991584),
sequence =
{<boost::equality_comparable<qpid::framing::SequenceNumber,
boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>> =
{<boost::equality_comparable1<qpid::framing::SequenceNumber,
boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t> >> =
{<boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>> =
{<boost::less_than_comparable1<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
{<boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
{<boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
{<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
fields>}, <No data fields>}, <No data fields>}, value = 0},
replicationId =
{<boost::equality_comparable<qpid::framing::SequenceNumber,
boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>> =
{<boost::equality_comparable1<qpid::framing::SequenceNumber,
boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t> >> =
{<boost::less_than_comparable<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::Se---Type <return> to continue, or q
<return> to quit---
quenceNumber, boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >,
boost::detail::empty_base<qpid::framing::SequenceNumber>,
boost::detail::true_t>> =
{<boost::less_than_comparable1<qpid::framing::SequenceNumber,
boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > > >> =
{<boost::incrementable<qpid::framing::SequenceNumber,
boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> > >> =
{<boost::decrementable<qpid::framing::SequenceNumber,
boost::detail::empty_base<qpid::framing::SequenceNumber> >> =
{<boost::detail::empty_base<qpid::framing::SequenceNumber>> = {<No data
fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data
fields>}, <No data fields>}, <No data fields>}, value = 0},
isReplicationIdSet = false}, delivery = 0x0, disposition = 0,
index = 14, tag = {size = 4, start = 0x7fffec227790 ""}, static TAG_WIDTH =
4, tagData = "\000\000\000\016"}
__PRETTY_FUNCTION__ = "virtual void
qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*)"
#5 0x00007ffff423d358 in qpid::broker::amqp::Session::writable
(this=0x7fffc8006bf0, link=0x7fffc80239a0, delivery=0x7fffdc000fe0)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Session.cpp:723
sender = {_M_node = 0x7fffc80296a0}
__PRETTY_FUNCTION__ = "void
qpid::broker::amqp::Session::writable(pn_link_t*, pn_delivery_t*)"
#6 0x00007ffff41e7667 in qpid::broker::amqp::Connection::doDeliveryUpdated
(this=0x7fffc80047a8, delivery=0x7fffdc000fe0)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:665
i = {_M_node = 0x7fffc8013b90}
link = 0x7fffc80239a0
__PRETTY_FUNCTION__ = "void
qpid::broker::amqp::Connection::doDeliveryUpdated(pn_delivery_t*)"
#7 0x00007ffff41e5863 in qpid::broker::amqp::Connection::process
(this=0x7fffc80047a8) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:458
__PRETTY_FUNCTION__ = "virtual void
qpid::broker::amqp::Connection::process()"
event = 0x7fffc8009680
#8 0x00007ffff41e2ed4 in qpid::broker::amqp::Connection::decode
(this=0x7fffc80047a8, buffer=0x7ffff7e27010 "", size=83)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Connection.cpp:199
now = 140737168171232
__PRETTY_FUNCTION__ = "virtual size_t
qpid::broker::amqp::Connection::decode(const char*, size_t)"
n = 83
#9 0x00007ffff42319ca in qpid::broker::amqp::Sasl::decode
(this=0x7fffc8004740, buffer=0x7ffff7e27010 "", size=83)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/broker/amqp/Sasl.cpp:52
decoded = 0
total = 0
__PRETTY_FUNCTION__ = "virtual size_t
qpid::broker::amqp::Sasl::decode(const char*, size_t)"
#10 0x00007ffff7233255 in qpid::sys::AsynchIOHandler::readbuff
(this=0x7fffc8000b40, buff=0x7fffc8001960) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/AsynchIOHandler.cpp:138
decoded = 0
__PRETTY_FUNCTION__ = "void
qpid::sys::AsynchIOHandler::readbuff(qpid::sys::AsynchIO&,
qpid::sys::AsynchIO::BufferBase*)"
#11 0x00007ffff7a6a3a8 in boost::_mfi::mf2<void,
qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000ce0,
p=0x7fffc8000b40,
a1=..., a2=0x7fffc8001960) at
/usr/include/boost/bind/mem_fn_template.hpp:280
No locals.
#12 0x00007ffff7a691ac in
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> >::operator()<boost::_mfi::mf2<void,
qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>, boost::_bi::list2<qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*&> > (this=0x7fffc8000cf0, f=..., a=...)
at /usr/include/boost/bind/bind.hpp:392
No locals.
#13 0x00007ffff7a686ca in boost::_bi::bind_t<void, boost::_mfi::mf2<void,
qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>,
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> > >::operator()<qpid::sys::AsynchIO,
qpid::sys::AsynchIOBufferBase*> (this=0x7fffc8000ce0, a1=...,
a2=@0x7fffecea6708: 0x7fffc8001960) at
/usr/include/boost/bind/bind_template.hpp:61
---Type <return> to continue, or q <return> to quit---
a = {<boost::_bi::storage2<qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*&>> =
{<boost::_bi::storage1<qpid::sys::AsynchIO&>> = {a1_ = @0x7fffc8000b80},
a2_ = @0x7fffecea6708}, <No data fields>}
#14 0x00007ffff7a67a58 in
boost::detail::function::void_function_obj_invoker2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>,
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> > >, void, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>::invoke (
function_obj_ptr=..., a0=..., a1=0x7fffc8001960) at
/usr/include/boost/function/function_template.hpp:153
f = 0x7fffc8000ce0
#15 0x00007ffff7196a2c in boost::function2<void, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fffc8000cd8, a0=...,
a1=0x7fffc8001960)
at /usr/include/boost/function/function_template.hpp:767
No locals.
#16 0x00007ffff7193bef in qpid::sys::posix::AsynchIO::readable
(this=0x7fffc8000b80, h=...) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/AsynchIO.cpp:453
duration = 1
buff = 0x7fffc8001960
readCount = 65536
rc = 83
readStartTime = {timepoint = 110113377219333}
total = 83
readCalls = 1
__PRETTY_FUNCTION__ = "void
qpid::sys::posix::AsynchIO::readable(qpid::sys::DispatchHandle&)"
#17 0x00007ffff719b858 in boost::_mfi::mf1<void,
qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>::operator()
(this=0x7fffc8000ba0, p=0x7fffc8000b80, a1=...)
at /usr/include/boost/bind/mem_fn_template.hpp:165
No locals.
#18 0x00007ffff719abe1 in
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
boost::arg<1> >::operator()<boost::_mfi::mf1<void,
qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
boost::_bi::list1<qpid::sys::DispatchHandle&> > (this=0x7fffc8000bb0,
f=..., a=...) at /usr/include/boost/bind/bind.hpp:313
No locals.
#19 0x00007ffff7199ec0 in boost::_bi::bind_t<void, boost::_mfi::mf1<void,
qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
boost::arg<1> > >::operator()<qpid::sys::DispatchHandle>
(this=0x7fffc8000ba0, a1=...) at
/usr/include/boost/bind/bind_template.hpp:32
a = {<boost::_bi::storage1<qpid::sys::DispatchHandle&>> = {a1_ =
@0x7fffc8000b88}, <No data fields>}
#20 0x00007ffff7198ed4 in
boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void,
boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
qpid::sys::DispatchHandle&>,
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>,
boost::arg<1> > >, void, qpid::sys::DispatchHandle&>::invoke
(function_obj_ptr=..., a0=...)
at /usr/include/boost/function/function_template.hpp:153
f = 0x7fffc8000ba0
#21 0x00007ffff7236fe3 in boost::function1<void,
qpid::sys::DispatchHandle&>::operator() (this=0x7fffc8000b98, a0=...) at
/usr/include/boost/function/function_template.hpp:767
No locals.
#22 0x00007ffff7236641 in qpid::sys::DispatchHandle::processEvent
(this=0x7fffc8000b88, type=qpid::sys::Poller::READABLE)
at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/DispatchHandle.cpp:280
__PRETTY_FUNCTION__ = "virtual void
qpid::sys::DispatchHandle::processEvent(qpid::sys::Poller::EventType)"
#23 0x00007ffff71bd280 in qpid::sys::Poller::Event::process
(this=0x7fffecea6c90) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Poller.h:131
No locals.
#24 0x00007ffff71bc5c6 in qpid::sys::Poller::run (this=0x680640) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/epoll/EpollPoller.cpp:522
event = {handle = 0x7fffc8000b88, type =
qpid::sys::Poller::READABLE}
ss = {__val = {18446744067267100671, 18446744073709551615 <repeats
15 times>}}
__PRETTY_FUNCTION__ = "virtual void qpid::sys::Poller::run()"
---Type <return> to continue, or q <return> to quit---
#25 0x00007ffff723537b in qpid::sys::Dispatcher::run (this=0x7fffffffdd10)
at /home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/Dispatcher.cpp:37
No locals.
#26 0x00007ffff71b0b8d in qpid::sys::(anonymous namespace)::runRunnable
(p=0x7fffffffdd10) at
/home/mbroadst/Downloads/qpid-cpp-0.34.99/src/qpid/sys/posix/Thread.cpp:35
No locals.
#27 0x00007ffff6859182 in start_thread (arg=0x7fffecea7700) at
pthread_create.c:312
__res = <optimized out>
pd = 0x7fffecea7700
now = <optimized out>
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737168176896,
9029394154174007709, 1, 0, 140737168177600, 140737168176896,
-9029431446891673187, -9029375100312499811},
mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0},
data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
not_first_call = <optimized out>
pagesize_m1 = <optimized out>
sp = <optimized out>
freesize = <optimized out>
__PRETTY_FUNCTION__ = "start_thread"
#28 0x00007ffff658647d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Tue, Jan 12, 2016 at 8:39 AM, Matt Broadstone <mb...@gmail.com> wrote:
> On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
>
>> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>>
>>> Looks like I did just get a valid assertion, but I'm not even clear
>>> anymore
>>> whether this is related to the initially reported bug (since we're trying
>>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>>
>>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is
>>> now 0
>>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
>>> handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
>>> qpidd:
>>>
>>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>>> virtual void
>>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>>> Assertion `r.delivery == delivery' failed.
>>>
>>
>> Do you have the core for that? If so can you check the values of
>> 'delivery' and 'r.delivery'? Is either of them 0?
>>
>>
>>
> Hi Gordon,
> I unfortunately don't have access to the box at the moment (and won't for
> a few hours, if its even still in a reproducible state), but I'll try to
> get a core next time. In the meantime, do you have any ideas for values I
> should check on the sending side that might cause this? I can certainly
> look through all of that code and see if I can make a smaller case that
> exhibits this behavior.
>
> Matt
>
>
Hi Gordon,
Just got this again, and I'm (sort of) able to reproduce it. I have a core
file for you, if you'd like me to mail it directly to you? Do you have any
thoughts on what could cause the problem in the first place? This is really
hanging us up over here unfortunately..
Regards,
Matt
>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
>> For additional commands, e-mail: users-help@qpid.apache.org
>>
>>
>
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Tue, Jan 12, 2016 at 5:08 AM, Gordon Sim <gs...@redhat.com> wrote:
> On 01/11/2016 09:29 PM, Matt Broadstone wrote:
>
>> Looks like I did just get a valid assertion, but I'm not even clear
>> anymore
>> whether this is related to the initially reported bug (since we're trying
>> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>>
>> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is
>> now 0
>> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
>> handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
>> qpidd:
>>
>> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
>> virtual void
>> qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
>> Assertion `r.delivery == delivery' failed.
>>
>
> Do you have the core for that? If so can you check the values of
> 'delivery' and 'r.delivery'? Is either of them 0?
>
>
>
Hi Gordon,
I unfortunately don't have access to the box at the moment (and won't for a
few hours, if its even still in a reproducible state), but I'll try to get
a core next time. In the meantime, do you have any ideas for values I
should check on the sending side that might cause this? I can certainly
look through all of that code and see if I can make a smaller case that
exhibits this behavior.
Matt
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
>
Re: spurious ABRT in qpidd
Posted by Gordon Sim <gs...@redhat.com>.
On 01/11/2016 09:29 PM, Matt Broadstone wrote:
> Looks like I did just get a valid assertion, but I'm not even clear anymore
> whether this is related to the initially reported bug (since we're trying
> to throw the kitchen sink at it to cause ABRTs). The log indicated:
>
> 2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is now 0
> 2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
> handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
> qpidd:
> /build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
> virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
> Assertion `r.delivery == delivery' failed.
Do you have the core for that? If so can you check the values of
'delivery' and 'r.delivery'? Is either of them 0?
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Mon, Jan 11, 2016 at 3:47 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Mon, Jan 11, 2016 at 1:18 PM, Matt Broadstone <mb...@gmail.com>
> wrote:
>
>> On Mon, Jan 11, 2016 at 1:15 PM, Gordon Sim <gs...@redhat.com> wrote:
>>
>>> On 01/11/2016 05:37 PM, Matt Broadstone wrote:
>>>
>>>> I'm having trouble tracking down the root cause of a thrown SIGABRT in
>>>> qpidd, and was wondering for some advice from the list. Specifically,
>>>> it
>>>> seems to be after a period of little to no activity, a large burst of
>>>> traffic hits the broker and the only information we're seeing in the
>>>> logs
>>>> is:
>>>>
>>>> Jan 11 15:58:33 test-box kernel: [ 652.903997] init: qpidd main process
>>>> (2239) killed by ABRT signal
>>>> Jan 11 15:58:33 test-box kernel: [ 652.911661] init: qpidd main process
>>>> ended, respawning
>>>>
>>>> We're running ubuntu 14.04 (trusty) on this machine, with the packages
>>>> off
>>>> the official qpid PPA. I tried running the services with trace logging
>>>> enabled to no avail (there were no strange packets, and no error
>>>> messages
>>>> about bad assertions). Attaching gdb to the process also resulted in no
>>>> relevant information, so I'm running out of ideas of what to try next.
>>>> AFAICT the only `abort()` present in the codebase is in the assertion
>>>> code,
>>>> which would print something about around the assertion failure.
>>>>
>>>> Any thoughts on what I might try to help resolve this issue?
>>>>
>>>
>>> Could it be a memory issue? I.e. the qpidd processes exceeding some
>>> memory limit and being killed by the oom killer?
>>>
>>>
>> I thought so at first too, but I believe we would see a kernel message
>> related to that if that were the case, not to mention that the server had
>> something like 120GB of free RAM at the time as well. I'm quite willing to
>> test that theory more thoroughly if you have a recommended means of doing
>> so?
>>
>>
> I wish I could tell you that I have a quick reproducible test case that
> only used qpid code, unfortunately we don't it's always in concert with a
> number of other services. Is it possible that this could be triggered from
> some proton code and that no message would be output? We're actually
> experiencing this problem on a loop on one of our servers currently and
> there's something like 452GB free memory, so I'm inclined to rule out
> memory as the root cause.
>
>
Looks like I did just get a valid assertion, but I'm not even clear anymore
whether this is related to the initially reported bug (since we're trying
to throw the kitchen sink at it to cause ABRTs). The log indicated:
2016-01-11 21:21:21 [Broker] debug clean(): 0 messages remain; head is now 0
2016-01-11 21:21:21 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:56687
handling outgoing delivery for 0x7f3fdc262590 on session 0x7f3fdc111650
qpidd:
/build/qpid-cpp-RtJ4Dg/qpid-cpp-0.34/src/qpid/broker/amqp/Outgoing.cpp:115:
virtual void qpid::broker::amqp::OutgoingFromQueue::handle(pn_delivery_t*):
Assertion `r.delivery == delivery' failed.
So in the current test we are back on 0.34 built with proton 0.10. This is
the initial configuration that caused us pain, but we had been testing
against trunk (0.35) with proton 0.11.1 the past few days, which was
exhibiting the same initial stated problem. Hope that helps.
>
>
>> Matt
>>
>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
>>> For additional commands, e-mail: users-help@qpid.apache.org
>>>
>>>
>>
>
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Mon, Jan 11, 2016 at 1:18 PM, Matt Broadstone <mb...@gmail.com> wrote:
> On Mon, Jan 11, 2016 at 1:15 PM, Gordon Sim <gs...@redhat.com> wrote:
>
>> On 01/11/2016 05:37 PM, Matt Broadstone wrote:
>>
>>> I'm having trouble tracking down the root cause of a thrown SIGABRT in
>>> qpidd, and was wondering for some advice from the list. Specifically, it
>>> seems to be after a period of little to no activity, a large burst of
>>> traffic hits the broker and the only information we're seeing in the logs
>>> is:
>>>
>>> Jan 11 15:58:33 test-box kernel: [ 652.903997] init: qpidd main process
>>> (2239) killed by ABRT signal
>>> Jan 11 15:58:33 test-box kernel: [ 652.911661] init: qpidd main process
>>> ended, respawning
>>>
>>> We're running ubuntu 14.04 (trusty) on this machine, with the packages
>>> off
>>> the official qpid PPA. I tried running the services with trace logging
>>> enabled to no avail (there were no strange packets, and no error messages
>>> about bad assertions). Attaching gdb to the process also resulted in no
>>> relevant information, so I'm running out of ideas of what to try next.
>>> AFAICT the only `abort()` present in the codebase is in the assertion
>>> code,
>>> which would print something about around the assertion failure.
>>>
>>> Any thoughts on what I might try to help resolve this issue?
>>>
>>
>> Could it be a memory issue? I.e. the qpidd processes exceeding some
>> memory limit and being killed by the oom killer?
>>
>>
> I thought so at first too, but I believe we would see a kernel message
> related to that if that were the case, not to mention that the server had
> something like 120GB of free RAM at the time as well. I'm quite willing to
> test that theory more thoroughly if you have a recommended means of doing
> so?
>
>
I wish I could tell you that I have a quick reproducible test case that
only used qpid code, unfortunately we don't it's always in concert with a
number of other services. Is it possible that this could be triggered from
some proton code and that no message would be output? We're actually
experiencing this problem on a loop on one of our servers currently and
there's something like 452GB free memory, so I'm inclined to rule out
memory as the root cause.
> Matt
>
>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
>> For additional commands, e-mail: users-help@qpid.apache.org
>>
>>
>
Re: spurious ABRT in qpidd
Posted by Matt Broadstone <mb...@gmail.com>.
On Mon, Jan 11, 2016 at 1:15 PM, Gordon Sim <gs...@redhat.com> wrote:
> On 01/11/2016 05:37 PM, Matt Broadstone wrote:
>
>> I'm having trouble tracking down the root cause of a thrown SIGABRT in
>> qpidd, and was wondering for some advice from the list. Specifically, it
>> seems to be after a period of little to no activity, a large burst of
>> traffic hits the broker and the only information we're seeing in the logs
>> is:
>>
>> Jan 11 15:58:33 test-box kernel: [ 652.903997] init: qpidd main process
>> (2239) killed by ABRT signal
>> Jan 11 15:58:33 test-box kernel: [ 652.911661] init: qpidd main process
>> ended, respawning
>>
>> We're running ubuntu 14.04 (trusty) on this machine, with the packages off
>> the official qpid PPA. I tried running the services with trace logging
>> enabled to no avail (there were no strange packets, and no error messages
>> about bad assertions). Attaching gdb to the process also resulted in no
>> relevant information, so I'm running out of ideas of what to try next.
>> AFAICT the only `abort()` present in the codebase is in the assertion
>> code,
>> which would print something about around the assertion failure.
>>
>> Any thoughts on what I might try to help resolve this issue?
>>
>
> Could it be a memory issue? I.e. the qpidd processes exceeding some memory
> limit and being killed by the oom killer?
>
>
I thought so at first too, but I believe we would see a kernel message
related to that if that were the case, not to mention that the server had
something like 120GB of free RAM at the time as well. I'm quite willing to
test that theory more thoroughly if you have a recommended means of doing
so?
Matt
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
>
Re: spurious ABRT in qpidd
Posted by Gordon Sim <gs...@redhat.com>.
On 01/11/2016 05:37 PM, Matt Broadstone wrote:
> I'm having trouble tracking down the root cause of a thrown SIGABRT in
> qpidd, and was wondering for some advice from the list. Specifically, it
> seems to be after a period of little to no activity, a large burst of
> traffic hits the broker and the only information we're seeing in the logs
> is:
>
> Jan 11 15:58:33 test-box kernel: [ 652.903997] init: qpidd main process
> (2239) killed by ABRT signal
> Jan 11 15:58:33 test-box kernel: [ 652.911661] init: qpidd main process
> ended, respawning
>
> We're running ubuntu 14.04 (trusty) on this machine, with the packages off
> the official qpid PPA. I tried running the services with trace logging
> enabled to no avail (there were no strange packets, and no error messages
> about bad assertions). Attaching gdb to the process also resulted in no
> relevant information, so I'm running out of ideas of what to try next.
> AFAICT the only `abort()` present in the codebase is in the assertion code,
> which would print something about around the assertion failure.
>
> Any thoughts on what I might try to help resolve this issue?
Could it be a memory issue? I.e. the qpidd processes exceeding some
memory limit and being killed by the oom killer?
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org