A bug about ACE_Logging_Strategy

[spen...@gmail.com]

We have found a threads-safety problem in
ACE_Logging_Strategy::handle_timeout() method.
In our application,there are mutiple threads writing log to a shared
ofstream object.Also there is one reatctor thread calling the
ACE_Logging_Strategy::handle_timeout() method.But sometime our program
crashed with this stack backtrace:

(gdb) bt
#0 0xb7c1bb4a in memcpy () from /lib/tls/i686/cmov/libc.so.6
#1 0xb7d9c006 in std::basic_streambuf<char, std::char_traits<char>
>::xsputn () from /usr/lib/libstdc++.so.6
#2 0xb7d66d59 in std::basic_filebuf<char, std::char_traits<char>
>::xsputn () from /usr/lib/libstdc++.so.6
#3 0xb7d911df in std::operator<< <std::char_traits<char> > () from /
usr/lib/libstdc++.so.6
#4 0xb7ed8f15 in ACE_Log_Record::print (this=0x2befe228,
host_name=0x0, verbose_flag=4, s=@0x80521c8) at Log_Record.cpp:302
#5 0xb7ed70a6 in ACE_Log_Msg::log (this=0x8588a58,
log_record=@0x2befe228, suppress_stderr=0) at Log_Msg.cpp:2197
#6 0xb7ed749b in ACE_Log_Msg::log (this=0x8588a58,
format_str=0xb7f9ef3d "", log_priority=LM_TRACE, argp=0xb7f9ef3c "\n")
at Log_Msg.cpp:2047
#7 0xb7ed8055 in ACE_Log_Msg::log (this=0x8588a58,
log_priority=LM_TRACE, format_str=0xb7f9ef2a "%*s(%t) leaving %s\n")
at Log_Msg.cpp:961
#8 0xb7f9d9b3 in ~JAWS_Trace (this=0x2befe338) at Trace.cpp:139
#9 0xb70ff7b3 in StorageWriteState::service (this=0x85aaa28,
ec=0x291b4d70, data=0x291b4d70) at StorageWriteState.cpp:63
#10 0xb7f94739 in JAWS_Protocol_Handler::service (this=0x291b4d70) at
Protocol_Handler.cpp:38
#11 0xb7f86e0e in JAWS_Concurrency_Impl::svc (this=0x8057a34) at
Concurrency.cpp:38
#12 0xb7f1c794 in ACE_Task_Base::svc_run (args=0x8057a34) at Task.cpp:
258
#13 0xb7f1d108 in ACE_Thread_Adapter::invoke_i (this=0x8057ca8) at
Thread_Adapter.cpp:151
#14 0xb7f1d2d6 in ACE_Thread_Adapter::invoke (this=0x8057ca8) at
Thread_Adapter.cpp:95
#15 0xb7eb0c51 in ace_thread_adapter (args=0x8057ca8) at
Base_Thread_Adapter.cpp:137
#16 0xb7e04240 in start_thread () from /lib/tls/i686/cmov/
libpthread.so.0
#17 0xb7c7a4ae in clone () from /lib/tls/i686/cmov/libc.so.6

We found the reason is the calling of ostream<>::tellp () will change
the state of the internal basic_filebuf<> object of this ostream<>
object. We catched the call stack of that moment:

