------------------------------------------------------------ revno: 14058 revision-id: squid3@treenet.co.nz-20160615220816-yqh6bmry6ijvfwi1 parent: squid3@treenet.co.nz-20160524200503-1nn3hijw86ti726r author: Alex Rousskov committer: Amos Jeffries branch nick: 3.5 timestamp: Thu 2016-06-16 10:08:16 +1200 message: 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. ------------------------------------------------------------ # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: squid3@treenet.co.nz-20160615220816-yqh6bmry6ijvfwi1 # target_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # testament_sha1: 1d7a703d3dfe6ebd05138880652ab78c3260a323 # timestamp: 2016-06-15 22:51:04 +0000 # source_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # base_revision_id: squid3@treenet.co.nz-20160524200503-\ # 1nn3hijw86ti726r # # Begin patch === modified file 'src/Debug.h' --- src/Debug.h 2016-01-01 00:14:27 +0000 +++ src/Debug.h 2016-06-15 22:08:16 +0000 @@ -49,38 +49,51 @@ { 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 *); + /// 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; } + + /// 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(); + private: - // Hack: replaces global ::xassert() to debug debugging assertions - static void xassert(const char *msg, const char *file, int line); - - /// 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);} - }; - - static OutStream *CurrentDebug; - static int TheDepth; // level of nested debugging calls + static Context *Current; ///< deepest active context; nil outside debugs() }; extern FILE *debug_log; @@ -91,15 +104,15 @@ /* 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 @@ 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; === modified file 'src/adaptation/ecap/Host.cc' --- src/adaptation/ecap/Host.cc 2016-02-23 15:58:54 +0000 +++ src/adaptation/ecap/Host.cc 2016-06-15 22:08:16 +0000 @@ -147,18 +147,16 @@ { 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 === modified file 'src/base/Lock.h' --- src/base/Lock.h 2016-01-01 00:14:27 +0000 +++ src/base/Lock.h 2016-06-15 22:08:16 +0000 @@ -33,7 +33,7 @@ /// 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 @@ /// 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_; === modified file 'src/client_side.cc' --- src/client_side.cc 2016-05-02 10:51:18 +0000 +++ src/client_side.cc 2016-06-15 22:08:16 +0000 @@ -3778,7 +3778,7 @@ 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)); */ === modified file 'src/debug.cc' --- src/debug.cc 2016-03-23 14:46:37 +0000 +++ src/debug.cc 2016-06-15 22:08:16 +0000 @@ -22,8 +22,6 @@ 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 @@ 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 @@ { /* level 0,1 go to syslog */ - if (Debug::level > 1) + if (Debug::Level() > 1) return; if (!Debug::log_syslog) @@ -162,7 +160,7 @@ 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 @@ 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 @@ return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : ""; } -int Debug::TheDepth = 0; - -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::finishDebug() -{ - 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; -} - -// 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) -{ - - if (CurrentDebug) { - *CurrentDebug << "assertion failed: " << file << ":" << line << - ": \"" << msg << "\""; - } - abort(); +Debug::Context *Debug::Current = NULL; + +Debug::Context::Context(const int aSection, const int aLevel): + level(aLevel), + sectionLevel(Levels[aSection]), + upper(Current) +{ + formatStream(); +} + +/// Optimization: avoids new Context creation for every debugs(). +void +Debug::Context::rewind(const int aSection, const int aLevel) +{ + 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::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) +{ + Context *future = NULL; + + // prepare future context + if (Current) { + // all reentrant debugs() calls get here; create a dedicated context + future = new Context(section, level); + } else { + // Optimization: Nearly all debugs() calls get here; avoid allocations + static Context *topContext = new Context(1, 1); + topContext->rewind(section, level); + future = topContext; + } + + Current = future; + + return future->buf; +} + +void +Debug::Finish() +{ + // 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 @@ // 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_); === modified file 'src/esi/Expression.cc' --- src/esi/Expression.cc 2016-01-01 00:14:27 +0000 +++ src/esi/Expression.cc 2016-06-15 22:08:16 +0000 @@ -116,8 +116,6 @@ 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 @@ 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 === modified file 'src/servers/FtpServer.cc' --- src/servers/FtpServer.cc 2016-03-23 15:43:55 +0000 +++ src/servers/FtpServer.cc 2016-06-15 22:08:16 +0000 @@ -1303,7 +1303,7 @@ 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(); === modified file 'src/ssl/support.cc' --- src/ssl/support.cc 2016-04-19 15:04:09 +0000 +++ src/ssl/support.cc 2016-06-15 22:08:16 +0000 @@ -135,7 +135,7 @@ } 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); === modified file 'src/tests/stub_debug.cc' --- src/tests/stub_debug.cc 2016-01-01 00:14:27 +0000 +++ src/tests/stub_debug.cc 2016-06-15 22:08:16 +0000 @@ -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,71 +78,52 @@ 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() -{ - 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; -} - -void -Debug::xassert(const char *msg, const char *file, int line) -{ - - if (CurrentDebug) { - *CurrentDebug << "assertion failed: " << file << ":" << line << - ": \"" << msg << "\""; - } - abort(); -} - const char* SkipBuildPrefix(const char* path) { return path; } +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); +} + +std::ostringstream & +Debug::Start(const int section, const int level) +{ + Current = new Context(section, level); + return Current->buf; +} + +void +Debug::Finish() +{ + if (Current) { + _db_print("%s\n", Current->buf.str().c_str()); + delete Current; + Current = NULL; + } +} + std::ostream & Raw::print(std::ostream &os) const { @@ -157,10 +135,13 @@ // 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;