debug.cc

Go to the documentation of this file.

/*
 * Copyright (C) 1996-2023 The Squid Software Foundation and contributors
 *
 * Squid software is distributed under GPLv2+ license and includes
 * contributions from numerous individuals and organizations.
 * Please see the COPYING and CONTRIBUTORS files for details.
 */
 
/* DEBUG: section 00    Debug Routines */
 
#include "squid.h"
#include "base/TextException.h"
#include "debug/Stream.h"
#include "fd.h"
#include "ipc/Kids.h"
#include "time/gadgets.h"
#include "util.h"
 
#include <algorithm>
#include <deque>
#include <functional>
#include <memory>
#include <optional>
 
char *Debug::debugOptions = nullptr;
int Debug::override_X = 0;
bool Debug::log_syslog = false;
int Debug::Levels[MAX_DEBUG_SECTIONS];
char *Debug::cache_log = nullptr;
int Debug::rotateNumber = -1;
 
using DebugRecordCount = uint64_t;
 
class DebugModule;
 
static DebugModule *Module_ = nullptr;
 
static std::optional<int> ExplicitStderrLevel;
 
static int DefaultStderrLevel = -1;
 
static constexpr int EarlyMessagesLevel = DBG_IMPORTANT;
 
static std::string ProcessLabel;
 
static const char *debugLogTime(const timeval &);
 
#if HAVE_SYSLOG
#ifdef LOG_LOCAL4
static int syslog_facility = 0;
#endif
#endif
 
#if _SQUID_WINDOWS_
extern LPCRITICAL_SECTION dbg_mutex;
typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
#endif
 
static void ResetSections(const int level = DBG_IMPORTANT);
 
static bool DidResetSections = false;
 
class DebugFile
{
public:
    DebugFile() {}
    ~DebugFile() { clear(); }
    DebugFile(DebugFile &&) = delete; // no copying or moving of any kind
 
    void reset(FILE *newFile, const char *newName);
 
    void clear() { reset(nullptr, nullptr); }
 
    FILE *file() { return file_; }
 
    char *name = nullptr;
 
private:
    friend void ResyncDebugLog(FILE *newFile);
 
    FILE *file_ = nullptr; 
};
 
class DebugMessageHeader
{
public:
    DebugMessageHeader(const DebugRecordCount aRecordNumber, const Debug::Context &);
 
    DebugRecordCount recordNumber; 
    struct timeval timestamp; 
    int section; 
    int level; 
    bool forceAlert; 
};
 
// 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!
using CompiledDebugMessageBody = std::string;
 
class CompiledDebugMessage
{
public:
    using Header = DebugMessageHeader;
    using Body = CompiledDebugMessageBody;
 
    CompiledDebugMessage(const Header &, const Body &);
 
    Header header; 
    Body body; 
};
 
// 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.
using CompiledDebugMessages = std::deque<CompiledDebugMessage>;
 
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;
 
    bool collectingEarlyMessages() const { return bool(earlyMessages); }
 
    void stopEarlyMessageCollection();
 
    EarlyMessages releaseEarlyMessages() { return EarlyMessages(earlyMessages.release()); }
 
    void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 
protected:
    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; 
    };
 
    virtual bool shouldWrite(const DebugMessageHeader &) const = 0;
 
    virtual void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) = 0;
 
    void saveMessage(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 
    static void StopSavingAndLog(DebugChannel &, DebugChannel * = nullptr);
 
    void writeToStream(FILE &, const DebugMessageHeader &, const CompiledDebugMessageBody &);
 
    void noteWritten(const DebugMessageHeader &);
 
protected:
    const char * const name = nullptr; 
 
    DebugRecordCount written = 0;
 
    DebugRecordCount lastWrittenRecordNumber = 0;
 
    EarlyMessages earlyMessages;
};
 
class CacheLogChannel: public DebugChannel
{
public:
    CacheLogChannel(): DebugChannel("cache_log") {}
 
protected:
    /* DebugChannel API */
    bool shouldWrite(const DebugMessageHeader &) const final;
    void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
};
 