(gdb) bt
#0 0xb7cec09e in std::basic_filebuf<char, std::char_traits<char>
>::_M_seek () from /usr/lib/libstdc++.so.6
#1 0xb7cede2a in std::basic_filebuf<char, std::char_traits<char>
>::seekoff () from /usr/lib/libstdc++.so.6
#2 0xb7d14e5d in std::ostream::tellp () from /usr/lib/libstdc++.so.6
#3 0xb7e5f0a4 in ACE_Logging_Strategy::handle_timeout
(this=0xb7f2dac0) at Logging_Strategy.cpp:404
#4 0xb7e2dcb1 in
ACE_Event_Handler_Handle_Timeout_Upcall<ACE_Recursive_Thread_Mutex>::timeout
(this=0x80515d0,
timer_queue=@0x8051528, event_handler=0xb7f2dac0, act=0x0,
recurring_timer=1, cur_time=@0x2ce852e8)
at /data/jinwei/svn_root/ireport/common/ace/ACE_wrappers/ace/
Timer_Queue_T.cpp:408
#5 0xb7e4b20d in ACE_Dev_Poll_Reactor::dispatch_timer_handler
(this=0x8051470, guard=@0x2ce85394)
at /data/jinwei/svn_root/ireport/common/ace/ACE_wrappers/ace/
Timer_Queue_T.inl:170
#6 0xb7e4d92c in ACE_Dev_Poll_Reactor::dispatch (this=0x8051470,
guard=@0x2ce85394) at Dev_Poll_Reactor.cpp:1230
#7 0xb7e4da56 in ACE_Dev_Poll_Reactor::handle_events_i
(this=0x8051470, max_wait_time=0x0, guard=@0x2ce85394)
at Dev_Poll_Reactor.cpp:1211
#8 0xb7e4db21 in ACE_Dev_Poll_Reactor::handle_events (this=0x8051470,
max_wait_time=0x0) at Dev_Poll_Reactor.cpp:1166
#9 0xb7e8bf02 in ACE_Reactor::run_reactor_event_loop (this=0x80518f0,
eh=0) at Reactor.cpp:233
#10 0xb7f16be7 in
JAWS_Event_Dispatcher::JAWS_Event_Dispatcher_Reactor_Event_Loop () at
Event_Dispatcher.cpp:32
#11 0xb7ea2108 in ACE_Thread_Adapter::invoke_i (this=0x804c720) at
Thread_Adapter.cpp:151
#12 0xb7ea22d6 in ACE_Thread_Adapter::invoke (this=0x804c720) at
Thread_Adapter.cpp:95
#13 0xb7e35c51 in ace_thread_adapter (args=0x804c720) at
Base_Thread_Adapter.cpp:137
#14 0xb7d89240 in start_thread () from /lib/tls/i686/cmov/
libpthread.so.0
#15 0xb7bff4ae in clone () from /lib/tls/i686/cmov/libc.so.6

Sometimes basic_filebuf<>::_M_seek () method will set NULL to an
internal buffer pointer of the basic_filebuf<> object, and this
pointer would be pass to memcpy () as an argument when we output some
thing through this basic_filebuf<> object. We have viewed the source
of the ACE_Logging_Strategy::handle_timeout():

int
ACE_Logging_Strategy::handle_timeout (const ACE_Time_Value &,
const void *)
{
#if defined (ACE_LACKS_IOSTREAM_TOTALLY)
if ((size_t) ACE_OS::ftell (this->log_msg_->msg_ostream ()) > this-
>max_size_)
#else
if ((size_t) this->log_msg_->msg_ostream ()->tellp () > this-
>max_size_)
#endif /* ACE_LACKS_IOSTREAM_TOTALLY */
{
// Lock out any other logging.
if (this->log_msg_->acquire ())
.........

The calling of "this->log_msg_->msg_ostream ()->tellp ()" is not thead-
safed! So we modified the code and tested it. Everything is ok now.

We shared this experience to peploes. Good luck to everyone.

ps:
I will detail this problem in my blog: http://blog.tom.com/blogger2007
Some one also have a problem about ostream<>::tellp() at url:
http://www.thescripts.com/forum/thread139342.html

[Douglas C. Schmidt]

Hi,

To ensure that we have proper version/platform/compiler information,
please make sure you fill out the appropriate problem report form
(PRF), which is in

$ACE_ROOT/PROBLEM-REPORT-FORM
$TAO_ROOT/PROBLEM-REPORT-FORM

or in

$ACE_ROOT/BUG-REPORT-FORM
$TAO_ROOT/BUG-REPORT-FORM

in older versions of ACE+TAO. Make sure to include this information
when asking any questions about ACE+TAO since otherwise we have to
"guess" what version/platform/compiler/options you've using, which is
very error-prone and slows down our responsiveness. If you don't use
the PRF, therefore, it is less likely that someone from the core
ACE+TAO developer team will be able to answer your question.
Naturally, we encourage and appreciate other members of the ACE+TAO
user community who can respond to questions that they have the answers
to.

Thanks,

Doug

--
Dr. Douglas C. Schmidt Professor and Associate Chair
Electrical Engineering and Computer Science TEL: (615) 343-8197
Vanderbilt University WEB: www.dre.vanderbilt.edu/~schmidt
Nashville, TN 37203 NET: d.sc...@vanderbilt.edu

[spen...@gmail.com]

Hi, i have send a PRF to ace-...@cs.wustl.edu.
Alos i have detailed this problem at url: http://blog.tom.com/blogger2007/article/1296.html

[spen...@gmail.com]

Sorry, I made some mistakes on the PRF. I have sent a new PRF in a
plain-txt email again.