[Boost-users] Tracking down a race condition

Subject: [Boost-users] Tracking down a race condition
From: Stephen Torri (storri_at_[hidden])
Date: 2010-01-23 16:09:20

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();
}