/*
- * Copyright (C) 1996-2015 The Squid Software Foundation and contributors
+ * Copyright (C) 1996-2021 The Squid Software Foundation and contributors
*
* Squid software is distributed under GPLv2+ license and includes
* contributions from numerous individuals and organizations.
#include "squid.h"
#include "Debug.h"
+#include "fd.h"
#include "ipc/Kids.h"
#include "SquidTime.h"
#include "util.h"
+#include <algorithm>
+
/* for shutting_down flag in xassert() */
#include "globals.h"
int Debug::log_stderr = -1;
bool Debug::log_syslog = false;
int Debug::Levels[MAX_DEBUG_SECTIONS];
-int Debug::level;
-int Debug::sectionLevel;
char *Debug::cache_log = NULL;
int Debug::rotateNumber = -1;
-FILE *debug_log = NULL;
-static char *debug_log_file = NULL;
static int Ctx_Lock = 0;
static const char *debugLogTime(void);
static const char *debugLogKid(void);
#ifdef LOG_LOCAL4
static int syslog_facility = 0;
#endif
-static void _db_print_syslog(const char *format, va_list args);
+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);
typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
#endif
+/// a (FILE*, file name) pair that uses stderr FILE as the last resort
+class DebugFile
+{
+public:
+ DebugFile() {}
+ ~DebugFile() { clear(); }
+ DebugFile(DebugFile &&) = delete; // no copying or moving of any kind
+
+ /// switches to the new pair, absorbing FILE and duping the name
+ void reset(FILE *newFile, const char *newName);
+
+ /// 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; }
+
+ char *name = nullptr;
+
+private:
+ friend void ResyncDebugLog(FILE *newFile);
+
+ FILE *file_ = nullptr; ///< opened "real" file or nil; never stderr
+};
+
+/// configured cache.log file or stderr
+/// safe during static initialization, even if it has not been constructed yet
+static DebugFile TheLog;
+
+FILE *
+DebugStream() {
+ return TheLog.file();
+}
+
+void
+StopUsingDebugLog()
+{
+ TheLog.clear();
+}
+
void
-_db_print(const char *format,...)
+ResyncDebugLog(FILE *newFile)
+{
+ TheLog.file_ = newFile;
+}
+
+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);
+}
+
+static
+void
+_db_print(const bool forceAlert, const char *format,...)
{
char f[BUFSIZ];
f[0]='\0';
_db_print_stderr(f, args2);
#if HAVE_SYSLOG
- _db_print_syslog(format, args3);
+ _db_print_syslog(forceAlert, format, args3);
#endif
#if _SQUID_WINDOWS_
static void
_db_print_stderr(const char *format, va_list args)
{
- if (Debug::log_stderr < Debug::level)
+ if (Debug::log_stderr < Debug::Level())
return;
if (debug_log == stderr)
#if HAVE_SYSLOG
static void
-_db_print_syslog(const char *format, va_list args)
+_db_print_syslog(const bool forceAlert, const char *format, va_list args)
{
/* level 0,1 go to syslog */
- if (Debug::level > 1)
- return;
+ if (!forceAlert) {
+ if (Debug::Level() > 1)
+ return;
- if (!Debug::log_syslog)
- return;
+ if (!Debug::log_syslog)
+ return;
+ }
char tmpbuf[BUFSIZ];
tmpbuf[0] = '\0';
tmpbuf[BUFSIZ - 1] = '\0';
- syslog(Debug::level == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
+ syslog(forceAlert ? LOG_ALERT : (Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE), "%s", tmpbuf);
}
#endif /* HAVE_SYSLOG */
debugOpenLog(const char *logfile)
{
if (logfile == NULL) {
- debug_log = stderr;
+ TheLog.clear();
return;
}
- if (debug_log_file)
- xfree(debug_log_file);
+ // 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;
- debug_log_file = xstrdup(logfile); /* keep a static copy */
-
- if (debug_log && debug_log != stderr)
- fclose(debug_log);
-
- debug_log = fopen(logfile, "a+");
-
- if (!debug_log) {
+ if (auto log = fopen(logfilename, "a+")) {
+#if _SQUID_WINDOWS_
+ setmode(fileno(log), O_TEXT);
+#endif
+ TheLog.reset(log, logfilename);
+ } else {
fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile);
perror(logfile);
fprintf(stderr, " messages will be sent to 'stderr'.\n");
fflush(stderr);
- debug_log = stderr;
+ TheLog.clear();
}
-
-#if _SQUID_WINDOWS_
- setmode(fileno(debug_log), O_TEXT);
-#endif
}
#if HAVE_SYSLOG
}
fprintf(stderr, "unknown syslog facility '%s'\n", facility);
- exit(1);
+ exit(EXIT_FAILURE);
}
#else
void
_db_rotate_log(void)
{
- if (debug_log_file == NULL)
+ if (!TheLog.name)
return;
#ifdef S_ISREG
struct stat sb;
- if (stat(debug_log_file, &sb) == 0)
+ if (stat(TheLog.name, &sb) == 0)
if (S_ISREG(sb.st_mode) == 0)
return;
#endif
/* Rotate numbers 0 through N up one */
for (int i = Debug::rotateNumber; i > 1;) {
--i;
- snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1);
- snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i);
+ snprintf(from, MAXPATHLEN, "%s.%d", TheLog.name, i - 1);
+ snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, i);
#if _SQUID_WINDOWS_
remove
(to);
#endif
- rename(from, to);
+ errno = 0;
+ if (rename(from, to) == -1) {
+ const auto saved_errno = errno;
+ debugs(0, DBG_IMPORTANT, "log rotation failed: " << xstrerr(saved_errno));
+ }
}
- /*
- * You can't rename open files on Microsoft "operating systems"
- * so we close before renaming.
- */
-#if _SQUID_WINDOWS_
- if (debug_log != stderr)
- fclose(debug_log);
-#endif
/* Rotate the current log to .0 */
if (Debug::rotateNumber > 0) {
- snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, 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_
- remove
- (to);
+ errno = 0;
+ if (remove(to) == -1) {
+ const auto saved_errno = errno;
+ debugs(0, DBG_IMPORTANT, "removal of log file " << to << " failed: " << xstrerr(saved_errno));
+ }
+ TheLog.clear(); // Windows cannot rename() open files
#endif
- rename(debug_log_file, to);
+ errno = 0;
+ if (rename(from, to) == -1) {
+ const auto saved_errno = errno;
+ debugs(0, DBG_IMPORTANT, "renaming file " << from << " to "
+ << to << "failed: " << xstrerr(saved_errno));
+ }
}
- /* Close and reopen the log. It may have been renamed "manually"
- * before HUP'ing us. */
- if (debug_log != stderr)
- debugOpenLog(Debug::cache_log);
+ // 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 *
time_t t = getCurrentTime();
struct tm *tm;
- static char buf[128];
+ static char buf[128]; // arbitrary size, big enough for the below timestamp strings.
static time_t last_t = 0;
- if (Debug::level > 1) {
- char buf2[128];
+ 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];
tm = localtime(&t);
- strftime(buf2, 127, "%Y/%m/%d %H:%M:%S", tm);
- buf2[127] = '\0';
- snprintf(buf, 127, "%s.%03d", buf2, (int) current_time.tv_usec / 1000);
+ strftime(buf2, sizeof(buf2), "%Y/%m/%d %H:%M:%S", tm);
+ buf2[sizeof(buf2)-1] = '\0';
+ const int sz = snprintf(buf, sizeof(buf), "%s.%03d", buf2, static_cast<int>(current_time.tv_usec / 1000));
+ assert(0 < sz && sz < static_cast<int>(sizeof(buf)));
last_t = t;
} else if (t != last_t) {
tm = localtime(&t);
- strftime(buf, 127, "%Y/%m/%d %H:%M:%S", tm);
+ 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;
}
- buf[127] = '\0';
+ buf[sizeof(buf)-1] = '\0';
return buf;
}
if (Ctx_Valid_Level < Ctx_Reported_Level) {
if (Ctx_Reported_Level != Ctx_Valid_Level + 1)
- _db_print("ctx: exit levels from %2d down to %2d\n",
+ _db_print(false, "ctx: exit levels from %2d down to %2d\n",
Ctx_Reported_Level, Ctx_Valid_Level + 1);
else
- _db_print("ctx: exit level %2d\n", Ctx_Reported_Level);
+ _db_print(false, "ctx: exit level %2d\n", Ctx_Reported_Level);
Ctx_Reported_Level = Ctx_Valid_Level;
}
while (Ctx_Reported_Level < Ctx_Current_Level) {
++Ctx_Reported_Level;
++Ctx_Valid_Level;
- _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
+ _db_print(false, "ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
ctx_get_descr(Ctx_Reported_Level));
}
return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
}
-int Debug::TheDepth = 0;
+Debug::Context *Debug::Current = nullptr;
-Debug::OutStream *Debug::CurrentDebug(NULL);
-
-std::ostream &
-Debug::getDebugOut()
+Debug::Context::Context(const int aSection, const int aLevel):
+ level(aLevel),
+ sectionLevel(Levels[aSection]),
+ upper(Current),
+ forceAlert(false)
{
- assert(TheDepth >= 0);
- ++TheDepth;
- if (TheDepth > 1) {
- assert(CurrentDebug);
- *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{";
- } else {
- assert(!CurrentDebug);
- CurrentDebug = new Debug::OutStream;
- // set default formatting flags
- CurrentDebug->setf(std::ios::fixed);
- CurrentDebug->precision(2);
- }
- return *CurrentDebug;
+ formatStream();
}
+/// Optimization: avoids new Context creation for every debugs().
void
-Debug::finishDebug()
+Debug::Context::rewind(const int aSection, const int aLevel)
{
- assert(TheDepth >= 0);
- assert(CurrentDebug);
- if (TheDepth > 1) {
- *CurrentDebug << "}-" << TheDepth << std::endl;
- } else {
- assert(TheDepth == 1);
- _db_print("%s\n", CurrentDebug->str().c_str());
- delete CurrentDebug;
- CurrentDebug = NULL;
- }
- --TheDepth;
+ level = aLevel;
+ sectionLevel = Levels[aSection];
+ assert(upper == Current);
+
+ buf.str(std::string());
+ buf.clear();
+ // debugs() users are supposed to preserve format, but
+ // some do not, so we have to waste cycles resetting it for all.
+ formatStream();
}
-// Hack: replaces global ::xassert() to debug debugging assertions
-// Relies on assert macro calling xassert() without a specific scope.
+/// configures default formatting for the debugging stream
void
-Debug::xassert(const char *msg, const char *file, int line)
+Debug::Context::formatStream()
{
-
- if (CurrentDebug) {
- *CurrentDebug << "assertion failed: " << file << ":" << line <<
- ": \"" << msg << "\"";
- }
- abort();
+ 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.
}
-size_t
-BuildPrefixInit()
+std::ostringstream &
+Debug::Start(const int section, const int level)
{
- // XXX: This must be kept in sync with the actual debug.cc location
- const char *ThisFileNameTail = "src/debug.cc";
+ Context *future = nullptr;
- const char *file=__FILE__;
+ // prepare future context
+ if (Current) {
+ // all reentrant debugs() calls get here; create a dedicated context
+ 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;
+ }
- // Disable heuristic if it does not work.
- if (!strstr(file, ThisFileNameTail))
- return 0;
+ Current = future;
- return strlen(file)-strlen(ThisFileNameTail);
+ return future->buf;
}
-const char*
-SkipBuildPrefix(const char* path)
+void
+Debug::Finish()
{
- static const size_t BuildPrefixLength = BuildPrefixInit();
+ // 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());
+ Current->forceAlert = false;
+
+ Context *past = Current;
+ Current = past->upper;
+ if (Current)
+ delete past;
+ // else it was a static topContext from Debug::Start()
+}
- return path+BuildPrefixLength;
+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;
+}
+
+/// print data bytes using hex notation
+void
+Raw::printHex(std::ostream &os) const
+{
+ const auto savedFill = os.fill('0');
+ const auto savedFlags = os.flags(); // std::ios_base::fmtflags
+ os << std::hex;
+ std::for_each(data_, data_ + size_,
+ [&os](const char &c) { os << std::setw(2) << static_cast<uint8_t>(c); });
+ os.flags(savedFlags);
+ os.fill(savedFill);
}
std::ostream &
// finalize debugging level if no level was set explicitly via minLevel()
const int finalLevel = (level >= 0) ? level :
- (size_ > 40 ? DBG_DATA : Debug::sectionLevel);
- if (finalLevel <= Debug::sectionLevel) {
- os << (label_ ? '=' : ' ');
- if (data_)
- os.write(data_, size_);
- else
+ (size_ > 40 ? DBG_DATA : Debug::SectionLevel());
+ if (finalLevel <= Debug::SectionLevel()) {
+ if (label_)
+ os << '=';
+ else if (useGap_)
+ os << ' ';
+ if (data_) {
+ if (useHex_)
+ printHex(os);
+ else
+ os.write(data_, size_);
+ } else {
os << "[null]";
+ }
}
return os;
projects / thirdparty / squid.git / blobdiff