class StderrChannel: public DebugChannel
{
public:
    StderrChannel(): DebugChannel("stderr") {}
 
    void takeOver(CacheLogChannel &);
 
    void stopCoveringForCacheLog();
 
    bool enabled(const int messageDebugLevel) const;
 
protected:
    /* DebugChannel API */
    bool shouldWrite(const DebugMessageHeader &) const final;
    void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
 
private:
    bool coveringForCacheLog = false;
};
 
class SyslogChannel: public DebugChannel
{
public:
    SyslogChannel(): DebugChannel("syslog") {}
 
    void markOpened() { opened = true; }
 
protected:
    /* DebugChannel API */
    bool shouldWrite(const DebugMessageHeader &) const final;
    void write(const DebugMessageHeader &, const CompiledDebugMessageBody &) final;
 
private:
    bool opened = false; 
};
 
class DebugModule
{
public:
    DebugModule();
 
    // we provide debugging services for the entire duration of the program
    ~DebugModule() = delete;
 
    void prepareToDie();
 
    void log(const DebugMessageHeader &, const CompiledDebugMessageBody &);
 
    void useCacheLog();
 
    void banCacheLogUse();
 
public:
    CacheLogChannel cacheLogChannel;
    StderrChannel stderrChannel;
    SyslogChannel syslogChannel;
};
 
class LoggingSectionGuard
{
public:
    LoggingSectionGuard();
    ~LoggingSectionGuard();
 
    static bool Busy() { return LoggingConcurrencyLevel; }
 
private:
    static size_t LoggingConcurrencyLevel;
};
 
size_t LoggingSectionGuard::LoggingConcurrencyLevel = 0;
 
static Debug::Context *WaitingForIdle = nullptr;
 
static DebugFile TheLog;
 
FILE *
DebugStream() {
    return TheLog.file() ? TheLog.file() : stderr;
}
 
static void
ResetSections(const int level)
{
    DidResetSections = true;
    for (auto &sectionLevel: Debug::Levels)
        sectionLevel = level;
}
 
static void
LabelThisProcess(const char * const name, const std::optional<int> id = std::optional<int>())
{
    assert(name);
    assert(strlen(name));
    std::stringstream os;
    os << ' ' << name;
    if (id.has_value()) {
        assert(id.value() >= 0);
        os << id.value();
    }
    ProcessLabel = os.str();
}
 
void
Debug::NameThisHelper(const char * const name)
{
    LabelThisProcess(name);
 
    if (const auto parentProcessDebugOptions = getenv("SQUID_DEBUG")) {
        assert(!debugOptions);
        debugOptions = xstrdup(parentProcessDebugOptions);
    }
 
    // do not restrict helper (i.e. stderr) logging beyond debug_options
    EnsureDefaultStderrLevel(DBG_DATA);
 
    // helpers do not write to cache.log directly; instead, ipcCreate()
    // diverts helper stderr output to cache.log of the parent process
    BanCacheLogUse();
 
    SettleStderr();
    SettleSyslog();
 
    debugs(84, 2, "starting " << name << " with PID " << getpid());
}
 
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", std::optional<int>(kidIdentifier));
    else
        ProcessLabel.clear(); // probably already empty
}
 
/* 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 (!DidResetSections)
        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
DebugModule::useCacheLog()
{
    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);
}
 
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
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),
            ProcessLabel.c_str(),
            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),
    section(context.section),
    level(context.level),
    forceAlert(context.forceAlert)
{
    (void)getCurrentTime(); // update current_time
    timestamp = current_time;
}
 
/* CompiledDebugMessage */
 
CompiledDebugMessage::CompiledDebugMessage(const Header &aHeader, const Body &aBody):
    header(aHeader),
    body(aBody)
{
}
 
/* DebugFile */
 
