From: Alex Rousskov Date: Wed, 28 Jul 2021 12:21:45 +0000 (+0000) Subject: Remove legacy context-based debugging in favor of CodeContext (#866) X-Git-Tag: SQUID_6_0_1~306 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=908aa0cafd20f7d49826bc16ee33c3bbe1f8fd6e;p=thirdparty%2Fsquid.git Remove legacy context-based debugging in favor of CodeContext (#866) Added in 1998, context-based debugging has been neglected and - only covers two relatively small contexts - unsafe in the presence of exceptions - produces noise (e.g., "ctx: exit level 0" messages) - delayed "ctx: exit" messages confuse admins - uses deprecated urlXXX() API - difficult to extend to more contexts without performance overheads - usually provides less info in fewer contexts (than CodeContext) --- diff --git a/src/Debug.h b/src/Debug.h index a6dd7d6dfd..939b27d446 100644 --- a/src/Debug.h +++ b/src/Debug.h @@ -33,11 +33,6 @@ #define assert(EX) ((EX)?((void)0):xassert("EX", __FILE__, __LINE__)) #endif -/* context-based debugging, the actual type is subject to change */ -typedef int Ctx; -Ctx ctx_enter(const char *descr); -void ctx_exit(Ctx ctx); - /* defined debug section limits */ #define MAX_DEBUG_SECTIONS 100 diff --git a/src/MemObject.cc b/src/MemObject.cc index 5186934ac8..2457cb447d 100644 --- a/src/MemObject.cc +++ b/src/MemObject.cc @@ -106,7 +106,6 @@ MemObject::MemObject() MemObject::~MemObject() { debugs(20, 3, "MemObject destructed, this=" << this); - const Ctx ctx = ctx_enter(hasUris() ? urlXXX() : "[unknown_ctx]"); #if URL_CHECKSUM_DEBUG checkUrlChecksum(); @@ -119,8 +118,6 @@ MemObject::~MemObject() } data_hdr.freeContent(); - - ctx_exit(ctx); /* must exit before we free mem->url */ } HttpReply & diff --git a/src/base/CodeContext.h b/src/base/CodeContext.h index 5f128e6910..f56f6f3fbb 100644 --- a/src/base/CodeContext.h +++ b/src/base/CodeContext.h @@ -14,6 +14,37 @@ #include +/** \file + * + * Most error-reporting code cannot know what transaction or task Squid was + * working on when the error occurred. For example, when Squid HTTP request + * parser discovers a malformed header field, the parser can report the field + * contents, but that information is often useless for the admin without + * processing context details like which client sent the request or what the + * requested URL was. Moreover, even when the error reporting code does have + * access to some context details, it cannot separate important facts from noise + * because such classification is usually deployment-specific (i.e. cannot be + * hard-coded) and requires human expertise. The situation is aggravated by a + * busy Squid instance constantly switching from one processing context to + * another. + * + * To solve these problems, Squid assigns a CodeContext object to a processing + * context. When Squid switches to another processing context, it switches the + * current CodeContext object as well. When Squid prints a level-0 or level-1 + * message to cache.log, it asks the current CodeContext object (if any) to + * report context details, allowing the admin to correlate the cache.log message + * with an access.log record. + * + * Squid also reports processing context changes to cache.log when Squid + * level-5+ debugging is enabled. + * + * CodeContext is being retrofitted into existing code with lots of places that + * switch processing context. Identifying and adjusting all those places takes + * time. Until then, there will be incorrect and missing context attributions. + * + * @{ + **/ + /// Interface for reporting what Squid code is working on. /// Such reports are usually requested outside creator's call stack. /// They are especially useful for attributing low-level errors to transactions. @@ -117,5 +148,7 @@ CallContextCreator(Fun &&creator) CodeContext::Reset(savedCodeContext); } +/// @} + #endif diff --git a/src/debug.cc b/src/debug.cc index c66e13cc5b..b48f88128a 100644 --- a/src/debug.cc +++ b/src/debug.cc @@ -29,10 +29,8 @@ 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); -static void ctx_print(void); #if HAVE_SYSLOG #ifdef LOG_LOCAL4 static int syslog_facility = 0; @@ -159,10 +157,6 @@ _db_print(const bool forceAlert, const char *format,...) EnterCriticalSection(dbg_mutex); #endif - /* give a chance to context-based debugging to print current context */ - if (!Ctx_Lock) - ctx_print(); - va_start(args1, format); va_start(args2, format); va_start(args3, format); @@ -194,10 +188,6 @@ _db_print_file(const char *format, va_list args) if (debug_log == NULL) return; - /* give a chance to context-based debugging to print current context */ - if (!Ctx_Lock) - ctx_print(); - vfprintf(debug_log, format, args); fflush(debug_log); } @@ -626,169 +616,6 @@ xassert(const char *msg, const char *file, int line) abort(); } -/* - * Context-based Debugging - * - * Rationale - * --------- - * - * When you have a long nested processing sequence, it is often impossible - * for low level routines to know in what larger context they operate. If a - * routine coredumps, one can restore the context using debugger trace. - * However, in many case you do not want to coredump, but just want to report - * a potential problem. A report maybe useless out of problem context. - * - * To solve this potential problem, use the following approach: - * - * int - * top_level_foo(const char *url) - * { - * // define current context - * // note: we stack but do not dup ctx descriptions! - * Ctx ctx = ctx_enter(url); - * ... - * // go down; middle_level_bar will eventually call bottom_level_boo - * middle_level_bar(method, protocol); - * ... - * // exit, clean after yourself - * ctx_exit(ctx); - * } - * - * void - * bottom_level_boo(int status, void *data) - * { - * // detect exceptional condition, and simply report it, the context - * // information will be available somewhere close in the log file - * if (status == STRANGE_STATUS) - * debugs(13, 6, "DOS attack detected, data: " << data); - * ... - * } - * - * Current implementation is extremely simple but still very handy. It has a - * negligible overhead (descriptions are not duplicated). - * - * When the _first_ debug message for a given context is printed, it is - * prepended with the current context description. Context is printed with - * the same debugging level as the original message. - * - * Note that we do not print context every type you do ctx_enter(). This - * approach would produce too many useless messages. For the same reason, a - * context description is printed at most _once_ even if you have 10 - * debugging messages within one context. - * - * Contexts can be nested, of course. You must use ctx_enter() to enter a - * context (push it onto stack). It is probably safe to exit several nested - * contexts at _once_ by calling ctx_exit() at the top level (this will pop - * all context till current one). However, as in any stack, you cannot start - * in the middle. - * - * Analysis: - * i) locate debugging message, - * ii) locate current context by going _upstream_ in your log file, - * iii) hack away. - * - * - * To-Do: - * ----- - * - * decide if we want to dup() descriptions (adds overhead) but allows to - * add printf()-style interface - * - * implementation: - * --------------- - * - * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably - * have a bug if your nesting goes that deep. - */ - -#define CTX_MAX_LEVEL 255 - -/* - * produce a warning when nesting reaches this level and then double - * the level - */ -static int Ctx_Warn_Level = 32; -/* all descriptions has been printed up to this level */ -static int Ctx_Reported_Level = -1; -/* descriptions are still valid or active up to this level */ -static int Ctx_Valid_Level = -1; -/* current level, the number of nested ctx_enter() calls */ -static int Ctx_Current_Level = -1; -/* saved descriptions (stack) */ -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; - - if (Ctx_Current_Level <= CTX_MAX_LEVEL) - Ctx_Descrs[Ctx_Current_Level] = descr; - - if (Ctx_Current_Level == Ctx_Warn_Level) { - debugs(0, DBG_CRITICAL, "# ctx: suspiciously deep (" << Ctx_Warn_Level << ") nesting:"); - Ctx_Warn_Level *= 2; - } - - return Ctx_Current_Level; -} - -void -ctx_exit(Ctx ctx) -{ - assert(ctx >= 0); - Ctx_Current_Level = (ctx >= 0) ? ctx - 1 : -1; - - if (Ctx_Valid_Level > Ctx_Current_Level) - Ctx_Valid_Level = Ctx_Current_Level; -} - -/* - * the idea id to print each context description at most once but provide enough - * info for deducing the current execution stack - */ -static void -ctx_print(void) -{ - /* lock so _db_print will not call us recursively */ - ++Ctx_Lock; - /* ok, user saw [0,Ctx_Reported_Level] descriptions */ - /* first inform about entries popped since user saw them */ - - if (Ctx_Valid_Level < Ctx_Reported_Level) { - if (Ctx_Reported_Level != Ctx_Valid_Level + 1) - _db_print(false, "ctx: exit levels from %2d down to %2d\n", - Ctx_Reported_Level, Ctx_Valid_Level + 1); - else - _db_print(false, "ctx: exit level %2d\n", Ctx_Reported_Level); - - Ctx_Reported_Level = Ctx_Valid_Level; - } - - /* report new contexts that were pushed since last report */ - while (Ctx_Reported_Level < Ctx_Current_Level) { - ++Ctx_Reported_Level; - ++Ctx_Valid_Level; - _db_print(false, "ctx: enter level %2d: '%s'\n", Ctx_Reported_Level, - ctx_get_descr(Ctx_Reported_Level)); - } - - /* unlock */ - --Ctx_Lock; -} - -/* checks for nulls and overflows */ -static const char * -ctx_get_descr(Ctx ctx) -{ - if (ctx < 0 || ctx > CTX_MAX_LEVEL) - return ""; - - return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : ""; -} - Debug::Context *Debug::Current = nullptr; Debug::Context::Context(const int aSection, const int aLevel): diff --git a/src/http.cc b/src/http.cc index 6c0f19005f..a635202a4d 100644 --- a/src/http.cc +++ b/src/http.cc @@ -650,17 +650,12 @@ HttpStateData::processReplyHeader() { /** Creates a blank header. If this routine is made incremental, this will not do */ - /* NP: all exit points to this function MUST call ctx_exit(ctx) */ - Ctx ctx = ctx_enter(entry->mem_obj->urlXXX()); - debugs(11, 3, "processReplyHeader: key '" << entry->getMD5Text() << "'"); assert(!flags.headers_parsed); - if (!inBuf.length()) { - ctx_exit(ctx); + if (!inBuf.length()) return; - } /* Attempt to parse the first line; this will define where the protocol, status, reason-phrase and header begin */ { @@ -688,7 +683,6 @@ HttpStateData::processReplyHeader() inBuf = hp->remaining(); } else { debugs(33, 5, "Incomplete response, waiting for end of response headers"); - ctx_exit(ctx); return; } } @@ -701,7 +695,6 @@ HttpStateData::processReplyHeader() HttpReply *newrep = new HttpReply; newrep->sline.set(Http::ProtocolVersion(), hp->parseStatusCode); setVirginReply(newrep); - ctx_exit(ctx); return; } } @@ -737,7 +730,6 @@ HttpStateData::processReplyHeader() if (newrep->sline.version.protocol == AnyP::PROTO_HTTP && Http::Is1xx(newrep->sline.status())) { handle1xx(newrep); - ctx_exit(ctx); return; } @@ -758,8 +750,6 @@ HttpStateData::processReplyHeader() checkDateSkew(vrep); processSurrogateControl (vrep); - - ctx_exit(ctx); } /// ignore or start forwarding the 1xx response (a.k.a., control message) @@ -959,7 +949,6 @@ HttpStateData::haveParsedReplyHeaders() { Client::haveParsedReplyHeaders(); - Ctx ctx = ctx_enter(entry->mem_obj->urlXXX()); HttpReply *rep = finalReply(); const Http::StatusCode statusCode = rep->sline.status(); @@ -1083,8 +1072,6 @@ HttpStateData::haveParsedReplyHeaders() headersLog(1, 0, request->method, rep); #endif - - ctx_exit(ctx); } HttpStateData::ConnectionStatus diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc index 4a8d0525db..db5d8bfe3f 100644 --- a/src/tests/stub_debug.cc +++ b/src/tests/stub_debug.cc @@ -37,16 +37,6 @@ DebugStream() return stderr; } -Ctx -ctx_enter(const char *) -{ - return -1; -} - -void -ctx_exit(Ctx) -{} - void _db_init(const char *, const char *) {}