[boost] Re: [Boost-testing] Re: [thread] test_read_write_mutex breaks regressiontesting

From: Caleb Epstein (caleb.epstein_at_[hidden])
Date: 2005-04-26 14:44:39

On 4/26/05, Caleb Epstein <caleb.epstein_at_[hidden]> wrote:

> OK, after seeing two of these tests continue to perform poorly and
> hang in some cases, I decided it was time to break out the big guns:
> Purify.  It found a number of problems with test_mutex and
> test_read_write_mutex, which seem to be triggered by Boost.Test making
> use of a string after it has been freed.
> 
> Attached is the Purify output from test_mutex and test_read_write_mutex.

Digging a little deeper, I think the root of the problem is that
multiple threads are touching the guts of the Boost.Test logging code
at the same time, and its static variables are being manipulated
without thread protections.

Here's where Purify notices the problem:

(/opt/SUNWspro/bin/../WS6U2/bin/sparcv9/dbx) where
current thread: t_at_6
  [1] purify_stop_here(0x1, 0x6b8c4, 0x0, 0x0, 0x0, 0x0), at 0x7e944
  [2] _x_trap_and_go(0x74, 0x0, 0x42, 0x0, 0x0, 0x0), at 0x7e8dc
  [3] std::transform<char*,char*,char(*)(char)>(first = 0x1f2e7f
"hread/test/util.inl", last = 0x1f2e92 "", result = 0x1f2e7f
"hread/test/util.inl", op = 0xb1e98 =
&boost::unit_test::set_unix_slash(char)), line 452 in "algorithm.cc"
=>[4] boost::unit_test::unit_test_log_t::operator<<(this = 0x1d336c, f
= STRUCT), line 277 in "unit_test_log.ipp"
  [5] boost::test_tools::tt_detail::check_impl(pr = CLASS, check_descr
= CLASS, file_name = CLASS, line_num = 34U, tl = PASS, ct =
CHECK_EQUAL, num_of_args = 2U, ...), line 144 in "test_tools.ipp"
  [6] boost::test_tools::tt_detail::check_impl<boost::test_tools::tt_detail::equal_impl_frwd,int,int>(P
= STRUCT, check_descr = CLASS, file_name = CLASS, line_num = 34U,
tool_level = CHECK, ct = CHECK_EQUAL, arg0 = 1, arg0_descr = 0x191f95
"boost::xtime_get(&xt, boost::TIME_UTC)", arg1 = 1, arg1_descr =
0x191fbc "static_cast<int>(boost::TIME_UTC)"), line 402 in
"test_tools.hpp"
  [7] __unnamed_lpburU7kbCGP9::delay(secs = 0, msecs = 100, nsecs =
0), line 34 in "util.inl"
  [8] test_lock<boost::mutex>::operator()(this = 0x7e27fbe3), line 44
in "test_mutex.cpp"
  [9] do_test_mutex(), line 169 in "test_mutex.cpp"
  [10] boost::detail::function::void_function_invoker0<void(*)(),void>::invoke(function_ptr
= UNION), line 103 in "function_template.hpp"
  [11] boost::function0<void,int>::operator()(this = 0x7e27fd24), line
576 in "function_template.hpp"
  [12] thread_proxy(param = 0x7e3ffb38), line 113 in "thread.cpp"

And here is the method in question:

(/opt/SUNWspro/bin/../WS6U2/bin/sparcv9/dbx) l
  271   unit_test_log_t&
  272   unit_test_log_t::operator<<( log::file const& f )
  273   {
  274       assign_op( s_log_impl().m_entry_data.m_file, f.m_file_name, 0 );
  275   
  276       // normalize file name
  277       std::transform( s_log_impl().m_entry_data.m_file.begin(),
s_log_impl().m_entry_data.m_file.end(),
  278                       s_log_impl().m_entry_data.m_file.begin(),
  279                       &set_unix_slash );
  280   

But s_log_impl().m_entry_data.m_file is not equal to f.m_file_name as
it should be:

(/opt/SUNWspro/bin/../WS6U2/bin/sparcv9/dbx) print f.m_file_name
f.m_file_name = {
    m_begin = 0x191f52
"/home/nbde52d/src/boost-regression/boost/libs/thread/test/util.inl"
    m_end   = 0x191f94 ""
}

(/opt/SUNWspro/bin/../WS6U2/bin/sparcv9/dbx) print
s_log_impl().m_entry_data.m_file
boost::unit_test::__unnamed_lpburnXebCmne::s_log_impl().m_entry_data.m_file = {
    __data_   = {
        __data_ = 0x1f2f10 "../libs/thread/test/test_mutex.cpp"
    }
    __nullref = struct
__rwstd::__null_string_ref_rep<char,std::char_traits<char>,std::allocator<char>,__rwstd::__string_ref_rep<std::allocator<char>
> > /* STATIC CLASS */
}

-- 
Caleb Epstein
caleb dot epstein at gmail dot com