void
DebugFile::reset(FILE *newFile, const char *newName)
{
    // callers must use nullptr instead of the used-as-the-last-resort stderr
    assert(newFile != stderr || !stderr);
 
    if (file_) {
        fd_close(fileno(file_));
        fclose(file_);
    }
    file_ = newFile; // may be nil
 
    if (file_)
        fd_open(fileno(file_), FD_LOG, Debug::cache_log);
 
    xfree(name);
    name = newName ? xstrdup(newName) : nullptr;
 
    // all open files must have a name
    // all cleared files must not have a name
    assert(!file_ == !name);
}
 
void
Debug::LogMessage(const Context &context)
{
#if _SQUID_WINDOWS_
    /* Multiple WIN32 threads may call this simultaneously */
 
    if (!dbg_mutex) {
        HMODULE krnl_lib = GetModuleHandle("Kernel32");
        PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount = NULL;
 
        if (krnl_lib)
            InitializeCriticalSectionAndSpinCount =
                (PFInitializeCriticalSectionAndSpinCount) GetProcAddress(krnl_lib,
                        "InitializeCriticalSectionAndSpinCount");
 
        dbg_mutex = static_cast<CRITICAL_SECTION*>(xcalloc(1, sizeof(CRITICAL_SECTION)));
 
        if (InitializeCriticalSectionAndSpinCount) {
            /* let multiprocessor systems EnterCriticalSection() fast */
 
            if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) {
                if (const auto logFile = TheLog.file()) {
                    fprintf(logFile, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
                    fflush(logFile);
                }
 
                fprintf(stderr, "FATAL: %s: can't initialize critical section\n", __FUNCTION__);
                abort();
            } else
                InitializeCriticalSection(dbg_mutex);
        }
    }
 
    EnterCriticalSection(dbg_mutex);
#endif
 
    static DebugRecordCount LogMessageCalls = 0;
    const DebugMessageHeader header(++LogMessageCalls, context);
    Module().log(header, context.buf.str());
 
#if _SQUID_WINDOWS_
    LeaveCriticalSection(dbg_mutex);
#endif
}
 
static void
debugArg(const char *arg)
{
    int s = 0;
    int l = 0;
 
    if (!strncasecmp(arg, "rotate=", 7)) {
        arg += 7;
        Debug::rotateNumber = atoi(arg);
        return;
    } else if (!strncasecmp(arg, "ALL", 3)) {
        s = -1;
        arg += 4;
    } else {
        s = atoi(arg);
        while (*arg && *arg++ != ',');
    }
 
    l = atoi(arg);
    assert(s >= -1);
 
    if (s >= MAX_DEBUG_SECTIONS)
        s = MAX_DEBUG_SECTIONS-1;
 
    if (l < 0)
        l = 0;
 
    if (l > 10)
        l = 10;
 
    if (s >= 0) {
        Debug::Levels[s] = l;
        return;
    }
 
    ResetSections(l);
}
 
static void
debugOpenLog(const char *logfile)
{
    assert(logfile);
 
    // Bug 4423: ignore the stdio: logging module name if present
    const char *logfilename;
    if (strncmp(logfile, "stdio:",6) == 0)
        logfilename = logfile + 6;
    else
        logfilename = logfile;
 
    if (auto log = fopen(logfilename, "a+")) {
#if _SQUID_WINDOWS_
        setmode(fileno(log), O_TEXT);
#endif
        TheLog.reset(log, logfilename);
        Module().useCacheLog();
    } else {
        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));
    }
}
 
#if HAVE_SYSLOG
#ifdef LOG_LOCAL4
 
static struct syslog_facility_name {
    const char *name;
    int facility;
}
 
