From: Eduard Bagdasaryan Date: Fri, 11 Jun 2021 13:24:04 +0000 (+0000) Subject: cache_log_message directive (#775) X-Git-Tag: SQUID_6_0_1~324 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=c59baaa84bb320c7ef99275b078d5b8769b52e8f;p=thirdparty%2Fsquid.git cache_log_message directive (#775) This directive controls cache.log printing of important messages. Rationale: In any given deployment environment, many of the cache.log messages that Squid logs by default are noise. Some of them should probably never be logged by default, but some are useful or even critical in certain other environments. No single approach to logging is going to satisfy all needs. The existing debug_options directive operates on large message groups and is not suitable for controlling individual critical or important messages. The current implementation uses hard-coded manually-assigned opaque message IDs. We have also experimented with an automated generation of message IDs, including meaningful IDs and compiler-generated IDs created by various advanced C++ preprocessing and template tricks. All of the automation considered (and some partially implemented) were rejected for being overall worse than the current manual approach. TODO: The usefulness of ID ranges will diminish with time. We could support named (hard-coded) sets of message IDs (e.g., "startup", "shutdown", and "configuration"). However, sets make it easier to accidentally suppress an important new message during an upgrade. --- diff --git a/doc/Makefile.am b/doc/Makefile.am index 3ab4ffa5ef..39970a958f 100644 --- a/doc/Makefile.am +++ b/doc/Makefile.am @@ -12,4 +12,5 @@ DEFAULT_MIME_TABLE = $(sysconfdir)/mime.conf DEFAULT_ERROR_DIR = $(datadir)/errors EXTRA_DIST = \ + debug-messages.dox \ debug-sections.txt diff --git a/doc/debug-messages.dox b/doc/debug-messages.dox new file mode 100644 index 0000000000..7ed7fcfe8e --- /dev/null +++ b/doc/debug-messages.dox @@ -0,0 +1,66 @@ +/* + * 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. + * Please see the COPYING and CONTRIBUTORS files for details. + */ + +/** +\page ControlledCacheLogMessages Message IDs and gists for cache_log_message +\verbatim +ID Message gist +== ============ +2 Preparing for shutdown after ... requests +3 Waiting ... seconds for active connections to finish +4 Set Current Directory to ... +5 Service Name: ... +6 Process ID ... +7 Process Roles: ... +8 With ... file descriptors available +9 Shutting down... +10 Squid Cache (Version ...): Exiting normally. +11 Adaptation support is ... +12 Shutdown: Basic authentication. +13 Accepting ... connections at ... +14 Closing HTTP(S) port ... +15 Adding nameserver ... from squid.conf +16 DNS IPv6 socket created at ..., FD ... +17 Open FD ... ... +18 Loading cache_dir # ... from ... +19 helperOpenServers: Starting .../ ... ' ...' processes +20 helperOpenServers: No ' ...' processes needed. +21 HTCP Disabled. +22 Removing ... +23 Created ... +24 Initializing IP Cache... +25 Squid plugin modules loaded: ... +26 Logfile: opening log ... +27 Logfile: closing log ... +28 Finished loading MIME types and icons. +29 Configuring ... .../ .../ ... +30 storeLateRelease: released ... objects +31 Swap maxSize ... KB, estimated ... objects +32 Target number of buckets: ... +33 Using ... Store buckets +34 Max Mem size: ... +35 Max Swap size: ... KB +36 Using Least Load store dir selection +37 Not currently OK to rewrite swap log. +38 storeDirWriteCleanLogs: Operation aborted. +39 storeDirWriteCleanLogs: Starting... +40 Finished. Wrote ... entries. +41 Took ... seconds (... entries/sec). +42 Store logging disabled +43 Completed Validation Procedure ...Validated ... Entries ...store_swap_size = ... KB +46 Finished rebuilding storage from disk. ... Entries scanned ... Invalid entries ... With invalid flags ... Objects loaded ... Objects expired ... Objects canceled ... Duplicate URLs purged ... Swapfile clashes avoided ...Took ... seconds ( ... objects/sec). +56 Beginning Validation Procedure +57 Indexing cache entries: ... +58 ALE missing ... +59 Shutdown: Digest authentication. +60 Shutdown: Negotiate authentication. +61 Shutdown: NTLM authentication. +63 Resuming indexing cache_dir # ... from ... +64 DNS IPv4 socket created at ..., FD ... +\endverbatim +*/ diff --git a/scripts/source-maintenance.sh b/scripts/source-maintenance.sh index 8d5a64d5a2..4a3451d52f 100755 --- a/scripts/source-maintenance.sh +++ b/scripts/source-maintenance.sh @@ -202,8 +202,110 @@ checkMakeNamedErrorDetails () return $problems } +# extract IDs and gists of cache_log_message debugs() in the given source file +collectDebugMessagesFrom () +{ + source="$1" + destination="doc/debug-messages.tmp" + + # Merge multi-line debugs() into one-liners and remove '//...' comments. + awk 'BEGIN { found=0; dbgLine=""; } { + if ($0 ~ /[ \t]debugs[ \t]*\(/) + found = 1; + if (found) { + commented = match($0, /\);[ \t]*\/\//); + if (commented) + $0 = substr($0, 1, RSTART+1); + dbgLine = dbgLine $0; + } + if ($0 ~ /\);/) { + if (found) { + found = 0; + print dbgLine; + dbgLine = ""; + } + } + }' $source > doc/debug-messages.tmp2 + + # sed expressions: + # - replace debugs() prefix with the message ID contained in it + # - remove simple parenthesized non-"string" items like (a ? b : c) + # - replace any remaining non-"string" items with ... + # - remove quotes around "strings" + # - remove excessive whitespace + # - remove debugs() statement termination sugar + grep -o -E '\bdebugs[^,]*,\s*(Critical|Important)[(][0-9]+.*' doc/debug-messages.tmp2 | \ + sed -r \ + -e 's/.*?(Critical|Important)[(]([0-9]+)[)],\s*/\2 /' \ + -e 's/<<\s*[(].*[)]\s*(<<|[)];)/<< ... \1/g' \ + -e 's/<<\s*[^"]*/.../g' \ + -e 's@([^\\])"@\1@g' \ + -e 's/\s\s*/ /g' \ + -e 's/[)];$//g' \ + >> $destination + + rm -f doc/debug-messages.tmp2 +} + +# make doc/debug-messages.dox from aggregate collectDebugMessagesFrom results +processDebugMessages () +{ + source="doc/debug-messages.tmp" + destination="doc/debug-messages.dox" + + if test '!' -s "$source"; then + echo "ERROR: Failed to find debugs() message IDs" + return 1; + fi + + repeatedIds=`awk '{print $1}' $source | sort -n | uniq -d` + if test "x$repeatedIds" != "x"; then + echo "ERROR: Repeated debugs() message IDs:" + echo "$repeatedIds" + echo "" + return 1; + fi + + repeatedGists=`awk '{$1=""; print substr($0,2)}' $source | sort | uniq -d` + if test "x$repeatedGists" != "x"; then + echo "ERROR: Repeated debugs() message gists:" + echo "$repeatedGists" + echo "" + return 1; + fi + + cat scripts/boilerplate.h > $destination + printf '/**\n' >> $destination + printf '\\page ControlledCacheLogMessages Message IDs and gists for cache_log_message\n' >> $destination + printf '\\verbatim\n' >> $destination + printf 'ID Message gist\n' >> $destination + printf '== ============\n' >> $destination + sort -n < $source >> $destination + printf '\\endverbatim\n' >> $destination + printf '*/\n' >> $destination + + rm -f $source +} + +# make doc/debug-sections.txt from aggregated by srcFormat extracts +processDebugSections () +{ + destination="doc/debug-sections.txt" + + sort -u < doc/debug-sections.tmp | sort -n > doc/debug-sections.tmp2 + cat scripts/boilerplate.h > $destination + echo "" >> $destination + cat doc/debug-sections.tmp2 >> $destination + + rm -f doc/debug-sections.tmp* +} + srcFormat () { + # remove stale temporary files that accumulate info extracted below + rm -f doc/debug-messages.tmp* + rm -f doc/debug-sections.tmp* + # # Scan for incorrect use of #ifdef/#ifndef # @@ -301,6 +403,8 @@ for FILENAME in `git ls-files`; do echo "ERROR: ${FILENAME} contains unsafe use of sprintf()" fi + collectDebugMessagesFrom ${FILENAME} + # # DEBUG Section list maintenance # @@ -353,6 +457,9 @@ for FILENAME in `git ls-files`; do fi done + + run_ processDebugSections || return + run_ processDebugMessages || return } # Build XPROF types file from current sources @@ -405,11 +512,8 @@ make -C src/http gperf-files run_ checkMakeNamedErrorDetails || exit 1 # Run formatting -echo "" >doc/debug-sections.tmp srcFormat || exit 1 -sort -u doc/debug-sections.tmp2 -cat scripts/boilerplate.h doc/debug-sections.tmp2 >doc/debug-sections.txt -rm doc/debug-sections.tmp doc/debug-sections.tmp2 + rm -f boilerplate_fix.sed exit $SeenErrors diff --git a/src/DebugMessages.h b/src/DebugMessages.h new file mode 100644 index 0000000000..66c1a6e79b --- /dev/null +++ b/src/DebugMessages.h @@ -0,0 +1,95 @@ +/* + * 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. + * Please see the COPYING and CONTRIBUTORS files for details. + */ + +/* DEBUG: section 00 Debug Routines */ + +#ifndef SQUID_DEBUG_MESSAGES_H +#define SQUID_DEBUG_MESSAGES_H + +#include "Debug.h" +#include "SquidConfig.h" + +#include +#include + +// XXX: Replace Debug class with namespace and use that namespace here. + +/// an identifier for messages supporting configuration via cache_log_message +typedef size_t DebugMessageId; + +/// manages configurable aspects of a debugs() message +class DebugMessage +{ +public: + /// whether the logging of this message has been customized + bool configured() const { return id > 0; } + + /// whether the default logging level of this message has been altered + bool levelled() const { return level >= 0; } + + /// whether the number of logging attempts have been limited + bool limited() const { return limit < std::numeric_limits::max(); } + + /// \returns appropriate debugging level for the message + int currentLevel(const int defaultLevel) const { + if (configured()) { + if (count_++ < limit) + return level; + return (level <= DBG_IMPORTANT) ? 3 : 8; + } + return defaultLevel; + } + + /// message identifier or, if the message has not been configured, zero + DebugMessageId id = 0; + + /* all these configurable members are ignored unless configured() */ + + /// debugging level (i.e., the second debugs() parameter) or -1 + int level = -1; + + /// logging attempts beyond this limit are logged at the DBG_DATA level + uint64_t limit = std::numeric_limits::max(); + +private: + /// the total number of attempts to log this message if it was configured() + mutable uint64_t count_ = 0; +}; + +/// The maximum used DebugMessage::id plus 1. Increase as you add new IDs. +constexpr DebugMessageId DebugMessageIdUpperBound = 65; + +/// a collection of DebugMessage objects (with fast access by message IDs) +class DebugMessages +{ +public: + /// configurable messages indexed by their IDs + typedef std::array Storage; + Storage messages; +}; + +// Using a template allows us to check message ID range at compile time. +/// \returns configured debugging level for the given message or defaultLevel +template +inline int +DebugMessageLevel(const int defaultLevel) +{ + static_assert(id > 0, "debugs() message ID must be positive"); + static_assert(id < DebugMessageIdUpperBound, "debugs() message ID must be smaller than DebugMessageIdUpperBound"); + if (const auto configured = Config.debugMessages) + return (configured->messages)[id].currentLevel(defaultLevel); + return defaultLevel; +} + +/* convenience macros for calling DebugMessageLevel */ +#define Critical(id) DebugMessageLevel(DBG_CRITICAL) +#define Important(id) DebugMessageLevel(DBG_IMPORTANT) +#define Dbg(id, defaultLevel) DebugMessageLevel(defaultLevel) + +#endif /* SQUID_DEBUG_MESSAGES_H */ + diff --git a/src/Instance.cc b/src/Instance.cc index 842d65dbf6..2b95b77737 100644 --- a/src/Instance.cc +++ b/src/Instance.cc @@ -8,6 +8,7 @@ #include "squid.h" #include "base/File.h" +#include "DebugMessages.h" #include "fs_io.h" #include "Instance.h" #include "parser/Tokenizer.h" @@ -163,7 +164,7 @@ RemoveInstance() if (ThePidFileToRemove.isEmpty()) // not the PidFilename()! return; // nothing to do - debugs(50, DBG_IMPORTANT, "Removing " << PidFileDescription(ThePidFileToRemove)); + debugs(50, Important(22), "Removing " << PidFileDescription(ThePidFileToRemove)); const char *filename = ThePidFileToRemove.c_str(); // avoid complex operations inside enter_suid() enter_suid(); safeunlink(filename, 0); @@ -210,6 +211,6 @@ Instance::WriteOurPid() // our written PID (and decide that they are dealing with a corrupted PID file). pidFile.synchronize(); - debugs(50, DBG_IMPORTANT, "Created " << TheFile); + debugs(50, Important(23), "Created " << TheFile); } diff --git a/src/LoadableModules.cc b/src/LoadableModules.cc index 6c695455fd..16a6655555 100644 --- a/src/LoadableModules.cc +++ b/src/LoadableModules.cc @@ -8,6 +8,7 @@ #include "squid.h" #include "Debug.h" +#include "DebugMessages.h" #include "LoadableModule.h" #include "LoadableModules.h" #include "wordlist.h" @@ -30,6 +31,6 @@ LoadableModulesConfigure(const wordlist *names) int count = 0; for (const wordlist *i = names; i; i = i->next, ++count) LoadModule(i->key); - debugs(1, DBG_IMPORTANT, "Squid plugin modules loaded: " << count); + debugs(1, Important(25), "Squid plugin modules loaded: " << count); } diff --git a/src/Makefile.am b/src/Makefile.am index efafea7cb8..63f1b3fa30 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -251,6 +251,7 @@ squid_SOURCES = \ CpuAffinitySet.cc \ CpuAffinitySet.h \ Debug.h \ + DebugMessages.h \ Downloader.cc \ Downloader.h \ ETag.cc \ diff --git a/src/Parsing.cc b/src/Parsing.cc index a5c5981705..5dfd3cf9b4 100644 --- a/src/Parsing.cc +++ b/src/Parsing.cc @@ -15,6 +15,7 @@ #include "Debug.h" #include "globals.h" #include "Parsing.h" +#include "sbuf/Stream.h" /* * These functions is the same as atoi/l/f, except that they check for errors @@ -57,16 +58,12 @@ unsigned int xatoui(const char *token, char eov) { int64_t input = xatoll(token, 10, eov); - if (input < 0) { - debugs(0, DBG_PARSE_NOTE(DBG_IMPORTANT), "ERROR: The input value '" << token << "' cannot be less than 0."); - self_destruct(); - } + if (input < 0) + throw TextException(ToSBuf("the input value '", token, "' cannot be less than 0"), Here()); unsigned int ret = (unsigned int) input; - if (input != static_cast(ret)) { - debugs(0, DBG_PARSE_NOTE(DBG_IMPORTANT), "ERROR: The value '" << token << "' is larger than the type 'unsigned int'."); - self_destruct(); - } + if (input != static_cast(ret)) + throw TextException(ToSBuf("the value '", token, "' is larger than the type 'unsigned int'"), Here()); return ret; } @@ -104,6 +101,15 @@ xatoll(const char *token, int base, char eov) return ret; } +uint64_t +xatoull(const char *token, int base, char eov) +{ + const auto number = xatoll(token, base, eov); + if (number < 0) + throw TextException(ToSBuf("the input value '", token, "' cannot be less than 0"), Here()); + return static_cast(number); +} + unsigned short xatos(const char *token) { diff --git a/src/Parsing.h b/src/Parsing.h index 9967b3d69b..4b50f00fa7 100644 --- a/src/Parsing.h +++ b/src/Parsing.h @@ -18,6 +18,7 @@ int xatoi(const char *token); unsigned int xatoui(const char *token, char eov = '\0'); long xatol(const char *token); int64_t xatoll(const char *token, int base, char eov = '\0'); +uint64_t xatoull(const char *token, int base, char eov = '\0'); unsigned short xatos(const char *token); /** diff --git a/src/SquidConfig.h b/src/SquidConfig.h index a680d006c5..0117ea7808 100644 --- a/src/SquidConfig.h +++ b/src/SquidConfig.h @@ -45,6 +45,7 @@ class ActionPasswordList; class CachePeer; class CustomLog; class CpuAffinityMap; +class DebugMessages; class external_acl; class HeaderManglers; class RefreshPattern; @@ -559,6 +560,8 @@ public: int connect_gap; int connect_timeout; } happyEyeballs; + + DebugMessages *debugMessages; ///< cache_log_message }; extern SquidConfig Config; diff --git a/src/acl/FilledChecklist.cc b/src/acl/FilledChecklist.cc index d2aa2d12dc..ac24664e82 100644 --- a/src/acl/FilledChecklist.cc +++ b/src/acl/FilledChecklist.cc @@ -11,6 +11,7 @@ #include "client_side.h" #include "comm/Connection.h" #include "comm/forward.h" +#include "DebugMessages.h" #include "ExternalACLEntry.h" #include "http/Stream.h" #include "HttpReply.h" @@ -75,7 +76,7 @@ showDebugWarning(const char *msg) return; ++count; - debugs(28, DBG_IMPORTANT, "ALE missing " << msg); + debugs(28, Important(58), "ALE missing " << msg); } void diff --git a/src/adaptation/Config.cc b/src/adaptation/Config.cc index b90fea8027..95bcf99bbe 100644 --- a/src/adaptation/Config.cc +++ b/src/adaptation/Config.cc @@ -15,6 +15,7 @@ #include "adaptation/Service.h" #include "adaptation/ServiceGroups.h" #include "ConfigParser.h" +#include "DebugMessages.h" #include "globals.h" #include "HttpReply.h" #include "HttpRequest.h" @@ -228,7 +229,7 @@ void Adaptation::Config::Finalize(bool enabled) { Enabled = enabled; - debugs(93, DBG_IMPORTANT, "Adaptation support is " << (Enabled ? "on" : "off.")); + debugs(93, Important(11), "Adaptation support is " << (Enabled ? "on" : "off.")); FinalizeEach(AllServices(), "message adaptation services"); FinalizeEach(AllGroups(), "message adaptation service groups"); diff --git a/src/auth/basic/Scheme.cc b/src/auth/basic/Scheme.cc index bf0be941f6..5d8161a898 100644 --- a/src/auth/basic/Scheme.cc +++ b/src/auth/basic/Scheme.cc @@ -10,6 +10,7 @@ #include "auth/basic/Config.h" #include "auth/basic/Scheme.h" #include "Debug.h" +#include "DebugMessages.h" #include "helper.h" Auth::Scheme::Pointer Auth::Basic::Scheme::_instance = NULL; @@ -37,7 +38,7 @@ Auth::Basic::Scheme::shutdownCleanup() return; _instance = NULL; - debugs(29, DBG_CRITICAL, "Shutdown: Basic authentication."); + debugs(29, Critical(12), "Shutdown: Basic authentication."); } Auth::SchemeConfig * diff --git a/src/auth/digest/Scheme.cc b/src/auth/digest/Scheme.cc index e0fa9997ad..ef46f0022d 100644 --- a/src/auth/digest/Scheme.cc +++ b/src/auth/digest/Scheme.cc @@ -10,6 +10,7 @@ #include "auth/digest/Config.h" #include "auth/digest/Scheme.h" #include "Debug.h" +#include "DebugMessages.h" #include "globals.h" #include "helper.h" @@ -40,7 +41,7 @@ Auth::Digest::Scheme::shutdownCleanup() authenticateDigestNonceShutdown(); _instance = NULL; - debugs(29, DBG_CRITICAL, "Shutdown: Digest authentication."); + debugs(29, Critical(59), "Shutdown: Digest authentication."); } Auth::SchemeConfig * diff --git a/src/auth/negotiate/Scheme.cc b/src/auth/negotiate/Scheme.cc index ffa6e76145..724620379a 100644 --- a/src/auth/negotiate/Scheme.cc +++ b/src/auth/negotiate/Scheme.cc @@ -10,6 +10,7 @@ #include "auth/negotiate/Config.h" #include "auth/negotiate/Scheme.h" #include "Debug.h" +#include "DebugMessages.h" #include "helper.h" Auth::Scheme::Pointer Auth::Negotiate::Scheme::_instance = NULL; @@ -37,7 +38,7 @@ Auth::Negotiate::Scheme::shutdownCleanup() return; _instance = NULL; - debugs(29, DBG_CRITICAL, "Shutdown: Negotiate authentication."); + debugs(29, Critical(60), "Shutdown: Negotiate authentication."); } Auth::SchemeConfig * diff --git a/src/auth/ntlm/Scheme.cc b/src/auth/ntlm/Scheme.cc index d869b71af5..03e8106ea2 100644 --- a/src/auth/ntlm/Scheme.cc +++ b/src/auth/ntlm/Scheme.cc @@ -10,6 +10,7 @@ #include "auth/ntlm/Config.h" #include "auth/ntlm/Scheme.h" #include "Debug.h" +#include "DebugMessages.h" #include "helper.h" Auth::Scheme::Pointer Auth::Ntlm::Scheme::_instance = NULL; @@ -37,7 +38,7 @@ Auth::Ntlm::Scheme::shutdownCleanup() return; _instance = NULL; - debugs(29, DBG_CRITICAL, "Shutdown: NTLM authentication."); + debugs(29, Critical(61), "Shutdown: NTLM authentication."); } Auth::SchemeConfig * diff --git a/src/cache_cf.cc b/src/cache_cf.cc index 46ea3facf3..1d7950c61d 100644 --- a/src/cache_cf.cc +++ b/src/cache_cf.cc @@ -28,6 +28,7 @@ #include "ConfigOption.h" #include "ConfigParser.h" #include "CpuAffinityMap.h" +#include "DebugMessages.h" #include "DiskIO/DiskIOModule.h" #include "eui/Config.h" #include "ExternalACL.h" @@ -162,6 +163,10 @@ static const char *const list_sep = ", \t\n\r"; // std::chrono::years requires C++20. Do our own rough calculation for now. static const double HoursPerYear = 24*365.2522; +static void parse_cache_log_message(DebugMessages **messages); +static void dump_cache_log_message(StoreEntry *entry, const char *name, const DebugMessages *messages); +static void free_cache_log_message(DebugMessages **messages); + static void parse_access_log(CustomLog ** customlog_definitions); static int check_null_access_log(CustomLog *customlog_definitions); static void dump_access_log(StoreEntry * entry, const char *name, CustomLog * definitions); @@ -4658,6 +4663,101 @@ static void free_note(Notes *notes) notes->clean(); } +static DebugMessageId ParseDebugMessageId(const char *value, const char eov) +{ + const auto id = xatoui(value, eov); + if (!(0 < id && id < DebugMessageIdUpperBound)) + throw TextException(ToSBuf("unknown cache_log_message ID: ", value), Here()); + return static_cast(id); +} + +static void parse_cache_log_message(DebugMessages **debugMessages) +{ + DebugMessage msg; + DebugMessageId minId = 0; + DebugMessageId maxId = 0; + + char *key = nullptr; + char *value = nullptr; + while (ConfigParser::NextKvPair(key, value)) { + if (strcmp(key, "id") == 0) { + if (minId > 0) + break; + minId = maxId = ParseDebugMessageId(value, '\0'); + } else if (strcmp(key, "ids") == 0) { + if (minId > 0) + break; + const auto dash = strchr(value, '-'); + if (!dash) + throw TextException(ToSBuf("malformed cache_log_message ID range: ", key, '=', value), Here()); + minId = ParseDebugMessageId(value, '-'); + maxId = ParseDebugMessageId(dash+1, '\0'); + if (minId > maxId) + throw TextException(ToSBuf("invalid cache_log_message ID range: ", key, '=', value), Here()); + } else if (strcmp(key, "level") == 0) { + if (msg.levelled()) + break; + const auto level = xatoi(value); + if (level < 0) + throw TextException(ToSBuf("negative cache_log_message level: ", value), Here()); + msg.level = level; + } else if (strcmp(key, "limit") == 0) { + if (msg.limited()) + break; + msg.limit = xatoull(value, 10); + } else { + throw TextException(ToSBuf("unsupported cache_log_message option: ", key), Here()); + } + key = value = nullptr; + } + + if (key && value) + throw TextException(ToSBuf("repeated or conflicting cache_log_message option: ", key, '=', value), Here()); + + if (!minId) + throw TextException("cache_log_message is missing a required id=... or ids=... option", Here()); + + if (!(msg.levelled() || msg.limited())) + throw TextException("cache_log_message is missing a required level=... or limit=... option", Here()); + + assert(debugMessages); + if (!*debugMessages) + *debugMessages = new DebugMessages(); + + for (auto id = minId; id <= maxId; ++id) { + msg.id = id; + (*debugMessages)->messages.at(id) = msg; + } +} + +static void dump_cache_log_message(StoreEntry *entry, const char *name, const DebugMessages *debugMessages) +{ + if (!debugMessages) + return; + + SBufStream out; + for (const auto &msg: debugMessages->messages) { + if (!msg.configured()) + continue; + out << name << " id=" << msg.id; + if (msg.levelled()) + out << " level=" << msg.level; + if (msg.limited()) + out << " limit=" << msg.limit; + out << "\n"; + } + const auto buf = out.buf(); + entry->append(buf.rawContent(), buf.length()); // may be empty +} + +static void free_cache_log_message(DebugMessages **debugMessages) +{ + // clear old messages to avoid cumulative effect across (re)configurations + assert(debugMessages); + delete *debugMessages; + *debugMessages = nullptr; +} + static bool FtpEspvDeprecated = false; static void parse_ftp_epsv(acl_access **ftp_epsv) { diff --git a/src/cf.data.depend b/src/cf.data.depend index 036009bf93..ffda0e0de4 100644 --- a/src/cf.data.depend +++ b/src/cf.data.depend @@ -97,3 +97,4 @@ sslproxy_ssl_bump_peeked acl sslproxy_cert_sign acl sslproxy_cert_adapt acl ftp_epsv acl +cache_log_message diff --git a/src/cf.data.pre b/src/cf.data.pre index de9369fdd4..a5d0624b7e 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -5534,6 +5534,52 @@ DOC_START rotated with "debug_options" DOC_END +NAME: cache_log_message +TYPE: cache_log_message +DEFAULT: none +DEFAULT_DOC: Use debug_options. +LOC: Config.debugMessages +DOC_START + Configures logging of individual cache.log messages. + + cache_log_message id= option... + cache_log_message ids=- option... + + Most messages have _not_ been instrumented to support this directive + yet. For the list of instrumented messages and their IDs, please see + the doc/debug-messages.txt file. + + Message ID corresponds to the message semantics rather than message + text or source code location. The ID is stable across Squid + instances and versions. Substantial changes in message semantics + result in a new ID assignment. To reduce the danger of suppressing + an important log message, the old IDs of removed (or substantially + changed) messages are never reused. + + If more than one cache_log_message directive refers to the same + message ID, the last directive wins. + + Use ids=min-max syntax to apply the same message configuration to an + inclusive range of message IDs. An ID range with N values has + exactly the same effect as typing N cache_log_message lines. + + At least one option is required. Supported options are: + + level=: The logging level to use for the message. Squid + command line options (-s and -d) as well as the debug_options + directive control which levels go to syslog, stderr, and/or + cache.log. In most environments, using level=2 or higher stops + Squid from logging the message anywhere. By default, the + hard-coded message-specific level is used. + + limit=: After logging the specified number of messages at + the configured (or default) debugging level DL, start using + level 3 (for DL 0 and 1) or 8 (for higher DL values). Usually, + level-3+ messages are not logged anywhere so this option can + often be used to effectively suppress the message. Each SMP + Squid process gets the same limit. +DOC_END + NAME: debug_options TYPE: eol DEFAULT: ALL,1 diff --git a/src/client_side.cc b/src/client_side.cc index 69175d4dc6..ddaef05ec7 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -76,6 +76,7 @@ #include "comm/TcpAcceptor.h" #include "comm/Write.h" #include "CommCalls.h" +#include "DebugMessages.h" #include "error/ExceptionErrorDetail.h" #include "errorpage.h" #include "fd.h" @@ -2401,7 +2402,7 @@ clientNegotiateSSL(int fd, void *data) return; case Security::IoResult::ioError: - debugs(83, (handshakeResult.important ? DBG_IMPORTANT : 2), "ERROR: " << handshakeResult.errorDescription << + debugs(83, (handshakeResult.important ? Important(62) : 2), "ERROR: " << handshakeResult.errorDescription << " while accepting a TLS connection on " << conn->clientConnection << ": " << handshakeResult.errorDetail); // TODO: No ConnStateData::tunnelOnError() on this forward-proxy code // path because we cannot know the intended connection target? @@ -3455,7 +3456,7 @@ clientListenerConnectionOpened(AnyP::PortCfgPointer &s, const Ipc::FdNoteId port // TCP: setup a job to handle accept() with subscribed handler AsyncJob::Start(new Comm::TcpAcceptor(s, FdNote(portTypeNote), sub)); - debugs(1, DBG_IMPORTANT, "Accepting " << + debugs(1, Important(13), "Accepting " << (s->flags.natIntercept ? "NAT intercepted " : "") << (s->flags.tproxyIntercept ? "TPROXY intercepted " : "") << (s->flags.tunnelSslBumping ? "SSL bumped " : "") << @@ -3495,7 +3496,7 @@ clientConnectionsClose() { for (AnyP::PortCfgPointer s = HttpPortList; s != NULL; s = s->next) { if (s->listenConn != NULL) { - debugs(1, DBG_IMPORTANT, "Closing HTTP(S) port " << s->listenConn->local); + debugs(1, Important(14), "Closing HTTP(S) port " << s->listenConn->local); s->listenConn->close(); s->listenConn = NULL; } diff --git a/src/debug.cc b/src/debug.cc index 319f470263..c66e13cc5b 100644 --- a/src/debug.cc +++ b/src/debug.cc @@ -10,6 +10,7 @@ #include "squid.h" #include "Debug.h" +#include "DebugMessages.h" #include "fd.h" #include "ipc/Kids.h" #include "SquidTime.h" @@ -27,6 +28,7 @@ bool Debug::log_syslog = false; int Debug::Levels[MAX_DEBUG_SECTIONS]; char *Debug::cache_log = NULL; int Debug::rotateNumber = -1; +DebugMessages TheDebugMessages; static int Ctx_Lock = 0; static const char *debugLogTime(void); static const char *debugLogKid(void); diff --git a/src/dns_internal.cc b/src/dns_internal.cc index d75f42ad35..cdb34cf201 100644 --- a/src/dns_internal.cc +++ b/src/dns_internal.cc @@ -18,6 +18,7 @@ #include "comm/Loops.h" #include "comm/Read.h" #include "comm/Write.h" +#include "DebugMessages.h" #include "dlink.h" #include "dns/forward.h" #include "dns/rfc3596.h" @@ -395,7 +396,7 @@ idnsParseNameservers(void) { bool result = false; for (auto &i : Config.dns.nameservers) { - debugs(78, DBG_IMPORTANT, "Adding nameserver " << i << " from squid.conf"); + debugs(78, Important(15), "Adding nameserver " << i << " from squid.conf"); idnsAddNameserver(i.c_str()); result = true; } @@ -1574,12 +1575,12 @@ Dns::Init(void) */ if (DnsSocketB >= 0) { comm_local_port(DnsSocketB); - debugs(78, DBG_IMPORTANT, "DNS Socket created at " << addrV6 << ", FD " << DnsSocketB); + debugs(78, Important(16), "DNS IPv6 socket created at " << addrV6 << ", FD " << DnsSocketB); Comm::SetSelect(DnsSocketB, COMM_SELECT_READ, idnsRead, NULL, 0); } if (DnsSocketA >= 0) { comm_local_port(DnsSocketA); - debugs(78, DBG_IMPORTANT, "DNS Socket created at " << addrV4 << ", FD " << DnsSocketA); + debugs(78, Important(64), "DNS IPv4 socket created at " << addrV4 << ", FD " << DnsSocketA); Comm::SetSelect(DnsSocketA, COMM_SELECT_READ, idnsRead, NULL, 0); } } diff --git a/src/fd.cc b/src/fd.cc index fba7e0a57e..8dbb977514 100644 --- a/src/fd.cc +++ b/src/fd.cc @@ -11,6 +11,7 @@ #include "squid.h" #include "comm/Loops.h" #include "Debug.h" +#include "DebugMessages.h" #include "fatal.h" #include "fd.h" #include "fde.h" @@ -283,7 +284,7 @@ fdDumpOpen(void) if (i == fileno(debug_log)) continue; - debugs(51, DBG_IMPORTANT, "Open FD "<< std::left<< std::setw(10) << + debugs(51, Important(17), "Open FD "<< std::left<< std::setw(10) << (F->bytes_read && F->bytes_written ? "READ/WRITE" : F->bytes_read ? "READING" : F->bytes_written ? "WRITING" : "UNSTARTED") << diff --git a/src/fs/rock/RockRebuild.cc b/src/fs/rock/RockRebuild.cc index d5b5815c6b..2d350c3751 100644 --- a/src/fs/rock/RockRebuild.cc +++ b/src/fs/rock/RockRebuild.cc @@ -10,6 +10,7 @@ #include "squid.h" #include "base/AsyncJobCalls.h" +#include "DebugMessages.h" #include "fs/rock/RockDbCell.h" #include "fs/rock/RockRebuild.h" #include "fs/rock/RockSwapDir.h" @@ -339,10 +340,10 @@ Rock::Rebuild::start() assert(IsResponsible(*sd)); if (!resuming) { - debugs(47, DBG_IMPORTANT, "Loading cache_dir #" << sd->index << + debugs(47, Important(18), "Loading cache_dir #" << sd->index << " from " << sd->filePath); } else { - debugs(47, DBG_IMPORTANT, "Resuming indexing cache_dir #" << sd->index << + debugs(47, Important(63), "Resuming indexing cache_dir #" << sd->index << " from " << sd->filePath << ':' << progressDescription()); } diff --git a/src/helper.cc b/src/helper.cc index f69e384faf..18460f0d37 100644 --- a/src/helper.cc +++ b/src/helper.cc @@ -15,6 +15,7 @@ #include "comm/Connection.h" #include "comm/Read.h" #include "comm/Write.h" +#include "DebugMessages.h" #include "fd.h" #include "fde.h" #include "format/Quoting.h" @@ -223,10 +224,10 @@ helperOpenServers(helper * hlp) /* figure out how many new child are actually needed. */ int need_new = hlp->childs.needNew(); - debugs(84, DBG_IMPORTANT, "helperOpenServers: Starting " << need_new << "/" << hlp->childs.n_max << " '" << shortname << "' processes"); + debugs(84, Important(19), "helperOpenServers: Starting " << need_new << "/" << hlp->childs.n_max << " '" << shortname << "' processes"); if (need_new < 1) { - debugs(84, DBG_IMPORTANT, "helperOpenServers: No '" << shortname << "' processes needed."); + debugs(84, Important(20), "helperOpenServers: No '" << shortname << "' processes needed."); } procname = (char *)xmalloc(strlen(shortname) + 3); diff --git a/src/htcp.cc b/src/htcp.cc index 523c40832e..7a2aace075 100644 --- a/src/htcp.cc +++ b/src/htcp.cc @@ -18,6 +18,7 @@ #include "comm/Loops.h" #include "comm/UdpOpenDialer.h" #include "compat/xalloc.h" +#include "DebugMessages.h" #include "globals.h" #include "htcp.h" #include "http.h" @@ -1438,7 +1439,7 @@ void htcpOpenPorts(void) { if (Config.Port.htcp <= 0) { - debugs(31, DBG_IMPORTANT, "HTCP Disabled."); + debugs(31, Important(21), "HTCP Disabled."); return; } diff --git a/src/ipcache.cc b/src/ipcache.cc index 192011cc8c..961358b8e2 100644 --- a/src/ipcache.cc +++ b/src/ipcache.cc @@ -11,6 +11,7 @@ #include "squid.h" #include "CacheManager.h" #include "cbdata.h" +#include "DebugMessages.h" #include "dlink.h" #include "dns/LookupDetails.h" #include "dns/rfc3596.h" @@ -685,7 +686,7 @@ void ipcache_init(void) { int n; - debugs(14, DBG_IMPORTANT, "Initializing IP Cache..."); + debugs(14, Important(24), "Initializing IP Cache..."); memset(&IpcacheStats, '\0', sizeof(IpcacheStats)); lru_list = dlink_list(); diff --git a/src/log/File.cc b/src/log/File.cc index af185b4a40..39c8e3d35c 100644 --- a/src/log/File.cc +++ b/src/log/File.cc @@ -9,6 +9,7 @@ /* DEBUG: section 50 Log file handling */ #include "squid.h" +#include "DebugMessages.h" #include "fatal.h" #include "fde.h" #include "log/File.h" @@ -41,7 +42,7 @@ logfileOpen(const char *path, size_t bufsz, int fatal_flag) int ret; const char *patharg; - debugs(50, DBG_IMPORTANT, "Logfile: opening log " << path); + debugs(50, Important(26), "Logfile: opening log " << path); Logfile *lf = new Logfile(path); patharg = path; @@ -90,7 +91,7 @@ logfileOpen(const char *path, size_t bufsz, int fatal_flag) void logfileClose(Logfile * lf) { - debugs(50, DBG_IMPORTANT, "Logfile: closing log " << lf->path); + debugs(50, Important(27), "Logfile: closing log " << lf->path); lf->f_flush(lf); lf->f_close(lf); delete lf; diff --git a/src/main.cc b/src/main.cc index e0f9449236..29bb7bd1c4 100644 --- a/src/main.cc +++ b/src/main.cc @@ -29,6 +29,7 @@ #include "CommandLine.h" #include "ConfigParser.h" #include "CpuAffinity.h" +#include "DebugMessages.h" #include "DiskIO/DiskIOModule.h" #include "dns/forward.h" #include "errorpage.h" @@ -290,8 +291,8 @@ SignalEngine::doShutdown(time_t wait) if (AvoidSignalAction("shutdown", do_shutdown)) return; - debugs(1, DBG_IMPORTANT, "Preparing for shutdown after " << statCounter.client_http.requests << " requests"); - debugs(1, DBG_IMPORTANT, "Waiting " << wait << " seconds for active connections to finish"); + debugs(1, Important(2), "Preparing for shutdown after " << statCounter.client_http.requests << " requests"); + debugs(1, Important(3), "Waiting " << wait << " seconds for active connections to finish"); #if KILL_PARENT_OPT if (!IamMasterProcess() && !parentKillNotified && ShutdownSignal > 0 && parentPid > 1) { @@ -1117,7 +1118,7 @@ mainSetCwd(void) if (Config.coredump_dir && strcmp("none", Config.coredump_dir) != 0) { if (mainChangeDir(Config.coredump_dir)) { - debugs(0, DBG_IMPORTANT, "Set Current Directory to " << Config.coredump_dir); + debugs(0, Important(4), "Set Current Directory to " << Config.coredump_dir); return; } } @@ -1150,7 +1151,7 @@ mainInitialize(void) Config.Port.icp = (unsigned short) icpPortNumOverride; debugs(1, DBG_CRITICAL, "Starting Squid Cache version " << version_string << " for " << CONFIG_HOST_TYPE << "..."); - debugs(1, DBG_CRITICAL, "Service Name: " << service_name); + debugs(1, Critical(5), "Service Name: " << service_name); #if _SQUID_WINDOWS_ if (WIN32_run_mode == _WIN_SQUID_RUN_MODE_SERVICE) { @@ -1159,12 +1160,12 @@ mainInitialize(void) debugs(1, DBG_CRITICAL, "Running on " << WIN32_OS_string); #endif - debugs(1, DBG_IMPORTANT, "Process ID " << getpid()); + debugs(1, Important(6), "Process ID " << getpid()); - debugs(1, DBG_IMPORTANT, "Process Roles:" << ProcessRoles()); + debugs(1, Important(7), "Process Roles:" << ProcessRoles()); setSystemLimits(); - debugs(1, DBG_IMPORTANT, "With " << Squid_MaxFD << " file descriptors available"); + debugs(1, Important(8), "With " << Squid_MaxFD << " file descriptors available"); #if _SQUID_WINDOWS_ @@ -2084,7 +2085,7 @@ SquidShutdown() WIN32_svcstatusupdate(SERVICE_STOP_PENDING, 10000); #endif - debugs(1, DBG_IMPORTANT, "Shutting down..."); + debugs(1, Important(9), "Shutting down..."); #if USE_SSL_CRTD Ssl::Helper::Shutdown(); #endif @@ -2168,7 +2169,7 @@ SquidShutdown() memClean(); - debugs(1, DBG_IMPORTANT, "Squid Cache (Version " << version_string << "): Exiting normally."); + debugs(1, Important(10), "Squid Cache (Version " << version_string << "): Exiting normally."); /* * DPW 2006-10-23 diff --git a/src/mime.cc b/src/mime.cc index 6c41421b06..b108931167 100644 --- a/src/mime.cc +++ b/src/mime.cc @@ -9,6 +9,7 @@ /* DEBUG: section 25 MIME Parsing and Internal Icons */ #include "squid.h" +#include "DebugMessages.h" #include "fde.h" #include "fs_io.h" #include "globals.h" @@ -331,7 +332,7 @@ mimeInit(char *filename) for (m = MimeTable; m != NULL; m = m->next) m->theIcon.load(); - debugs(25, DBG_IMPORTANT, "Finished loading MIME types and icons."); + debugs(25, Important(28), "Finished loading MIME types and icons."); } void diff --git a/src/neighbors.cc b/src/neighbors.cc index ce2e6182ba..488d1a154d 100644 --- a/src/neighbors.cc +++ b/src/neighbors.cc @@ -16,6 +16,7 @@ #include "CachePeer.h" #include "comm/Connection.h" #include "comm/ConnOpener.h" +#include "DebugMessages.h" #include "event.h" #include "FwdState.h" #include "globals.h" @@ -1198,7 +1199,7 @@ peerDNSConfigure(const ipcache_addrs *ia, const Dns::LookupDetails &, void *data CachePeer *p = (CachePeer *)data; if (p->n_addresses == 0) { - debugs(15, DBG_IMPORTANT, "Configuring " << neighborTypeStr(p) << " " << p->host << "/" << p->http_port << "/" << p->icp.port); + debugs(15, Important(29), "Configuring " << neighborTypeStr(p) << " " << p->host << "/" << p->http_port << "/" << p->icp.port); if (p->type == PEER_MULTICAST) debugs(15, DBG_IMPORTANT, " Multicast TTL = " << p->mcast.ttl); diff --git a/src/store.cc b/src/store.cc index aefc66c46a..6cb14e4934 100644 --- a/src/store.cc +++ b/src/store.cc @@ -17,6 +17,7 @@ #include "CollapsedForwarding.h" #include "comm/Connection.h" #include "comm/Read.h" +#include "DebugMessages.h" #if HAVE_DISKIO_MODULE_IPCIO #include "DiskIO/IpcIo/IpcIoFile.h" #endif @@ -1195,7 +1196,7 @@ storeLateRelease(void *) // TODO: this works but looks unelegant. for (int i = 0; i < 10; ++i) { if (LateReleaseStack.empty()) { - debugs(20, DBG_IMPORTANT, "storeLateRelease: released " << n << " objects"); + debugs(20, Important(30), "storeLateRelease: released " << n << " objects"); return; } else { e = LateReleaseStack.top(); diff --git a/src/store/Disks.cc b/src/store/Disks.cc index 6747f62880..b85da0f38d 100644 --- a/src/store/Disks.cc +++ b/src/store/Disks.cc @@ -12,6 +12,7 @@ #include "cache_cf.h" #include "ConfigParser.h" #include "Debug.h" +#include "DebugMessages.h" #include "globals.h" #include "profiler/Profiler.h" #include "sbuf/Stream.h" @@ -269,17 +270,17 @@ Store::Disks::init() /* this is very bogus, its specific to the any Store maintaining an * in-core index, not global */ size_t buckets = (Store::Root().maxSize() + Config.memMaxSize) / Config.Store.avgObjectSize; - debugs(20, DBG_IMPORTANT, "Swap maxSize " << (Store::Root().maxSize() >> 10) << + debugs(20, Important(31), "Swap maxSize " << (Store::Root().maxSize() >> 10) << " + " << ( Config.memMaxSize >> 10) << " KB, estimated " << buckets << " objects"); buckets /= Config.Store.objectsPerBucket; - debugs(20, DBG_IMPORTANT, "Target number of buckets: " << buckets); + debugs(20, Important(32), "Target number of buckets: " << buckets); /* ideally the full scan period should be configurable, for the * moment it remains at approximately 24 hours. */ store_hash_buckets = storeKeyHashBuckets(buckets); - debugs(20, DBG_IMPORTANT, "Using " << store_hash_buckets << " Store buckets"); - debugs(20, DBG_IMPORTANT, "Max Mem size: " << ( Config.memMaxSize >> 10) << " KB" << + debugs(20, Important(33), "Using " << store_hash_buckets << " Store buckets"); + debugs(20, Important(34), "Max Mem size: " << ( Config.memMaxSize >> 10) << " KB" << (Config.memShared ? " [shared]" : "")); - debugs(20, DBG_IMPORTANT, "Max Swap size: " << (Store::Root().maxSize() >> 10) << " KB"); + debugs(20, Important(35), "Max Swap size: " << (Store::Root().maxSize() >> 10) << " KB"); store_table = hash_create(storeKeyHashCmp, store_hash_buckets, storeKeyHashHash); @@ -315,7 +316,7 @@ Store::Disks::init() debugs(47, DBG_IMPORTANT, "Using Round Robin store dir selection"); } else { storeDirSelectSwapDir = storeDirSelectSwapDirLeastLoad; - debugs(47, DBG_IMPORTANT, "Using Least Load store dir selection"); + debugs(47, Important(36), "Using Least Load store dir selection"); } } @@ -708,12 +709,12 @@ storeDirWriteCleanLogs(int reopen) // initialization phases, before store log is initialized and ready. Also, // some stores do not support log cleanup during Store rebuilding. if (StoreController::store_dirs_rebuilding) { - debugs(20, DBG_IMPORTANT, "Not currently OK to rewrite swap log."); - debugs(20, DBG_IMPORTANT, "storeDirWriteCleanLogs: Operation aborted."); + debugs(20, Important(37), "Not currently OK to rewrite swap log."); + debugs(20, Important(38), "storeDirWriteCleanLogs: Operation aborted."); return 0; } - debugs(20, DBG_IMPORTANT, "storeDirWriteCleanLogs: Starting..."); + debugs(20, Important(39), "storeDirWriteCleanLogs: Starting..."); getCurrentTime(); start = current_time; @@ -771,8 +772,8 @@ storeDirWriteCleanLogs(int reopen) dt = tvSubDsec(start, current_time); - debugs(20, DBG_IMPORTANT, " Finished. Wrote " << n << " entries."); - debugs(20, DBG_IMPORTANT, " Took "<< std::setw(3)<< std::setprecision(2) << dt << + debugs(20, Important(40), " Finished. Wrote " << n << " entries."); + debugs(20, Important(41), " Took "<< std::setw(3) << std::setprecision(2) << dt << " seconds ("<< std::setw(6) << ((double) n / (dt > 0.0 ? dt : 1.0)) << " entries/sec)."); return n; diff --git a/src/store_log.cc b/src/store_log.cc index cd4def9c2b..f7b70d963f 100644 --- a/src/store_log.cc +++ b/src/store_log.cc @@ -9,6 +9,7 @@ /* DEBUG: section 20 Storage Manager Logging Functions */ #include "squid.h" +#include "DebugMessages.h" #include "format/Token.h" #include "HttpReply.h" #include "log/File.h" @@ -125,7 +126,7 @@ storeLogOpen(void) storeLogRegisterWithCacheManager(); if (Config.Log.store == NULL || strcmp(Config.Log.store, "none") == 0) { - debugs(20, DBG_IMPORTANT, "Store logging disabled"); + debugs(20, Important(42), "Store logging disabled"); return; } diff --git a/src/store_rebuild.cc b/src/store_rebuild.cc index d3c38a89b5..13da2ce0cd 100644 --- a/src/store_rebuild.cc +++ b/src/store_rebuild.cc @@ -9,6 +9,7 @@ /* DEBUG: section 20 Store Rebuild Routines */ #include "squid.h" +#include "DebugMessages.h" #include "event.h" #include "globals.h" #include "md5.h" @@ -96,9 +97,9 @@ storeCleanup(void *) if (currentSearch->isDone()) { debugs(20, 2, "Seen: " << seen << " entries"); - debugs(20, DBG_IMPORTANT, " Completed Validation Procedure"); - debugs(20, DBG_IMPORTANT, " Validated " << validated << " Entries"); - debugs(20, DBG_IMPORTANT, " store_swap_size = " << Store::Root().currentSize() / 1024.0 << " KB"); + debugs(20, Important(43), "Completed Validation Procedure" << + Debug::Extra << "Validated " << validated << " Entries" << + Debug::Extra << "store_swap_size = " << (Store::Root().currentSize()/1024.0) << " KB"); --StoreController::store_dirs_rebuilding; assert(0 == StoreController::store_dirs_rebuilding); @@ -152,18 +153,18 @@ storeRebuildComplete(StoreRebuildData *dc) const auto dt = tvSubDsec(counts.startTime, current_time); - debugs(20, DBG_IMPORTANT, "Finished rebuilding storage from disk."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.scancount << " Entries scanned"); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.invalid << " Invalid entries."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.badflags << " With invalid flags."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.objcount << " Objects loaded."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.expcount << " Objects expired."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.cancelcount << " Objects cancelled."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.dupcount << " Duplicate URLs purged."); - debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.clashcount << " Swapfile clashes avoided."); - debugs(20, DBG_IMPORTANT, " Took "<< std::setw(3)<< std::setprecision(2) << dt << " seconds ("<< std::setw(6) << + debugs(20, Important(46), "Finished rebuilding storage from disk." << + Debug::Extra << std::setw(7) << counts.scancount << " Entries scanned" << + Debug::Extra << std::setw(7) << counts.invalid << " Invalid entries" << + Debug::Extra << std::setw(7) << counts.badflags << " With invalid flags" << + Debug::Extra << std::setw(7) << counts.objcount << " Objects loaded" << + Debug::Extra << std::setw(7) << counts.expcount << " Objects expired" << + Debug::Extra << std::setw(7) << counts.cancelcount << " Objects canceled" << + Debug::Extra << std::setw(7) << counts.dupcount << " Duplicate URLs purged" << + Debug::Extra << std::setw(7) << counts.clashcount << " Swapfile clashes avoided" << + Debug::Extra << "Took " << std::setprecision(2) << dt << " seconds (" << ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec)."); - debugs(20, DBG_IMPORTANT, "Beginning Validation Procedure"); + debugs(20, Important(56), "Beginning Validation Procedure"); eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1); @@ -229,7 +230,7 @@ storeRebuildProgress(int sd_index, int total, int sofar) d += (double) RebuildProgress[sd_index].total; } - debugs(20, DBG_IMPORTANT, "Indexing cache entries: " << Progress(n, d)); + debugs(20, Important(57), "Indexing cache entries: " << Progress(n, d)); last_report = squid_curtime; }