From: Alex Rousskov Date: Thu, 3 Feb 2022 22:04:52 +0000 (+0000) Subject: Log early level-0/1 debugs() messages to cache_log (#950) X-Git-Tag: SQUID_6_0_1~242 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=61be1d8;p=thirdparty%2Fsquid.git Log early level-0/1 debugs() messages to cache_log (#950) Commit d7ca82e dropped cache.log-recording of debugs() messages produced by `finalizeConfig` runners (e.g., `WARNING: mem-cache size is...`). This change restores that functionality (by buffering early messages until the cache.log file is opened) and improves early debugs() handling as detailed below. ## Squid has three channels for debugs() messages: * cache.log (`cache_log`): Settles as squid.conf settings take effect. * stderr (mostly `-d`): Settles when command line options take effect. * syslog (mostly `-s`): Settles when command line options take effect. Squid always ignores debugging messages with section/level mismatching Debug::Levels configuration (driven by a combination of the `-k debug`, `-X`, and `debug_options` directives). _Beyond_ that ever-present top-level filter, each debugging channel has its own set of rules that determine which filtered debugs() messages the channel accepts; the following approximate summary is based on the changes in this commit: * cache.log: all messages; * stderr: either messages satisfying explicit `-d` level restrictions or messages that Squid failed to write to cache.log (if no `-d`); * syslog: level-0/1 messages and `ForceAllert` messages. This change encapsulates channel-specific logic in dedicated classes. ## Guiding design principles * **no repetition**: A channel must record each message at most once. * **no reordering**: Each channel must preserve same-process debugs() call order across all recorded messages. * **no loss**: Each channel must log all messages matching the channel configuration/filters. * **no delay**: Each channel must record each message ASAP. * **cache.log primacy**: Admins want messages logged to cache.log if possible and to stderr/syslog only if necessary or explicitly requested. * **cache.log locking**: No cache.log updates without a PID lock. ## The fix Commit d7ca82e dropped level-0/1 messages produced by `finalizeConfig` runners because, since that commit, the cache.log channel was opened _after_ the `finalizeConfig` event. Official code also dropped other, even earlier level-0/1 messages, violating the "cache.log primacy" principle. We now save early level-0/1 messages into a buffer. This buffering can be misinterpreted as violating the "no [artificial] delay" principle, but the messages are actually written to cache.log ASAP; without the buffer the messages would be missing from the "primary" cache.log and, in many use cases without stderr capturing, completely. If Squid fails to open cache.log, early messages saved for the cache.log channel are given to the stderr channel (following the "no loss" principle). The stderr channel logs those messages that obey explicit `-d` restrictions and do not violate the "no reordering" and "no repetition" principles. Violations are tracked by assigning each message its debugs() call sequence number. The early messages buffer is currently dedicated to level-0/1 messages because we were worried that level-2+ messages (if enabled via `-X`) would overflow any reasonably-sized buffer[^1]. Correctly handling such overflows is very difficult (we tried), so we avoid them instead. ## Side effects and surprises To allow admins to see early level-1 cache.log messages (without adding an `if early` check to the debugs() macro[^2]), we changed the _initial_ Debug::Levels value from `ALL,0` to `ALL,1`, matching the debug_options default set later. This fix uncovered a few early level-1 messages that were previously hidden[^3]: 09:46:36| Startup: Initializing Authentication Schemes ... 09:46:36| Startup: Initialized Authentication Scheme 'basic' 09:46:36| Startup: Initialized Authentication Scheme 'digest' 09:46:36| Startup: Initialized Authentication Scheme 'negotiate' 09:46:36| Startup: Initialized Authentication Scheme 'ntlm' 09:46:36| Startup: Initialized Authentication. 09:46:36| Processing Configuration File: .../squid.conf ... 09:46:36| Initializing https:// proxy context 09:46:36| Set Current Directory to /usr/local/squid/var The fact that many debugs() messages happen before cache_log can be opened is fairly obvious, but it is also true that stderr and syslog channels cannot write messages immediately. Both channels need to wait for the command line options to be parsed. Even the global `stderr` variable may not be available during very early debugs() calls! Each channel now buffers level-0/1 messages until it settles. Since the early message buffers are limited to level-0/1 messages, initial cache.log records logged by `squid -X` are level-0/1 messages, followed by true ALL,9 debugging. The admins can get early ALL,9 messages via stderr, of course. The `-z` command-line option no longer overrides `-d` settings. Squid no longer writes to cache_log after removing the PID file. fatal() text and the `Squid Cache...: Terminated abnormally.` message are no longer dropped during certain early process terminations. `squid -k ...` logs some new level-0/1 messages to stderr. Improved support for assert()/debugs() triggered from within the Debug module: Besides crashes, such "internal" debugs() could be logged before earlier "external" messages and some assert() messages could be lost. [^1]: The restriction to only buffer level-0/1 messages can be easily removed (after research and discussion) if there is consensus that the actual memory required to accumulate all typical level-2+ early messages is worth spending on making `squid -X` write all messages to cache.log. [^2]: Squid has thousands of debugs() calls (and counting), including many calls on performance-sensitive paths. Most debugs() calls should do nothing by default. Thus, the speed at which the debugs() macro can skip logging is an important common case on the performance sensitive path. Similarly, disruption to CPU processing pipeline due to top-level debugs() checks may be important. Actually writing the message to the cache.log may not be that important -- at that time, the performance battle can be considered lost -- but the initial rejection is. [^3]: This change is not about the levels of any specific messages. Wrong message levels (if any) should be fixed separately. This change does not imply that the newly discovered messages have wrong levels. --- diff --git a/src/Debug.h b/src/Debug.h index 0f65a62179..3e51c5d463 100644 --- a/src/Debug.h +++ b/src/Debug.h @@ -44,6 +44,8 @@ #define DBG_PARSE_NOTE(x) (opt_parse_cfg_only?0:(x)) /**< output is always to be displayed on '-k parse' but at level-x normally. */ +class DebugMessageHeader; + class Debug { @@ -54,16 +56,23 @@ public: public: Context(const int aSectionLevel, const int aLevel); + int section; ///< the debug section of the debugs() call int level; ///< minimum debugging level required by the debugs() call int sectionLevel; ///< maximum debugging level allowed during the call private: friend class Debug; + 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 + + /// whether this debugs() call originated when we were too busy handling + /// other logging needs (e.g., logging another concurrent debugs() call) + bool waitingForIdle; }; /// whether debugging the given section and the given level produces output @@ -77,7 +86,6 @@ public: static int rotateNumber; static int Levels[MAX_DEBUG_SECTIONS]; static int override_X; - static int log_stderr; static bool log_syslog; static void parseOptions(char const *); @@ -98,7 +106,65 @@ public: /// prefixes each grouped debugs() line after the first one in the group static std::ostream& Extra(std::ostream &os) { return os << "\n "; } + /// silently erases saved early debugs() messages (if any) + static void ForgetSaved(); + + /// Reacts to ongoing program termination (e.g., flushes buffered messages). + /// Call this _before_ logging the termination reason to maximize the + /// chances of that valuable debugs() getting through to the admin. + static void PrepareToDie(); + + /// Logs messages of Finish()ed debugs() calls that were queued earlier. + static void LogWaitingForIdle(); + + /* cache_log channel */ + + /// Starts using stderr as a cache_log file replacement. + /// Also applies configured debug_options (if any). + /// Call this or UseCacheLog() to stop early message accumulation. + static void BanCacheLogUse(); + + /// Opens and starts using the configured cache_log file. + /// Also applies configured debug_options (if any). + /// Call this or BanCacheLogUse() to stop early message accumulation. + static void UseCacheLog(); + + /// Closes and stops using cache_log (if it was open). + /// Starts using stderr as a cache_log file replacement. + static void StopCacheLogUse(); + + /* stderr channel */ + + /// In the absence of ResetStderrLevel() calls, future debugs() with + /// the given (or lower) level will be written to stderr (at least). If + /// called many times, the highest parameter wins. ResetStderrLevel() + /// overwrites this default-setting method, regardless of the calls order. + static void EnsureDefaultStderrLevel(int maxDefault); + + /// Future debugs() messages with the given (or lower) level will be written + /// to stderr (at least). If called many times, the last call wins. + static void ResetStderrLevel(int maxLevel); + + /// Finalizes stderr configuration when no (more) ResetStderrLevel() + /// and EnsureDefaultStderrLevel() calls are expected. + static void SettleStderr(); + + /// Whether at least some debugs() messages may be written to stderr. The + /// answer may be affected by BanCacheLogUse() and SettleStderr(). + static bool StderrEnabled(); + + /* syslog channel */ + + /// enables logging to syslog (using the specified facility, when not nil) + static void ConfigureSyslog(const char *facility); + + /// Finalizes syslog configuration when no (more) ConfigureSyslog() calls + /// are expected. + static void SettleSyslog(); + private: + static void LogMessage(const Context &); + static Context *Current; ///< deepest active context; nil outside debugs() }; @@ -108,9 +174,6 @@ FILE *DebugStream(); /// change-avoidance macro; new code should call DebugStream() instead #define debug_log DebugStream() -/// start logging to stderr (instead of cache.log, if any) -void StopUsingDebugLog(); - /// a hack for low-level file descriptor manipulations in ipcCreate() void ResyncDebugLog(FILE *newDestination); @@ -172,8 +235,6 @@ inline std::ostream& operator <<(std::ostream &os, const uint8_t d) } /* Legacy debug function definitions */ -void _db_init(const char *logfile, const char *options); -void _db_set_syslog(const char *facility); void _db_rotate_log(void); /// Prints raw and/or non-terminated data safely, efficiently, and beautifully. diff --git a/src/Instance.cc b/src/Instance.cc index 7c8305e929..83990ab583 100644 --- a/src/Instance.cc +++ b/src/Instance.cc @@ -165,6 +165,14 @@ RemoveInstance() return; // nothing to do debugs(50, Important(22), "Removing " << PidFileDescription(ThePidFileToRemove)); + + // Do not write to cache_log after our PID file is removed because another + // instance may already be logging there. Stop logging now because, if we + // wait until safeunlink(), some debugs() may slip through into the now + // "unlocked" cache_log, especially if we avoid the sensitive suid() area. + // Use stderr to capture late debugs() that did not make it into cache_log. + Debug::StopCacheLogUse(); + const char *filename = ThePidFileToRemove.c_str(); // avoid complex operations inside enter_suid() enter_suid(); safeunlink(filename, 0); diff --git a/src/base/Optional.h b/src/base/Optional.h index 27b9b29457..9d59923cb3 100644 --- a/src/base/Optional.h +++ b/src/base/Optional.h @@ -10,6 +10,8 @@ #define SQUID__SRC_BASE_OPTIONAL_H #include +#include +#include /// std::bad_optional_access replacement (until we upgrade to C++17) class BadOptionalAccess: public std::exception @@ -50,6 +52,14 @@ public: return hasValue_ ? value_ : static_cast(std::forward(defaultValue)); } + template + Optional &operator =(Other &&otherValue) + { + value_ = std::forward(otherValue); + hasValue_ = true; + return *this; + } + private: Value value_; // stored value; inaccessible/uninitialized unless hasValue_ bool hasValue_ = false; diff --git a/src/debug.cc b/src/debug.cc index 24362422fa..eaaf171ca4 100644 --- a/src/debug.cc +++ b/src/debug.cc @@ -9,6 +9,7 @@ /* DEBUG: section 00 Debug Routines */ #include "squid.h" +#include "base/Optional.h" #include "base/TextException.h" #include "Debug.h" #include "DebugMessages.h" @@ -18,35 +19,61 @@ #include "util.h" #include +#include +#include +#include /* for shutting_down flag in xassert() */ #include "globals.h" char *Debug::debugOptions = NULL; int Debug::override_X = 0; -int Debug::log_stderr = -1; bool Debug::log_syslog = false; int Debug::Levels[MAX_DEBUG_SECTIONS]; char *Debug::cache_log = NULL; int Debug::rotateNumber = -1; DebugMessages TheDebugMessages; -static const char *debugLogTime(void); + +/// a counter related to the number of debugs() calls +using DebugRecordCount = uint64_t; + +class DebugModule; + +/// Debugging module singleton. +static DebugModule *Module_ = nullptr; + +/// Explicitly configured maximum level for debugs() messages written to stderr. +/// debugs() messages with this (or lower) level will be written to stderr (and +/// possibly other channels). +static Optional ExplicitStderrLevel; + +/// ExplicitStderrLevel preference or default: Just like with +/// ExplicitStderrLevel, debugs() messages with this (or lower) level will be +/// written to stderr (and possibly other channels), but this setting is ignored +/// when ExplicitStderrLevel is set. This setting is also ignored after major +/// problems that prevent logging of important debugs() messages (e.g., failing +/// to open cache_log or assertions). +static int DefaultStderrLevel = -1; + +/// early debugs() with higher level are not buffered and, hence, may be lost +static constexpr int EarlyMessagesLevel = DBG_IMPORTANT; + +static const char *debugLogTime(time_t t); static const char *debugLogKid(void); #if HAVE_SYSLOG #ifdef LOG_LOCAL4 static int syslog_facility = 0; #endif -static void _db_print_syslog(const bool forceAlert, const char *format, va_list args); #endif -static void _db_print_stderr(const char *format, va_list args); -static void _db_print_file(const char *format, va_list args); #if _SQUID_WINDOWS_ extern LPCRITICAL_SECTION dbg_mutex; typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD); #endif -/// a (FILE*, file name) pair that uses stderr FILE as the last resort +static void ResetSections(const int level = DBG_IMPORTANT); + +/// a named FILE with very-early/late usage safety mechanisms class DebugFile { public: @@ -60,8 +87,8 @@ public: /// go back to the initial state void clear() { reset(nullptr, nullptr); } - /// logging stream; the only method that uses stderr as the last resort - FILE *file() { return file_ ? file_ : stderr; } + /// an opened cache_log stream or nil + FILE *file() { return file_; } char *name = nullptr; @@ -71,19 +98,361 @@ private: FILE *file_ = nullptr; ///< opened "real" file or nil; never stderr }; -/// configured cache.log file or stderr +/// meta-information of a Finish()ed debugs() message +class DebugMessageHeader +{ +public: + DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &); + + DebugRecordCount recordNumber; ///< LogMessage() calls before this message + time_t timestamp; ///< approximate debugs() call time + int section; ///< debugs() section + int level; ///< debugs() level + bool forceAlert; ///< debugs() forceAlert flag +}; + +// Avoid SBuf for CompiledDebugMessageBody: +// * SBuf's own debugging may create a lot of reentrant debugging noise. +// * Debug::Context::buf is an std::string-based STL ostream. Converting its +// buf() result to a different kind of string may increase complexity/cost. +// TODO: Consider switching to a simple fixed-size buffer and a matching stream! +/// The processed "content" (i.e. the last parameter) part of a debugs() call. +using CompiledDebugMessageBody = std::string; + +/// a fully processed debugs(), ready to be logged +class CompiledDebugMessage +{ +public: + using Header = DebugMessageHeader; + using Body = CompiledDebugMessageBody; + + CompiledDebugMessage(const Header &, const Body &); + + Header header; ///< debugs() meta-information; reflected in log line prefix + Body body; ///< the log line after the prefix (without the newline) +}; + +// We avoid PoolingAllocator for CompiledDebugMessages to minimize reentrant +// debugging noise. This noise reduction has negligible performance overhead +// because it only applied to early messages, and there are few of them. +/// debugs() messages captured in LogMessage() call order +using CompiledDebugMessages = std::deque; + +/// a receiver of debugs() messages (e.g., stderr or cache.log) +class DebugChannel +{ +public: + using EarlyMessages = std::unique_ptr; + + explicit DebugChannel(const char *aName); + virtual ~DebugChannel() = default; + + // no copying or moving or any kind (for simplicity sake and to prevent accidental copies) + DebugChannel(DebugChannel &&) = delete; + + /// whether we are still expecting (and buffering) early messages + bool collectingEarlyMessages() const { return bool(earlyMessages); } + + /// end early message buffering, logging any saved messages + void stopEarlyMessageCollection(); + + /// end early message buffering, without logging any saved messages + /// \returns (a possibly empty container with) saved messages or nil + EarlyMessages releaseEarlyMessages() { return EarlyMessages(earlyMessages.release()); } + + /// Write the message to the channel if the channel accepts (such) messages. + /// This writing may be delayed until the channel configuration is settled. + void log(const DebugMessageHeader &, const CompiledDebugMessageBody &); + +protected: + /// output iterator for writing CompiledDebugMessages to a given channel + class Logger + { + public: + using difference_type = void; + using value_type = void; + using pointer = void; + using reference = void; + using iterator_category = std::output_iterator_tag; + + explicit Logger(DebugChannel &ch): channel(ch) {} + + Logger &operator=(const CompiledDebugMessage &message) + { + if (Debug::Enabled(message.header.section, message.header.level)) + channel.get().log(message.header, message.body); + return *this; + } + + // These no-op operators are provided to satisfy LegacyOutputIterator requirements, + // as is customary for similar STL output iterators like std::ostream_iterator. + Logger &operator*() { return *this; } + Logger &operator++() { return *this; } + Logger &operator++(int) { return *this; } + + private: + // wrap: output iterators must be CopyAssignable; raw references are not + std::reference_wrapper channel; ///< output destination + }; + + /// whether we should write() the corresponding debugs() message now + /// (assumes some higher-level code applied cache.log section/level filter) + virtual bool shouldWrite(const DebugMessageHeader &) const = 0; + + /// write the corresponding debugs() message into the channel + virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) = 0; + + /// stores the given early message (if possible) or forgets it (otherwise) + void saveMessage(const DebugMessageHeader &, const CompiledDebugMessageBody &); + + /// stop saving and log() any "early" messages, in recordNumber order + static void StopSavingAndLog(DebugChannel &, DebugChannel * = nullptr); + + /// Formats a validated debugs() record and writes it to the given FILE. + void writeToStream(FILE &, const DebugMessageHeader &, const CompiledDebugMessageBody &); + + /// reacts to a written a debugs() message + void noteWritten(const DebugMessageHeader &); + +protected: + const char * const name = nullptr; ///< unique channel label for debugging + + /// the number of messages sent to the underlying channel so far + DebugRecordCount written = 0; + + /// DebugMessageHeader::recordNumber of the last message we wrote + DebugRecordCount lastWrittenRecordNumber = 0; + + /// debugs() messages waiting for the channel configuration to settle (and + /// the channel to open) so that their eligibility for logging can be + /// determined (and the messages can be actually written somewhere) + EarlyMessages earlyMessages; +}; + +/// DebugChannel managing messages destined for the configured cache_log file +class CacheLogChannel: public DebugChannel +{ +public: + CacheLogChannel(): DebugChannel("cache_log") {} + +protected: + /* DebugChannel API */ + virtual bool shouldWrite(const DebugMessageHeader &) const final; + virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final; +}; + +/// DebugChannel managing messages destined for "standard error stream" (stderr) +class StderrChannel: public DebugChannel +{ +public: + StderrChannel(): DebugChannel("stderr") {} + + /// start to take care of past/saved and future cacheLovirtual gChannel messages + void takeOver(CacheLogChannel &); + + /// stop providing a cache_log replacement (if we were providing it) + void stopCoveringForCacheLog(); + + /// \copydoc DebugChannel::shouldWrite() + bool enabled(const int messageDebugLevel) const; + +protected: + /* DebugChannel API */ + virtual bool shouldWrite(const DebugMessageHeader &) const final; + virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final; + +private: + /// whether we are the last resort for logging debugs() messages + bool coveringForCacheLog = false; +}; + +/// syslog DebugChannel +class SyslogChannel: public DebugChannel +{ +public: + SyslogChannel(): DebugChannel("syslog") {} + + void markOpened() { opened = true; } + +protected: + /* DebugChannel API */ + virtual bool shouldWrite(const DebugMessageHeader &) const final; + virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final; + +private: + bool opened = false; ///< whether openlog() was called +}; + +/// Manages private module state that must be available during program startup +/// and (especially) termination. Any non-trivial state objects must be +/// encapsulated here because debugs() may be called before dynamic +/// initialization or after the destruction of static objects in debug.cc. +class DebugModule +{ +public: + DebugModule(); + + // we provide debugging services for the entire duration of the program + ~DebugModule() = delete; + + /// \copydoc Debug::PrepareToDie() + void prepareToDie(); + + /// Log the given debugs() message to appropriate channel(s) (eventually). + /// Assumes the message has passed the global section/level filter. + void log(const DebugMessageHeader &, const CompiledDebugMessageBody &); + + /// Start using an open cache_log file as the primary debugs() destination. + /// Stop using stderr as a cache_log replacement (if we were doing that). + void useCacheLog(); + + /// Start using stderr as the primary debugs() destination. + /// Stop waiting for an open cache_log file (if we were doing that). + void banCacheLogUse(); + +public: + CacheLogChannel cacheLogChannel; + StderrChannel stderrChannel; + SyslogChannel syslogChannel; +}; + +/// Maintains the number of code paths on the current call stack that need +/// protection from new debugs() calls. Squid cannot _block_ re-entrant debugs() +/// calls, but the high-level debugs() handling code queues re-entrant logging +/// attempts when Busy() instead of letting them through to sensitive code. +class LoggingSectionGuard +{ +public: + LoggingSectionGuard(); + ~LoggingSectionGuard(); + + /// whether new debugs() messages must be queued + static bool Busy() { return LoggingConcurrencyLevel; } + +private: + /// the current number of protected callers + static size_t LoggingConcurrencyLevel; +}; + +size_t LoggingSectionGuard::LoggingConcurrencyLevel = 0; + +/// debugs() messages postponed due to LoggingSectionGuard::Busy(). This is the +/// head of the invasive Context::upper FIFO list of such messages. +static Debug::Context *WaitingForIdle = nullptr; + +/// cache_log file /// safe during static initialization, even if it has not been constructed yet +/// safe during program termination, even if it has been destructed already static DebugFile TheLog; FILE * DebugStream() { - return TheLog.file(); + return TheLog.file() ? TheLog.file() : stderr; +} + +/// used for the side effect: fills Debug::Levels with the given level +static void +ResetSections(const int level) +{ + for (auto §ionLevel: Debug::Levels) + sectionLevel = level; +} + +/* LoggingSectionGuard */ + +LoggingSectionGuard::LoggingSectionGuard() +{ + ++LoggingConcurrencyLevel; +} + +LoggingSectionGuard::~LoggingSectionGuard() +{ + if (--LoggingConcurrencyLevel == 0) + Debug::LogWaitingForIdle(); +} + +/* DebugModule */ + +// Depending on DBG_CRITICAL activity and command line options, this code may +// run as early as static initialization during program startup or as late as +// the first debugs(DBG_CRITICAL) call from the main loop. +DebugModule::DebugModule() +{ + // explicit initialization before any use by debugs() calls; see bug #2656 + tzset(); + + (void)std::atexit(&Debug::PrepareToDie); + + if (!Debug::override_X) + ResetSections(); +} + +void +DebugModule::log(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + cacheLogChannel.log(header, body); + stderrChannel.log(header, body); + syslogChannel.log(header, body); +} + +void +DebugModule::prepareToDie() +{ + const LoggingSectionGuard sectionGuard; + + // Switch to stderr to improve our chances to log _early_ debugs(). However, + // use existing cache_log and/or stderr levels for post-open/close ones. + if (cacheLogChannel.collectingEarlyMessages() && !TheLog.file()) + banCacheLogUse(); + + cacheLogChannel.stopEarlyMessageCollection(); + stderrChannel.stopEarlyMessageCollection(); + syslogChannel.stopEarlyMessageCollection(); + + // Explicit last-resort call because we want to dump any pending messages + // (possibly including an assertion) even if another call, higher in the + // call stack, is currently in the sensitive section. Squid is dying, and + // that other caller (if any) will not get control back and, hence, will not + // trigger a Debug::LogWaitingForIdle() check. In most cases, we will log + // any pending messages successfully here. In the remaining few cases, we + // will lose them just like we would lose them without this call. The + // (small) risk here is that we might abort() or crash trying. + Debug::LogWaitingForIdle(); + + // Do not close/destroy channels: While the Debug module is not _guaranteed_ + // to get control after prepareToDie(), debugs() calls are still very much + // _possible_, and we want to support/log them for as long as we can. } void -StopUsingDebugLog() +DebugModule::useCacheLog() { - TheLog.clear(); + assert(TheLog.file()); + stderrChannel.stopCoveringForCacheLog(); // in case it was covering + cacheLogChannel.stopEarlyMessageCollection(); // in case it was collecting +} + +void +DebugModule::banCacheLogUse() +{ + assert(!TheLog.file()); + stderrChannel.takeOver(cacheLogChannel); +} + +/// safe access to the debugging module +static +DebugModule & +Module() +{ + if (!Module_) { + Module_ = new DebugModule(); +#if !HAVE_SYSLOG + // Optimization: Do not wait for others to tell us what we already know. + Debug::SettleSyslog(); +#endif + } + + return *Module_; } void @@ -92,6 +461,239 @@ ResyncDebugLog(FILE *newFile) TheLog.file_ = newFile; } +/* DebugChannel */ + +DebugChannel::DebugChannel(const char * const aName): + name(aName), + earlyMessages(new CompiledDebugMessages()) +{ +} + +void +DebugChannel::stopEarlyMessageCollection() +{ + if (earlyMessages) + StopSavingAndLog(*this); + // else already stopped +} + +void +DebugChannel::log(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + if (header.recordNumber <= lastWrittenRecordNumber) + return; + + if (!shouldWrite(header)) + return saveMessage(header, body); + + // We only save messages until we learn whether the channel is going to be + // used. We now know that it will be used. Also logs saved early messages + // (if they became eligible now) before lastWrittenRecordNumber blocks them. + stopEarlyMessageCollection(); + + write(header, body); +} + +void +Debug::ForgetSaved() +{ + auto &module = Module(); + (void)module.cacheLogChannel.releaseEarlyMessages(); + (void)module.stderrChannel.releaseEarlyMessages(); + (void)module.syslogChannel.releaseEarlyMessages(); +} + +void +Debug::PrepareToDie() +{ + Module().prepareToDie(); +} + +void +DebugChannel::StopSavingAndLog(DebugChannel &channelA, DebugChannel *channelBOrNil) +{ + const LoggingSectionGuard sectionGuard; + + assert(&channelA != channelBOrNil); + const auto asOrNil = channelA.releaseEarlyMessages(); + const auto bsOrNil = channelBOrNil ? channelBOrNil->releaseEarlyMessages() : nullptr; + const auto &as = asOrNil ? *asOrNil : CompiledDebugMessages(); + const auto &bs = bsOrNil ? *bsOrNil : CompiledDebugMessages(); + + const auto writtenEarlier = channelA.written; + + std::merge(as.begin(), as.end(), bs.begin(), bs.end(), Logger(channelA), + [](const CompiledDebugMessage &mA, const CompiledDebugMessage &mB) { + return mA.header.recordNumber < mB.header.recordNumber; + }); + + const auto writtenNow = channelA.written - writtenEarlier; + if (const auto totalCount = as.size() + bs.size()) { + debugs(0, 5, "wrote " << writtenNow << " out of " << totalCount << '=' << + as.size() << '+' << bs.size() << " early messages to " << channelA.name); + } +} + +void +DebugChannel::saveMessage(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + if (!earlyMessages) + return; // we have stopped saving early messages + + if (header.level > EarlyMessagesLevel) + return; // this message is not important enough to save + + // Given small EarlyMessagesLevel, only a Squid bug can cause so many + // earlyMessages. Saving/dumping excessive messages correctly is not only + // difficult but is more likely to complicate triage than help: It is the + // first earlyMessages that are going to be the most valuable. Our assert() + // will dump them if at all possible. + assert(earlyMessages->size() < 1000); + + earlyMessages->emplace_back(header, body); +} + +void +DebugChannel::writeToStream(FILE &destination, const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + fprintf(&destination, "%s%s| %s\n", + debugLogTime(header.timestamp), + debugLogKid(), + body.c_str()); + noteWritten(header); +} + +void +DebugChannel::noteWritten(const DebugMessageHeader &header) +{ + ++written; + lastWrittenRecordNumber = header.recordNumber; +} + +/* CacheLogChannel */ + +bool +CacheLogChannel::shouldWrite(const DebugMessageHeader &) const +{ + return TheLog.file(); +} + +void +CacheLogChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + writeToStream(*TheLog.file(), header, body); + fflush(TheLog.file()); +} + +/* StderrChannel */ + +bool +StderrChannel::enabled(const int level) const +{ + if (!stderr) + return false; // nowhere to write + + if (ExplicitStderrLevel.has_value()) // explicit admin restrictions (-d) + return level <= ExplicitStderrLevel.value(); + + // whether the given level is allowed by emergency handling circumstances + // (coveringForCacheLog) or configuration aspects (e.g., -k or -z) + return coveringForCacheLog || level <= DefaultStderrLevel; +} + +bool +StderrChannel::shouldWrite(const DebugMessageHeader &header) const +{ + return enabled(header.level); +} + +void +StderrChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + writeToStream(*stderr, header, body); +} + +void +StderrChannel::takeOver(CacheLogChannel &cacheLogChannel) +{ + if (coveringForCacheLog) + return; + coveringForCacheLog = true; + + StopSavingAndLog(*this, &cacheLogChannel); +} + +void +StderrChannel::stopCoveringForCacheLog() +{ + if (!coveringForCacheLog) + return; + + coveringForCacheLog = false; + debugs(0, DBG_IMPORTANT, "Resuming logging to cache_log"); +} + +void +Debug::EnsureDefaultStderrLevel(const int maxDefault) +{ + if (DefaultStderrLevel < maxDefault) + DefaultStderrLevel = maxDefault; // may set or increase + // else: somebody has already requested a more permissive maximum +} + +void +Debug::ResetStderrLevel(const int maxLevel) +{ + ExplicitStderrLevel = maxLevel; // may set, increase, or decrease +} + +void +Debug::SettleStderr() +{ + auto &stderrChannel = Module().stderrChannel; + + stderrChannel.stopEarlyMessageCollection(); + + if (override_X) { + // Some users might expect -X to force -d9. Tell them what is happening. + const auto outcome = + stderrChannel.enabled(DBG_DATA) ? "; stderr will see all messages": + stderrChannel.enabled(DBG_CRITICAL) ? "; stderr will not see some messages": + "; stderr will see no messages"; + if (ExplicitStderrLevel) + debugs(0, DBG_CRITICAL, "Using -X and -d" << ExplicitStderrLevel.value() << outcome); + else + debugs(0, DBG_CRITICAL, "Using -X without -d" << outcome); + } +} + +bool +Debug::StderrEnabled() +{ + return Module().stderrChannel.enabled(DBG_CRITICAL); +} + +/* DebugMessageHeader */ + +DebugMessageHeader::DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &context): + recordNumber(aRecordNumber), + timestamp(getCurrentTime()), + section(context.section), + level(context.level), + forceAlert(context.forceAlert) +{ +} + +/* CompiledDebugMessage */ + +CompiledDebugMessage::CompiledDebugMessage(const Header &aHeader, const Body &aBody): + header(aHeader), + body(aBody) +{ +} + +/* DebugFile */ + void DebugFile::reset(FILE *newFile, const char *newName) { @@ -115,16 +717,10 @@ DebugFile::reset(FILE *newFile, const char *newName) assert(!file_ == !name); } -static +/// broadcasts debugs() message to the logging channels void -_db_print(const bool forceAlert, const char *format,...) +Debug::LogMessage(const Context &context) { - char f[BUFSIZ]; - f[0]='\0'; - va_list args1; - va_list args2; - va_list args3; - #if _SQUID_WINDOWS_ /* Multiple WIN32 threads may call this simultaneously */ @@ -143,12 +739,12 @@ _db_print(const bool forceAlert, const char *format,...) /* let multiprocessor systems EnterCriticalSection() fast */ if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) { - if (debug_log) { - fprintf(debug_log, "FATAL: _db_print: can't initialize critical section\n"); - fflush(debug_log); + if (const auto logFile = TheLog.file()) { + fprintf(logFile, "FATAL: %s: can't initialize critical section\n", __FUNCTION__); + fflush(logFile); } - fprintf(stderr, "FATAL: _db_print: can't initialize critical section\n"); + fprintf(stderr, "FATAL: %s: can't initialize critical section\n", __FUNCTION__); abort(); } else InitializeCriticalSection(dbg_mutex); @@ -158,86 +754,20 @@ _db_print(const bool forceAlert, const char *format,...) EnterCriticalSection(dbg_mutex); #endif - va_start(args1, format); - va_start(args2, format); - va_start(args3, format); - - snprintf(f, BUFSIZ, "%s%s| %s", - debugLogTime(), - debugLogKid(), - format); - - _db_print_file(f, args1); - _db_print_stderr(f, args2); - -#if HAVE_SYSLOG - _db_print_syslog(forceAlert, format, args3); -#else - (void)forceAlert; -#endif + static DebugRecordCount LogMessageCalls = 0; + const DebugMessageHeader header(++LogMessageCalls, context); + Module().log(header, context.buf.str()); #if _SQUID_WINDOWS_ LeaveCriticalSection(dbg_mutex); #endif - - va_end(args1); - va_end(args2); - va_end(args3); -} - -static void -_db_print_file(const char *format, va_list args) -{ - if (debug_log == NULL) - return; - - vfprintf(debug_log, format, args); - fflush(debug_log); } -static void -_db_print_stderr(const char *format, va_list args) -{ - if (Debug::log_stderr < Debug::Level()) - return; - - if (debug_log == stderr) - return; - - vfprintf(stderr, format, args); -} - -#if HAVE_SYSLOG -static void -_db_print_syslog(const bool forceAlert, const char *format, va_list args) -{ - /* level 0,1 go to syslog */ - - if (!forceAlert) { - if (Debug::Level() > 1) - return; - - if (!Debug::log_syslog) - return; - } - - char tmpbuf[BUFSIZ]; - tmpbuf[0] = '\0'; - - vsnprintf(tmpbuf, BUFSIZ, format, args); - - tmpbuf[BUFSIZ - 1] = '\0'; - - syslog(forceAlert ? LOG_ALERT : (Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE), "%s", tmpbuf); -} -#endif /* HAVE_SYSLOG */ - static void debugArg(const char *arg) { int s = 0; int l = 0; - int i; if (!strncasecmp(arg, "rotate=", 7)) { arg += 7; @@ -268,17 +798,13 @@ debugArg(const char *arg) return; } - for (i = 0; i < MAX_DEBUG_SECTIONS; ++i) - Debug::Levels[i] = l; + ResetSections(l); } static void debugOpenLog(const char *logfile) { - if (logfile == NULL) { - TheLog.clear(); - return; - } + assert(logfile); // Bug 4423: ignore the stdio: logging module name if present const char *logfilename; @@ -292,12 +818,16 @@ debugOpenLog(const char *logfile) setmode(fileno(log), O_TEXT); #endif TheLog.reset(log, logfilename); + Module().useCacheLog(); } else { - fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile); - perror(logfile); - fprintf(stderr, " messages will be sent to 'stderr'.\n"); - fflush(stderr); + const auto xerrno = errno; TheLog.clear(); + Module().banCacheLogUse(); + + // report the problem after banCacheLogUse() to improve our chances of + // reporting earlier debugs() messages (that cannot be written after us) + debugs(0, DBG_CRITICAL, "ERROR: Cannot open cache_log (" << logfilename << ") for writing;" << + Debug::Extra << "fopen(3) error: " << xstrerr(xerrno)); } } @@ -418,7 +948,7 @@ syslog_facility_names[] = { #endif -void +static void _db_set_syslog(const char *facility) { Debug::log_syslog = true; @@ -454,20 +984,57 @@ _db_set_syslog(const char *facility) #endif /* LOG_LOCAL4 */ } -#else /* HAVE_SYSLOG */ +/* SyslogChannel */ + +static int +SyslogPriority(const DebugMessageHeader &header) +{ + return header.forceAlert ? LOG_ALERT : + (header.level == 0 ? LOG_WARNING : LOG_NOTICE); +} void -_db_set_syslog(const char *) +SyslogChannel::write(const DebugMessageHeader &header, const CompiledDebugMessageBody &body) +{ + syslog(SyslogPriority(header), "%s", body.c_str()); + noteWritten(header); +} + +#else + +void +SyslogChannel::write(const DebugMessageHeader &, const CompiledDebugMessageBody &) +{ + assert(!"unreachable code because opened, shouldWrite() are always false"); +} + +#endif /* HAVE_SYSLOG */ + +bool +SyslogChannel::shouldWrite(const DebugMessageHeader &header) const { - throw TextException("Logging to syslog is not available on this platform", Here()); + if (!opened) + return false; + + assert(Debug::log_syslog); + return header.forceAlert || header.level <= DBG_IMPORTANT; } +void +Debug::ConfigureSyslog(const char *facility) +{ +#if HAVE_SYSLOG + _db_set_syslog(facility); +#else + (void)facility; + // TODO: Throw. + fatalf("Logging to syslog not available on this platform"); #endif +} void Debug::parseOptions(char const *options) { - int i; char *p = NULL; char *s = NULL; @@ -476,8 +1043,7 @@ Debug::parseOptions(char const *options) return; } - for (i = 0; i < MAX_DEBUG_SECTIONS; ++i) - Debug::Levels[i] = 0; + ResetSections(); if (options) { p = xstrdup(options); @@ -490,21 +1056,45 @@ Debug::parseOptions(char const *options) } void -_db_init(const char *logfile, const char *options) +Debug::BanCacheLogUse() { - Debug::parseOptions(options); + Debug::parseOptions(debugOptions); + Module().banCacheLogUse(); +} - debugOpenLog(logfile); +void +Debug::UseCacheLog() +{ + Debug::parseOptions(debugOptions); + debugOpenLog(cache_log); +} +void +Debug::StopCacheLogUse() +{ + if (TheLog.file()) { + // UseCacheLog() was successful. + Module().cacheLogChannel.stopEarlyMessageCollection(); // paranoid + TheLog.clear(); + } else { + // UseCacheLog() was not called at all or failed to open cache_log. + Module().banCacheLogUse(); // may already be banned + } +} + +void +Debug::SettleSyslog() +{ #if HAVE_SYSLOG && defined(LOG_LOCAL4) - if (Debug::log_syslog) + if (Debug::log_syslog) { openlog(APP_SHORTNAME, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility); + Module().syslogChannel.markOpened(); + } #endif /* HAVE_SYSLOG */ - /* Pre-Init TZ env, see bug #2656 */ - tzset(); + Module().syslogChannel.stopEarlyMessageCollection(); } void @@ -575,11 +1165,8 @@ _db_rotate_log(void) } static const char * -debugLogTime(void) +debugLogTime(const time_t t) { - - time_t t = getCurrentTime(); - struct tm *tm; static char buf[128]; // arbitrary size, big enough for the below timestamp strings. static time_t last_t = 0; @@ -618,22 +1205,39 @@ debugLogKid(void) 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; + void xassert(const char *msg, const char *file, int line) { + // if the non-trivial code below has itself asserted, then simplify instead + // of running out of stack and complicating triage + if (Asserting_) + abort(); + + Asserting_ = true; + debugs(0, DBG_CRITICAL, "FATAL: assertion failed: " << file << ":" << line << ": \"" << msg << "\""); - if (!shutting_down) + if (!shutting_down) { + Debug::PrepareToDie(); abort(); + } + + Asserting_ = false; } Debug::Context *Debug::Current = nullptr; Debug::Context::Context(const int aSection, const int aLevel): + section(aSection), level(aLevel), sectionLevel(Levels[aSection]), upper(Current), - forceAlert(false) + forceAlert(false), + waitingForIdle(false) { formatStream(); } @@ -642,11 +1246,13 @@ Debug::Context::Context(const int aSection, const int aLevel): void Debug::Context::rewind(const int aSection, const int aLevel) { + section = aSection; level = aLevel; sectionLevel = Levels[aSection]; assert(upper == Current); + assert(!waitingForIdle); - buf.str(std::string()); + 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. @@ -665,14 +1271,32 @@ Debug::Context::formatStream() // If this is not enough, use copyfmt(cleanStream) which is ~10% slower. } +void +Debug::LogWaitingForIdle() +{ + if (!WaitingForIdle) + return; // do not lock in vain because unlocking would calls us + + const LoggingSectionGuard sectionGuard; + while (const auto current = WaitingForIdle) { + assert(current->waitingForIdle); + LogMessage(*current); + WaitingForIdle = current->upper; + delete current; + } +} + std::ostringstream & Debug::Start(const int section, const int level) { Context *future = nullptr; - // prepare future context - if (Current) { - // all reentrant debugs() calls get here; create a dedicated context + if (LoggingSectionGuard::Busy()) { + // a very rare reentrant debugs() call that originated during Finish() and such + future = new Context(section, level); + future->waitingForIdle = true; + } else if (Current) { + // a rare reentrant debugs() call that originated between Start() and Finish() future = new Context(section, level); } else { // Optimization: Nearly all debugs() calls get here; avoid allocations @@ -689,13 +1313,31 @@ Debug::Start(const int section, const int level) void Debug::Finish() { + const LoggingSectionGuard sectionGuard; + // TODO: #include "base/CodeContext.h" instead if doing so works well. extern std::ostream &CurrentCodeContextDetail(std::ostream &os); if (Current->level <= DBG_IMPORTANT) Current->buf << CurrentCodeContextDetail; - // TODO: Optimize to remove at least one extra copy. - _db_print(Current->forceAlert, "%s\n", Current->buf.str().c_str()); + if (Current->waitingForIdle) { + const auto past = Current; + Current = past->upper; + past->upper = nullptr; + // do not delete `past` because we store it in WaitingForIdle below + + // waitingForIdle messages are queued here instead of Start() because + // their correct order is determined by the Finish() call timing/order. + // Linear search, but this list ought to be very short (usually empty). + auto *last = &WaitingForIdle; + while (*last) + last = &(*last)->upper; + *last = past; + + return; + } + + LogMessage(*Current); Current->forceAlert = false; Context *past = Current; diff --git a/src/fatal.cc b/src/fatal.cc index e2d539dec0..e95a2d0667 100644 --- a/src/fatal.cc +++ b/src/fatal.cc @@ -95,6 +95,7 @@ fatal_dump(const char *message) if (opt_catch_signals) storeDirWriteCleanLogs(0); + Debug::PrepareToDie(); abort(); } diff --git a/src/icmp/IcmpPinger.cc b/src/icmp/IcmpPinger.cc index 989e756f37..259cb7a978 100644 --- a/src/icmp/IcmpPinger.cc +++ b/src/icmp/IcmpPinger.cc @@ -60,7 +60,10 @@ IcmpPinger::Open(void) atexit(Win32SockCleanup); getCurrentTime(); - _db_init(NULL, "ALL,1"); + + Debug::debugOptions = xstrdup("ALL,1"); + Debug::BanCacheLogUse(); + setmode(0, O_BINARY); setmode(1, O_BINARY); x = read(0, buf, sizeof(wpi)); diff --git a/src/icmp/pinger.cc b/src/icmp/pinger.cc index 90a007219d..b2fdc682e7 100644 --- a/src/icmp/pinger.cc +++ b/src/icmp/pinger.cc @@ -105,8 +105,6 @@ main(int, char **) int max_fd = 0; struct timeval tv; - const char *debug_args = "ALL,10"; - char *t; time_t last_check_time = 0; /* @@ -118,15 +116,15 @@ main(int, char **) int squid_link = -1; /** start by initializing the pinger debug cache.log-pinger. */ - if ((t = getenv("SQUID_DEBUG"))) - debug_args = xstrdup(t); + const auto envOptions = getenv("SQUID_DEBUG"); + Debug::debugOptions = xstrdup(envOptions ? envOptions : "ALL,10"); getCurrentTime(); // determine IPv4 or IPv6 capabilities before using sockets. Ip::ProbeTransport(); - _db_init(NULL, debug_args); + Debug::BanCacheLogUse(); debugs(42, DBG_CRITICAL, "pinger: Initialising ICMP pinger ..."); diff --git a/src/main.cc b/src/main.cc index 989d37507c..b5fcdb72e7 100644 --- a/src/main.cc +++ b/src/main.cc @@ -398,6 +398,7 @@ usage(void) " -R Do not set REUSEADDR on port.\n" " -S Double-check swap during rebuild.\n" " -X Force full debugging.\n" + " Add -d9 to also write full debugging to stderr.\n" " -Y Only return UDP_HIT or UDP_MISS_NOFETCH during fast reload.\n", APP_SHORTNAME, CACHE_HTTP_PORT, DEFAULT_CONFIG_FILE, CACHE_ICP_PORT); exit(EXIT_FAILURE); @@ -518,8 +519,9 @@ mainHandleCommandLineOption(const int optId, const char *optValue) case 'd': /** \par d - * Set global option Debug::log_stderr to the number given following the option */ - Debug::log_stderr = xatoi(optValue); + * debugs() messages with the given debugging level (and the more + * important ones) should be written to stderr */ + Debug::ResetStderrLevel(xatoi(optValue)); break; case 'f': @@ -583,6 +585,10 @@ mainHandleCommandLineOption(const int optId, const char *optValue) else usage(); + // Cannot use cache.log: use stderr for important messages (by default) + // and stop expecting a Debug::UseCacheLog() call. + Debug::EnsureDefaultStderrLevel(DBG_IMPORTANT); + Debug::BanCacheLogUse(); break; case 'm': @@ -636,13 +642,13 @@ mainHandleCommandLineOption(const int optId, const char *optValue) * then performs actions for -s option. */ xfree(opt_syslog_facility); // ignore any previous options sent opt_syslog_facility = xstrdup(optValue); - _db_set_syslog(opt_syslog_facility); + Debug::ConfigureSyslog(opt_syslog_facility); break; case 's': /** \par s * Initialize the syslog for output */ - _db_set_syslog(opt_syslog_facility); + Debug::ConfigureSyslog(opt_syslog_facility); break; case 'u': @@ -681,9 +687,13 @@ mainHandleCommandLineOption(const int optId, const char *optValue) case 'z': /** \par z - * Set global option Debug::log_stderr and opt_create_swap_dirs */ - Debug::log_stderr = 1; + * Request cache_dir initialization */ opt_create_swap_dirs = 1; + // We will use cache.log, but this command is often executed on the + // command line, so use stderr to show important messages (by default). + // TODO: Generalize/fix this -z-specific and sometimes faulty logic with + // "use stderr when it is a tty [until we GoIntoBackground()]" logic. + Debug::EnsureDefaultStderrLevel(DBG_IMPORTANT); break; case optForeground: @@ -939,7 +949,7 @@ mainReconfigureFinish(void *) setUmask(Config.umask); Mem::Report(); setEffectiveUser(); - _db_init(Debug::cache_log, Debug::debugOptions); + Debug::UseCacheLog(); ipcache_restart(); /* clear stuck entries */ fqdncache_restart(); /* sigh, fqdncache too */ parseEtcHosts(); @@ -1338,6 +1348,8 @@ OnTerminate() terminating = true; debugs(1, DBG_CRITICAL, "FATAL: Dying from an exception handling failure; exception: " << CurrentException); + + Debug::PrepareToDie(); abort(); } @@ -1415,7 +1427,6 @@ ConfigureCurrentKid(const CommandLine &cmdLine) } /// Start directing debugs() messages to the configured cache.log. -/// Until this function is called, all allowed messages go to stderr. static void ConfigureDebugging() { @@ -1425,9 +1436,11 @@ ConfigureDebugging() fd_open(2, FD_LOG, "stderr"); } // we should not create cache.log outside chroot environment, if any - // XXX: With Config.chroot_dir set, SMP master process never calls db_init(). + // XXX: With Config.chroot_dir set, SMP master process calls Debug::BanCacheLogUse(). if (!Config.chroot_dir || Chrooted) - _db_init(Debug::cache_log, Debug::debugOptions); + Debug::UseCacheLog(); + else + Debug::BanCacheLogUse(); } static void @@ -1472,8 +1485,6 @@ SquidMain(int argc, char **argv) ConfigureCurrentKid(cmdLine); - Debug::parseOptions(NULL); - #if defined(SQUID_MAXFD_LIMIT) if (SQUID_MAXFD_LIMIT < Squid_MaxFD) @@ -1519,14 +1530,13 @@ SquidMain(int argc, char **argv) cmdLine.forEachOption(mainHandleCommandLineOption); + Debug::SettleStderr(); + Debug::SettleSyslog(); + if (opt_foreground && opt_no_daemon) { debugs(1, DBG_CRITICAL, "WARNING: --foreground command-line option has no effect with -N."); } - if (opt_parse_cfg_only) { - Debug::parseOptions("ALL,1"); - } - #if USE_WIN32_SERVICE if (opt_install_service) { @@ -1708,8 +1718,6 @@ SquidMain(int argc, char **argv) static void sendSignal(void) { - StopUsingDebugLog(); - #if USE_WIN32_SERVICE // WIN32_sendSignal() does not need the PID value to signal, // but we must exit if there is no valid PID (TODO: Why?). @@ -1857,6 +1865,9 @@ GoIntoBackground() throw TexcHere(ToSBuf("failed to fork(2) the master process: ", xstrerr(xerrno))); } else if (pid > 0) { // parent + // The fork() effectively duped any saved debugs() messages. For + // simplicity sake, let the child process deal with them. + Debug::ForgetSaved(); exit(EXIT_SUCCESS); } // child, running as a background daemon @@ -1932,7 +1943,7 @@ watch_child(const CommandLine &masterCommand) dup2(nullfd, 0); - if (Debug::log_stderr < 0) { + if (!Debug::StderrEnabled()) { dup2(nullfd, 1); dup2(nullfd, 2); } @@ -2141,17 +2152,6 @@ SquidShutdown() debugs(1, Important(10), "Squid Cache (Version " << version_string << "): Exiting normally."); - /* - * DPW 2006-10-23 - * We used to fclose(debug_log) here if it was set, but then - * we forgot to set it to NULL. That caused some coredumps - * because exit() ends up calling a bunch of destructors and - * such. So rather than forcing the debug_log to close, we'll - * leave it open so that those destructors can write some - * debugging if necessary. The file will be closed anyway when - * the process truly exits. - */ - exit(shutdown_status); } diff --git a/src/mem/old_api.cc b/src/mem/old_api.cc index c16e5fd0f5..c51625e2ab 100644 --- a/src/mem/old_api.cc +++ b/src/mem/old_api.cc @@ -430,13 +430,6 @@ Mem::Init(void) if (MemIsInitialized) return; - /** \par - * NOTE: Mem::Init() is called before the config file is parsed - * and before the debugging module has been initialized. Any - * debug messages here at level 0 or 1 will always be printed - * on stderr. - */ - /** * Then initialize all pools. * \par diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc index 73c043cb3a..55f9a0ffdf 100644 --- a/src/tests/stub_debug.cc +++ b/src/tests/stub_debug.cc @@ -24,11 +24,9 @@ char *Debug::cache_log= NULL; int Debug::rotateNumber = 0; int Debug::Levels[MAX_DEBUG_SECTIONS]; int Debug::override_X = 0; -int Debug::log_stderr = 1; bool Debug::log_syslog = false; void Debug::ForceAlert() STUB -void StopUsingDebugLog() STUB void ResyncDebugLog(FILE *) STUB FILE * @@ -37,53 +35,27 @@ DebugStream() return stderr; } -void -_db_init(const char *, const char *) -{} - -void -_db_set_syslog(const char *) -{} - void _db_rotate_log(void) {} -static void -_db_print_stderr(const char *format, va_list args); - -static void -_db_print(const char *format,...) +void +Debug::LogMessage(const Context &context) { - static char f[BUFSIZ]; - va_list args1; - va_list args2; - va_list args3; - - va_start(args1, format); - va_start(args2, format); - va_start(args3, format); - - snprintf(f, BUFSIZ, "%s| %s", - "stub time", //debugLogTime(squid_curtime), - format); - - _db_print_stderr(f, args2); - - va_end(args1); - va_end(args2); - va_end(args3); -} + if (context.level > DBG_IMPORTANT) + return; -static void -_db_print_stderr(const char *format, va_list args) -{ - if (1 < Debug::Level()) + if (!stderr) return; - vfprintf(stderr, format, args); + fprintf(stderr, "%s| %s\n", + "stub time", // debugLogTime(squid_curtime), + context.buf.str().c_str()); } +bool Debug::StderrEnabled() STUB_RETVAL(false) +void Debug::PrepareToDie() STUB + void Debug::parseOptions(char const *) {} @@ -91,6 +63,7 @@ Debug::parseOptions(char const *) Debug::Context *Debug::Current = nullptr; Debug::Context::Context(const int aSection, const int aLevel): + section(aSection), level(aLevel), sectionLevel(Levels[aSection]), upper(Current), @@ -111,7 +84,7 @@ void Debug::Finish() { if (Current) { - _db_print("%s\n", Current->buf.str().c_str()); + LogMessage(*Current); delete Current; Current = nullptr; } diff --git a/src/tests/test_http_range.cc b/src/tests/test_http_range.cc index ca16f9b6be..1f6e675c2b 100644 --- a/src/tests/test_http_range.cc +++ b/src/tests/test_http_range.cc @@ -131,8 +131,8 @@ main(int, char **) try { Mem::Init(); /* enable for debugging to console */ - // _db_init (NULL, NULL); - // Debug::Levels[64] = 9; + // Debug::debugOptions = xstrdup("ALL,1 64,9"); + // Debug::BanCacheLogUse(); testRangeParser("bytes=0-3"); testRangeParser("bytes=-3"); testRangeParser("bytes=1-"); diff --git a/src/tools.cc b/src/tools.cc index 0d3f6a5ffc..67d87140f8 100644 --- a/src/tools.cc +++ b/src/tools.cc @@ -358,6 +358,7 @@ death(int sig) puts(dead_msg()); } + Debug::PrepareToDie(); abort(); }