From ab8373b989f787d8aca04a3387e4debd7414bc64 Mon Sep 17 00:00:00 2001 From: James Turner Date: Tue, 5 Feb 2013 23:49:25 +0100 Subject: [PATCH] Rewrite logging code. Support multiple backends, and make it thread-safe. Use an internal thread to push log entries to backends, to avoid blocking the submitting thread for any time. --- simgear/debug/logstream.cxx | 275 +++++++++++++++++++++++++++------ simgear/debug/logstream.hxx | 296 +++++++----------------------------- 2 files changed, 286 insertions(+), 285 deletions(-) diff --git a/simgear/debug/logstream.cxx b/simgear/debug/logstream.cxx index 664038b9..9e4cafa8 100644 --- a/simgear/debug/logstream.cxx +++ b/simgear/debug/logstream.cxx @@ -20,95 +20,276 @@ // // $Id$ +#include "logstream.hxx" + #include +#include -#include "logstream.hxx" +#include + +#include +#include +#include -logstream *logstream::global_logstream = 0; +#include -bool logbuf::logging_enabled = true; +const char* debugClassToString(sgDebugClass c) +{ + switch (c) { + case SG_NONE: return "none"; + case SG_TERRAIN: return "terrain"; + case SG_ASTRO: return "astro"; + case SG_FLIGHT: return "flight"; + case SG_INPUT: return "input"; + case SG_GL: return "opengl"; + case SG_VIEW: return "view"; + case SG_COCKPIT: return "cockpit"; + case SG_GENERAL: return "general"; + case SG_MATH: return "math"; + case SG_EVENT: return "event"; + case SG_AIRCRAFT: return "aircraft"; + case SG_AUTOPILOT: return "autopilot"; + case SG_IO: return "io"; + case SG_CLIPPER: return "clipper"; + case SG_NETWORK: return "network"; + case SG_ATC: return "atc"; + case SG_NASAL: return "nasal"; + case SG_INSTR: return "instruments"; + case SG_SYSTEMS: return "systems"; + case SG_AI: return "ai"; + case SG_ENVIRONMENT:return "environment"; + case SG_SOUND: return "sound"; + case SG_NAVAID: return "navaid"; + default: return "unknown"; + } +} + +////////////////////////////////////////////////////////////////////////////// + +class FileLogCallback : public simgear::LogCallback +{ +public: + FileLogCallback(const std::string& aPath, sgDebugClass c, sgDebugPriority p) : + m_file(aPath.c_str(), std::ios_base::out | std::ios_base::trunc), + m_class(c), + m_priority(p) + { + } + + virtual void operator()(sgDebugClass c, sgDebugPriority p, + const char* file, int line, const std::string& message) + { + if ((c & m_class) == 0 || p < m_priority) return; + m_file << debugClassToString(c) << ":" << (int) p + << ":" << file << ":" << line << ":" << message << std::endl; + } +private: + std::ofstream m_file; + sgDebugClass m_class; + sgDebugPriority m_priority; +}; + +class StderrLogCallback : public simgear::LogCallback +{ +public: + StderrLogCallback() + { #ifdef _WIN32 - bool logbuf::has_console = true; + AllocConsole(); // but only if we want a console #endif -sgDebugClass logbuf::logClass = SG_NONE; -sgDebugPriority logbuf::logPriority = SG_INFO; -streambuf* logbuf::sbuf = NULL; + } -namespace { -struct ignore_me + virtual void operator()(sgDebugClass c, sgDebugPriority p, + const char* file, int line, const std::string& aMessage) + { + // if running under MSVC, we could use OutputDebugString here + + fprintf(stderr, "%s\n", aMessage.c_str()); + //fprintf(stderr, "%s:%d:%s:%d:%s\n", debugClassToString(c), p, + // file, line, aMessage.c_str()); + fflush(stderr); + } +private: + +}; + +class LogStreamPrivate : public SGThread { - ignore_me() +private: + /** + * storage of a single log entry. Note this is not used for a persistent + * store, but rather for short term buffering between the submitting + * and output threads. + */ + class LogEntry + { + public: + LogEntry(sgDebugClass c, sgDebugPriority p, + const char* f, int l, const std::string& msg) : + debugClass(c), debugPriority(p), file(f), line(l), + message(msg) + { + } + + sgDebugClass debugClass; + sgDebugPriority debugPriority; + const char* file; + int line; + std::string message; + }; +public: + LogStreamPrivate() : + m_logClass(SG_ALL), m_logPriority(SG_WARN), + m_isRunning(false) + { } + + SGMutex m_lock; + SGBlockingQueue m_entries; + std::vector m_callbacks; + sgDebugClass m_logClass; + sgDebugPriority m_logPriority; + bool m_isRunning; + + void startLog() + { + SGGuard g(m_lock); + if (m_isRunning) return; + m_isRunning = true; + start(); + } + + virtual void run() + { + while (1) { + LogEntry entry(m_entries.pop()); + if ((entry.debugClass == SG_NONE) && !strcmp(entry.file, "done")) { + return; + } + + // submit to each installed callback in turn + BOOST_FOREACH(simgear::LogCallback* cb, m_callbacks) { + (*cb)(entry.debugClass, entry.debugPriority, + entry.file, entry.line, entry.message); + } + } // of main thread loop + } + + bool stop() { - logstream::initGlobalLogstream(); + SGGuard g(m_lock); + if (!m_isRunning) { + return false; + } + + // log a special marker value, which will cause the thread to wakeup, + // and then exit + log(SG_NONE, SG_ALERT, "done", -1, ""); + join(); + + m_isRunning = false; + return true; + } + + void addCallback(simgear::LogCallback* cb) + { + bool wasRunning = stop(); + m_callbacks.push_back(cb); + if (wasRunning) { + startLog(); + } + } + + bool would_log( sgDebugClass c, sgDebugPriority p ) const + { + if (p >= SG_INFO) return true; + return ((c & m_logClass) != 0 && p >= m_logPriority); + } + + void log( sgDebugClass c, sgDebugPriority p, + const char* fileName, int line, const std::string& msg) + { + LogEntry entry(c, p, fileName, line, msg); + m_entries.push(entry); } }; -static ignore_me im; -} -logbuf::logbuf() -{ -// if ( sbuf == NULL ) -// sbuf = cerr.rdbuf(); -} +///////////////////////////////////////////////////////////////////////////// + +static logstream* global_logstream = NULL; +static LogStreamPrivate* global_privateLogstream = NULL; -logbuf::~logbuf() +logstream::logstream() { - if ( sbuf ) - sync(); + global_privateLogstream = new LogStreamPrivate; + global_privateLogstream->addCallback(new StderrLogCallback); + global_privateLogstream->startLog(); } void -logbuf::set_sb( streambuf* sb ) +logstream::setLogLevels( sgDebugClass c, sgDebugPriority p ) { - if ( sbuf ) - sync(); - - sbuf = sb; + // we don't guard writing these with a mutex, since we assume setting + // occurs very rarely, and any data races are benign. + global_privateLogstream->m_logClass = c; + global_privateLogstream->m_logPriority = p; } void -logbuf::set_log_level( sgDebugClass c, sgDebugPriority p ) -{ - logClass = c; - logPriority = p; +logstream::addCallback(simgear::LogCallback* cb) +{ + global_privateLogstream->addCallback(cb); } void -logbuf::set_log_classes (sgDebugClass c) +logstream::log( sgDebugClass c, sgDebugPriority p, + const char* fileName, int line, const std::string& msg) { - logClass = c; + global_privateLogstream->log(c, p, fileName, line, msg); } -sgDebugClass -logbuf::get_log_classes () +bool +logstream::would_log( sgDebugClass c, sgDebugPriority p ) const { - return logClass; + return global_privateLogstream->would_log(c,p); } -void -logbuf::set_log_priority (sgDebugPriority p) +sgDebugClass +logstream::get_log_classes() const { - logPriority = p; + return global_privateLogstream->m_logClass; } - + sgDebugPriority -logbuf::get_log_priority () +logstream::get_log_priority() const { - return logPriority; + return global_privateLogstream->m_logPriority; } void -logstream::setLogLevels( sgDebugClass c, sgDebugPriority p ) +logstream::set_log_priority( sgDebugPriority p) { - logbuf::set_log_level( c, p ); + global_privateLogstream->m_logPriority = p; +} + +void +logstream::set_log_classes( sgDebugClass c) +{ + global_privateLogstream->m_logClass = c; } -logstream * -logstream::initGlobalLogstream() +logstream& +sglog() { // Force initialization of cerr. static std::ios_base::Init initializer; if( !global_logstream ) - global_logstream = new logstream(std::cerr); - return global_logstream; + global_logstream = new logstream(); + return *global_logstream; +} + +void +logstream::logToFile( const SGPath& aPath, sgDebugClass c, sgDebugPriority p ) +{ + global_privateLogstream->addCallback(new FileLogCallback(aPath.str(), c, p)); } + diff --git a/simgear/debug/logstream.hxx b/simgear/debug/logstream.hxx index d3649a4a..87021903 100644 --- a/simgear/debug/logstream.hxx +++ b/simgear/debug/logstream.hxx @@ -26,222 +26,33 @@ #define _LOGSTREAM_H #include - -#ifdef _WIN32 -# include -#endif - -#include -#include -#include - #include -using std::streambuf; -using std::ostream; - -// -// TODO: -// -// 1. Change output destination. Done. -// 2. Make logbuf thread safe. -// 3. Read environment for default debugClass and debugPriority. -// - -/** - * logbuf is an output-only streambuf with the ability to disable sets of - * messages at runtime. Only messages with priority >= logbuf::logPriority - * and debugClass == logbuf::logClass are output. - */ -#ifdef SG_NEED_STREAMBUF_HACK -class logbuf : public __streambuf -#else -class logbuf : public std::streambuf -#endif -{ -public: - // logbuf( streambuf* sb ) : sbuf(sb) {} - /** Constructor */ - logbuf(); - - /** Destructor */ - ~logbuf(); - - /** - * Is logging enabled? - * @return true or false*/ - bool enabled() { return logging_enabled; } - - /** - * Set the logging level of subsequent messages. - * @param c debug class - * @param p priority - */ - void set_log_state( sgDebugClass c, sgDebugPriority p ); - - bool would_log( sgDebugClass c, sgDebugPriority p ) const; - - /** - * Set the global logging level. - * @param c debug class - * @param p priority - */ - static void set_log_level( sgDebugClass c, sgDebugPriority p ); - - - /** - * Set the allowed logging classes. - * @param c All enabled logging classes anded together. - */ - static void set_log_classes (sgDebugClass c); - - - /** - * Get the logging classes currently enabled. - * @return All enabled debug logging anded together. - */ - static sgDebugClass get_log_classes (); - - - /** - * Set the logging priority. - * @param c The priority cutoff for logging messages. - */ - static void set_log_priority (sgDebugPriority p); - - - /** - * Get the current logging priority. - * @return The priority cutoff for logging messages. - */ - static sgDebugPriority get_log_priority (); - - - /** - * Set the stream buffer - * @param sb stream buffer - */ - void set_sb( std::streambuf* sb ); - -#ifdef _WIN32 - static void has_no_console() { has_console = false; } -#endif - -protected: - - /** sync/flush */ - inline virtual int sync(); - - /** overflow */ - int_type overflow( int ch ); - // int xsputn( const char* s, istreamsize n ); - -private: - - // The streambuf used for actual output. Defaults to cerr.rdbuf(). - static std::streambuf* sbuf; - - static bool logging_enabled; -#ifdef _WIN32 - static bool has_console; -#endif - static sgDebugClass logClass; - static sgDebugPriority logPriority; - -private: - - // Not defined. - logbuf( const logbuf& ); - void operator= ( const logbuf& ); -}; +#include -inline int -logbuf::sync() -{ - return sbuf->pubsync(); -} - -inline void -logbuf::set_log_state( sgDebugClass c, sgDebugPriority p ) -{ - logging_enabled = ((c & logClass) != 0 && p >= logPriority); -} - -inline bool -logbuf::would_log( sgDebugClass c, sgDebugPriority p ) const -{ - return ((c & logClass) != 0 && p >= logPriority); -} - -inline logbuf::int_type -logbuf::overflow( int c ) -{ -#ifdef _WIN32 - if ( logging_enabled ) { - if ( !has_console ) { - AllocConsole(); - freopen("conin$", "r", stdin); - freopen("conout$", "w", stdout); - freopen("conout$", "w", stderr); - has_console = true; - } - return sbuf->sputc(c); - } - else - return EOF == 0 ? 1: 0; -#else - return logging_enabled ? sbuf->sputc(c) : (EOF == 0 ? 1: 0); -#endif -} - -/** - * logstream manipulator for setting the log level of a message. - */ -struct loglevel +// forward decls +class SGPath; + +namespace simgear { - loglevel( sgDebugClass c, sgDebugPriority p ) - : logClass(c), logPriority(p) {} - - sgDebugClass logClass; - sgDebugPriority logPriority; -}; - -/** - * A helper class that ensures a streambuf and ostream are constructed and - * destroyed in the correct order. The streambuf must be created before the - * ostream but bases are constructed before members. Thus, making this class - * a private base of logstream, declared to the left of ostream, we ensure the - * correct order of construction and destruction. - */ -struct logstream_base + +class LogCallback { - // logstream_base( streambuf* sb ) : lbuf(sb) {} - logstream_base() {} - - logbuf lbuf; +public: + virtual ~LogCallback() {} + virtual void operator()(sgDebugClass c, sgDebugPriority p, + const char* file, int line, const std::string& aMessage) = 0; }; + +} // of namespace simgear /** * Class to manage the debug logging stream. */ -class logstream : private logstream_base, public std::ostream +class logstream { public: - /** - * The default is to send messages to cerr. - * @param out output stream - */ - logstream( std::ostream& out ) - // : logstream_base(out.rdbuf()), - : logstream_base(), - std::ostream(&lbuf) { lbuf.set_sb(out.rdbuf());} - - /** - * Set the output stream - * @param out output stream - */ - void set_output( std::ostream& out ) { lbuf.set_sb( out.rdbuf() ); } - + static void initGlobalLogstream(); /** * Set the global log class and priority level. * @param c debug class @@ -249,42 +60,49 @@ public: */ void setLogLevels( sgDebugClass c, sgDebugPriority p ); - bool would_log( sgDebugClass c, sgDebugPriority p ) const - { - return lbuf.would_log( c, p ); - }; + bool would_log( sgDebugClass c, sgDebugPriority p ) const; + + void logToFile( const SGPath& aPath, sgDebugClass c, sgDebugPriority p ); + + void set_log_priority( sgDebugPriority p); + + void set_log_classes( sgDebugClass c); + + sgDebugClass get_log_classes() const; + + sgDebugPriority get_log_priority() const; /** - * Output operator to capture the debug level and priority of a message. - * @param l log level + * the core logging method */ - inline std::ostream& operator<< ( const loglevel& l ); + void log( sgDebugClass c, sgDebugPriority p, + const char* fileName, int line, const std::string& msg); + + /** + * \relates logstream + * Return the one and only logstream instance. + * We use a function instead of a global object so we are assured that cerr + * has been initialised. + * @return current logstream + */ friend logstream& sglog(); - static logstream *initGlobalLogstream(); -protected: - static logstream *global_logstream; -}; - -inline std::ostream& -logstream::operator<< ( const loglevel& l ) -{ - lbuf.set_log_state( l.logClass, l.logPriority ); - return *this; -} + + /** + * register a logging callback. Note callbacks are run in a + * dedicated thread, so callbacks which pass data to other threads + * must use appropriate locking. + */ + void addCallback(simgear::LogCallback* cb); + + // friend logstream& sglog(); +// static logstream *initGlobalLogstream(); -/** - * \relates logstream - * Return the one and only logstream instance. - * We use a function instead of a global object so we are assured that cerr - * has been initialised. - * @return current logstream - */ -inline logstream& -sglog() -{ - return *logstream::initGlobalLogstream(); -} +private: + // constructor + logstream(); +}; +logstream& sglog(); /** \def SG_LOG(C,P,M) * Log a message. @@ -296,10 +114,12 @@ sglog() # define SG_LOG(C,P,M) #else # define SG_LOG(C,P,M) do { \ - logstream& __tmplogstreamref(sglog()); \ - if(__tmplogstreamref.would_log(C,P)) { \ - __tmplogstreamref << loglevel(C,P) << M << std::endl; } \ - } while(0) + if(sglog().would_log(C,P)) { \ + std::ostringstream os; \ + os << M; \ + sglog().log(C, P, __FILE__, __LINE__, os.str()); \ + } \ +} while(0) #endif #define SG_ORIGIN __FILE__ ":" SG_STRINGIZE(__LINE__) -- 2.39.5