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
#include
#include
#include
#include
#include
#include
#include
#include
#include
#include
#include
#include
#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 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 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_lockboost::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_ptrboost::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_ptrboost::thread ( new boost::thread ( boost::bind ( &Trace::threadMain, this ) ) );
}
Trace::~Trace()
{
// stop thread
{
boost::lock_guardboost::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_guardboost::mutex lock ( m_lock );
m_queue.push_back ( trace );
}
m_condition.notify_one();
}
void Trace::threadMain()
{
boost::unique_lockboost::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_lockboost::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();
}
