[Ace-users] [ace-users] A bug about ACE_Logging_Strategy

Douglas C. Schmidt schmidt at dre.vanderbilt.edu
Mon Dec 24 16:33:11 CST 2007


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


or in


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



>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 /
>#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
>#11 0xb7f86e0e in JAWS_Concurrency_Impl::svc (this=0x8057a34) at
>#12 0xb7f1c794 in ACE_Task_Base::svc_run (args=0x8057a34) at Task.cpp:
>#13 0xb7f1d108 in ACE_Thread_Adapter::invoke_i (this=0x8057ca8) at
>#14 0xb7f1d2d6 in ACE_Thread_Adapter::invoke (this=0x8057ca8) at
>#15 0xb7eb0c51 in ace_thread_adapter (args=0x8057ca8) at
>#16 0xb7e04240 in start_thread () from /lib/tls/i686/cmov/
>#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
>    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/
>#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/
>#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
>#11 0xb7ea2108 in ACE_Thread_Adapter::invoke_i (this=0x804c720) at
>#12 0xb7ea22d6 in ACE_Thread_Adapter::invoke (this=0x804c720) at
>#13 0xb7e35c51 in ace_thread_adapter (args=0x804c720) at
>#14 0xb7d89240 in start_thread () from /lib/tls/i686/cmov/
>#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():
>ACE_Logging_Strategy::handle_timeout (const ACE_Time_Value &,
>                                      const void *)
>  if ((size_t) ACE_OS::ftell (this->log_msg_->msg_ostream ()) > this-
>  if ((size_t) this->log_msg_->msg_ostream ()->tellp () > this-
>    {
>      // 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.
>     I will detail this problem in my blog: http://blog.tom.com/blogger2007
>     Some one also have a problem about ostream<>::tellp() at url:

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.schmidt at vanderbilt.edu

More information about the Ace-users mailing list