Hangup

[ajk]

(gdb) bt
#0 0xb73891b4 in lll_lock_wait () from /lib/libpthread.so.0
#1 0xb73849e5 in _L_lock_89 () from /lib/libpthread.so.0
#2 0xb73842f2 in pthread_mutex_lock () from /lib/libpthread.so.0
#3 0xb746bd86 in pthread_mutex_lock () from /lib/libc.so.6
#4 0x08062b61 in boost::mutex::lock (this=0x820b064) at /usr/include/boost/thread/pthread/mutex.hpp:50
#5 0x08066114 in logger::logline::open (this=0xbfbe10fb) at tlate/../logger/logline.hh:78
#6 0x08066168 in logline (this=0xbfbe10fb, doOpen=true) at tlate/../logger/logline.hh:40
#7 0x0806633f in boost::assertion_failed (expr=0x818d54b "hours_str.length() <= 2",

function=0x818e740 "OutItrT boost::date_time::time_facet<time_type, CharT, OutItrT>::put(OutItrT, std::ios_base&, typename boost::date_time::date_facet<typename time_type::date_type, CharT, OutItrT>::char_type, const typ"..., file=0x818d818 "/usr/include/boost/date_time/time_facet.hpp", line=449) at assert_handler.cc:35

#8 0x080e86bc in boost::date_time::time_facet<boost::posix_time::ptime, char, std::ostreambuf_iterator<char, std::char_traits<char> > >::put (this=0x8538218, a_next=

{<std::iterator<std::output_iterator_tag, void, void, void, void>> = {<No data fields>}, _M_sbuf = 0x83c4ed4, _M_failed = false}, a_ios=@0x83c4f5c, a_fill=32 ' ', a_time_dur=@0xbfbe12a4)

at /usr/include/boost/date_time/time_facet.hpp:449

#9 0x080e8851 in boost::posix_time::operator<< <char, std::char_traits<char> > (os=@0x83c4ed0, td=@0xbfbe12a4) at /usr/include/boost/date_time/posix_time/posix_time_io.hpp:186
#10 0x080e89d3 in logger::logline::operator<< <boost::posix_time::time_duration> (this=0xbfbe12bb, t=

{<boost::date_time::time_duration<boost::posix_time::time_duration, boost::date_time::time_resolution_traits<boost::date_time::time_resolution_traits_adapted64_impl, micro, 1000000, 6u, int> >> = {<boost::less_than_comparable<boost::posix_time::time_duration, boost::equality_comparable<boost::posix_time::time_duration, boost::posix_time::time_duration, boost::detail::empty_base<boost::posix_time::time_duration>, boost::detail::false_t>, boost::detail::empty_base<boost::posix_time::time_duration>, boost::detail::true_t>> = {<boost::less_than_comparable1<boost::posix_time::time_duration, boost::equality_comparable<boost::posix_time::time_duration, boost::posix_time::time_duration, boost::detail::empty_base<boost::posix_time::time_duration>, boost::detail::false_t> >> = {<boost::equality_comparable<boost::posix_time::time_duration, boost::posix_time::time_duration, boost::detail::empty_base<boost::posix_time::time_duration>, boost::detail::false_t>> = {<boost::equality_comparable1<boost::posix_time::time_duration, boost::detail::empty_base<boost::posix_time::time_duration> >> = {<boost::detail::empty_base<boost::posix_time::time_duration>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, ticks_ = {value_ = 605257291469296292}}, <No data fields>}) at nntp/../logger/logline.hh:51

#11 0x0812ed7f in nntp::connection::tick (this=0x8664e20) at nntp/connection.cc:530
#12 0x080707d0 in server::tick_handler (this=0xbfbe1544) at server.cc:142
#13 0x08078891 in boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > >::operator()<boost::system::error_code> (

this=0xbfbe1380, a1=@0xbfbe138c) at /usr/include/boost/bind/bind_template.hpp:32

#14 0x080788b8 in boost::asio::detail::binder1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > >, boost::system::error_code>::operator() (this=0xbfbe1380) at /usr/include/boost/asio/detail/bind_handler.hpp:39
#15 0x080788d1 in boost::asio::asio_handler_invoke<boost::asio::detail::binder1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > >, boost::system::error_code> > (function=

{handler_ = {f_ = {f_ = 0x8070720 <server::tick_handler(boost::system::error_code)>}, l_ = {<boost::_bi::storage2<boost::_bi::value<server*>, boost::arg<1> >> = {<boost::_bi::storage1<boost::_bi::value<server*> >> = {a1_ = {t_ = 0xbfbe1544}}, <No data fields>}, <No data fields>}}, arg1_ = {m_val = 0, m_cat = 0xb76ef460}}) at /usr/include/boost/asio/handler_invoke_hook.hpp:62

#16 0x08078916 in boost_asio_handler_invoke_helpers::invoke<boost::asio::detail::binder1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > >, boost::system::error_code>, boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > > > (

function=@0xbfbe13b4, context=0xbfbe13b4) at /usr/include/boost/asio/detail/handler_invoke_helpers.hpp:39

