/* DEBUG: section 00 Debug Routines */
#include "squid.h"
+#include "base/Optional.h"
#include "base/TextException.h"
#include "Debug.h"
#include "DebugMessages.h"
#include "util.h"
#include <algorithm>
+#include <deque>
+#include <functional>
+#include <memory>
/* 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<int> 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:
/// 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;
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<CompiledDebugMessage>;
+
+/// a receiver of debugs() messages (e.g., stderr or cache.log)
+class DebugChannel
+{
+public:
+ using EarlyMessages = std::unique_ptr<CompiledDebugMessages>;
+
+ 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<DebugChannel> 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
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)
{
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 */
/* 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);
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;
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;
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));
}
}
#endif
-void
+static void
_db_set_syslog(const char *facility)
{
Debug::log_syslog = true;
#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;
return;
}
- for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
- Debug::Levels[i] = 0;
+ ResetSections();
if (options) {
p = xstrdup(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
}
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;
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();
}
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.
// 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
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;
projects / thirdparty / squid.git / commitdiff
