From 879c39f72fa77f60c565dbda90ffd6cf8721b369 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Tue, 12 Apr 2022 22:32:19 +0000 Subject: [PATCH] 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. --- src/debug/Stream.h | 10 ++++++ src/debug/debug.cc | 76 +++++++++++++++++++++++++++++++++--------- src/icmp/Icmp4.cc | 2 +- src/icmp/Icmp6.cc | 2 +- src/icmp/IcmpPinger.cc | 4 +-- src/icmp/pinger.cc | 26 ++++++--------- src/main.cc | 1 + 7 files changed, 86 insertions(+), 35 deletions(-) diff --git a/src/debug/Stream.h b/src/debug/Stream.h index fa3bffc007..e0a6d23438 100644 --- 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 df4bfccb34..10508ca669 100644 --- 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 §ionLevel: Debug::Levels) sectionLevel = level; } +/// optimization: formats ProcessLabel once for frequent debugs() reuse +static void +LabelThisProcess(const char * const name, const Optional id = Optional()) +{ + 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(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 68a2a27a5c..15e913d1b4 100644 --- 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 5fce0481c9..06f8c9d4f1 100644 --- 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 3b0412fbcd..837a758e9b 100644 --- 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 188e8af439..96ce9b0661 100644 --- 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 37860db7fc..4af501e717 100644 --- 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. -- 2.47.2