Added logdelta system to allow control of log priorities based on source filename, line and function name.

See simgear/debug/logdelta.hxx for usage.

simgear/debug/CMakeLists.txt

@@ -5,6 +5,6 @@ set(HEADERS debug_types.h
     logstream.hxx BufferedLogCallback.hxx OsgIoCapture.hxx
     LogCallback.hxx LogEntry.hxx)
 set(SOURCES logstream.cxx BufferedLogCallback.cxx
-    LogCallback.cxx LogEntry.cxx)
+    LogCallback.cxx LogEntry.cxx logdelta.cxx)
 
 simgear_component(debug debug "${SOURCES}" "${HEADERS}")

simgear/debug/LogEntry.cxx

@@ -26,6 +26,7 @@ LogEntry::~LogEntry()
 {
     if (freeFilename) {
         free(const_cast<char*>(file));
+        free(const_cast<char*>(function));
     }
 }
 
@@ -34,11 +35,13 @@ LogEntry::LogEntry(const LogEntry& c) : debugClass(c.debugClass),
                                         originalPriority(c.originalPriority),
                                         file(c.file),
                                         line(c.line),
+                                        function(c.function),
                                         message(c.message),
                                         freeFilename(c.freeFilename)
 {
     if (c.freeFilename) {
         file = strdup(c.file);
+        function = strdup(c.function);
     }
 }
 

simgear/debug/LogEntry.hxx

@@ -30,9 +30,17 @@ class LogEntry
 public:
     LogEntry(sgDebugClass c, sgDebugPriority p,
              sgDebugPriority op,
-             const char* f, int l, const std::string& msg) : debugClass(c), debugPriority(p), originalPriority(op),
+             const char* file, int line, const char* function,
-                                                             file(f), line(l),
+             const std::string& msg, bool freeFilename)
-                                                             message(msg)
+    :
+    debugClass(c),
+    debugPriority(p),
+    originalPriority(op),
+    file(file),
+    line(line),
+    function(function),
+    message(msg),
+    freeFilename(freeFilename)
     {
     }
 
@@ -46,6 +54,7 @@ public:
     const sgDebugPriority originalPriority;
     const char* file;
     const int line;
+    const char* function;
     const std::string message;
 
     bool freeFilename = false; ///< if true, we own, and therefore need to free, the memory pointed to by 'file'

simgear/debug/logdelta.cxx

