Improve debugs() handling in helpers (#1011)

This change also reduces libdebug dependency on globals.cc, improving
libdebug reusability.

Also do not default-reset debug sections after they were explicitly set:

* In most sbin/squid contexts, DebugModule constructor is called before
  Debug::parseOptions(). That call order results in the Levels array
  being reset to default values before it is reset to configured values.
  No problem.

* In sbin/squid -X context, DebugModule constructor is called after
  Debug::parseOptions(), but the override_X flag protected the Levels
  array from being reset to default values in this case. No problem.

* In helper contexts, DebugModule constructor may be called after
  Debug::parseOptions(), and the override_X flag stays false. This order
  results in the parseOptions() effects erased by ResetSections() called
  from the constructor.

This bug was detected while trying to understand why pinger's hard-coded
(and wrong) ALL,10 default has no effect on pinger's debugging. The two
bugs cancelled each other.

The following changes affect pinger (now) and other helpers that will
eventually use libdebug and its new NameThisHelper() API:

* Label helper debugs() lines with the helper name (e.g., "pinger"),
  similar to how we already label SMP debugs() lines with "kidN". This
  change improves cache.log readability, distinguishes output from
  different helpers, and distinguishes helper output from sbin/squid
  output in non-SMP logs.

* Make sure level-1 debugs() messages are logged.

* Stop pointless accumulation of cache.log and syslog channel messages.

* Automatically honor SQUID_DEBUG environment variable set by the parent
  Squid process. The pinger helper was already honoring it.

The following changes are specific to pinger:

* Removed the now-duplicated references to "pinger" in pinger debugs().

* Do not default pinger debugging levels to ALL,10. The default pinger
  debugging levels should be the same as the default Squid debugging
  levels (i.e. "ALL,1"). Bugs in the debugging module prevented the
  hard-coded "ALL,10" (or any other elevated setting) from having an
  effect, but we now fixed the last of those bugs. AFAICT, the change of
  default from ALL,1 to ALL,10 in commit cc192b5 was accidental.

diff --git a/src/debug/Stream.h b/src/debug/Stream.h
index fa3bffc007f838fd79966d2f3ee14def448f4981..e0a6d23438baf6d23bbe99f3d6216d01738a5907 100644 (file)
--- a/src/debug/Stream.h
+++ b/src/debug/Stream.h
@@ -88,6 +88,16 @@ public:
     static int override_X;
     static bool log_syslog;
 
+    // TODO: Convert all helpers to use debugs() and NameThisHelper() APIs.
+    /// Use the given name for debugs() messages from this helper process.
+    /// Side effect: Commits to using helper-appropriate debug levels/channels.
+    /// \sa NameThisKid()
+    static void NameThisHelper(const char *name);
+
+    /// Use the given ID for debugs() messages from this SMP kid process.
+    /// \sa NameThisHelper()
+    static void NameThisKid(int kidIdentifier);
+
     static void parseOptions(char const *);
 
     /// minimum level required by the current debugs() call

diff --git a/src/debug/debug.cc b/src/debug/debug.cc
index df4bfccb346c12641434fbf4021537c3d109a1cb..10508ca669c4c2a68dccd4ea87e148b35dc71c50 100644 (file)
--- a/src/debug/debug.cc
+++ b/src/debug/debug.cc
@@ -53,8 +53,11 @@ static int DefaultStderrLevel = -1;
 /// early debugs() with higher level are not buffered and, hence, may be lost
 static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
 
+/// pre-formatted name of the current process for debugs() messages (or empty)
+static std::string ProcessLabel;
+
 static const char *debugLogTime(time_t t);
-static const char *debugLogKid(void);
+
 #if HAVE_SYSLOG
 #ifdef LOG_LOCAL4
 static int syslog_facility = 0;
@@ -68,6 +71,12 @@ typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECT
 
 static void ResetSections(const int level = DBG_IMPORTANT);
 
+/// Whether ResetSections() has been called already. We need to keep track of
+/// this state because external code may trigger ResetSections() before the
+/// DebugModule constructor has a chance to ResetSections() to their defaults.
+/// TODO: Find a way to static-initialize Debug::Levels instead.
+static bool DidResetSections = false;
+
 /// a named FILE with very-early/late usage safety mechanisms
 class DebugFile
 {
@@ -349,10 +358,58 @@ DebugStream() {
 static void
 ResetSections(const int level)
 {
+    DidResetSections = true;
     for (auto &sectionLevel: Debug::Levels)
         sectionLevel = level;
 }
 
+/// optimization: formats ProcessLabel once for frequent debugs() reuse
+static void
+LabelThisProcess(const char * const name, const Optional<int> id = Optional<int>())
+{
+    assert(name);
+    assert(strlen(name));
+    std::stringstream os;
+    os << ' ' << name;
+    if (id.has_value()) {
+        assert(id.value() >= 0);
+        os << id.value();
+    }
+    ProcessLabel = os.str();
+}
+
+void
+Debug::NameThisHelper(const char * const name)
+{
+    LabelThisProcess(name);
+
+    if (const auto parentProcessDebugOptions = getenv("SQUID_DEBUG")) {
+        assert(!debugOptions);
+        debugOptions = xstrdup(parentProcessDebugOptions);
+    }
+
+    // do not restrict helper (i.e. stderr) logging beyond debug_options
+    EnsureDefaultStderrLevel(DBG_DATA);
+
+    // helpers do not write to cache.log directly; instead, ipcCreate()
+    // diverts helper stderr output to cache.log of the parent process
+    BanCacheLogUse();
+
+    SettleStderr();
+    SettleSyslog();
+}
+
+void
+Debug::NameThisKid(const int kidIdentifier)
+{
+    // to reduce noise and for backward compatibility, do not label kid messages
+    // in non-SMP mode
+    if (kidIdentifier)
+        LabelThisProcess("kid", Optional<int>(kidIdentifier));
+    else
+        ProcessLabel.clear(); // probably already empty
+}
+
 /* LoggingSectionGuard */
 
 LoggingSectionGuard::LoggingSectionGuard()
@@ -378,7 +435,7 @@ DebugModule::DebugModule()
 
     (void)std::atexit(&Debug::PrepareToDie);
 
-    if (!Debug::override_X)
+    if (!DidResetSections)
         ResetSections();
 }
 
@@ -553,7 +610,7 @@ DebugChannel::writeToStream(FILE &destination, const DebugMessageHeader &header,
 {
     fprintf(&destination, "%s%s| %s\n",
             debugLogTime(header.timestamp),
-            debugLogKid(),
+            ProcessLabel.c_str(),
             body.c_str());
     noteWritten(header);
 }
@@ -1187,19 +1244,6 @@ debugLogTime(const time_t t)
     return buf;
 }
 
-static const char *
-debugLogKid(void)
-{
-    if (KidIdentifier != 0) {
-        static char buf[16];
-        if (!*buf) // optimization: fill only once after KidIdentifier is set
-            snprintf(buf, sizeof(buf), " kid%d", KidIdentifier);
-        return buf;
-    }
-
-    return "";
-}
-
 /// Whether there are any xassert() calls in the call stack. Treat as private to
 /// xassert(): It is moved out only to simplify the asserting code path.
 static auto Asserting_ = false;

diff --git a/src/icmp/Icmp4.cc b/src/icmp/Icmp4.cc
index 68a2a27a5c767bf2728f4e8c60128b94ccf46b72..15e913d1b43583de18f6ef7bddb393d91a592630 100644 (file)
--- a/src/icmp/Icmp4.cc
+++ b/src/icmp/Icmp4.cc
@@ -74,7 +74,7 @@ Icmp4::Open(void)
     }
 
     icmp_ident = getpid() & 0xffff;
-    debugs(42, DBG_IMPORTANT, "pinger: ICMP socket opened.");
+    debugs(42, DBG_IMPORTANT, "ICMP socket opened.");
 
     return icmp_sock;
 }

