From dae0d0ff8bf6097d1d66576b2434c3e6b716585d Mon Sep 17 00:00:00 2001 From: Richard Harrison Date: Thu, 29 Nov 2018 19:29:14 +0100 Subject: [PATCH] Logging changes. 1. Anything that comes in from OSG will always be logged; it seems somewhat redundant to have to set the FG log level to be identical to the OSG log level to see these messages. 2. Console output will now have delta time (since start), priority and class. 3. Log file output wil also have delta time (since start), priority and class. Times are displayed as delta decimal seconds since the logger was created e.g. 1294.06 [INFO]:terrain Some log message --- simgear/debug/OsgIoCapture.hxx | 39 +++++++++++++--------- simgear/debug/debug_types.h | 5 ++- simgear/debug/logstream.cxx | 60 +++++++++++++++++++++++++++++++--- simgear/debug/logstream.hxx | 1 + 4 files changed, 84 insertions(+), 21 deletions(-) diff --git a/simgear/debug/OsgIoCapture.hxx b/simgear/debug/OsgIoCapture.hxx index 7804dda2..9f14e441 100644 --- a/simgear/debug/OsgIoCapture.hxx +++ b/simgear/debug/OsgIoCapture.hxx @@ -6,10 +6,10 @@ using namespace osg; /** - * merge OSG output into our logging system, so it gets recorded to file, - * and so we can display a GUI console with renderer issues, especially - * shader compilation warnings and errors. - */ +* merge OSG output into our logging system, so it gets recorded to file, +* and so we can display a GUI console with renderer issues, especially +* shader compilation warnings and errors. +*/ class NotifyLogger : public osg::NotifyHandler { public: @@ -22,24 +22,33 @@ public: if (strstr(message, "the final reference count was")) { // as this is going to segfault ignore the translation of severity and always output the message. SG_LOG(SG_GL, SG_ALERT, message); - int* trigger_segfault = 0; - *trigger_segfault = 0; +#ifndef DEBUG + throw new std::string(message); + //int* trigger_segfault = 0; + //*trigger_segfault = 0; +#endif return; } - SG_LOG(SG_GL, translateSeverity(severity), message); + char*tmessage = strdup(message); + char*lf = strrchr(tmessage, '\n'); + if (lf) + *lf = 0; + + SG_LOG(SG_OSG, translateSeverity(severity), tmessage); + free(tmessage); } private: sgDebugPriority translateSeverity(osg::NotifySeverity severity) { switch (severity) { - case osg::ALWAYS: - case osg::FATAL: return SG_ALERT; - case osg::WARN: return SG_WARN; - case osg::NOTICE: - case osg::INFO: return SG_INFO; - case osg::DEBUG_FP: - case osg::DEBUG_INFO: return SG_DEBUG; - default: return SG_ALERT; + case osg::ALWAYS: + case osg::FATAL: return SG_ALERT; + case osg::WARN: return SG_WARN; + case osg::NOTICE: + case osg::INFO: return SG_INFO; + case osg::DEBUG_FP: + case osg::DEBUG_INFO: return SG_DEBUG; + default: return SG_ALERT; } } }; diff --git a/simgear/debug/debug_types.h b/simgear/debug/debug_types.h index cc856556..9289cb48 100644 --- a/simgear/debug/debug_types.h +++ b/simgear/debug/debug_types.h @@ -35,7 +35,10 @@ typedef enum { SG_TERRASYNC = 0x01000000, SG_PARTICLES = 0x02000000, SG_HEADLESS = 0x04000000, - SG_UNDEFD = 0x08000000, // For range checking + // SG_OSG (OSG notify) - will always be displayed regardless of FG log settings as OSG log level is configured + // separately and thus it makes more sense to allow these message through. + SG_OSG = 0x08000000, + SG_UNDEFD = 0x10000000, // For range checking SG_ALL = 0xFFFFFFFF } sgDebugClass; diff --git a/simgear/debug/logstream.cxx b/simgear/debug/logstream.cxx index 4e2f6ee4..eeda8901 100644 --- a/simgear/debug/logstream.cxx +++ b/simgear/debug/logstream.cxx @@ -38,6 +38,7 @@ #include #include +#include #if defined (SG_WINDOWS) // for AllocConsole, OutputDebugString @@ -61,7 +62,12 @@ LogCallback::LogCallback(sgDebugClass c, sgDebugPriority p) : bool LogCallback::shouldLog(sgDebugClass c, sgDebugPriority p) const { - return ((c & m_class) != 0 && p >= m_priority); + + if ((c & m_class) != 0 && p >= m_priority) + return true; + if (c == SG_OSG) // always have OSG logging as it OSG logging is configured separately. + return true; + return false; } void LogCallback::setLogLevels( sgDebugClass c, sgDebugPriority p ) @@ -69,6 +75,18 @@ void LogCallback::setLogLevels( sgDebugClass c, sgDebugPriority p ) m_priority = p; m_class = c; } +const char* LogCallback::debugPriorityToString(sgDebugPriority p) +{ + switch (p) { + case SG_ALERT: return "ALRT"; + case SG_BULK: return "BULK"; + case SG_DEBUG: return "DBUG"; + case SG_INFO: return "INFO"; + case SG_POPUP: return "POPU"; + case SG_WARN: return "WARN"; + default: return "UNKN"; + } +} const char* LogCallback::debugClassToString(sgDebugClass c) { @@ -101,6 +119,7 @@ const char* LogCallback::debugClassToString(sgDebugClass c) case SG_TERRASYNC: return "terrasync"; case SG_PARTICLES: return "particles"; case SG_HEADLESS: return "headless"; + case SG_OSG: return "OSG"; default: return "unknown"; } } @@ -112,18 +131,41 @@ const char* LogCallback::debugClassToString(sgDebugClass c) class FileLogCallback : public simgear::LogCallback { public: + SGTimeStamp logTimer; FileLogCallback(const SGPath& aPath, sgDebugClass c, sgDebugPriority p) : simgear::LogCallback(c, p) { m_file.open(aPath, std::ios_base::out | std::ios_base::trunc); + logTimer.stamp(); } virtual void operator()(sgDebugClass c, sgDebugPriority p, const char* file, int line, const std::string& message) { if (!shouldLog(c, p)) return; - m_file << debugClassToString(c) << ":" << (int) p - << ":" << file << ":" << line << ":" << message << std::endl; + + +// fprintf(stderr, "%7.2f [%.8s]:%-10s %s\n", logTimer.elapsedMSec() / 1000.0, debugPriorityToString(p), debugClassToString(c), aMessage.c_str()); + m_file + << std::fixed + << std::setprecision(2) + << std::setw(8) + << std::right + << (logTimer.elapsedMSec() / 1000.0) + << std::setw(8) + << std::left + << " ["+std::string(debugPriorityToString(p))+"]:" + << std::setw(10) + << std::left + << debugClassToString(c) + << " " + << file + << ":" + << line + << ":" + << message << std::endl; + //m_file << debugClassToString(c) << ":" << (int)p + // << ":" << file << ":" << line << ":" << message << std::endl; } private: sg_ofstream m_file; @@ -132,9 +174,12 @@ private: class StderrLogCallback : public simgear::LogCallback { public: + SGTimeStamp logTimer; + StderrLogCallback(sgDebugClass c, sgDebugPriority p) : simgear::LogCallback(c, p) { + logTimer.stamp(); } #if defined (SG_WINDOWS) @@ -148,8 +193,9 @@ public: const char* file, int line, const std::string& aMessage) { if (!shouldLog(c, p)) return; - - fprintf(stderr, "%s\n", aMessage.c_str()); + //fprintf(stderr, "%s\n", aMessage.c_str()); + fprintf(stderr, "%8.2f [%.8s]:%-10s %s\n", logTimer.elapsedMSec()/1000.0, debugPriorityToString(p), debugClassToString(c), aMessage.c_str()); + // file, line, aMessage.c_str()); //fprintf(stderr, "%s:%d:%s:%d:%s\n", debugClassToString(c), p, // file, line, aMessage.c_str()); fflush(stderr); @@ -470,6 +516,10 @@ public: // Testing mode, so always log. if (m_testMode) return true; + // SG_OSG (OSG notify) - will always be displayed regardless of FG log settings as OSG log level is configured + // separately and thus it makes more sense to allow these message through. + if (p == SG_OSG) return true; + p = translatePriority(p); if (p >= SG_INFO) return true; return ((c & m_logClass) != 0 && p >= m_logPriority); diff --git a/simgear/debug/logstream.hxx b/simgear/debug/logstream.hxx index 6d951d4c..30c656c7 100644 --- a/simgear/debug/logstream.hxx +++ b/simgear/debug/logstream.hxx @@ -52,6 +52,7 @@ protected: bool shouldLog(sgDebugClass c, sgDebugPriority p) const; static const char* debugClassToString(sgDebugClass c); + static const char* debugPriorityToString(sgDebugPriority p); private: sgDebugClass m_class; sgDebugPriority m_priority;