@@ -0,0 +1,246 @@
+#include "debug_types.h"
+
+#include <iostream>
+#include <map>
+#include <string>
+#include <vector>
+
+#include <assert.h>
+
+
+/* A single item in SG_LOG_DELTAS. */
+struct logDeltaItem
+{
+    logDeltaItem(const std::string& file_prefix, int line,
+            const std::string& function_prefix, int delta)
+    :
+    file_prefix(file_prefix),
+    line(line),
+    function_prefix(function_prefix),
+    delta(delta)
+    {}
+    std::string file_prefix;
+    int         line;
+    std::string function_prefix;
+    int         delta;
+};
+
+/* A single item in SG_LOG_DELTAS for use in logDelta's cache. */
+struct logDeltaCacheItem
+{
+    logDeltaCacheItem(const char* file, int line, const char* function)
+    :
+    file(file),
+    line(line),
+    function(function)
+    {}
+    const char* file;
+    int         line;
+    const char* function;
+};
+
+/* We compare logDeltaCacheItem's based on the raw values of the <file> and
+<function> pointer values rather than doing string comparisons; this works
+because these are generally from __FILE__ and __FUNCTION__ so don't change. */
+bool operator < (const logDeltaCacheItem& a, const logDeltaCacheItem& b)
+{
+    if (a.file != b.file) {
+        return a.file < b.file;
+    }
+    if (a.function != b.function) {
+        return a.function < b.function;
+    }
+    return a.line < b.line;
+}
+
+struct logDelta
+{
+    logDelta()
+    {
+        // We output diagnostics to std::cerr during this startup phase.
+        //
+        const char* items = getenv("SG_LOG_DELTAS");
+        if (!items) {
+            std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                    << "$SG_LOG_DELTAS is not set"
+                    << "\n";
+            return;
+        }
+
+        std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                << "Parsing $SG_LOG_DELTAS: '" << items << "'"
+                << "\n";
+
+        std::string text = items;
+        for(;;) {
+            if (text.empty()) break;
+            
+            std::string item = next_subitem(text, " ,");
+            std::string item_orig = item;
+            
+            std::string ffl = next_subitem(item, "=");
+            std::string delta = item;
+            
+            if (delta.empty()
+                    or delta.find_first_not_of("0123456789-+") != std::string::npos
+                    ) {
+                std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                        << "Ignoring item '" << item_orig << "'"
+                        << " because invalid delta '" << delta
+                        << "'\n";
+                continue;
+            }
+            int delta2 = atoi(delta.c_str());
+            
+            std::string file = next_subitem(ffl, ":");
+            std::string function = next_subitem(ffl, ":");
+            std::string line = next_subitem(ffl, ":");
+            
+            if (line.empty()) {
+                /* If <function> is all digits, treat as line number. */
+                if (function.find_first_not_of("0123456789-+") == std::string::npos) {
+                    std::swap(function, line);
+                }
+            }
+            
+            int line2 = -1;
+            if (!line.empty()) {
+                if (line.find_first_not_of("0123456789-+") != std::string::npos) {
+                    std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                            << "Ignoring item '" << item_orig << "'"
+                            << " because invalid line number '" << line
+                            << "'\n";
+                    continue;
+                }
+                line2 = atoi(line.c_str());
+            }
+            if (1) std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                    << "adding"
+                    << " file_prefix=" << file
+                    << " function_prefix=" << function
+                    << " line=" << line2
+                    << " delta=" << delta2
+                    << "\n";
+            m_items.push_back(logDeltaItem(file, line2, function, delta2));
+        }
+    }
+    
+    /* Returns delta logging level for (file,line,function), using m_items and
+    caching results in m_cache. */
+    int operator()(const char* file, int line, const char* function)
+    {
+        if (m_items.empty()) {
+            // Fast path in default case where SG_LOG_DELTAS not set.
+            return 0;
+        }
+        if (!file)      file = "";
+        if (!function)  function = "";
+        logDeltaCacheItem flf(file, line, function);
+        
+        auto it = m_cache.find(flf);
+        
+        if (it == m_cache.end()) {
+            auto best = m_items.end();
+            for (auto item=m_items.begin(); item!=m_items.end(); ++item) {
+                if (startswith(file, item->file_prefix)
+                        && startswith(function, item->function_prefix)
+                        && (item->line == -1 || line == item->line)
+                        ) {
+                    // (file,line,function) matches <item>.
+                    if (best == m_items.end() || cmp(*item, *best) > 0) {
+                        // Prefer longer matches.
+                        best = item;
+                    }
+                }
+            }
+            int delta = (best == m_items.end()) ? 0 : best->delta;
+            m_cache[flf] = delta;
+            it = m_cache.find(flf);
+            
+            assert(m_cache.find(flf)->second == delta);
+            if (0 and delta != 0) {
+                std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                        << "caching delta=" << delta
+                        << " for: " << file << ":" << line << ":" << function
+                        << "\n";
+            }
+        }
+        
+        int delta = it->second;
+        if (0) {
+            std::cerr << __FILE__ << ":" << __LINE__ << ": "
+                        << "returning delta=" << delta
+                        << " for: " << file << ":" << line << ":" << function
+                        << "\n";
+        }
+        return delta;
+    }
+    
+    static bool startswith(const std::string s, const std::string& prefix)
+    {
+        return s.rfind(prefix, 0) == 0;
+    }
+    
+    /* Implements comparison of matching logDeltaItem's. We prefer longer
+    filename prefixes and longer function name prefixes. */
+    static int cmp(const logDeltaItem& a, const logDeltaItem& b)
+    {
+        if (a.file_prefix.size() != b.file_prefix.size()) {
+            return a.file_prefix.size() - b.file_prefix.size();
+        }
+        if (a.function_prefix.size() != b.function_prefix.size()) {
+            return a.function_prefix.size() - b.function_prefix.size();
+        }
+        return 0;
+    }
+    
+    /* Splits <io_item> at first char in <separators>. Changes io_item to be
+    the remainder and returns the first portion. */
+    static std::string next_subitem(std::string& io_item, const char* separators)
+    {
+        std::string ret;
+        size_t p = io_item.find_first_of(separators);
+        if (p == std::string::npos) {
+            ret = io_item;
+            io_item = "";
+        }
+        else {
+            ret = io_item.substr(0, p);
+            io_item = io_item.substr(p+1);
+        }
+        return ret;
+    }
+    
+    private:
+        std::map<logDeltaCacheItem, int>    m_cache;
+        std::vector<logDeltaItem>           m_items;
+};
+
+/* log_delta(filename, line, function) returns the logging level delta for the
+specified line of code. */
+static logDelta log_delta;
+
+sgDebugPriority logDeltaAdd(sgDebugPriority priority,
+        const char* file, int line, const char* function,
+        bool freeFilename)
+{
+    if (freeFilename) {
+        // <file> and <function> are from strdup() so using them in std::map
+        // key is unreliable and will leak memory.
+        return priority;
+    }
+    int priority_new = (int) priority + log_delta(file, line, function);
+    
+    // Don't cause new popups.
+    if (priority < SG_POPUP and priority_new >= SG_POPUP) {
+        priority_new = SG_POPUP - 1;
+    }
+    // Keep new priority within range of sgDebugPriority enum.
+    if (priority_new < SG_BULK) {
+        priority_new = SG_BULK;
+    }
+    if (priority_new > SG_MANDATORY_INFO) {
+        priority_new = SG_MANDATORY_INFO;
+    }
+    return (sgDebugPriority) priority_new;
+}