diff --git a/src/icmp/Icmp6.cc b/src/icmp/Icmp6.cc
index 5fce0481c9aa23fdf570801221e532fa3a238407..06f8c9d4f1f4df350656c04eda0eaf2312554c3f 100644 (file)
--- a/src/icmp/Icmp6.cc
+++ b/src/icmp/Icmp6.cc
@@ -106,7 +106,7 @@ Icmp6::Open(void)
     }
 
     icmp_ident = getpid() & 0xffff;
-    debugs(42, DBG_IMPORTANT, "pinger: ICMPv6 socket opened");
+    debugs(42, DBG_IMPORTANT, "ICMPv6 socket opened");
 
     return icmp_sock;
 }

diff --git a/src/icmp/IcmpPinger.cc b/src/icmp/IcmpPinger.cc
index 3b0412fbcd1d8246331e89703252f00f26550a6f..837a758e9b31344d9e1d1477cd01380f4e09075f 100644 (file)
--- a/src/icmp/IcmpPinger.cc
+++ b/src/icmp/IcmpPinger.cc
@@ -130,7 +130,7 @@ IcmpPinger::Open(void)
     }
 
     getCurrentTime();
-    debugs(42, DBG_IMPORTANT, "pinger: Squid socket opened");
+    debugs(42, DBG_IMPORTANT, "Squid socket opened");
 
     /* windows uses a socket stream as a dual-direction channel */
     socket_to_squid = icmp_sock;
@@ -222,7 +222,7 @@ IcmpPinger::SendResult(pingerReplyData &preply, int len)
 
     if (send(socket_to_squid, &preply, len, 0) < 0) {
         int xerrno = errno;
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: send failure: " << xstrerr(xerrno));
+        debugs(42, DBG_CRITICAL, "FATAL: send failure: " << xstrerr(xerrno));
         Close();
         exit(EXIT_FAILURE);
     }

diff --git a/src/icmp/pinger.cc b/src/icmp/pinger.cc
index 188e8af439f6c3444bba46ec7db9ac69d30b3b67..96ce9b0661734d81db5bd6fc26b3e9f61ba4d9b2 100644 (file)
--- a/src/icmp/pinger.cc
+++ b/src/icmp/pinger.cc
@@ -115,41 +115,37 @@ main(int, char **)
     int icmp6_worker = -1;
     int squid_link = -1;
 
