From 2a74cc9e5f16bc47ad7ff547878c8457161bf0b0 Mon Sep 17 00:00:00 2001 From: Julian Smith Date: Sat, 12 Sep 2020 00:05:24 +0100 Subject: [PATCH] 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 | 2 +- simgear/debug/LogEntry.cxx | 5 +- simgear/debug/LogEntry.hxx | 17 ++- simgear/debug/logdelta.cxx | 246 +++++++++++++++++++++++++++++++++++ simgear/debug/logdelta.hxx | 45 +++++++ simgear/debug/logstream.cxx | 45 ++++--- simgear/debug/logstream.hxx | 21 ++- simgear/io/HTTPClient.cxx | 2 +- 8 files changed, 352 insertions(+), 31 deletions(-) create mode 100644 simgear/debug/logdelta.cxx create mode 100644 simgear/debug/logdelta.hxx diff --git a/simgear/debug/CMakeLists.txt b/simgear/debug/CMakeLists.txt index 0b2a2bab..e474d382 100644 --- a/simgear/debug/CMakeLists.txt +++ b/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}") diff --git a/simgear/debug/LogEntry.cxx b/simgear/debug/LogEntry.cxx index 5f8c5357..e6be0871 100644 --- a/simgear/debug/LogEntry.cxx +++ b/simgear/debug/LogEntry.cxx @@ -26,6 +26,7 @@ LogEntry::~LogEntry() { if (freeFilename) { free(const_cast(file)); + free(const_cast(function)); } } @@ -34,12 +35,14 @@ 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); } } -} // namespace simgear \ No newline at end of file +} // namespace simgear diff --git a/simgear/debug/LogEntry.hxx b/simgear/debug/LogEntry.hxx index 9a4cce63..70cea9a7 100644 --- a/simgear/debug/LogEntry.hxx +++ b/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), - file(f), line(l), - message(msg) + const char* file, int line, const char* function, + const std::string& msg, bool freeFilename) + : + debugClass(c), + debugPriority(p), + originalPriority(op), + file(file), + line(line), + function(function), + message(msg), + freeFilename(freeFilename) { } @@ -46,9 +54,10 @@ 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' }; -} // namespace simgear \ No newline at end of file +} // namespace simgear diff --git a/simgear/debug/logdelta.cxx b/simgear/debug/logdelta.cxx new file mode 100644 index 00000000..00654326 --- /dev/null +++ b/simgear/debug/logdelta.cxx @@ -0,0 +1,246 @@ +#include "debug_types.h" + +#include +#include +#include +#include + +#include + + +/* 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 and + 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 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 . + 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 at first char in . 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 m_cache; + std::vector 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) { + // and 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; +} diff --git a/simgear/debug/logdelta.hxx b/simgear/debug/logdelta.hxx new file mode 100644 index 00000000..9652b93d --- /dev/null +++ b/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: + + = + := + ::= + := + + 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); diff --git a/simgear/debug/logstream.cxx b/simgear/debug/logstream.cxx index 7900bb65..92adbe34 100644 --- a/simgear/debug/logstream.cxx +++ b/simgear/debug/logstream.cxx @@ -22,6 +22,7 @@ #include +#include "logdelta.hxx" #include "logstream.hxx" #include @@ -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(p) == static_cast(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, - bool freeFilename) + const char* fileName, int line, const char* function, + 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); - entry.freeFilename = freeFilename; + simgear::LogEntry entry(c, tp, p, fileName, line, function, msg, 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 diff --git a/simgear/debug/logstream.hxx b/simgear/debug/logstream.hxx index 4c52b935..c58c3cb0 100644 --- a/simgear/debug/logstream.hxx +++ b/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__) diff --git a/simgear/io/HTTPClient.cxx b/simgear/io/HTTPClient.cxx index c50634ea..7611dd4d 100644 --- a/simgear/io/HTTPClient.cxx +++ b/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); }