From ea3f56e21ee0d7dd570092cabe23161b363f8cec Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 8 Sep 2023 06:05:36 +0000 Subject: [PATCH] Restore errno in %err_detail for ERR_CONNECT_FAIL (#1368) Squid was sometimes logging %err_code/%err_detail as ERR_CONNECT_FAIL/WITH_SERVER. It now logs ERR_CONNECT_FAIL/WITH_SERVER+errno=111 (or similar). When dealing with two error details, Squid was ignoring the latter one. The new ErrorDetails code combines multiple details, reusing the existing Security::ErrorDetail::brief() "a+b+c" syntax. The new detail accumulation functionality may help detail other errors. At least some of the logged errno details were lost in commit ba3fe8d. --- src/base/IoManip.h | 44 +++++++++++++++++++++++++ src/cf.data.pre | 8 ++++- src/client_side.cc | 4 +-- src/error/Detail.h | 11 +++++++ src/error/Error.cc | 66 +++++++++++++++++++++++++++++++------- src/error/Error.h | 32 +++++++++++++++--- src/errorpage.cc | 13 +++----- src/format/Format.cc | 4 +-- src/servers/FtpServer.cc | 2 +- src/tests/stub_liberror.cc | 4 +++ 10 files changed, 159 insertions(+), 29 deletions(-) diff --git a/src/base/IoManip.h b/src/base/IoManip.h index 3feb928a11..d8ac5287c6 100644 --- a/src/base/IoManip.h +++ b/src/base/IoManip.h @@ -13,6 +13,7 @@ #include #include +#include /// Safely prints an object pointed to by the given pointer: [label] /// Prints nothing at all if the pointer is nil. @@ -101,5 +102,48 @@ inline AsHex asHex(const Integer n) { return AsHex(n); } /// Prints the first n data bytes using hex notation. Does nothing if n is 0. void PrintHex(std::ostream &, const char *data, size_t n); +/// std::ostream manipulator to print containers as flat lists +template +class AsList +{ +public: + explicit AsList(const Container &c): container(c) {} + + /// a character to print before the first item (if any) + auto &prefixedBy(const char ch) { prefix = ch; return *this; } + + /// a character to print between consecutive items (if any) + auto &delimitedBy(const char ch) { delimiter = ch; return *this; } + +public: + const Container &container; ///< zero or more items to print + + std::optional prefix; ///< \copydoc prefixedBy() + std::optional delimiter; ///< \copydoc delimitedBy() +}; + +template +inline std::ostream & +operator <<(std::ostream &os, const AsList &manipulator) +{ + bool opened = false; + for (const auto &item: manipulator.container) { + if (!opened) { + if (manipulator.prefix) + os << *manipulator.prefix; + opened = true; + } else { + if (manipulator.delimiter) + os << *manipulator.delimiter; + } + os << item; + } + return os; +} + +/// a helper to ease AsList object creation +template +inline auto asList(const Container &c) { return AsList(c); } + #endif /* SQUID_SRC_BASE_IO_MANIP_H */ diff --git a/src/cf.data.pre b/src/cf.data.pre index 010bf88456..f20e598277 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4688,7 +4688,13 @@ DOC_START sn Unique sequence number per log line entry err_code The ID of an error response served by Squid or a similar internal error identifier. - err_detail Additional err_code-dependent error information. + + err_detail Additional err_code-dependent error information. Multiple + details are separated by the plus sign ('+'). Admins should not + rely on a particular detail listing order, the uniqueness of the + entries, or individual detail text stability. All those properties + depend on many unstable factors, including external libraries. + note The annotation specified by the argument. Also logs the adaptation meta headers set by the adaptation_meta configuration parameter. diff --git a/src/client_side.cc b/src/client_side.cc index 1bca92017f..e62bcf0fc7 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -3989,9 +3989,9 @@ ConnStateData::terminateAll(const Error &rawError, const LogTagsErrors <e) auto error = rawError; // (cheap) copy so that we can detail // We detail even ERR_NONE: There should be no transactions left, and // detailed ERR_NONE will be unused. Otherwise, this detail helps in triage. - if (!error.detail) { + if (error.details.empty()) { static const auto d = MakeNamedErrorDetail("WITH_CLIENT"); - error.detail = d; + error.details.push_back(d); } debugs(33, 3, pipeline.count() << '/' << pipeline.nrequests << " after " << error); diff --git a/src/error/Detail.h b/src/error/Detail.h index ec4df88a6d..059c4bd28e 100644 --- a/src/error/Detail.h +++ b/src/error/Detail.h @@ -31,6 +31,17 @@ public: /// \returns all available details; may be customized for the given request /// suitable for error pages and other output meant for human consumption virtual SBuf verbose(const HttpRequestPointer &) const = 0; + + // Duplicate details for the same error typically happen when we update some + // error storage (e.g., ALE) twice from the same detail source (e.g., the + // same HttpRequest object reachable via two different code/pointer paths) + // or retag the error with the same context information (e.g., WITH_CLIENT). + // In all those cases, comparing detail object addresses is enough to detect + // duplicates. In other cases (if they exist), a duplicate detail would + // imply inefficient or buggy error detailing code. Instead of spending ink + // and CPU cycles on hiding them, this comparison may expose those (minor) + // problems (in hope that they get fixed). + bool equals(const ErrorDetail &other) const { return this == &other; } }; /// creates a new NamedErrorDetail object with a unique name diff --git a/src/error/Error.cc b/src/error/Error.cc index d42cc7f161..6789474c72 100644 --- a/src/error/Error.cc +++ b/src/error/Error.cc @@ -9,31 +9,75 @@ /* DEBUG: section 04 Error Management */ #include "squid.h" +#include "base/IoManip.h" #include "debug/Stream.h" #include "error/Error.h" +void +Error::update(const err_type recentCategory) +{ + if (recentCategory == ERR_NONE) + return; // no category given + + if (category == recentCategory) + return; // no new category given + + if (category != ERR_NONE) { + debugs(4, 5, "ignoring: " << errorTypeName(recentCategory) << "; keeping " << *this); + return; // the category given earlier has won + } + + category = recentCategory; + debugs(4, 3, "new: " << errorTypeName(category)); +} + +void +Error::update(const ErrorDetail::Pointer &recentDetail) +{ + if (!recentDetail) + return; // no new detail given + + // an error can only have a few details so linear search is faster than indexing + for (const auto &oldDetail: details) { + if (recentDetail->equals(*oldDetail)) + return; // the given detail is already present + } + + details.push_back(recentDetail); + debugs(4, 3, "new: " << recentDetail); +} + void Error::update(const Error &recent) { - if (*this) - debugs(4, 5, "old: " << *this); - if (!recent) - return; // no changes - debugs(4, 3, "recent: " << recent); // checking category and detail separately may cause inconsistency, but // may result in more details available if they only become available later - if (category == ERR_NONE) - category = recent.category; // may still be ERR_NONE - if (!detail) - detail = recent.detail; // may still be nil + update(recent.category); + for (const auto &recentDetail: recent.details) + update(recentDetail); +} + +void +Error::update(const err_type recentCategory, const ErrorDetail::Pointer &recentDetail) +{ + // Optimization: Do not simply call update(Error(...)) here because that + // would require allocating and freeing heap memory for storing the detail. + update(recentCategory); + update(recentDetail); +} + +std::ostream & +operator <<(std::ostream &os, const ErrorDetails &details) +{ + os << AsList(details).delimitedBy('+'); + return os; } std::ostream & operator <<(std::ostream &os, const Error &error) { os << errorTypeName(error.category); - if (error.detail) - os << '/' << *error.detail; + os << AsList(error.details).prefixedBy('/').delimitedBy('+'); return os; } diff --git a/src/error/Error.h b/src/error/Error.h index fc3ed42f9d..a1074b6269 100644 --- a/src/error/Error.h +++ b/src/error/Error.h @@ -11,29 +11,53 @@ #include "error/Detail.h" #include "error/forward.h" +#include "mem/PoolingAllocator.h" #include +#include + +/// zero or more details of a single error +using ErrorDetails = std::vector >; + +/// prints all given details separated by '+'; +/// if no details were given, prints nothing +std::ostream &operator <<(std::ostream &, const ErrorDetails &); /// a transaction problem class Error { public: Error() = default; Error(const err_type c): category(c) {} ///< support implicit conversions - Error(const err_type c, const ErrorDetailPointer &d): category(c), detail(d) {} + Error(const err_type c, const ErrorDetailPointer &d): Error(c) { update(d); } explicit operator bool() const { return category != ERR_NONE; } /// if necessary, stores the given error information (if any) void update(const Error &); - /// convenience wrapper for update(Error) - void update(const err_type c, const ErrorDetailPointer &d) { update(Error(c, d)); } + /// if necessary, stores the given error information (if any); + /// more convenient and faster alternative to calling update(Error(c, d)) + void update(err_type, const ErrorDetailPointer &); + + /// if necessary, stores the given error category (if any), leaving details unchanged; + /// the first non-ERR_NONE category wins; + /// more convenient alternative to calling update(Error(c)) + void update(err_type); + + /// records an additional error detail (if any), leaving category unchanged + /// more convenient and faster alternative to calling update(Error(ERR_NONE, d)) + /// \param detail either nil or a pointer to a new or an already known detail + void update(const ErrorDetailPointer &detail); /// switch to the default "no error information" state void clear() { *this = Error(); } err_type category = ERR_NONE; ///< primary error classification (or ERR_NONE) - ErrorDetailPointer detail; ///< additional details about the error + + /// Zero or more details of a single error, in temporal order of discovery + /// without duplicates or nil pointers. The order/timing of update() calls + /// is used to approximate detail discovery time. + ErrorDetails details; }; extern const char *err_type_str[]; diff --git a/src/errorpage.cc b/src/errorpage.cc index 0f648a4681..8200e28f7f 100644 --- a/src/errorpage.cc +++ b/src/errorpage.cc @@ -1348,15 +1348,12 @@ ErrorState::BuildHttpReply() // Make sure error codes get back to the client side for logging and // error tracking. if (request) { - if (detail) - request->detailError(type, detail); - else - request->detailError(type, SysErrorDetail::NewIfAny(xerrno)); + request->error.update(type, detail); + request->error.update(SysErrorDetail::NewIfAny(xerrno)); } else if (ale) { - if (detail) - ale->updateError(Error(type, detail)); - else - ale->updateError(Error(type, SysErrorDetail::NewIfAny(xerrno))); + Error err(type, detail); + err.update(SysErrorDetail::NewIfAny(xerrno)); + ale->updateError(err); } return rep; diff --git a/src/format/Format.cc b/src/format/Format.cc index e7e689d381..d0c6719f45 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -1004,8 +1004,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS case LFT_SQUID_ERROR_DETAIL: if (const auto error = al->error()) { - if (const auto detail = error->detail) { - sb = detail->brief(); + if (!error->details.empty()) { + sb = ToSBuf(error->details); out = sb.c_str(); } } diff --git a/src/servers/FtpServer.cc b/src/servers/FtpServer.cc index 65d628cb42..976fe4e1f1 100644 --- a/src/servers/FtpServer.cc +++ b/src/servers/FtpServer.cc @@ -1103,7 +1103,7 @@ Ftp::Server::writeErrorReply(const HttpReply *reply, const int scode) if (request->error) mb.appendf("%i-%s\r\n", scode, errorPageName(request->error.category)); - if (const auto &detail = request->error.detail) { + for (const auto &detail: request->error.details) { mb.appendf("%i-Error-Detail-Brief: " SQUIDSBUFPH "\r\n", scode, SQUIDSBUFPRINT(detail->brief())); mb.appendf("%i-Error-Detail-Verbose: " SQUIDSBUFPH "\r\n", scode, SQUIDSBUFPRINT(detail->verbose(request))); } diff --git a/src/tests/stub_liberror.cc b/src/tests/stub_liberror.cc index 94a1ffa941..3baa65e3e0 100644 --- a/src/tests/stub_liberror.cc +++ b/src/tests/stub_liberror.cc @@ -15,10 +15,14 @@ const char * err_type_str[ERR_MAX] = {}; +void Error::update(err_type) STUB_NOP +void Error::update(const ErrorDetailPointer &) STUB_NOP void Error::update(const Error &) STUB_NOP +void Error::update(err_type, const ErrorDetailPointer &) STUB_NOP std::ostream &operator <<(std::ostream &os, const Error &) STUB_RETVAL(os) std::ostream &operator <<(std::ostream &os, const ErrorDetail::Pointer &) STUB_RETVAL(os) +std::ostream &operator <<(std::ostream &os, const ErrorDetails &) STUB_RETVAL(os) ErrorDetail::Pointer MakeNamedErrorDetail(const char *) STUB_RETVAL(ErrorDetail::Pointer()) -- 2.39.5