]> 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>
Fri, 20 May 2016 13:20:27 +0000 (01:20 +1200)
committerAmos Jeffries <squid3@treenet.co.nz>
Fri, 20 May 2016 13:20:27 +0000 (01:20 +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/security/NegotiationHistory.cc
src/servers/FtpServer.cc
src/ssl/support.cc
src/tests/stub_debug.cc

index 22bd4c87f229ffc42c5af1afcb3ee8e34731515e..f98d96289342ed8049588bb54e1fe1840b09b23e 100644 (file)
@@ -52,36 +52,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
-    {
-        MEMPROXY_CLASS(OutStream);
-    public:
-        void *operator new[] (size_t size) throw(std::bad_alloc) = delete; //{return xmalloc(size);}
-        void operator delete[] (void *address) throw() = delete; // {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;
@@ -97,15 +112,15 @@ const char * SkipBuildPrefix(const char* path);
  */
 #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)
 
@@ -141,10 +156,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 cface5666495f29243a27879aeaeefa0c3a21120..cbd5ab817fc177593448da88f006e5fa0137d25f 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) :
+           nullptr;
 }
 
 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 8e826f47127f1dc9643cc5d45d179e8fb05e84bf..74ca44c8559dff6ef53265397ea99de50721b47c 100644 (file)
@@ -2661,7 +2661,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 3d3216a30c7593186ef149caf7f36fb98386ad90..296807972af5cbe4d0657907c29bb7e5964a93d4 100644 (file)
@@ -24,8 +24,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;
@@ -136,7 +134,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)
@@ -151,7 +149,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)
@@ -164,7 +162,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 */
 
@@ -526,7 +524,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);
@@ -728,55 +726,75 @@ ctx_get_descr(Ctx ctx)
     return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
 }
 
-int Debug::TheDepth = 0;
+Debug::Context *Debug::Current = nullptr;
 
-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 = nullptr;
+
+    // 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
@@ -826,8 +844,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_) {
             if (useHex_)
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 57fcdecf6c095cf878799c7ebfe4f2a8880bf2a8..f6366052e9314675d3fd4c2e6e0960ad364aa3c2 100644 (file)
@@ -75,7 +75,7 @@ Security::NegotiationHistory::retrieveNegotiatedInfo(Security::SessionPtr ssl)
         version_ = toProtocolVersion(ssl->version);
     }
 
-    if (do_debug(83, 5)) {
+    if (Debug::Enabled(83, 5)) {
         BIO *b = SSL_get_rbio(ssl);
         Ssl::Bio *bio = static_cast<Ssl::Bio *>(b->ptr);
         debugs(83, 5, "SSL connection info on FD " << bio->fd() <<
index 45506c726e666bde3f7c6a158398e6b6797e2eee..5728ca32cfd3b1e83bdc4775ed235b8d7b8ed98e 100644 (file)
@@ -1305,7 +1305,7 @@ Ftp::Server::handleRequest(HttpRequest *request)
     Must(header.has(Http::HdrType::FTP_ARGUMENTS));
     String &params = header.findEntry(Http::HdrType::FTP_ARGUMENTS)->value;
 
-    if (do_debug(9, 2)) {
+    if (Debug::Enabled(9, 2)) {
         MemBuf mb;
         mb.init();
         request->pack(&mb);
index 1205bd41b37b06ba75cf236528892dc636f9a990..70be136beaec6241c38a7d769afd133a277611ca 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 cbdf9ea178ac287b9ef3159ff1928de35dd88cb6..d6904a653c7a19bc22ade7040e05a346e098a693 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;
@@ -80,49 +77,48 @@ _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);
+void
+Debug::parseOptions(char const *)
+{}
 
-std::ostream &
-Debug::getDebugOut()
+const char*
+SkipBuildPrefix(const char* path)
 {
-    if (!CurrentDebug) {
-        CurrentDebug = new Debug::OutStream;
-        CurrentDebug->setf(std::ios::fixed);
-        CurrentDebug->precision(2);
-    }
-    return *CurrentDebug;
+    return path;
 }
 
-void
-Debug::parseOptions(char const *)
-{}
+Debug::Context *Debug::Current = nullptr;
 
-void
-Debug::finishDebug()
+Debug::Context::Context(const int aSection, const int aLevel):
+    level(aLevel),
+    sectionLevel(Levels[aSection]),
+    upper(Current)
 {
-    std::cerr << "debugs: " << CurrentDebug->str() << std::endl;
-    delete CurrentDebug;
-    CurrentDebug = NULL;
+    buf.setf(std::ios::fixed);
+    buf.precision(2);
 }
 
-void
-Debug::xassert(const char *msg, const char *file, int line)
+std::ostringstream &
+Debug::Start(const int section, const int level)
 {
-    getDebugOut() << "assertion failed: " << file << ":" << line <<
-                  ": \"" << msg << "\"";
-    abort();
+    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 = nullptr;
+    }
 }
 
 std::ostream &
@@ -136,10 +132,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;