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 64a64bca4d2dd90af5a7e166c70e980a55b7865e..4ce6c6b734ac5e34ff4979aabc41fa9785eeb290 100644 (file)
--- 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 2916e7853eb7082cee375c2a90c493e5061dcbca..df75e9d96a7526bcdb1da30a47d1f1cefbece240 100644 (file)
--- 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 dc60cfc93db8b476d32e7c4ae78a7864b6730b8e..030419c85af7418a0d5e5a5296dd5aa01ba53f10 100755 (executable)
--- 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 f4a62191b71992de44c87a755dacc7c7da8fc736..1da9f8ab90fdca5000945115f67880d425f7e192 100644 (file)
--- 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);