-    /** start by initializing the pinger debug cache.log-pinger. */
-    const auto envOptions = getenv("SQUID_DEBUG");
-    Debug::debugOptions = xstrdup(envOptions ? envOptions : "ALL,10");
+    Debug::NameThisHelper("pinger");
 
     getCurrentTime();
 
     // determine IPv4 or IPv6 capabilities before using sockets.
     Ip::ProbeTransport();
 
-    Debug::BanCacheLogUse();
-
-    debugs(42, DBG_CRITICAL, "pinger: Initialising ICMP pinger ...");
+    debugs(42, DBG_CRITICAL, "Initialising ICMP pinger ...");
 
     icmp4_worker = icmp4.Open();
     if (icmp4_worker < 0) {
-        debugs(42, DBG_CRITICAL, "ERROR: pinger: Unable to start ICMP pinger.");
+        debugs(42, DBG_CRITICAL, "ERROR: Unable to start ICMP pinger.");
     }
     max_fd = max(max_fd, icmp4_worker);
 
 #if USE_IPV6
     icmp6_worker = icmp6.Open();
     if (icmp6_worker <0 ) {
-        debugs(42, DBG_CRITICAL, "ERROR: pinger: Unable to start ICMPv6 pinger.");
+        debugs(42, DBG_CRITICAL, "ERROR: Unable to start ICMPv6 pinger.");
     }
     max_fd = max(max_fd, icmp6_worker);
 #endif
 
     /** abort if neither worker could open a socket. */
     if (icmp4_worker < 0 && icmp6_worker < 0) {
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: Unable to open any ICMP sockets.");
+        debugs(42, DBG_CRITICAL, "FATAL: Unable to open any ICMP sockets.");
         exit(EXIT_FAILURE);
     }
 
     if ( (squid_link = control.Open()) < 0) {
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: Unable to setup Pinger control sockets.");
+        debugs(42, DBG_CRITICAL, "FATAL: Unable to setup Pinger control sockets.");
         icmp4.Close();
         icmp6.Close();
         exit(EXIT_FAILURE); // fatal error if the control channel fails.
@@ -158,14 +154,14 @@ main(int, char **)
 
     if (setgid(getgid()) < 0) {
         int xerrno = errno;
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: setgid(" << getgid() << ") failed: " << xstrerr(xerrno));
+        debugs(42, DBG_CRITICAL, "FATAL: setgid(" << getgid() << ") failed: " << xstrerr(xerrno));
         icmp4.Close();
         icmp6.Close();
         exit(EXIT_FAILURE);
     }
     if (setuid(getuid()) < 0) {
         int xerrno = errno;
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: setuid(" << getuid() << ") failed: " << xstrerr(xerrno));
+        debugs(42, DBG_CRITICAL, "FATAL: setuid(" << getuid() << ") failed: " << xstrerr(xerrno));
         icmp4.Close();
         icmp6.Close();
         exit(EXIT_FAILURE);
@@ -179,7 +175,7 @@ main(int, char **)
     caps = cap_init();
     if (!caps) {
         int xerrno = errno;
-        debugs(42, DBG_CRITICAL, "FATAL: pinger: cap_init() failed: " << xstrerr(xerrno));
+        debugs(42, DBG_CRITICAL, "FATAL: cap_init() failed: " << xstrerr(xerrno));
         icmp4.Close();
         icmp6.Close();
         exit(EXIT_FAILURE);
@@ -187,7 +183,7 @@ main(int, char **)
         if (cap_set_proc(caps) != 0) {
             int xerrno = errno;
             // cap_set_proc(cap_init()) is expected to never fail
-            debugs(42, DBG_CRITICAL, "FATAL: pinger: cap_set_proc(none) failed: " << xstrerr(xerrno));
+            debugs(42, DBG_CRITICAL, "FATAL: cap_set_proc(none) failed: " << xstrerr(xerrno));
             cap_free(caps);
             icmp4.Close();
             icmp6.Close();
@@ -234,7 +230,7 @@ main(int, char **)
 
         if (PINGER_TIMEOUT + last_check_time < squid_curtime) {
             if (send(LINK_TO_SQUID, &tv, 0, 0) < 0) {
-                debugs(42, DBG_CRITICAL, "pinger: Closing. No requests in last " << PINGER_TIMEOUT << " seconds.");
+                debugs(42, DBG_CRITICAL, "Closing. No requests in last " << PINGER_TIMEOUT << " seconds.");
                 control.Close();
                 exit(EXIT_FAILURE);
             }

diff --git a/src/main.cc b/src/main.cc
index 37860db7fc963586bfcb34622edaaf23aed18e25..4af501e7175d53cc43c6338916ca7675886a9319 100644 (file)
--- a/src/main.cc
+++ b/src/main.cc
@@ -1419,6 +1419,7 @@ ConfigureCurrentKid(const CommandLine &cmdLine)
         TheKidName.assign(APP_SHORTNAME);
         KidIdentifier = 0;
     }
+    Debug::NameThisKid(KidIdentifier);
 }
 
 /// Start directing debugs() messages to the configured cache.log.