simgear/debug/logdelta.hxx

@@ -0,0 +1,45 @@
+#pragma once
+
+#include "debug_types.h"
+
+/*
+Support for additional logging control based on source filename, line number
+and function name.
+
+If environmental variable SG_LOG_DELTAS is defined, we use it to
+increment/decrement logging levels based on source filename prefixes, function
+name prefixes and source line numbers.
+
+SG_LOG_DELTAS is a comma or space-separated list of individual items, each of
+which specifies a source filename prefix, a function name prefix, a line number
+and a log level delta.
+
+Items are not added together, and the order in which items are specified does
+not matter. Instead, matching items with longer filename prefixes override
+matching items with short filename prefixes. If filename prefixes are the same
+length, we compare based on the length of the items' function prefixes.
+
+The syntax for each item is one of:
+
+    <filename-prefix>=<delta>
+    <filename-prefix>:<function-prefix>=<delta>
+    <filename-prefix>:<function-prefix>:<line>=<delta>
+    <filename-prefix>:<line>=<delta>
+
+<delta> is required. The other fields can be empty, in which case they match
+anything. So '=1' will increment the logging level for all calls to SG_LOG().
+
+For example:
+    SG_LOG_DELTAS="flightgear/=-1,flightgear/src/Scenery/SceneryPager.cxx=+2,simgear/scene/=1"
+
+This will increment diagnostics level for all code in
+flightgear/src/Scenery/SceneryPager.cxx by 2, and increment diagnostics
+level in simgear/scene/ by 1. All code in flightgear/ (apart from code in
+flightgear/src/Scenery/SceneryPager.cxx) will have its diagnostic level
+decremented by 1.
+*/
+
+/* Returns new priority based on delta for file:line:function. */
+sgDebugPriority logDeltaAdd(sgDebugPriority priority,
+        const char* file, int line, const char* function,
+        bool freeFilename);

simgear/debug/logstream.cxx

@@ -22,6 +22,7 @@
 
 #include <simgear_config.h>
 
