]> git.ipfire.org Git - thirdparty/squid.git/commitdiff
Do not allow low-level debugging to hide important/critical messages.
authorAlex Rousskov <rousskov@measurement-factory.com>
Wed, 15 Jun 2016 22:08:16 +0000 (10:08 +1200)
committerAmos Jeffries <squid3@treenet.co.nz>
Wed, 15 Jun 2016 22:08:16 +0000 (10:08 +1200)
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.

src/Debug.h
src/adaptation/ecap/Host.cc
src/base/Lock.h
src/client_side.cc
src/debug.cc
src/esi/Expression.cc
src/servers/FtpServer.cc
src/ssl/support.cc
src/tests/stub_debug.cc

index cc28d5ed5b9383c31d3d3fde6a4baa51395e1e34..6819d57821dd6c2ebccc41ee2e838e15841c9b2a 100644 (file)
@@ -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;
index 720c7bd148e9ceffd306af3aa0ebe19c489b081d..140553ba0e768552ba5f14cf69825b136e9c110e 100644 (file)
@@ -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
index dfc8ddc1c3f247fa85f3d1fd1699df7851e83814..3a389eb0b6d75bb5a634cfa1fe2ca09a3334438e 100644 (file)
@@ -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<void*>(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<void*>(this) << " from count " << count_);
 #endif
         assert(count_ > 0);
         return --count_;
index d348fdf016629b3fa91864c2de508eb1e93b8cbb..e05b6a243058eebe4e7c6926fc2f4fea9814648a 100644 (file)
@@ -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)); */
index 7ee6e62d64694a2a064e87fe60e8bd4d989bba38..b2a789186c4c363c559583ec7814b973f75e7f00 100644 (file)
@@ -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] : "<null>";
 }
 
-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_);
index bf176f3d5fa4476978dfd38465bcc42992125ba1..8a1d3e95c43b903b31b5a8d10aedd321a3fb4b16 100644 (file)
@@ -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
index babdd161180ed3ff74237ac757cba4e251b7e344..12df5efcc2825d375b3f07ef0f642b9cb058550f 100644 (file)
@@ -1303,7 +1303,7 @@ Ftp::Server::handleRequest(HttpRequest *request)
     Must(header.has(HDR_FTP_ARGUMENTS));
     String &params = header.findEntry(HDR_FTP_ARGUMENTS)->value;
 
-    if (do_debug(9, 2)) {
+    if (Debug::Enabled(9, 2)) {
         MemBuf mb;
         Packer p;
         mb.init();
index 60ee84c3bcbeeaf8814d8a82ac623d245fdefd66..6f01a9431302ae507b719636087c7e9667a90d53 100644 (file)
@@ -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);
index 561b5636c2a1b1918dec9cb4f4e769b6c3b4b8cf..13efc6e185da10961137e1908b2e7008c74b1bc1 100644 (file)
 #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;