/*
- * $Id$
- *
- * DEBUG: section 0 Debug Routines
- * AUTHOR: Harvest Derived
- *
- * SQUID Web Proxy Cache http://www.squid-cache.org/
- * ----------------------------------------------------------
- *
- * Squid is the result of efforts by numerous individuals from
- * the Internet community; see the CONTRIBUTORS file for full
- * details. Many organizations have provided support for Squid's
- * development; see the SPONSORS file for full details. Squid is
- * Copyrighted (C) 2001 by the Regents of the University of
- * California; see the COPYRIGHT file for full details. Squid
- * incorporates software developed and/or copyrighted by other
- * sources; see the CREDITS file for full details.
- *
- * This program is free software; you can redistribute it and/or modify
- * it under the terms of the GNU General Public License as published by
- * the Free Software Foundation; either version 2 of the License, or
- * (at your option) any later version.
- *
- * This program is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
- * GNU General Public License for more details.
- *
- * You should have received a copy of the GNU General Public License
- * along with this program; if not, write to the Free Software
- * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
+ * Copyright (C) 1996-2017 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.
*/
-#include "config.h"
+/* DEBUG: section 00 Debug Routines */
+
+#include "squid.h"
#include "Debug.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;
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);
static void ctx_print(void);
#if HAVE_SYSLOG
#ifdef LOG_LOCAL4
static void _db_print_stderr(const char *format, va_list args);
static void _db_print_file(const char *format, va_list args);
-#ifdef _SQUID_MSWIN_
-SQUIDCEXTERN LPCRITICAL_SECTION dbg_mutex;
+#if _SQUID_WINDOWS_
+extern LPCRITICAL_SECTION dbg_mutex;
typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
#endif
va_list args2;
va_list args3;
-#ifdef _SQUID_MSWIN_
+#if _SQUID_WINDOWS_
/* Multiple WIN32 threads may call this simultaneously */
if (!dbg_mutex) {
va_start(args2, format);
va_start(args3, format);
- snprintf(f, BUFSIZ, "%s| %s",
+ snprintf(f, BUFSIZ, "%s%s| %s",
debugLogTime(),
+ debugLogKid(),
format);
_db_print_file(f, args1);
_db_print_syslog(format, args3);
#endif
-#ifdef _SQUID_MSWIN_
+#if _SQUID_WINDOWS_
LeaveCriticalSection(dbg_mutex);
#endif
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)
{
/* level 0,1 go to syslog */
- if (Debug::level > 1)
+ if (Debug::Level() > 1)
return;
if (!Debug::log_syslog)
tmpbuf[BUFSIZ - 1] = '\0';
- syslog(Debug::level == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
+ syslog(Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
}
#endif /* HAVE_SYSLOG */
return;
}
- for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
+ for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
Debug::Levels[i] = l;
}
if (debug_log_file)
xfree(debug_log_file);
- debug_log_file = xstrdup(logfile); /* keep a static copy */
+ debug_log_file = xstrdup(logfile); /* keep a static copy */
if (debug_log && debug_log != stderr)
fclose(debug_log);
- debug_log = fopen(logfile, "a+");
+ // 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 = fopen(logfilename, "a+");
if (!debug_log) {
fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile);
debug_log = stderr;
}
-#ifdef _SQUID_WIN32_
+#if _SQUID_WINDOWS_
setmode(fileno(debug_log), O_TEXT);
-
#endif
}
struct syslog_facility_name *n;
- for (n = syslog_facility_names; n->name; n++) {
+ for (n = syslog_facility_names; n->name; ++n) {
if (strcmp(n->name, facility) == 0) {
syslog_facility = n->facility;
return;
return;
}
- for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
+ for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
Debug::Levels[i] = 0;
if (options) {
*/
/* Rotate numbers 0 through N up one */
for (int i = Debug::rotateNumber; i > 1;) {
- i--;
+ --i;
snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1);
snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i);
-#ifdef _SQUID_MSWIN_
+#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.
*/
-#ifdef _SQUID_MSWIN_
+#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);
-#ifdef _SQUID_MSWIN_
- remove
- (to);
+#if _SQUID_WINDOWS_
+ errno = 0;
+ if (remove(to) == -1) {
+ const auto saved_errno = errno;
+ debugs(0, DBG_IMPORTANT, "removal of log file " << to << " failed: " << xstrerr(saved_errno));
+ }
#endif
- rename(debug_log_file, to);
+ errno = 0;
+ if (rename(debug_log_file, to) == -1) {
+ const auto saved_errno = errno;
+ debugs(0, DBG_IMPORTANT, "renaming file " << debug_log_file << " to "
+ << to << "failed: " << xstrerr(saved_errno));
+ }
}
/* Close and reopen the log. It may have been renamed "manually"
static char buf[128];
static time_t last_t = 0;
- if (Debug::level > 1) {
+ if (Debug::Level() > 1) {
char buf2[128];
tm = localtime(&t);
strftime(buf2, 127, "%Y/%m/%d %H:%M:%S", tm);
return buf;
}
+static const char *
+debugLogKid(void)
+{
+ if (KidIdentifier != 0) {
+ static char buf[16];
+ if (!*buf) // optimization: fill only once after KidIdentifier is set
+ snprintf(buf, sizeof(buf), " kid%d", KidIdentifier);
+ return buf;
+ }
+
+ return "";
+}
+
void
xassert(const char *msg, const char *file, int line)
{
- debugs(0, 0, "assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
+ debugs(0, DBG_CRITICAL, "assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
if (!shutting_down)
abort();
/* "safe" get secription */
static const char *ctx_get_descr(Ctx ctx);
-
Ctx
ctx_enter(const char *descr)
{
- Ctx_Current_Level++;
+ ++Ctx_Current_Level;
if (Ctx_Current_Level <= CTX_MAX_LEVEL)
Ctx_Descrs[Ctx_Current_Level] = descr;
if (Ctx_Current_Level == Ctx_Warn_Level) {
- debugs(0, 0, "# ctx: suspiciously deep (" << Ctx_Warn_Level << ") nesting:");
+ debugs(0, DBG_CRITICAL, "# ctx: suspiciously deep (" << Ctx_Warn_Level << ") nesting:");
Ctx_Warn_Level *= 2;
}
ctx_print(void)
{
/* lock so _db_print will not call us recursively */
- Ctx_Lock++;
+ ++Ctx_Lock;
/* ok, user saw [0,Ctx_Reported_Level] descriptions */
/* first inform about entries popped since user saw them */
/* report new contexts that were pushed since last report */
while (Ctx_Reported_Level < Ctx_Current_Level) {
- Ctx_Reported_Level++;
- Ctx_Valid_Level++;
+ ++Ctx_Reported_Level;
+ ++Ctx_Valid_Level;
_db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
ctx_get_descr(Ctx_Reported_Level));
}
/* unlock */
- Ctx_Lock--;
+ --Ctx_Lock;
}
/* checks for nulls and overflows */
return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
}
-int Debug::TheDepth = 0;
+Debug::Context *Debug::Current = nullptr;
-std::ostream &
-Debug::getDebugOut()
+Debug::Context::Context(const int aSection, const int aLevel):
+ level(aLevel),
+ sectionLevel(Levels[aSection]),
+ upper(Current)
{
- assert(TheDepth >= 0);
- ++TheDepth;
- if (TheDepth > 1) {
- assert(CurrentDebug);
- *CurrentDebug << std::endl << "reentrant debuging " << TheDepth << "-{";
- } else {
- assert(!CurrentDebug);
- CurrentDebug = new std::ostringstream();
- // 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()
+{
+ 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.
+}
+
+std::ostringstream &
+Debug::Start(const int section, const int level)
{
+ Context *future = nullptr;
- if (CurrentDebug) {
- *CurrentDebug << "assertion failed: " << file << ":" << line <<
- ": \"" << msg << "\"";
+ // 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;
}
- abort();
+
+ Current = future;
+
+ return future->buf;
}
-std::ostringstream (*Debug::CurrentDebug)(NULL);
+void
+Debug::Finish()
+{
+ // TODO: Optimize to remove at least one extra copy.
+ _db_print("%s\n", Current->buf.str().c_str());
+
+ Context *past = Current;
+ Current = past->upper;
+ if (Current)
+ delete past;
+ // else it was a static topContext from Debug::Start()
+}
-const size_t
+size_t
BuildPrefixInit()
{
// XXX: This must be kept in sync with the actual debug.cc location
return path+BuildPrefixLength;
}
+
+/// 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 &
+Raw::print(std::ostream &os) const
+{
+ if (label_)
+ os << ' ' << label_ << '[' << size_ << ']';
+
+ if (!size_)
+ return os;
+
+ // 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_) {
+ if (useHex_)
+ printHex(os);
+ else
+ os.write(data_, size_);
+ } else {
+ os << "[null]";
+ }
+ }
+
+ return os;
+}
+