#17 0x08079c26 in boost::asio::detail::handler_queue::handler_wrapper<boost::asio::detail::binder1<boost::_bi::bind_t<void, boost::_mfi::mf1<void, server, boost::system::error_code>, boost::_bi::list2<boost::_bi::value<server*>, boost::arg<1> > >, boost::system::error_code> >::do_call (base=0xb415060) at /usr/include/boost/asio/detail/handler_queue.hpp:192
#18 0x08084566 in boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor<false> >::do_one (this=0x83ea7d8, lock=@0xbfbe14ac, this_idle_thread=0xbfbe1474, ec=@0xbfbe14e8)

at /usr/include/boost/asio/detail/task_io_service.hpp:268

#19 0x0808476c in boost::asio::detail::task_io_service<boost::asio::detail::epoll_reactor<false> >::run_one (this=0x83ea7d8, ec=@0xbfbe14e8) at /usr/include/boost/asio/detail/task_io_service.hpp:119
#20 0x080847f9 in boost::asio::io_service::run_one (this=0xbfbe169c) at /usr/include/boost/asio/impl/io_service.ipp:71
#21 0x080708d6 in server::run (this=0xbfbe1544) at server.cc:125
#22 0x0805a144 in main (argc=Cannot access memory at address 0x80
) at alue_posix.cc:198
(gdb)

[ajk]

(gdb) print startup_timestamp
$1 = {<boost::date_time::base_time<boost::posix_time::ptime, boost::date_time::counted_time_system<boost::date_time::counted_time_rep<boost::posix_time::millisec_posix_time_system_config> > >> = {<boost::less_than_comparable<boost::posix_time::ptime, boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t>, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::true_t>> = {<boost::less_than_comparable1<boost::posix_time::ptime, boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t> >> = {<boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t>> = {<boost::equality_comparable1<boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime> >> = {<boost::detail::empty_base<boost::posix_time::ptime>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, time_ = {time_count_ = {value_ = 212143927052000000}}}, <No data fields>}
(gdb) print client_activity_timestamp
$2 = {<boost::date_time::base_time<boost::posix_time::ptime, boost::date_time::counted_time_system<boost::date_time::counted_time_rep<boost::posix_time::millisec_posix_time_system_config> > >> = {<boost::less_than_comparable<boost::posix_time::ptime, boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t>, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::true_t>> = {<boost::less_than_comparable1<boost::posix_time::ptime, boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t> >> = {<boost::equality_comparable<boost::posix_time::ptime, boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime>, boost::detail::false_t>> = {<boost::equality_comparable1<boost::posix_time::ptime, boost::detail::empty_base<boost::posix_time::ptime> >> = {<boost::detail::empty_base<boost::posix_time::ptime>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, time_ = {time_count_ = {value_ = 212144287389000000}}}, <No data fields>}

[ajk]

This appears to be a boost::date_time bug, fixed in Boost 0.41 ( boost:changeset:56506).

[ajk]

Actually, the assertion failure in the crash here is what was caused by the Boost bug (and has now been worked around in changeset:16ae75ffd14588202aace31aaacf230469fd0758).

The actual bug here is that the assertion failure can occur while logger is locked in the same thread, which causes a deadlock.

[ajk]

Fixed in changeset:41603a0f7acf173ecace38718deb66801483644

[ajk]

Fixed in changeset:341603a0f7acf173ecace38718deb66801483644.