Personally I will first try to output few lines of simple message to std err, see if if key codes (i.e. add_Trace(), processTraces(), constructor and destructor, ...) was executed AND in the correct order, providing that the problem is not too race to replicate. If it does not help then only I will use gdb for stepping through it (http://www.google.com.sg/search?q=gdb+tutorial). Honestly I'm relatively green in using gdb especially in debugging multi-threaded code so please share your approach :)


On Sun, Jan 24, 2010 at 5:09 AM, Stephen Torri <storri@torri.org> wrote:
In the logging example I have been working on to learn more about boost
threads I have run across what I think is a race condition. If I compile
and run this sample program it will sometimes write out an error message
to a file. For example:

2010-01-23_16:2:23 (pid=10948 thread_id=0x92ce448) (II) funky

Other times I see the file is blank. So can I say conclusively that its
a race condition? No. Either what is happening is a race condition where
the file is closed before the contents are written to the file or
something else is causing the logging message to be written sometimes
and not at others.

So to recap:

--- How can you track down a race condition?
--- Can I use 'strace' or 'gdb'?

Stephen

-------------------------------------------
#include <boost/cstdint.hpp>
#include <boost/shared_ptr.hpp>
#include <boost/thread/mutex.hpp>
#include <boost/thread/condition_variable.hpp>
#include <boost/thread/thread.hpp>
#include <boost/utility.hpp>
#include <boost/thread/once.hpp>
#include <boost/scoped_ptr.hpp>
#include <boost/type_traits/aligned_storage.hpp>
#include <boost/bind.hpp>
#include <boost/format.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/cstdint.hpp>

#include <fstream>
#include <sstream>
#include <vector>

namespace myproject { namespace api {

   /*!
    * \brief Trace level constants
    * \date 2003
    * \author Stephen Torri
    */
   class TraceLevel {
   public:
     enum Values {
       NONE = 0,
       WARN = 10,
       ERROR = 20,
       INFO = 30,
       DEBUG = 40,
       DETAIL = 50,
       DATA = 60
     };
   };

 } // namespace api
} // namespace myproject

namespace myproject { namespace interface {

   class ITraceable {
   public:

     typedef boost::shared_ptr<ITraceable> ptr_t;

     virtual std::string get_Formatted_String() = 0;

     virtual boost::uint32_t getLevel() = 0;

     virtual boost::uint32_t getPID() = 0;

     virtual boost::thread::id getThreadID() = 0;
   };
 } // namespace interface
} // namespace myproject

namespace myproject { namespace trace {

   class StringTraceable : public interface::ITraceable
   {
   public:

     StringTraceable ( boost::uint32_t area, boost::uint32_t level, std::string name )
       : m_area ( area ),
         m_level ( level ),
         m_name ( name )
     {
#ifndef WIN32
       m_pid = getpid();
#else
       m_pid = GetCurrentProcessId();
#endif /* WIN32 */

       m_thread_id = boost::this_thread::get_id();
     }

     virtual ~StringTraceable(){}

     virtual std::string get_Formatted_String()
     {
       return m_name;
     }

     virtual boost::uint32_t getLevel()
     {
       return m_level;
     }

     virtual boost::uint32_t getPID()
     {
       return m_pid;
     }

     virtual boost::thread::id getThreadID()
     {
       return m_thread_id;
     }

   private:

     boost::uint32_t m_area;
     boost::uint32_t m_level;
     boost::uint32_t m_pid;
     boost::thread::id m_thread_id;
     std::string m_name;
   };

   template <typename UnsignedType>
   class NumberTraceable : public interface::ITraceable
   {
   public:

     NumberTraceable ( boost::uint32_t area, boost::uint32_t level, std::string name, UnsignedType line )
       : m_area ( area ),
         m_level ( level ),
         m_name ( name ),
         m_line ( line )
     {
#ifndef WIN32
       m_pid = getpid();
#else
       m_pid = GetCurrentProcessId();
#endif /* WIN32 */

       m_thread_id = boost::this_thread::get_id();
     }

     virtual ~NumberTraceable(){}

     virtual std::string get_Formatted_String()
     {
       return m_name;
     }

     virtual boost::uint32_t getLevel()
     {
       return m_level;
     }

     virtual boost::uint32_t getPID()
     {
       return m_pid;
     }

     virtual boost::thread::id getThreadID()
     {
       return m_thread_id;
     }

   private:

     boost::uint32_t m_area;
     boost::uint32_t m_level;
     boost::uint32_t m_pid;
     boost::thread::id m_thread_id;
     std::string m_name;
     UnsignedType m_line;
   };


   template <typename T>
   struct storage_for
   {
     boost::aligned_storage<sizeof(T), boost::alignment_of<T>::value> data;
   };

   template <typename T>
   class Singleton : boost::noncopyable
   {
   public:

     static T& Instance()
     {
       boost::call_once ( init, m_flag );
       return *m_obj;
     }

     static void init ()
     {
       m_obj.reset ( new T() );
     }

   protected:

     ~Singleton(){}
     Singleton(){}

   private:

     static boost::scoped_ptr<T> m_obj;
     static boost::once_flag m_flag;
   };

 } // namespace trace
} // namespace trace

template <typename T> boost::scoped_ptr<T> myproject::trace::Singleton<T>::m_obj ( 0 );
template <typename T> boost::once_flag myproject::trace::Singleton<T>::m_flag = BOOST_ONCE_INIT;

namespace myproject { namespace trace {

   class Trace_State_Utils {
   public:

     static std::string get_Level_String ( boost::uint32_t level )
     {
       // Write message prefix
       if ( level == api::TraceLevel::WARN )
           {
               return "(WW) ";
           }
       else if ( level == api::TraceLevel::ERROR )
           {
               return "(EE) ";
           }
       else if ( level == api::TraceLevel::INFO )
           {
               return "(II) ";
           }
       else if ( level == api::TraceLevel::DEBUG )
           {
               return "(DEBUG) ";
           }
       else if ( level == api::TraceLevel::DETAIL )
           {
               return "(DETAIL) ";
           }
       else if ( level == api::TraceLevel::DATA )
           {
               return "(DATA) ";
           }
       else
           {
               // We should not be here
               abort();
           }
     }
   };


   /* Idea taken from http://www.codeproject.com/debug/xytrace.asp
    * (28 Jan 2002 - Xiangyang Liu)
    *
    * I have modified this so that we don't use varargs and use constant types
    */
   class Trace_State {
   public:

     typedef boost::shared_ptr<Trace_State> ptr_t;

     Trace_State()
       : m_file_prefix ( "Trace" )
     {}


     virtual ~Trace_State();

     Trace_State ( std::string prefix );

     void set_Trace_File_Prefix ( std::string name );

     void set_Trace_Level ( boost::uint32_t level );

     void set_Trace_Area_Mask ( boost::uint32_t mask );

     void open_Trace_File ( void );

     std::string get_ID_String ( void );

     void close_Trace_File ( void );

     boost::uint32_t get_Trace_Level ( void ) const;

     boost::uint32_t get_Trace_Area_Mask ( void ) const;

     bool is_Valid_Level ( boost::uint32_t lvl );

     bool is_Valid_Area_Mask ( boost::uint32_t mask );


     void write_Message ( interface::ITraceable::ptr_t trace )
     {
       // Write ID
       m_log_stream << boost::format("%s (pid=%d thread_id=" )
         % this->get_ID_String()
         % trace->getPID()
                    << trace->getThreadID()
                    << ") "
                    << std::flush;

       m_log_stream << Trace_State_Utils::get_Level_String(trace->getLevel()) << trace->get_Formatted_String() << std::endl << std::flush;
     }


   private:

     std::string m_file_prefix;

     std::ofstream m_log_stream;
   };

 } /* namespace trace */
} /* namespace trace */


namespace myproject { namespace trace {

   Trace_State::Trace_State( std::string prefix )
       : m_file_prefix ( prefix )
   {}

   Trace_State::~Trace_State()
   {
       this->close_Trace_File();
   }

   void
   Trace_State::set_Trace_File_Prefix ( std::string name )
   {
   }

   bool
   Trace_State::is_Valid_Level ( boost::uint32_t lvl )
   {
     return true;
   }

   bool
   Trace_State::is_Valid_Area_Mask ( boost::uint32_t )
   {
     return true;
   }

   void
   Trace_State::set_Trace_Level ( boost::uint32_t level )
   {
   }

   void
   Trace_State::set_Trace_Area_Mask ( boost::uint32_t mask )
   {
   }

   void
   Trace_State::open_Trace_File ( void )
   {
       if ( ! m_log_stream.is_open() )
           {
             // Create file name
             std::stringstream name;

             name << boost::format("%s_%s.txt")
               % m_file_prefix
               % this->get_ID_String();

             std::string file_name = name.str();

             m_log_stream.open ( file_name.c_str() );
           }
   }

   std::string
   Trace_State::get_ID_String ( void )
   {
       // Create id string
       std::stringstream name;

       // Get current time
       boost::posix_time::ptime now = boost::posix_time::second_clock::local_time();

       std::tm tm_ref = boost::posix_time::to_tm ( now );

       boost::gregorian::date today = now.date();

       name << boost::format ( "%1%_%2%:%3%:%4%" )
           % boost::gregorian::to_iso_extended_string ( today )
           % tm_ref.tm_hour
           % tm_ref.tm_min
           % tm_ref.tm_sec;

       return name.str();
   }

   void
   Trace_State::close_Trace_File ( void )
   {
       if ( m_log_stream.is_open() )
           {
             m_log_stream << std::flush;

             m_log_stream.close();
           }
   }

   boost::uint32_t
   Trace_State::get_Trace_Level ( void ) const
   {
       return 0;
   }

   boost::uint32_t
   Trace_State::get_Trace_Area_Mask ( void ) const
   {
       return 0;
   }

} /* namespace trace */
} /* namespace trace */



namespace myproject { namespace trace {

   //
   // Turn Trace into a singleton class that contains a worker thread
   // - Wait for data
   //   - If data exists then process
   //   - Else wait
   // Add method for adding a ITraceable object. This will lock the logging vector, add
   //  element then signal the boost condition variable
   class Trace : public Singleton<Trace> {

     friend class Singleton<Trace>;

   public:

     ~Trace();

     static void write_Trace ( boost::uint32_t area, boost::uint32_t level, std::string name )
     {
       interface::ITraceable::ptr_t string_ptr ( new StringTraceable ( area, level, name ) );
       Trace::Instance().add_Trace ( string_ptr );
     }

     template <typename UnsignedType>
     static void write_Trace ( boost::uint32_t area, boost::uint32_t level, std::string format, UnsignedType value )
     {
       interface::ITraceable::ptr_t unsigned_ptr ( new NumberTraceable<UnsignedType> ( area, level, format, value ) );
       Trace::Instance().add_Trace ( unsigned_ptr );
     }

     void add_Trace ( interface::ITraceable::ptr_t trace );

     void set_Trace_Level ( boost::uint32_t level );

     void set_Trace_Area_Mask ( boost::uint32_t mask );

     void open_Trace_File ();

     void close_Trace_File();

   private:

     Trace();

     // Worker thread functions
     void threadMain();
     void processTraces(boost::unique_lock<boost::mutex>& lock);

     // Synchronization variables
     boost::mutex m_lock;
     boost::condition_variable m_condition;

     // Data variables
     typedef std::vector < myproject::interface::ITraceable::ptr_t > QueueType;
     QueueType m_queue;

     // Thread variables
     boost::shared_ptr<boost::thread> m_thread;
     bool m_hasWork;

     // Logging
     Trace_State m_state;
   };

 } /* namespace trace */
} /* namespace myproject */

namespace myproject { namespace trace {

   Trace::Trace ()
     : m_hasWork ( true ),
       m_state ( "Trace" )
   {
     // start thread
     m_thread = boost::shared_ptr<boost::thread> ( new boost::thread ( boost::bind ( &Trace::threadMain, this ) ) );
   }

   Trace::~Trace()
   {
     // stop thread
     {
       boost::lock_guard<boost::mutex> lock ( m_lock );
       m_hasWork = false;
     }

     m_condition.notify_one();

     m_thread->join();
   }

   void Trace::add_Trace ( interface::ITraceable::ptr_t trace )
   {
     // lock queue
     {
       boost::lock_guard<boost::mutex> lock ( m_lock );
       m_queue.push_back ( trace );
     }

     m_condition.notify_one();
   }

   void Trace::threadMain()
   {
     boost::unique_lock<boost::mutex> lock ( m_lock );

     while ( m_hasWork )
       {
         if ( m_queue.size() == 0 )
           {
             m_condition.wait ( lock );
           }
         else
           {
             this->processTraces(lock);
           }
       }
   }

   void Trace::processTraces(boost::unique_lock<boost::mutex>& lock)
   {
     assert ( lock.owns_lock() );

     QueueType local_queue ( m_queue.begin(), m_queue.end() );
     m_queue.clear();

     lock.unlock();

     for ( QueueType::iterator pos = local_queue.begin();
           pos != local_queue.end();
           pos++ )
       {
         myproject::interface::ITraceable::ptr_t trace_obj = (*pos);
         m_state.write_Message ( trace_obj );
       }

     lock.lock();
   }

   void Trace::set_Trace_Level ( boost::uint32_t level )
   {
     m_state.set_Trace_Level ( level );
   }

   void Trace::set_Trace_Area_Mask ( boost::uint32_t mask )
   {
     m_state.set_Trace_Area_Mask ( mask );
   }

   void Trace::open_Trace_File()
   {
     m_state.open_Trace_File();
   }

   void Trace::close_Trace_File()
   {
     m_state.close_Trace_File();
   }

 } /* namespace trace */
} /* namespace myproject */


int main ( int, char** )
{
 namespace trace = myproject::trace;
 namespace api = myproject::api;

 trace::Trace::Instance().open_Trace_File();

 myproject::interface::ITraceable::ptr_t tmp_ptr ( new trace::StringTraceable( 0, api::TraceLevel::INFO, "funky" ) );

 trace::Trace::Instance().add_Trace ( tmp_ptr );

 trace::Trace::Instance().close_Trace_File();
}


_______________________________________________
Boost-users mailing list
Boost-users@lists.boost.org
http://lists.boost.org/mailman/listinfo.cgi/boost-users