From: Amos Jeffries <amosjeffries@squid-cache.org>
Date: Fri, 18 Apr 2008 06:12:01 +0000 (-0600)
Subject: Author: rousskov
X-Git-Tag: SQUID_3_0_STABLE5~17
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=c575be2dbf7ee4d7d77ec85c9760e7061be30453;p=thirdparty%2Fsquid.git

Author: rousskov
Bug 2224 fix: reentrant debugging crashes Squid

Reentrant debugging occurs when something being written into the debugging
stream produces its own debugging. For example, a field accessor method may
make cbdata-validation calls, which would produce debugging. Logging such
field would crash Squid if sufficiently high debugging level is enabled.

With this change, the Debug methods detect reentrant calls and mostly ignore
them, allowing the caller to append debugging information to the existing
debug stream. A short debugging label is added before and after the reentrant
debugging message to reduce confusion that overlapping debugging statements
may cause during log analysis.
---

diff --git a/src/Debug.h b/src/Debug.h
index 64a64bca4d..4ce6c6b734 100644
--- a/src/Debug.h
+++ b/src/Debug.h
@@ -1,6 +1,6 @@
 
 /*
- * $Id: Debug.h,v 1.10 2007/08/24 01:02:09 amosjeffries Exp $
+ * $Id: Debug.h,v 1.13 2008/02/26 18:43:30 rousskov Exp $
  *
  * DEBUG: section 0     Debug Routines
  * AUTHOR: Harvest Derived
@@ -64,7 +64,11 @@ public:
     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);
+	
     static std::ostringstream *CurrentDebug;
+    static int TheDepth; // level of nested debugging calls
 };
 
 /* Debug stream */
diff --git a/src/client_side.cc b/src/client_side.cc
index 2916e7853e..df75e9d96a 100644
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: client_side.cc,v 1.770 2007/12/04 03:35:52 hno Exp $
+ * $Id: client_side.cc,v 1.778 2008/02/26 18:43:58 rousskov Exp $
  *
  * DEBUG: section 33    Client-side Routines
  * AUTHOR: Duane Wessels
@@ -1406,8 +1406,7 @@ ClientSocketContext::canPackMoreRanges() const
     /* first update "i" if needed */
 
     if (!http->range_iter.debt()) {
-        debugs(33, 5, "ClientSocketContext::canPackMoreRanges: At end of current range spec for FD " <<
-               fd());
+        debugs(33, 5, "ClientSocketContext::canPackMoreRanges: At end of current range spec for FD " << fd());
 
         if (http->range_iter.pos.incrementable())
             ++http->range_iter.pos;
@@ -1463,7 +1462,7 @@ ClientSocketContext::getNextRangeOffset() const
 void
 ClientSocketContext::pullData()
 {
-    debugs(33, 5, "ClientSocketContext::pullData: FD " << fd() << " attempting to pull upstream data");
+    debugs(33, 5, "ClientSocketContext::pullData: FD " << fd() );
 
     /* More data will be coming from the stream. */
     StoreIOBuffer readBuffer;
@@ -1490,8 +1489,7 @@ ClientSocketContext::socketState()
             /* filter out data according to range specs */
 
             if (!canPackMoreRanges()) {
-                debugs(33, 5, "ClientSocketContext::socketState: Range request has hit end of returnable range sequence on FD " <<
-                       fd());
+                debugs(33, 5, "ClientSocketContext::socketState: Range request has hit end of returnable range sequence on FD " << fd() );
 
                 if (http->request->flags.proxy_keepalive)
                     return STREAM_COMPLETE;
diff --git a/src/debug.cc b/src/debug.cc
index dc60cfc93d..030419c85a 100755
--- a/src/debug.cc
+++ b/src/debug.cc
@@ -1,5 +1,5 @@
 /*
- * $Id: debug.cc,v 1.106.2.1 2008/02/25 03:01:01 amosjeffries Exp $
+ * $Id: debug.cc,v 1.109 2008/02/26 18:43:30 rousskov Exp $
  *
  * DEBUG: section 0     Debug Routines
  * AUTHOR: Harvest Derived
@@ -734,21 +734,50 @@ ctx_get_descr(Ctx ctx) {
     return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
 }
 
+int Debug::TheDepth = 0;
+
 std::ostream &
 Debug::getDebugOut() {
-    assert (CurrentDebug == NULL);
-    CurrentDebug = new std::ostringstream();
-    // set default formatting flags
-    CurrentDebug->setf(std::ios::fixed);
-    CurrentDebug->precision(2);
+    assert(TheDepth >= 0);
+    ++TheDepth;
+    if (TheDepth > 1) {
+        assert(CurrentDebug);
+        *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{";
+    } else {
+        assert(!CurrentDebug);
+        CurrentDebug = new std::ostringstream();
+        // set default formatting flags
+        CurrentDebug->setf(std::ios::fixed);
+        CurrentDebug->precision(2);
+    }
     return *CurrentDebug;
 }
 
 void
 Debug::finishDebug() {
-    _db_print("%s\n", CurrentDebug->str().c_str());
-    delete CurrentDebug;
-    CurrentDebug = NULL;
+    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();
 }
 
 std::ostringstream (*Debug::CurrentDebug)(NULL);
diff --git a/test-suite/test_tools.cc b/test-suite/test_tools.cc
index f4a62191b7..1da9f8ab90 100644
--- a/test-suite/test_tools.cc
+++ b/test-suite/test_tools.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: test_tools.cc,v 1.9 2006/09/03 21:05:22 hno Exp $
+ * $Id: test_tools.cc,v 1.10 2008/02/26 18:44:16 rousskov Exp $
  *
  * AUTHOR: Robert Collins
  *
@@ -161,18 +161,48 @@ debug_trap(const char *message) {
     fatal(message);
 }
 
+int Debug::TheDepth = 0;
+
 std::ostream &
 Debug::getDebugOut() {
-    assert (CurrentDebug == NULL);
-    CurrentDebug = new std::ostringstream();
+    assert(TheDepth >= 0);
+    ++TheDepth;
+    if (TheDepth > 1) {
+        assert(CurrentDebug);
+        *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{";
+    } else {
+        assert(!CurrentDebug);
+        CurrentDebug = new std::ostringstream();
+        // set default formatting flags
+        CurrentDebug->setf(std::ios::fixed);
+        CurrentDebug->precision(2);
+    }
     return *CurrentDebug;
 }
 
 void
 Debug::finishDebug() {
-    _db_print("%s\n", CurrentDebug->str().c_str());
-    delete CurrentDebug;
-    CurrentDebug = NULL;
+    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();
 }
 
 std::ostringstream *Debug::CurrentDebug (NULL);