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

@@ -20,95 +20,276 @@
 //
 // $Id$
 
-#include <iostream>
-
 #include "logstream.hxx"
 
-logstream *logstream::global_logstream = 0;
+#include <iostream>
+#include <fstream>
 
-bool            logbuf::logging_enabled = true;
+#include <boost/foreach.hpp>
-#ifdef _WIN32
-   bool         logbuf::has_console = true;
-#endif
-sgDebugClass    logbuf::logClass        = SG_NONE;
-sgDebugPriority logbuf::logPriority     = SG_INFO;
-streambuf*      logbuf::sbuf            = NULL;
 
-namespace {
+#include <simgear/threads/SGThread.hxx>
-struct ignore_me
+#include <simgear/threads/SGQueue.hxx>
+#include <simgear/threads/SGGuard.hxx>
+
+#include <simgear/misc/sg_path.hxx>
+
+const char* debugClassToString(sgDebugClass c)
 {
-    ignore_me()
+    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)
     {
-        logstream::initGlobalLogstream();
+    }
+    
+    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
+        AllocConsole(); // but only if we want a console
+#endif
+    }
+
+    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
+{
+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<LogEntry> m_entries;
+    std::vector<simgear::LogCallback*> m_callbacks;    
+    sgDebugClass m_logClass;
+    sgDebugPriority m_logPriority;
+    bool m_isRunning;
+    
+    void startLog()
+    {
+        SGGuard<SGMutex> 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()
+    {
+        SGGuard<SGMutex> 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()
+/////////////////////////////////////////////////////////////////////////////
+
+static logstream* global_logstream = NULL;
+static LogStreamPrivate* global_privateLogstream = NULL;
+
+logstream::logstream()
 {
-//     if ( sbuf == NULL )
+    global_privateLogstream = new LogStreamPrivate;
-// 	sbuf = cerr.rdbuf();
+    global_privateLogstream->addCallback(new StderrLogCallback);
-}
+    global_privateLogstream->startLog();
-
-logbuf::~logbuf()
-{
-    if ( sbuf )
-	    sync();
-}
-
-void
-logbuf::set_sb( streambuf* sb )
-{
-    if ( sbuf )
-	    sync();
-
-    sbuf = sb;
-}
-
-void
-logbuf::set_log_level( sgDebugClass c, sgDebugPriority p )
-{
-    logClass = c;
-    logPriority = p;
-}
-
-void
-logbuf::set_log_classes (sgDebugClass c)
-{
-    logClass = c;
-}
-
-sgDebugClass
-logbuf::get_log_classes ()
-{
-    return logClass;
-}
-
-void
-logbuf::set_log_priority (sgDebugPriority p)
-{
-    logPriority = p;
-}
-
-sgDebugPriority
-logbuf::get_log_priority ()
-{
-    return logPriority;
 }
 
 void
 logstream::setLogLevels( sgDebugClass c, sgDebugPriority p )
 {
-    logbuf::set_log_level( c, p );
+    // 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;
 }
 
-logstream *
+void
-logstream::initGlobalLogstream()
+logstream::addCallback(simgear::LogCallback* cb)
+{   
+    global_privateLogstream->addCallback(cb);
+}
+
+void
+logstream::log( sgDebugClass c, sgDebugPriority p,
+        const char* fileName, int line, const std::string& msg)
+{
+    global_privateLogstream->log(c, p, fileName, line, msg);
+}
+
+bool
+logstream::would_log( sgDebugClass c, sgDebugPriority p ) const
+{
+    return global_privateLogstream->would_log(c,p);
+}
+
+sgDebugClass
+logstream::get_log_classes() const
+{
+    return global_privateLogstream->m_logClass;
+}
+    
+sgDebugPriority
+logstream::get_log_priority() const
+{
+    return global_privateLogstream->m_logPriority;
+}
+
+void
+logstream::set_log_priority( sgDebugPriority p)
+{
+    global_privateLogstream->m_logPriority = p;
+}
+    
+void
+logstream::set_log_classes( sgDebugClass c)
+{
+    global_privateLogstream->m_logClass = c;
+}
+
+logstream&
+sglog()
 {
     // Force initialization of cerr.
     static std::ios_base::Init initializer;
     if( !global_logstream )
-        global_logstream = new logstream(std::cerr);
+        global_logstream = new logstream();
-    return global_logstream;
+    return *global_logstream;
 }
+
+void
+logstream::logToFile( const SGPath& aPath, sgDebugClass c, sgDebugPriority p )
+{
+    global_privateLogstream->addCallback(new FileLogCallback(aPath.str(), c, p));
+}
+

simgear/debug/logstream.hxx

@@ -26,222 +26,33 @@
 #define _LOGSTREAM_H
 
 #include <simgear/compiler.h>
-
-#ifdef _WIN32
-#  include <windows.h>
-#endif
-
-#include <streambuf>
-#include <ostream>
-#include <cstdio>
-
 #include <simgear/debug/debug_types.h>
 
-using std::streambuf;
+#include <sstream>
-using std::ostream;
 
-//
+// forward decls
-// TODO:
+class SGPath;
-//
+      
-// 1. Change output destination. Done.
+namespace simgear
-// 2. Make logbuf thread safe.
+{
-// 3. Read environment for default debugClass and debugPriority.
+     
-//
+class LogCallback
-
-/**
- * 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) {}
+    virtual ~LogCallback() {}
-    /** Constructor */
+    virtual void operator()(sgDebugClass c, sgDebugPriority p, 
-    logbuf();
+        const char* file, int line, const std::string& aMessage) = 0;
-
-    /** 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& );
-};
-
-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
-{
-    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
-{
-    // logstream_base( streambuf* sb ) : lbuf(sb) {}
-    logstream_base() {}
-
-    logbuf lbuf;
 };
+     
+} // of namespace simgear
 
 /**
  * Class to manage the debug logging stream.
  */
-class logstream : private logstream_base, public std::ostream
+class logstream
 {
 public:
-    /**
+    static void initGlobalLogstream();
-     * 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() ); }
-
     /**
      * 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
+    bool would_log(  sgDebugClass c, sgDebugPriority p ) const;
-    {
+
-        return lbuf.would_log( c, p );
+    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.
+     * the core logging method
-     * @param l log level
      */
-    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;
+     * 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();
+
+private:
+    // constructor
+    logstream();
 };
 
-inline std::ostream&
+logstream& sglog();
-logstream::operator<< ( const loglevel& l )
-{
-    lbuf.set_log_state( l.logClass, l.logPriority );
-    return *this;
-}
-
-/**
- * \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();
-}
-
 
 /** \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(sglog().would_log(C,P)) {                      \
-	if(__tmplogstreamref.would_log(C,P)) {                      \
+        std::ostringstream os;                             \
-        __tmplogstreamref << loglevel(C,P) << M << std::endl; } \
+        os << M;                                       \
-	} while(0)
+        sglog().log(C, P, __FILE__, __LINE__, os.str()); \
+    } \
+} while(0)
 #endif
 
 #define SG_ORIGIN __FILE__ ":" SG_STRINGIZE(__LINE__)