+#include "logdelta.hxx"
 #include "logstream.hxx"
 
 #include <cstring>
@@ -401,7 +402,7 @@ public:
 
             // log a special marker value, which will cause the thread to wakeup,
             // and then exit
-            log(SG_NONE, SG_ALERT, "done", -1, "", false);
+            log(SG_NONE, SG_ALERT, "done", -1, "", "", false);
         }
         join();
 
@@ -450,7 +451,9 @@ public:
         }
     }
 
-    bool would_log( sgDebugClass c, sgDebugPriority p ) const
+    bool would_log( sgDebugClass c, sgDebugPriority p,
+            const char* file, int line, const char* function,
+            bool freeFilename ) const
     {
         // Testing mode, so always log.
         if (m_testMode) return true;
@@ -459,28 +462,30 @@ public:
         // separately and thus it makes more sense to allow these message through.
         if (static_cast<unsigned>(p) == static_cast<unsigned>(SG_OSG)) return true;
 
-        p = translatePriority(p);
+        p = translatePriority(p, file, line, function, freeFilename);
         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,
+            const char* fileName, int line, const char* function,
-             bool freeFilename)
+            const std::string& msg, bool freeFilename)
     {
-        auto tp = translatePriority(p);
+        auto tp = translatePriority(p, fileName, line, function, freeFilename);
         if (!m_fileLine) {
             /* This prevents output of file:line in StderrLogCallback. */
             line = -line;
         }
 
-        simgear::LogEntry entry(c, tp, p, fileName, line, msg);
+        simgear::LogEntry entry(c, tp, p, fileName, line, function, msg, freeFilename);
-        entry.freeFilename = freeFilename;
         m_entries.push(entry);
     }
 
-    sgDebugPriority translatePriority(sgDebugPriority in) const
+    sgDebugPriority translatePriority(sgDebugPriority in,
+            const char* filename, int line, const char* function,
+            bool freeFilename) const
     {
+        in = logDeltaAdd(in, filename, line, function, freeFilename);
         if (in == SG_DEV_WARN) {
             return m_developerMode ? SG_WARN : SG_DEBUG;
         }
@@ -540,20 +545,24 @@ logstream::removeCallback(simgear::LogCallback* cb)
 
 void
 logstream::log( sgDebugClass c, sgDebugPriority p,
-        const char* fileName, int line, const std::string& msg)
+        const char* fileName, int line, const char* function,
+        const std::string& msg)
 {
-    d->log(c, p, fileName, line, msg, false);
+    d->log(c, p, fileName, line, function, msg, false);
 }
 
 void
 logstream::logCopyingFilename( sgDebugClass c, sgDebugPriority p,
-         const char* fileName, int line, const std::string& msg)
+         const char* fileName, int line, const char* function,
+         const std::string& msg)
 {
-    d->log(c, p, strdup(fileName), line, msg, true);
+    d->log(c, p, strdup(fileName), line, strdup(function), msg, true);
 }
 
 
-void logstream::hexdump(sgDebugClass c, sgDebugPriority p, const char* fileName, int line, const void *mem, unsigned int len, unsigned int columns)
+void logstream::hexdump(sgDebugClass c, sgDebugPriority p,
+        const char* fileName, int line, const char* function,
+        const void *mem, unsigned int len, unsigned int columns)
 {
     unsigned int i, j;
     char temp[3000], temp1[3000];
@@ -601,7 +610,7 @@ void logstream::hexdump(sgDebugClass c, sgDebugPriority p, const char* fileName,
                     strcat(temp, ".");
                 }
             }
-            log(c, p, fileName, line, temp );
+            log(c, p, fileName, line, function, temp );
             *temp = 0;
         }
     }
@@ -634,9 +643,11 @@ logstream::has_popup()
 }
 
 bool
-logstream::would_log( sgDebugClass c, sgDebugPriority p ) const
+logstream::would_log( sgDebugClass c, sgDebugPriority p,
+        const char* file, int line, const char* function,
+        bool freeFilename ) const
 {
-    return d->would_log(c,p);
+    return d->would_log(c, p, file, line, function, freeFilename);
 }
 
 sgDebugClass

