]> git.ipfire.org Git - thirdparty/squid.git/blobdiff - src/debug.cc
SourceFormat Enforcement
[thirdparty/squid.git] / src / debug.cc
index 75bdeb480b038889886799ed0fe5e9f49759f594..3d420801434b7da388b2243a4e45d7e24ad1f9c2 100644 (file)
@@ -1,42 +1,20 @@
 /*
- * $Id$
- *
- * DEBUG: section 00    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 "ipc/Kids.h"
+
+#include <algorithm>
 
 /* for shutting_down flag in xassert() */
 #include "globals.h"
@@ -46,7 +24,6 @@ int Debug::override_X = 0;
 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;
@@ -64,8 +41,8 @@ static void _db_print_syslog(const char *format, va_list args);
 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
 
@@ -78,7 +55,7 @@ _db_print(const char *format,...)
     va_list args2;
     va_list args3;
 
-#ifdef _SQUID_MSWIN_
+#if _SQUID_WINDOWS_
     /* Multiple WIN32 threads may call this simultaneously */
 
     if (!dbg_mutex) {
@@ -131,7 +108,7 @@ _db_print(const char *format,...)
     _db_print_syslog(format, args3);
 #endif
 
-#ifdef _SQUID_MSWIN_
+#if _SQUID_WINDOWS_
     LeaveCriticalSection(dbg_mutex);
 #endif
 
@@ -157,7 +134,7 @@ _db_print_file(const char *format, va_list args)
 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)
@@ -172,7 +149,7 @@ _db_print_syslog(const char *format, va_list args)
 {
     /* level 0,1 go to syslog */
 
-    if (Debug::level > 1)
+    if (Debug::Level() > 1)
         return;
 
     if (!Debug::log_syslog)
@@ -185,7 +162,7 @@ _db_print_syslog(const char *format, va_list args)
 
     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 */
 
@@ -225,7 +202,7 @@ debugArg(const char *arg)
         return;
     }
 
-    for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
+    for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
         Debug::Levels[i] = l;
 }
 
@@ -240,12 +217,19 @@ debugOpenLog(const char *logfile)
     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);
@@ -255,9 +239,8 @@ debugOpenLog(const char *logfile)
         debug_log = stderr;
     }
 
-#ifdef _SQUID_WIN32_
+#if _SQUID_WINDOWS_
     setmode(fileno(debug_log), O_TEXT);
-
 #endif
 }
 
@@ -396,7 +379,7 @@ _db_set_syslog(const char *facility)
 
         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;
@@ -428,7 +411,7 @@ Debug::parseOptions(char const *options)
         return;
     }
 
-    for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
+    for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
         Debug::Levels[i] = 0;
 
     if (options) {
@@ -485,32 +468,44 @@ _db_rotate_log(void)
      */
     /* 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"
@@ -529,7 +524,7 @@ debugLogTime(void)
     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);
@@ -562,7 +557,7 @@ debugLogKid(void)
 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();
@@ -661,17 +656,16 @@ static const char *Ctx_Descrs[CTX_MAX_LEVEL + 1];
 /* "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;
     }
 
@@ -696,7 +690,7 @@ static void
 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 */
 
@@ -712,14 +706,14 @@ ctx_print(void)
 
     /* 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 */
@@ -732,58 +726,78 @@ ctx_get_descr(Ctx ctx)
     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
@@ -805,3 +819,44 @@ SkipBuildPrefix(const char* path)
 
     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;
+}
+