syslog_facility_names[] = {
 
#ifdef LOG_AUTH
    {
        "auth", LOG_AUTH
    },
#endif
#ifdef LOG_AUTHPRIV
    {
        "authpriv", LOG_AUTHPRIV
    },
#endif
#ifdef LOG_CRON
    {
        "cron", LOG_CRON
    },
#endif
#ifdef LOG_DAEMON
    {
        "daemon", LOG_DAEMON
    },
#endif
#ifdef LOG_FTP
    {
        "ftp", LOG_FTP
    },
#endif
#ifdef LOG_KERN
    {
        "kern", LOG_KERN
    },
#endif
#ifdef LOG_LPR
    {
        "lpr", LOG_LPR
    },
#endif
#ifdef LOG_MAIL
    {
        "mail", LOG_MAIL
    },
#endif
#ifdef LOG_NEWS
    {
        "news", LOG_NEWS
    },
#endif
#ifdef LOG_SYSLOG
    {
        "syslog", LOG_SYSLOG
    },
#endif
#ifdef LOG_USER
    {
        "user", LOG_USER
    },
#endif
#ifdef LOG_UUCP
    {
        "uucp", LOG_UUCP
    },
#endif
#ifdef LOG_LOCAL0
    {
        "local0", LOG_LOCAL0
    },
#endif
#ifdef LOG_LOCAL1
    {
        "local1", LOG_LOCAL1
    },
#endif
#ifdef LOG_LOCAL2
    {
        "local2", LOG_LOCAL2
    },
#endif
#ifdef LOG_LOCAL3
    {
        "local3", LOG_LOCAL3
    },
#endif
#ifdef LOG_LOCAL4
    {
        "local4", LOG_LOCAL4
    },
#endif
#ifdef LOG_LOCAL5
    {
        "local5", LOG_LOCAL5
    },
#endif
#ifdef LOG_LOCAL6
    {
        "local6", LOG_LOCAL6
    },
#endif
#ifdef LOG_LOCAL7
    {
        "local7", LOG_LOCAL7
    },
#endif
    {
        nullptr, 0
    }
};
 
#endif
 
static void
_db_set_syslog(const char *facility)
{
    Debug::log_syslog = true;
 
#ifdef LOG_LOCAL4
#ifdef LOG_DAEMON
 
    syslog_facility = LOG_DAEMON;
#else
 
    syslog_facility = LOG_LOCAL4;
#endif /* LOG_DAEMON */
 
    if (facility) {
 
        struct syslog_facility_name *n;
 
        for (n = syslog_facility_names; n->name; ++n) {
            if (strcmp(n->name, facility) == 0) {
                syslog_facility = n->facility;
                return;
            }
        }
 
        fprintf(stderr, "unknown syslog facility '%s'\n", facility);
        exit(EXIT_FAILURE);
    }
 
#else
    if (facility)
        fprintf(stderr, "syslog facility type not supported on your system\n");
 
#endif /* LOG_LOCAL4 */
}
 
/* SyslogChannel */
 
static int
SyslogPriority(const DebugMessageHeader &header)
{
    return header.forceAlert ? LOG_ALERT :
           (header.level == 0 ? LOG_WARNING : LOG_NOTICE);
}
 
void
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
{
    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)
{
    char *p = nullptr;
    char *s = nullptr;
 
    if (override_X) {
        debugs(0, 9, "command-line -X overrides: " << options);
        return;
    }
 
    ResetSections();
 
    if (options) {
        p = xstrdup(options);
 
        for (s = strtok(p, w_space); s; s = strtok(nullptr, w_space))
            debugArg(s);
 
        xfree(p);
    }
}
 
void
Debug::BanCacheLogUse()
{
    Debug::parseOptions(debugOptions);
    Module().banCacheLogUse();
}
 
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) {
        openlog(APP_SHORTNAME, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility);
        Module().syslogChannel.markOpened();
    }
 
#endif /* HAVE_SYSLOG */
 
    Module().syslogChannel.stopEarlyMessageCollection();
}
 
