From: Alex Rousskov Date: Wed, 15 Jun 2016 22:08:16 +0000 (+1200) Subject: Do not allow low-level debugging to hide important/critical messages. X-Git-Tag: SQUID_3_5_20~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4e4f1f3e3693585ae46087952e43fbc620ddd421;p=thirdparty%2Fsquid.git Do not allow low-level debugging to hide important/critical messages. Removed debugs() side effects that inadvertently resulted in some important/critical messages logged at the wrong debugging level and, hence, becoming invisible to the admin. The removed side effects set the "current" debugging level when a debugs() parameter called a function that also called debugs(). The last nested debugs() called affected the level of all debugs() still in progress! Related changes: * Reentrant debugging messages no longer clobber parent messages. Each debugging message is logged separately, in the natural order of debugs() calls that would have happened if debugs() were a function (that gets already evaluated arguments) and not a macro (that evaluates its arguments in the middle of the call). This order is "natural" because good macros work like functions from the caller point of view. * Assertions hit while evaluating debugs() parameters are now logged instead of being lost with the being-built debugs() log line. * 10-20% faster debugs() performance because we no longer allocate a new std::ostringstream buffer for the vast majority of debugs() calls. Only reentrant calls get a new buffer. * Removed old_debug(), addressing an old "needs to die" to-do. * Removed do_debug() that changed debugging level while testing whether debugging is needed. Use side-effect-free Debug::Enabled() instead. Also removed the OutStream wrapper class. The wrapper was added in trunk revision 13767 that promised to (but did not?) MemPool the debug output buffers. We no longer "new" the buffer stream so a custom new() method would be unused. Besides, the r13767 explanation implied that providing a Child::new() method would somehow overwrite Parent::allocator_type, which did not compute for me. Finally, Squid "new"s other allocator- enabled STL objects without overriding their new methods so either the same problem is still there or it did not exist (or was different?). Also removed Debug::xassert() because the debugs() assertions now work OK without that hack. --- diff --git a/src/Debug.h b/src/Debug.h index cc28d5ed5b..6819d57821 100644 --- a/src/Debug.h +++ b/src/Debug.h @@ -49,38 +49,51 @@ class Debug { public: + /// meta-information for debugs() or a similar debugging call + class Context + { + public: + Context(const int aSectionLevel, const int aLevel); + + int level; ///< minimum debugging level required by the debugs() call + int sectionLevel; ///< maximum debugging level allowed during the call + + private: + friend class Debug; + void rewind(const int aSection, const int aLevel); + void formatStream(); + Context *upper; ///< previous or parent record in nested debugging calls + std::ostringstream buf; ///< debugs() output sink + }; + + /// whether debugging the given section and the given level produces output + static bool Enabled(const int section, const int level) + { + return level <= Debug::Levels[section]; + } + static char *debugOptions; static char *cache_log; static int rotateNumber; static int Levels[MAX_DEBUG_SECTIONS]; - static int level; ///< minimum debugging level required by debugs() call - static int sectionLevel; ///< maximum debugging level allowed now static int override_X; static int log_stderr; static bool log_syslog; - static std::ostream &getDebugOut(); - static void finishDebug(); static void parseOptions(char const *); -private: - // Hack: replaces global ::xassert() to debug debugging assertions - static void xassert(const char *msg, const char *file, int line); + /// minimum level required by the current debugs() call + static int Level() { return Current ? Current->level : 1; } + /// maximum level currently allowed + static int SectionLevel() { return Current ? Current->sectionLevel : 1; } - /// Wrapper class to prevent SquidNew.h overrides getting confused - /// with the libc++6 std::ostringstream definitions - class OutStream : public std::ostringstream - { - // XXX: use MEMPROXY_CLASS() once that no longer pulls in typedefs.h and enums.h and globals.h - public: - void *operator new(size_t size) throw(std::bad_alloc) {return xmalloc(size);} - void operator delete(void *address) throw() {xfree(address);} - void *operator new[] (size_t size) throw(std::bad_alloc) ; //{return xmalloc(size);} - void operator delete[] (void *address) throw() ; // {xfree(address);} - }; + /// opens debugging context and returns output buffer + static std::ostringstream &Start(const int section, const int level); + /// logs output buffer created in Start() and closes debugging context + static void Finish(); - static OutStream *CurrentDebug; - static int TheDepth; // level of nested debugging calls +private: + static Context *Current; ///< deepest active context; nil outside debugs() }; extern FILE *debug_log; @@ -91,15 +104,15 @@ const char * SkipBuildPrefix(const char* path); /* Debug stream */ #define debugs(SECTION, LEVEL, CONTENT) \ do { \ - if ((Debug::level = (LEVEL)) <= Debug::Levels[SECTION]) { \ - Debug::sectionLevel = Debug::Levels[SECTION]; \ - std::ostream &_dbo=Debug::getDebugOut(); \ - if (Debug::level > DBG_IMPORTANT) { \ - _dbo << (SECTION) << ',' << (LEVEL) << "| " \ + const int _dbg_level = (LEVEL); \ + if (Debug::Enabled((SECTION), _dbg_level)) { \ + std::ostream &_dbo = Debug::Start((SECTION), _dbg_level); \ + if (_dbg_level > DBG_IMPORTANT) { \ + _dbo << (SECTION) << ',' << _dbg_level << "| " \ << SkipBuildPrefix(__FILE__)<<"("<<__LINE__<<") "<<__FUNCTION__<<": "; \ } \ _dbo << CONTENT; \ - Debug::finishDebug(); \ + Debug::Finish(); \ } \ } while (/*CONSTCOND*/ 0) @@ -135,10 +148,6 @@ inline std::ostream& operator <<(std::ostream &os, const uint8_t d) return (os << (int)d); } -/* Legacy debug style. Still used in some places. needs to die... */ -#define do_debug(SECTION, LEVEL) ((Debug::level = (LEVEL)) <= Debug::Levels[SECTION]) -#define old_debug(SECTION, LEVEL) if do_debug((SECTION), (LEVEL)) _db_print - /* Legacy debug function definitions */ void _db_init(const char *logfile, const char *options); void _db_print(const char *,...) PRINTF_FORMAT_ARG1; diff --git a/src/adaptation/ecap/Host.cc b/src/adaptation/ecap/Host.cc index 720c7bd148..140553ba0e 100644 --- a/src/adaptation/ecap/Host.cc +++ b/src/adaptation/ecap/Host.cc @@ -147,18 +147,16 @@ Adaptation::Ecap::Host::openDebug(libecap::LogVerbosity lv) { const int squidLevel = SquidLogLevel(lv); const int squidSection = 93; // XXX: this should be a global constant - // XXX: Debug.h should provide this to us - if ((Debug::level = squidLevel) <= Debug::Levels[squidSection]) - return &Debug::getDebugOut(); - else - return NULL; + return Debug::Enabled(squidSection, squidLevel) ? + &Debug::Start(squidSection, squidLevel) : + NULL; } void Adaptation::Ecap::Host::closeDebug(std::ostream *debug) { if (debug) - Debug::finishDebug(); + Debug::Finish(); } Adaptation::Ecap::Host::MessagePtr diff --git a/src/base/Lock.h b/src/base/Lock.h index dfc8ddc1c3..3a389eb0b6 100644 --- a/src/base/Lock.h +++ b/src/base/Lock.h @@ -33,7 +33,7 @@ public: /// All locks must be cleared before it may be destroyed. void lock() const { #if defined(LOCKCOUNT_DEBUG) - old_debug(0,1)("Incrementing this %p from count %u\n",this,count_); + debugs(0,1, "Incrementing this " << static_cast(this) << " from count " << count_); #endif assert(count_ < UINT32_MAX); ++count_; @@ -43,7 +43,7 @@ public: /// All locks must be cleared before it may be destroyed. uint32_t unlock() const { #if defined(LOCKCOUNT_DEBUG) - old_debug(0,1)("Decrementing this %p from count %u\n",this,count_); + debugs(0,1, "Decrementing this " << static_cast(this) << " from count " << count_); #endif assert(count_ > 0); return --count_; diff --git a/src/client_side.cc b/src/client_side.cc index d348fdf016..e05b6a2430 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -3778,7 +3778,7 @@ clientNegotiateSSL(int fd, void *data) debugs(83, 2, "clientNegotiateSSL: Session " << SSL_get_session(ssl) << " reused on FD " << fd << " (" << fd_table[fd].ipaddr << ":" << (int)fd_table[fd].remote_port << ")"); } else { - if (do_debug(83, 4)) { + if (Debug::Enabled(83, 4)) { /* Write out the SSL session details.. actually the call below, but * OpenSSL headers do strange typecasts confusing GCC.. */ /* PEM_write_SSL_SESSION(debug_log, SSL_get_session(ssl)); */ diff --git a/src/debug.cc b/src/debug.cc index 7ee6e62d64..b2a789186c 100644 --- a/src/debug.cc +++ b/src/debug.cc @@ -22,8 +22,6 @@ int Debug::override_X = 0; int Debug::log_stderr = -1; bool Debug::log_syslog = false; int Debug::Levels[MAX_DEBUG_SECTIONS]; -int Debug::level; -int Debug::sectionLevel; char *Debug::cache_log = NULL; int Debug::rotateNumber = -1; FILE *debug_log = NULL; @@ -134,7 +132,7 @@ _db_print_file(const char *format, va_list args) static void _db_print_stderr(const char *format, va_list args) { - if (Debug::log_stderr < Debug::level) + if (Debug::log_stderr < Debug::Level()) return; if (debug_log == stderr) @@ -149,7 +147,7 @@ _db_print_syslog(const char *format, va_list args) { /* level 0,1 go to syslog */ - if (Debug::level > 1) + if (Debug::Level() > 1) return; if (!Debug::log_syslog) @@ -162,7 +160,7 @@ _db_print_syslog(const char *format, va_list args) tmpbuf[BUFSIZ - 1] = '\0'; - syslog(Debug::level == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf); + syslog(Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf); } #endif /* HAVE_SYSLOG */ @@ -512,7 +510,7 @@ debugLogTime(void) static char buf[128]; static time_t last_t = 0; - if (Debug::level > 1) { + if (Debug::Level() > 1) { char buf2[128]; tm = localtime(&t); strftime(buf2, 127, "%Y/%m/%d %H:%M:%S", tm); @@ -714,55 +712,75 @@ ctx_get_descr(Ctx ctx) return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : ""; } -int Debug::TheDepth = 0; +Debug::Context *Debug::Current = NULL; -Debug::OutStream *Debug::CurrentDebug(NULL); +Debug::Context::Context(const int aSection, const int aLevel): + level(aLevel), + sectionLevel(Levels[aSection]), + upper(Current) +{ + formatStream(); +} -std::ostream & -Debug::getDebugOut() +/// Optimization: avoids new Context creation for every debugs(). +void +Debug::Context::rewind(const int aSection, const int aLevel) { - assert(TheDepth >= 0); - ++TheDepth; - if (TheDepth > 1) { - assert(CurrentDebug); - *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{"; - } else { - assert(!CurrentDebug); - CurrentDebug = new Debug::OutStream; - // set default formatting flags - CurrentDebug->setf(std::ios::fixed); - CurrentDebug->precision(2); - } - return *CurrentDebug; + level = aLevel; + sectionLevel = Levels[aSection]; + assert(upper == Current); + + buf.str(std::string()); + buf.clear(); + // debugs() users are supposed to preserve format, but + // some do not, so we have to waste cycles resetting it for all. + formatStream(); } +/// configures default formatting for the debugging stream void -Debug::finishDebug() +Debug::Context::formatStream() +{ + const static std::ostringstream cleanStream; + buf.flags(cleanStream.flags() | std::ios::fixed); + buf.width(cleanStream.width()); + buf.precision(2); + buf.fill(' '); + // If this is not enough, use copyfmt(cleanStream) which is ~10% slower. +} + +std::ostringstream & +Debug::Start(const int section, const int level) { - assert(TheDepth >= 0); - assert(CurrentDebug); - if (TheDepth > 1) { - *CurrentDebug << "}-" << TheDepth << std::endl; + Context *future = NULL; + + // prepare future context + if (Current) { + // all reentrant debugs() calls get here; create a dedicated context + future = new Context(section, level); } else { - assert(TheDepth == 1); - _db_print("%s\n", CurrentDebug->str().c_str()); - delete CurrentDebug; - CurrentDebug = NULL; + // Optimization: Nearly all debugs() calls get here; avoid allocations + static Context *topContext = new Context(1, 1); + topContext->rewind(section, level); + future = topContext; } - --TheDepth; + + Current = future; + + return future->buf; } -// Hack: replaces global ::xassert() to debug debugging assertions -// Relies on assert macro calling xassert() without a specific scope. void -Debug::xassert(const char *msg, const char *file, int line) +Debug::Finish() { - - if (CurrentDebug) { - *CurrentDebug << "assertion failed: " << file << ":" << line << - ": \"" << msg << "\""; - } - abort(); + // TODO: Optimize to remove at least one extra copy. + _db_print("%s\n", Current->buf.str().c_str()); + + Context *past = Current; + Current = past->upper; + if (Current) + delete past; + // else it was a static topContext from Debug::Start() } size_t @@ -799,8 +817,8 @@ Raw::print(std::ostream &os) const // finalize debugging level if no level was set explicitly via minLevel() const int finalLevel = (level >= 0) ? level : - (size_ > 40 ? DBG_DATA : Debug::sectionLevel); - if (finalLevel <= Debug::sectionLevel) { + (size_ > 40 ? DBG_DATA : Debug::SectionLevel()); + if (finalLevel <= Debug::SectionLevel()) { os << (label_ ? '=' : ' '); if (data_) os.write(data_, size_); diff --git a/src/esi/Expression.cc b/src/esi/Expression.cc index bf176f3d5f..8a1d3e95c4 100644 --- a/src/esi/Expression.cc +++ b/src/esi/Expression.cc @@ -116,8 +116,6 @@ static int addmember(stackmember * stack, int *stackdepth, static int membercompare(stackmember a, stackmember b); static char const *trim(char const *s); static stackmember getsymbol(const char *s, char const **endptr); -static void printliteral(stackmember s); -static void printmember(stackmember s); /* -2 = failed to compate * -1 = a less than b @@ -846,105 +844,106 @@ getsymbol(const char *s, char const **endptr) return rv; } -void -printliteral(stackmember s) +static void +printLiteral(std::ostream &os, const stackmember &s) { switch (s.valuestored) { case ESI_LITERAL_INVALID: - old_debug(86, 1)( " Invalid " ); + os << " Invalid "; break; case ESI_LITERAL_FLOAT: - old_debug(86,1)("%f", s.value.floating); + os << s.value.floating; break; case ESI_LITERAL_STRING: - old_debug(86,1)("'%s'", s.value.string); + os << '\'' << s.value.string << '\''; break; case ESI_LITERAL_INT: - old_debug(86,1)("%d", s.value.integral); + os << s.value.integral; break; case ESI_LITERAL_BOOL: - old_debug(86,1)("%s",s.value.integral ? "true" : "false"); + os << (s.value.integral ? "true" : "false"); } } -void -printmember(stackmember s) +static std::ostream & +operator <<(std::ostream &os, const stackmember &s) { switch (s.valuetype) { case ESI_EXPR_INVALID: - old_debug(86,1)(" Invalid "); + os << " Invalid "; break; case ESI_EXPR_LITERAL: - printliteral(s); + printLiteral(os, s); break; case ESI_EXPR_EXPR: - old_debug(86,1)("%s", s.value.integral ? "true" : "false"); + os << (s.value.integral ? "true" : "false"); break; case ESI_EXPR_OR: - old_debug(86,1)("|"); + os << "|"; break; case ESI_EXPR_AND: - old_debug(86,1)("&"); + os << "&"; break; case ESI_EXPR_NOT: - old_debug(86,1)("!"); + os << "!"; break; case ESI_EXPR_START: - old_debug(86,1)("("); + os << "("; break; case ESI_EXPR_END: - old_debug(86,1)(")"); + os << ")"; break; case ESI_EXPR_EQ: - old_debug(86,1)("=="); + os << "=="; break; case ESI_EXPR_NOTEQ: - old_debug(86,1)("!="); + os << "!="; break; case ESI_EXPR_LESS: - old_debug(86,1)("<"); + os << "<"; break; case ESI_EXPR_LESSEQ: - old_debug(86,1)("<="); + os << "<="; break; case ESI_EXPR_MORE: - old_debug(86,1)(">"); + os << ">"; break; case ESI_EXPR_MOREEQ: - old_debug(86,1)(">="); + os << ">="; break; } + + return os; } void dumpstack(stackmember * stack, int depth) { - int i; - - for (i = 0; i < depth; ++i) - printmember(stack[i]); - - if (depth) - old_debug(86,1)("\n"); + if (depth) { + std::ostringstream buf; + for (int i = 0; i < depth; ++i) + buf << stack[i]; + debugs(86,1, buf.str()); + } } int diff --git a/src/servers/FtpServer.cc b/src/servers/FtpServer.cc index babdd16118..12df5efcc2 100644 --- a/src/servers/FtpServer.cc +++ b/src/servers/FtpServer.cc @@ -1303,7 +1303,7 @@ Ftp::Server::handleRequest(HttpRequest *request) Must(header.has(HDR_FTP_ARGUMENTS)); String ¶ms = header.findEntry(HDR_FTP_ARGUMENTS)->value; - if (do_debug(9, 2)) { + if (Debug::Enabled(9, 2)) { MemBuf mb; Packer p; mb.init(); diff --git a/src/ssl/support.cc b/src/ssl/support.cc index 60ee84c3bc..6f01a94313 100644 --- a/src/ssl/support.cc +++ b/src/ssl/support.cc @@ -135,7 +135,7 @@ ssl_temp_rsa_cb(SSL * ssl, int anInt, int keylen) } if (newkey) { - if (do_debug(83, 5)) + if (Debug::Enabled(83, 5)) PEM_write_RSAPrivateKey(debug_log, rsa, NULL, NULL, 0, NULL, NULL); debugs(83, DBG_IMPORTANT, "Generated ephemeral RSA key of length " << keylen); diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc index 561b5636c2..13efc6e185 100644 --- a/src/tests/stub_debug.cc +++ b/src/tests/stub_debug.cc @@ -17,14 +17,11 @@ #include "Debug.h" FILE *debug_log = NULL; -int Debug::TheDepth = 0; char *Debug::debugOptions; char *Debug::cache_log= NULL; int Debug::rotateNumber = 0; int Debug::Levels[MAX_DEBUG_SECTIONS]; -int Debug::level; -int Debug::sectionLevel; int Debug::override_X = 0; int Debug::log_stderr = 1; bool Debug::log_syslog = false; @@ -81,69 +78,50 @@ _db_print(const char *format,...) static void _db_print_stderr(const char *format, va_list args) { - if (1 < Debug::level) + if (1 < Debug::Level()) return; vfprintf(stderr, format, args); } -Debug::OutStream *Debug::CurrentDebug(NULL); - -std::ostream & -Debug::getDebugOut() -{ - assert(TheDepth >= 0); - ++TheDepth; - if (TheDepth > 1) { - assert(CurrentDebug); - *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{"; - } else { - assert(!CurrentDebug); - CurrentDebug = new Debug::OutStream; - // set default formatting flags - CurrentDebug->setf(std::ios::fixed); - CurrentDebug->precision(2); - } - return *CurrentDebug; -} - void Debug::parseOptions(char const *) { return; } -void -Debug::finishDebug() +const char* +SkipBuildPrefix(const char* path) { - assert(TheDepth >= 0); - assert(CurrentDebug); - if (TheDepth > 1) { - *CurrentDebug << "}-" << TheDepth << std::endl; - } else { - assert(TheDepth == 1); - _db_print("%s\n", CurrentDebug->str().c_str()); - delete CurrentDebug; - CurrentDebug = NULL; - } - --TheDepth; + return path; } -void -Debug::xassert(const char *msg, const char *file, int line) +Debug::Context *Debug::Current = NULL; + +Debug::Context::Context(const int aSection, const int aLevel): + level(aLevel), + sectionLevel(Levels[aSection]), + upper(Current) { + buf.setf(std::ios::fixed); + buf.precision(2); +} - if (CurrentDebug) { - *CurrentDebug << "assertion failed: " << file << ":" << line << - ": \"" << msg << "\""; - } - abort(); +std::ostringstream & +Debug::Start(const int section, const int level) +{ + Current = new Context(section, level); + return Current->buf; } -const char* -SkipBuildPrefix(const char* path) +void +Debug::Finish() { - return path; + if (Current) { + _db_print("%s\n", Current->buf.str().c_str()); + delete Current; + Current = NULL; + } } std::ostream & @@ -157,10 +135,13 @@ Raw::print(std::ostream &os) const // finalize debugging level if no level was set explicitly via minLevel() const int finalLevel = (level >= 0) ? level : - (size_ > 40 ? DBG_DATA : Debug::sectionLevel); - if (finalLevel <= Debug::sectionLevel) { + (size_ > 40 ? DBG_DATA : Debug::SectionLevel()); + if (finalLevel <= Debug::SectionLevel()) { os << (label_ ? '=' : ' '); - os.write(data_, size_); + if (data_) + os.write(data_, size_); + else + os << "[null]"; } return os;