Do not apply custom debugs() format to Debug::Extra lines (#1345)

Some debugs() callers set and leave custom std::ostream formats like
std::hex. Such behavior should be considered natural/correct because,
from those callers point of view, they see and control the entire
debugging message. Stream formats obviously must not cross debugs()
boundaries, and, from those callers point of view, those boundaries are
the message they explicitly call with. Here is a hypothetical example:

    debugs(33, DBG_CRITICAL, "Invalid QoS flag: " << std::hex << flag);

When we automatically add extra information to debugging messages (e.g.,
to detail which transaction has failed, what listening port is
misconfigured, or where the exception was thrown from), the "extra"
lines are added in a completely different code context. That detailing
code also sees a seemingly isolated printing context and should not be
expected to remember to reset debugging stream flags "just in case":

    os << Debug::Extra << "listening port: " << s.port();

The combination of natural code expectations, may result in very
misleading messages because, for example, hexadecimal numbers may look
just like decimal ones. We have seen that happening to transaction IDs
and here is an example based on the above debugs() that complains about
an invalid QoS flag on http_port 80 (but logs port 50):

    2023/05/09 16:44:13| Invalid QoS flag: deadbeef
        listening port: 50

This change would break any _deliberate_ format "bleeds" from primary
debugs() messages to Debug::Extra lines, but no such bleeding cases are
known, and they are too confusing/fragile to be encouraged/supported.

diff --git a/src/debug/Stream.h b/src/debug/Stream.h
index 2e96994b51de28df339fd2676e3afe9d0349e9f9..47178251932857cca6f841949696db6afcba0e21 100644 (file)
--- a/src/debug/Stream.h
+++ b/src/debug/Stream.h
@@ -62,7 +62,6 @@ public:
         friend class DebugMessageHeader;
 
         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
         bool forceAlert; ///< the current debugs() will be a syslog ALERT
@@ -110,8 +109,9 @@ public:
     /// configures the active debugging context to write syslog ALERT
     static void ForceAlert();
 
-    /// prefixes each grouped debugs() line after the first one in the group
-    static std::ostream& Extra(std::ostream &os) { return os << "\n    "; }
+    /// Prefixes each grouped debugs() line after the first one in the group.
+    /// Resets debugging stream format to the initial/default one.
+    static std::ostream& Extra(std::ostream &);
 
     /// silently erases saved early debugs() messages (if any)
     static void ForgetSaved();
@@ -170,6 +170,7 @@ public:
     static void SettleSyslog();
 
 private:
+    static void FormatStream(std::ostream &);
     static void LogMessage(const Context &);
 
     static Context *Current; ///< deepest active context; nil outside debugs()

diff --git a/src/debug/debug.cc b/src/debug/debug.cc
index 901ca350400713d2d20ce004dd4e4cd1a1ad9e4c..0ea6430634ec88915ff740efda981b448f4a7529 100644 (file)
--- a/src/debug/debug.cc
+++ b/src/debug/debug.cc
@@ -1277,7 +1277,7 @@ Debug::Context::Context(const int aSection, const int aLevel):
     forceAlert(false),
     waitingForIdle(false)
 {
-    formatStream();
+    FormatStream(buf);
 }
 
 /// Optimization: avoids new Context creation for every debugs().
@@ -1292,14 +1292,12 @@ Debug::Context::rewind(const int aSection, const int aLevel)
 
     buf.str(CompiledDebugMessageBody());
     buf.clear();
-    // debugs() users are supposed to preserve format, but
-    // some do not, so we have to waste cycles resetting it for all.
-    formatStream();
+    FormatStream(buf);
 }
 
 /// configures default formatting for the debugging stream
 void
-Debug::Context::formatStream()
+Debug::FormatStream(std::ostream &buf)
 {
     const static std::ostringstream cleanStream;
     buf.flags(cleanStream.flags() | std::ios::fixed);
@@ -1309,6 +1307,17 @@ Debug::Context::formatStream()
     // If this is not enough, use copyfmt(cleanStream) which is ~10% slower.
 }
 
+std::ostream &
+Debug::Extra(std::ostream &os)
+{
+    // Prevent previous line formats bleeding onto this line: Previous line code
+    // may not even be aware of some detailing code automatically adding extras.
+    FormatStream(os);
+
+    os << "\n    ";
+    return os;
+}
+
 void
 Debug::LogWaitingForIdle()
 {

diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc
index 89c505ab4d06fe45929caf6cbaad7daf366ac845..044f6ff00bbef00b4abd97e58e1c1450fdfe8e0a 100644 (file)
--- a/src/tests/stub_debug.cc
+++ b/src/tests/stub_debug.cc
@@ -39,6 +39,16 @@ void
 _db_rotate_log(void)
 {}
 
+void
+Debug::FormatStream(std::ostream &buf)
+{
+    const static std::ostringstream cleanStream;
+    buf.flags(cleanStream.flags() | std::ios::fixed);
+    buf.width(cleanStream.width());
+    buf.precision(2);
+    buf.fill(' ');
+}
+
 void
 Debug::LogMessage(const Context &context)
 {
@@ -53,6 +63,14 @@ Debug::LogMessage(const Context &context)
             context.buf.str().c_str());
 }
 
+std::ostream &
+Debug::Extra(std::ostream &os)
+{
+    FormatStream(os);
+    os << "\n    ";
+    return os;
+}
+
 bool Debug::StderrEnabled() STUB_RETVAL(false)
 void Debug::PrepareToDie() STUB
 
@@ -69,8 +87,7 @@ Debug::Context::Context(const int aSection, const int aLevel):
     upper(Current),
     forceAlert(false)
 {
-    buf.setf(std::ios::fixed);
-    buf.precision(2);
+    FormatStream(buf);
 }
 
 std::ostringstream &