void
_db_rotate_log(void)
{
    if (!TheLog.name)
        return;
 
#ifdef S_ISREG
    struct stat sb;
    if (stat(TheLog.name, &sb) == 0)
        if (S_ISREG(sb.st_mode) == 0)
            return;
#endif
 
    char from[MAXPATHLEN];
    from[0] = '\0';
 
    char to[MAXPATHLEN];
    to[0] = '\0';
 
    /*
     * NOTE: we cannot use xrename here without having it in a
     * separate file -- tools.c has too many dependencies to be
     * used everywhere debug.c is used.
     */
    /* Rotate numbers 0 through N up one */
    for (int i = Debug::rotateNumber; i > 1;) {
        --i;
        snprintf(from, MAXPATHLEN, "%s.%d", TheLog.name, i - 1);
        snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, i);
#if _SQUID_WINDOWS_
        remove
        (to);
#endif
        errno = 0;
        if (rename(from, to) == -1) {
            const auto saved_errno = errno;
            debugs(0, DBG_IMPORTANT, "ERROR: log rotation failed: " << xstrerr(saved_errno));
        }
    }
 
    /* Rotate the current log to .0 */
    if (Debug::rotateNumber > 0) {
        // form file names before we may clear TheLog below
        snprintf(from, MAXPATHLEN, "%s", TheLog.name);
        snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, 0);
 
#if _SQUID_WINDOWS_
        errno = 0;
        if (remove(to) == -1) {
            const auto saved_errno = errno;
            debugs(0, DBG_IMPORTANT, "ERROR: removal of log file " << to << " failed: " << xstrerr(saved_errno));
        }
        TheLog.clear(); // Windows cannot rename() open files
#endif
        errno = 0;
        if (rename(from, to) == -1) {
            const auto saved_errno = errno;
            debugs(0, DBG_IMPORTANT, "ERROR: renaming file " << from << " to "
                   << to << "failed: " << xstrerr(saved_errno));
        }
    }
 
    // Close (if we have not already) and reopen the log because
    // it may have been renamed "manually" before HUP'ing us.
    debugOpenLog(Debug::cache_log);
}
 
static const char *
debugLogTime(const timeval &t)
{
    static char buf[128]; // arbitrary size, big enough for the below timestamp strings.
    static time_t last_t = 0;
 
    if (Debug::Level() > 1) {
        // 4 bytes smaller than buf to ensure .NNN catenation by snprintf()
        // is safe and works even if strftime() fills its buffer.
        char buf2[sizeof(buf)-4];
        const auto tm = localtime(&t.tv_sec);
        strftime(buf2, sizeof(buf2), "%Y/%m/%d %H:%M:%S", tm);
        buf2[sizeof(buf2)-1] = '\0';
        const auto sz = snprintf(buf, sizeof(buf), "%s.%03d", buf2, static_cast<int>(t.tv_usec / 1000));
        assert(0 < sz && sz < static_cast<int>(sizeof(buf)));
        // force buf reset for subsequent level-0/1 messages that should have no milliseconds
        last_t = 0;
    } else if (t.tv_sec != last_t) {
        const auto tm = localtime(&t.tv_sec);
        const int sz = strftime(buf, sizeof(buf), "%Y/%m/%d %H:%M:%S", tm);
        assert(0 < sz && sz <= static_cast<int>(sizeof(buf)));
        last_t = t.tv_sec;
    }
 
    buf[sizeof(buf)-1] = '\0';
    return buf;
}
 
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 << "\"");
 
    Debug::PrepareToDie();
    abort();
}
 
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),
    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(CompiledDebugMessageBody());
    buf.clear();
    // debugs() users are supposed to preserve format, but
    // some do not, so we have to waste cycles resetting it for all.
    formatStream();
}
 
void
Debug::Context::formatStream()
{
    const static std::ostringstream cleanStream;
    buf.flags(cleanStream.flags() | std::ios::fixed);
    buf.width(cleanStream.width());
    buf.precision(2);
    buf.fill(' ');
    // 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;
 
    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
        static Context *topContext = new Context(1, 1);
        topContext->rewind(section, level);
        future = topContext;
    }
 
    Current = future;
 
    return future->buf;
}
 
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;
 
    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;
    Current = past->upper;
    if (Current)
        delete past;
    // else it was a static topContext from Debug::Start()
}
 
void
Debug::ForceAlert()
{
    //  the ForceAlert(ostream) manipulator should only be used inside debugs()
    if (Current)
        Current->forceAlert = true;
}
 
std::ostream&
ForceAlert(std::ostream& s)
{
    Debug::ForceAlert();
    return s;
}