simgear/debug/logstream.hxx

@@ -74,7 +74,9 @@ public:
      */
     void setLogLevels( sgDebugClass c, sgDebugPriority p );
 
-    bool would_log(  sgDebugClass c, sgDebugPriority p ) const;
+    bool would_log(  sgDebugClass c, sgDebugPriority p,
+            const char* file, int line, const char* function,
+            bool freeFilename=false ) const;
 
     void logToFile( const SGPath& aPath, sgDebugClass c, sgDebugPriority p );
 
@@ -108,7 +110,8 @@ public:
      * the core logging method
      */
     void log( sgDebugClass c, sgDebugPriority p,
-            const char* fileName, int line, const std::string& msg);
+            const char* fileName, int line, const char* function,
+            const std::string& msg);
 
     // overload of above, which can transfer ownership of the file-name.
     // this is unecesary overhead when logging from C++, since __FILE__ points
@@ -116,12 +119,15 @@ public:
     // example) since during shutdown the filename is freed by Nasal GC
     // asynchronously with the logging thread.
     void logCopyingFilename( sgDebugClass c, sgDebugPriority p,
-             const char* fileName, int line, const std::string& msg);
+             const char* fileName, int line, const char* function,
+             const std::string& msg);
     
     /**
     * output formatted hex dump of memory block
     */
-    void hexdump(sgDebugClass c, sgDebugPriority p, const char* fileName, int line, const void *mem, unsigned int len, unsigned int columns = 16);
+    void hexdump(sgDebugClass c, sgDebugPriority p,
+            const char* fileName, int line, const char* function,
+            const void *mem, unsigned int len, unsigned int columns = 16);
 
 
     /**
@@ -195,9 +201,9 @@ logstream& sglog();
  * @param M message
  */
 # define SG_LOGX(C,P,M) \
-    do { if(sglog().would_log(C,P)) {                         \
+    do { if(sglog().would_log(C,P, __FILE__, __LINE__, __FUNCTION__)) { \
         std::ostringstream os; os << M;                  \
-        sglog().log(C, P, __FILE__, __LINE__, os.str()); \
+        sglog().log(C, P, __FILE__, __LINE__, __FUNCTION__, os.str()); \
         if ((P) == SG_POPUP) sglog().popup(os.str());    \
     } } while(0)
 #ifdef FG_NDEBUG
@@ -207,7 +213,8 @@ logstream& sglog();
 #else
 # define SG_LOG(C,P,M)	SG_LOGX(C,P,M)
 # define SG_LOG_NAN(C,P,M) do { SG_LOGX(C,P,M); throw std::overflow_error(M); } while(0)
-# define SG_LOG_HEXDUMP(C,P,MEM,LEN) if(sglog().would_log(C,P)) sglog().hexdump(C, P, __FILE__, __LINE__, MEM, LEN)
+# define SG_LOG_HEXDUMP(C,P,MEM,LEN) if(sglog().would_log(C,P, __FILE__, __LINE__, __FUNCTION__)) \
+        sglog().hexdump(C, P, __FILE__, __LINE__, __FUNCTION__, MEM, LEN)
 #endif
 
 #define SG_ORIGIN __FILE__ ":" SG_STRINGIZE(__LINE__)

simgear/io/HTTPClient.cxx

@@ -264,7 +264,7 @@ void Client::makeRequest(const Request_ptr& r)
     curl_easy_setopt(curlRequest, CURLOPT_USERAGENT, d->userAgent.c_str());
     curl_easy_setopt(curlRequest, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1);
 
-    if (sglog().would_log(SG_TERRASYNC, SG_DEBUG)) {
+    if (sglog().would_log(SG_TERRASYNC, SG_DEBUG, __FILE__, __LINE__, __FUNCTION__)) {
         curl_easy_setopt(curlRequest, CURLOPT_VERBOSE, 1);
     }