Added %err_code and %err_detail logformat codes to record details about transaction failures. For example, when Squid responds with 500 Internal Server Error, it is often useful to know what went wrong. This patch : - log a detail string instead of numbers for common errors - log a label with the detail code number for generic errors (system errors, or exceptions) - adds more details about errors, especially those detected with exceptions: We record a hash of the filename and the source code line number of the first caught exception. - adds two scripts which can help the developers to find the exact position of the caught exception: 1) The calc-must-ids.pl take as argument one or more files and compute for each Must expression in the given files its id; 2) The calc-must-ids.sh can be used to find the exact position of a Must expression from its id. Example usage: # ./scripts/calc-must-ids.sh 0xB79EF14 ./src/adaptation/ecap/MessageRep.cc:356: 0xB79EF14 Must(false); === added file 'scripts/calc-must-ids.pl' --- scripts/calc-must-ids.pl 1970-01-01 00:00:00 +0000 +++ scripts/calc-must-ids.pl 2010-10-19 12:54:56 +0000 @@ -0,0 +1,65 @@ +#!/usr/bin/perl +# +# Author: Tsantilas Christos +# (C) 2010 The Measurement Factory +# +# Usage: +# calc-must-ids.pl file1 file2 ... +# Compute the ids of Must expressions of the given files. +# It returns one line per Must expression in the form: +# filename: line: MustID 'Must Text' +# + +use warnings; +use strict; + +# This constant should be synced with ERR_DETAIL_EXCEPTION_START enum +# defined in src/err_detail_type.h +use constant ERR_DETAIL_EXCEPTION_START => 110000; + +my $file; +while ($file = shift @ARGV) { + ComputeMustIds($file); +} +sub FileNameHash +{ +# Please keep in sync this function with the FileNameHash function in +# src/base/TextException.cc file + my($name) = @_; + $name =~ s/.*\///g; + my($i) = 0; + my($j) =0; + my($n) = 0; + my(@na) = split(//, $name); + for($j=0; $j < @na; $j++) { + $n = $n ^ (271 * ord($na[$j])); + } + $i = $n ^ ($j *271); + + # Currently 18bits of a 32 bit integer used for filename hash + # (max hash=262143), and 14 bits for storing line number + $i = $i % 262143; + return $i; +} + +sub ComputeMustIds +{ + my($file) = @_; + my($hash) = FileNameHash($file); + if(!open(IN, "<$file")) { + printf STDERR "error opening file $file. Ignore ..."; + return; + } + while(<IN>) { + my($line) = $_; + my($id); + if ( $line =~ /^\s*Must\s*\(/ || $line =~ /^\s*throw\s*TexcHere\s*\(/){ + $line =~ s/^\s*//; + $id= ($hash <<14) | ($. & 0x3FFF); + $id += ERR_DETAIL_EXCEPTION_START; +# print "$file:$.: $id $line"; + printf "%s:%d: 0x%X %s", $file, $., $id, $line; + } + } + close(IN); +} === added file 'scripts/calc-must-ids.sh' --- scripts/calc-must-ids.sh 1970-01-01 00:00:00 +0000 +++ scripts/calc-must-ids.sh 2010-10-19 12:58:16 +0000 @@ -0,0 +1,22 @@ +#!/bin/sh +# +# Usage: +# calc-must-ids.sh [MustID] +# Given an id it searches for the related Must expression in all +# source files. If no arguments given it returns all Must expressions +# with its ids and their exact position in the source files. +# +# Example usage: +# # ./scripts/calc-must-ids.sh 0xB79EF14 +# ./src/adaptation/ecap/MessageRep.cc:356: 0xB79EF14 Must(false); +# + +if test -z "$1"; then + find . -name "*.cc" -o -name "*.h" -o -name "*.cci" | \ + xargs `dirname $0`/calc-must-ids.pl +else + find . -name "*.cc" -o -name "*.h" -o -name "*.cci" | \ + xargs `dirname $0`/calc-must-ids.pl | grep ": $1 " +fi + + === modified file 'src/HttpRequest.cc' --- src/HttpRequest.cc 2010-09-12 00:10:47 +0000 +++ src/HttpRequest.cc 2010-10-08 09:52:48 +0000 @@ -27,40 +27,41 @@ * 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) 2003, Robert Collins <robertc@squid-cache.org> */ #include "squid.h" #include "HttpRequest.h" #include "auth/UserRequest.h" #include "HttpHeaderRange.h" #include "MemBuf.h" #include "Store.h" #if ICAP_CLIENT #include "adaptation/icap/icap_log.h" #endif #include "acl/FilledChecklist.h" +#include "err_detail_type.h" HttpRequest::HttpRequest() : HttpMsg(hoRequest) { init(); } HttpRequest::HttpRequest(const HttpRequestMethod& aMethod, protocol_t aProtocol, const char *aUrlpath) : HttpMsg(hoRequest) { static unsigned int id = 1; debugs(93,7, HERE << "constructed, this=" << this << " id=" << ++id); init(); initHTTP(aMethod, aProtocol, aUrlpath); } HttpRequest::~HttpRequest() { clean(); debugs(93,7, HERE << "destructed, this=" << this); } @@ -84,40 +85,41 @@ auth_user_request = NULL; pinned_connection = NULL; port = 0; canonical = NULL; memset(&flags, '\0', sizeof(flags)); range = NULL; ims = -1; imslen = 0; lastmod = -1; max_forwards = -1; client_addr.SetEmpty(); #if USE_SQUID_EUI client_eui48.clear(); client_eui64.clear(); #endif my_addr.SetEmpty(); body_pipe = NULL; // hier dnsWait = -1; errType = ERR_NONE; + errDetail = ERR_DETAIL_NONE; peer_login = NULL; // not allocated/deallocated by this class peer_domain = NULL; // not allocated/deallocated by this class vary_headers = NULL; tag = null_string; extacl_user = null_string; extacl_passwd = null_string; extacl_log = null_string; extacl_message = null_string; pstate = psReadyToParseStartLine; #if FOLLOW_X_FORWARDED_FOR indirect_client_addr.SetEmpty(); #endif /* FOLLOW_X_FORWARDED_FOR */ #if USE_ADAPTATION adaptHistory_ = NULL; #endif #if ICAP_CLIENT icapHistory_ = NULL; #endif rangeOffsetLimit = -2; //a value of -2 means not checked yet } @@ -446,40 +448,54 @@ request_flags::destinationIPLookedUp() const { return destinationIPLookedUp_; } request_flags request_flags::cloneAdaptationImmune() const { // At the time of writing, all flags where either safe to copy after // adaptation or were not set at the time of the adaptation. If there // are flags that are different, they should be cleared in the clone. return *this; } bool HttpRequest::bodyNibbled() const { return body_pipe != NULL && body_pipe->consumedSize() > 0; } +void +HttpRequest::detailError(err_type aType, int aDetail) +{ + if (errType || errDetail) + debugs(11, 5, HERE << "old error details: " << errType << '/' << errDetail); + debugs(11, 5, HERE << "current error details: " << aType << '/' << aDetail); + // checking type and detail separately may cause inconsistency, but + // may result in more details available if they only become available later + if (!errType) + errType = aType; + if (!errDetail) + errDetail = aDetail; +} + const char *HttpRequest::packableURI(bool full_uri) const { if (full_uri) return urlCanonical((HttpRequest*)this); if (urlpath.size()) return urlpath.termedBuf(); return "/"; } void HttpRequest::packFirstLineInto(Packer * p, bool full_uri) const { // form HTTP request-line packerPrintf(p, "%s %s HTTP/%d.%d\r\n", RequestMethodStr(method), packableURI(full_uri), http_ver.major, http_ver.minor); } @@ -586,40 +602,43 @@ #endif #if USE_SQUID_EUI client_eui48 = aReq->client_eui48; client_eui64 = aReq->client_eui64; #endif my_addr = aReq->my_addr; dnsWait = aReq->dnsWait; #if USE_ADAPTATION adaptHistory_ = aReq->adaptHistory(); #endif #if ICAP_CLIENT icapHistory_ = aReq->icapHistory(); #endif // This may be too conservative for the 204 No Content case // may eventually need cloneNullAdaptationImmune() for that. flags = aReq->flags.cloneAdaptationImmune(); + errType = aReq->errType; + errDetail = aReq->errDetail; + auth_user_request = aReq->auth_user_request; if (aReq->pinned_connection) { pinned_connection = cbdataReference(aReq->pinned_connection); } return true; } void HttpRequest::recordLookup(const DnsLookupDetails &dns) { if (dns.wait >= 0) { // known delay if (dnsWait >= 0) // have recorded DNS wait before dnsWait += dns.wait; else dnsWait = dns.wait; } } int64_t HttpRequest::getRangeOffsetLimit() === modified file 'src/HttpRequest.h' --- src/HttpRequest.h 2010-09-11 23:58:15 +0000 +++ src/HttpRequest.h 2010-10-04 08:01:58 +0000 @@ -109,40 +109,43 @@ debugs(23, 3, "HttpRequest::SetHost() given IP: " << host_addr); host_is_numeric = 1; } }; inline const char* GetHost(void) const { return host; }; inline const int GetHostIsNumeric(void) const { return host_is_numeric; }; #if USE_ADAPTATION /// Returns possibly nil history, creating it if adapt. logging is enabled Adaptation::History::Pointer adaptLogHistory() const; /// Returns possibly nil history, creating it if requested Adaptation::History::Pointer adaptHistory(bool createIfNone = false) const; #endif #if ICAP_CLIENT /// Returns possibly nil history, creating it if icap logging is enabled Adaptation::Icap::History::Pointer icapHistory() const; #endif void recordLookup(const DnsLookupDetails &detail); + /// sets error detail if no earlier detail was available + void detailError(err_type aType, int aDetail); + protected: void clean(); void init(); public: HttpRequestMethod method; char login[MAX_LOGIN_SZ]; private: char host[SQUIDHOSTNAMELEN]; int host_is_numeric; /*** * The client side connection data of pinned connections for the client side * request related objects */ ConnStateData *pinned_connection; @@ -177,40 +180,41 @@ Ip::Address client_addr; #if FOLLOW_X_FORWARDED_FOR Ip::Address indirect_client_addr; #endif /* FOLLOW_X_FORWARDED_FOR */ #if USE_SQUID_EUI /* TODO these might be merged into one field if we can reliably map the EUI-48 into EUI-64 there are some OS differences in the upper bytes. */ Eui::Eui48 client_eui48; Eui::Eui64 client_eui64; #endif Ip::Address my_addr; HierarchyLogEntry hier; int dnsWait; ///< sum of DNS lookup delays in milliseconds, for %dt err_type errType; + int errDetail; ///< errType-specific detail about the transaction error char *peer_login; /* Configured peer login:password */ char *peer_host; /* Selected peer host*/ time_t lastmod; /* Used on refreshes */ const char *vary_headers; /* Used when varying entities are detected. Changes how the store key is calculated */ char *peer_domain; /* Configured peer forceddomain */ String tag; /* Internal tag for this request */ String extacl_user; /* User name returned by extacl lookup */ String extacl_passwd; /* Password returned by extacl lookup */ String extacl_log; /* String to be used for access.log purposes */ String extacl_message; /* String to be used for error page purposes */ === modified file 'src/Makefile.am' --- src/Makefile.am 2010-10-05 11:34:01 +0000 +++ src/Makefile.am 2010-10-11 12:51:58 +0000 @@ -508,40 +508,41 @@ $(SSL_ALL_SOURCE) \ $(WIN32_ALL_SOURCE) \ $(LOADABLE_MODULES_SOURCES) \ DiskIO/DiskThreads/aiops.cc \ DiskIO/DiskThreads/aiops_win32.cc noinst_HEADERS = \ client_side_request.cci \ MemBuf.cci \ MemBuf.h \ Store.cci \ StoreEntryStream.h \ String.cci \ SquidString.h \ SquidTime.h BUILT_SOURCES = \ cf_gen_defines.cci \ cf_parser.cci \ err_type.cc \ + err_detail_type.cc \ globals.cc \ hier_code.cc \ icp_opcode.cc \ lookup_t.cc \ repl_modules.cc \ swap_log_op.cc CLEANFILES += $(BUILT_SOURCES) nodist_squid_SOURCES = \ $(DISKIO_GEN_SOURCE) \ $(BUILT_SOURCES) squid_LDADD = \ $(COMMON_LIBS) \ comm/libcomm-listener.la \ eui/libeui.la \ icmp/libicmp.la icmp/libicmp-core.la \ log/liblog.la \ $(XTRA_OBJS) \ @@ -751,40 +752,43 @@ DEFAULT_LOGFILED = $(libexecdir)/`echo log_file_daemon | sed '$(transform);s/$$/$(EXEEXT)/'` DEFAULT_DISKD = $(libexecdir)/`echo diskd | sed '$(transform);s/$$/$(EXEEXT)/'` DEFAULT_ICON_DIR = $(datadir)/icons DEFAULT_ERROR_DIR = $(datadir)/errors # Make location configure settings available to the code DEFS += -DDEFAULT_CONFIG_FILE=\"$(DEFAULT_CONFIG_FILE)\" -DDEFAULT_SQUID_DATA_DIR=\"$(datadir)\" -DDEFAULT_SQUID_CONFIG_DIR=\"$(sysconfdir)\" snmp_core.o snmp_agent.o: ../snmplib/libsnmp.a $(top_srcdir)/include/cache_snmp.h globals.cc: globals.h mk-globals-c.awk $(AWK) -f $(srcdir)/mk-globals-c.awk < $(srcdir)/globals.h > $@ || ($(RM) -f $@ && exit 1) ## Generate files containing string arrays for various enums.... hier_code.cc: hier_code.h mk-string-arrays.awk $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/hier_code.h > $@ || ($(RM) -f $@ && exit 1) err_type.cc: err_type.h mk-string-arrays.awk $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/err_type.h > $@ || ($(RM) -f $@ && exit 1) +err_detail_type.cc: err_detail_type.h mk-string-arrays.awk + $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/err_detail_type.h | sed 's/ERR_DETAIL_//' > $@ || ($(RM) -f $@ && exit 1) + lookup_t.cc: lookup_t.h mk-string-arrays.awk $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/lookup_t.h > $@ || ($(RM) -f $@ && exit 1) icp_opcode.cc: icp_opcode.h mk-string-arrays.awk $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/icp_opcode.h > $@ || ($(RM) -f $@ && exit 1) swap_log_op.cc: swap_log_op.h mk-string-arrays.awk $(AWK) -f $(srcdir)/mk-string-arrays.awk < $(srcdir)/swap_log_op.h > $@ || ($(RM) -f $@ && exit 1) ## other generated files... cache_diff: cache_diff.o debug.o globals.o store_key_md5.o $(CC) -o $@ $(LDFLAGS) $@.o debug.o globals.o store_key_md5.o $(STD_APP_LIBS) test_cache_digest: test_cache_digest.o CacheDigest.o debug.o globals.o store_key_md5.o $(CC) -o $@ $(LDFLAGS) $@.o CacheDigest.o debug.o globals.o store_key_md5.o $(STD_APP_LIBS) ## If autodependency works well this is not needed anymore cache_cf.o: cf_parser.cci === modified file 'src/Server.cc' --- src/Server.cc 2010-09-11 00:12:53 +0000 +++ src/Server.cc 2010-10-08 09:54:36 +0000 @@ -23,40 +23,41 @@ * * 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. * */ #include "squid.h" #include "base/TextException.h" #include "Server.h" #include "Store.h" #include "fde.h" /* for fd_table[fd].closing */ #include "HttpRequest.h" #include "HttpReply.h" #include "errorpage.h" +#include "err_detail_type.h" #include "SquidTime.h" #if USE_ADAPTATION #include "adaptation/AccessCheck.h" #include "adaptation/Iterator.h" #endif // implemented in client_side_reply.cc until sides have a common parent extern void purgeEntriesByUrl(HttpRequest * req, const char *url); ServerStateData::ServerStateData(FwdState *theFwdState): AsyncJob("ServerStateData"), requestSender(NULL), #if USE_ADAPTATION adaptedHeadSource(NULL), adaptationAccessCheckPending(false), startedAdaptation(false), #endif receivedWholeRequestBody(false) { @@ -749,44 +750,47 @@ completeForwarding(); quitIfAllDone(); } // common part of noteAdaptation*Aborted and noteBodyConsumerAborted methods void ServerStateData::handleAdaptationAborted(bool bypassable) { debugs(11,5, HERE << "handleAdaptationAborted; bypassable: " << bypassable << ", entry empty: " << entry->isEmpty()); if (abortOnBadEntry("entry went bad while ICAP aborted")) return; // TODO: bypass if possible if (entry->isEmpty()) { debugs(11,9, HERE << "creating ICAP error entry after ICAP failure"); ErrorState *err = errorCon(ERR_ICAP_FAILURE, HTTP_INTERNAL_SERVER_ERROR, request); - err->xerrno = errno; + err->xerrno = ERR_DETAIL_ICAP_RESPMOD_EARLY; fwd->fail(err); fwd->dontRetry(true); } + else if (request) { // update logged info directly + request->detailError(ERR_ICAP_FAILURE, ERR_DETAIL_ICAP_RESPMOD_LATE); + } abortTransaction("ICAP failure"); } void ServerStateData::adaptationAclCheckDone(Adaptation::ServiceGroupPointer group) { adaptationAccessCheckPending = false; if (abortOnBadEntry("entry went bad while waiting for ICAP ACL check")) return; // TODO: Should nonICAP and postICAP path check this on the server-side? // That check now only happens on client-side, in processReplyAccess(). if (virginReply()->expectedBodyTooLarge(*request)) { sendBodyIsTooLargeError(); return; } // TODO: Should we check receivedBodyTooLarge on the server-side as well? === modified file 'src/adaptation/icap/ModXact.cc' --- src/adaptation/icap/ModXact.cc 2010-09-14 00:12:15 +0000 +++ src/adaptation/icap/ModXact.cc 2010-10-11 06:40:37 +0000 @@ -3,40 +3,41 @@ */ #include "squid.h" #include "AccessLogEntry.h" #include "adaptation/History.h" #include "adaptation/icap/Client.h" #include "adaptation/icap/Config.h" #include "adaptation/icap/History.h" #include "adaptation/icap/Launcher.h" #include "adaptation/icap/ModXact.h" #include "adaptation/icap/ServiceRep.h" #include "adaptation/Initiator.h" #include "auth/UserRequest.h" #include "base/TextException.h" #include "ChunkedCodingParser.h" #include "comm.h" #include "HttpMsg.h" #include "HttpRequest.h" #include "HttpReply.h" #include "SquidTime.h" +#include "err_detail_type.h" // flow and terminology: // HTTP| --> receive --> encode --> write --> |network // end | <-- send <-- parse <-- read <-- |end // TODO: replace gotEncapsulated() with something faster; we call it often CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, ModXact); CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, ModXactLauncher); static const size_t TheBackupLimit = BodyPipe::MaxCapacity; Adaptation::Icap::ModXact::State::State() { memset(this, 0, sizeof(*this)); } Adaptation::Icap::ModXact::ModXact(HttpMsg *virginHeader, HttpRequest *virginCause, Adaptation::Icap::ServiceRep::Pointer &aService): AsyncJob("Adaptation::Icap::ModXact"), @@ -588,49 +589,59 @@ debugs(93, 7, HERE << "will stop consuming" << status()); stopConsumingFrom(virgin.body_pipe); } void Adaptation::Icap::ModXact::parseMore() { debugs(93, 5, HERE << "have " << readBuf.contentSize() << " bytes to parse" << status()); debugs(93, 5, HERE << "\n" << readBuf.content()); if (state.parsingHeaders()) parseHeaders(); if (state.parsing == State::psBody) parseBody(); } void Adaptation::Icap::ModXact::callException(const std::exception &e) { if (!canStartBypass || isRetriable) { + if (!isRetriable) { + if (const TextException *te = dynamic_cast<const TextException *>(&e)) + detailError(ERR_DETAIL_EXCEPTION_START + te->id()); + else + detailError(ERR_DETAIL_EXCEPTION_OTHER); + } Adaptation::Icap::Xaction::callException(e); return; } try { debugs(93, 3, HERE << "bypassing " << inCall << " exception: " << e.what() << ' ' << status()); bypassFailure(); + } catch (const TextException &bypassTe) { + detailError(ERR_DETAIL_EXCEPTION_START + bypassTe.id()); + Adaptation::Icap::Xaction::callException(bypassTe); } catch (const std::exception &bypassE) { + detailError(ERR_DETAIL_EXCEPTION_OTHER); Adaptation::Icap::Xaction::callException(bypassE); } } void Adaptation::Icap::ModXact::bypassFailure() { disableBypass("already started to bypass", false); Must(!isRetriable); // or we should not be bypassing // TODO: should the same be enforced for isRepeatable? Check icap_repeat?? prepEchoing(); startSending(); // end all activities associated with the ICAP server stopParsing(); stopWriting(true); // or should we force it? @@ -1144,56 +1155,60 @@ if (state.sending == State::sendingVirgin) echoMore(); } // adapted body consumer wants more adapted data and // possibly freed some buffer space void Adaptation::Icap::ModXact::noteMoreBodySpaceAvailable(BodyPipe::Pointer) { if (state.sending == State::sendingVirgin) echoMore(); else if (state.sending == State::sendingAdapted) parseMore(); else Must(state.sending == State::sendingUndecided); } // adapted body consumer aborted void Adaptation::Icap::ModXact::noteBodyConsumerAborted(BodyPipe::Pointer) { + detailError(ERR_DETAIL_ICAP_XACT_BODY_CONSUMER_ABORT); mustStop("adapted body consumer aborted"); } Adaptation::Icap::ModXact::~ModXact() { delete bodyParser; } // internal cleanup void Adaptation::Icap::ModXact::swanSong() { debugs(93, 5, HERE << "swan sings" << status()); stopWriting(false); stopSending(false); + if (theInitiator.set()) // we have not sent the answer to the initiator + detailError(ERR_DETAIL_ICAP_XACT_OTHER); + // update adaptation history if start was called and we reserved a slot Adaptation::History::Pointer ah = virginRequest().adaptLogHistory(); if (ah != NULL && adaptHistoryId >= 0) ah->recordXactFinish(adaptHistoryId); Adaptation::Icap::Xaction::swanSong(); } void prepareLogWithRequestDetails(HttpRequest *, AccessLogEntry *); void Adaptation::Icap::ModXact::finalizeLogInfo() { HttpRequest * request_ = NULL; HttpReply * reply_ = NULL; if (!(request_ = dynamic_cast<HttpRequest*>(adapted.header))) { request_ = (virgin.cause? virgin.cause: dynamic_cast<HttpRequest*>(virgin.header)); reply_ = dynamic_cast<HttpReply*>(adapted.header); } Adaptation::Icap::History::Pointer h = request_->icapHistory(); @@ -1806,40 +1821,47 @@ theWritten += size; Must(theWritten <= theAd); if (wroteEof) theState = stIeof; // written size is irrelevant else if (theWritten >= theAd) theState = stDone; } bool Adaptation::Icap::ModXact::fillVirginHttpHeader(MemBuf &mb) const { if (virgin.header == NULL) return false; virgin.header->firstLineBuf(mb); return true; } +void Adaptation::Icap::ModXact::detailError(int errDetail) +{ + if (HttpRequest *request = virgin.cause ? + virgin.cause : dynamic_cast<HttpRequest*>(virgin.header)) { + request->detailError(ERR_ICAP_FAILURE, errDetail); + } +} /* Adaptation::Icap::ModXactLauncher */ Adaptation::Icap::ModXactLauncher::ModXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, Adaptation::ServicePointer aService): AsyncJob("Adaptation::Icap::ModXactLauncher"), Adaptation::Icap::Launcher("Adaptation::Icap::ModXactLauncher", aService) { virgin.setHeader(virginHeader); virgin.setCause(virginCause); updateHistory(true); } Adaptation::Icap::Xaction *Adaptation::Icap::ModXactLauncher::createXaction() { Adaptation::Icap::ServiceRep::Pointer s = dynamic_cast<Adaptation::Icap::ServiceRep*>(theService.getRaw()); Must(s != NULL); return new Adaptation::Icap::ModXact(virgin.header, virgin.cause, s); } === modified file 'src/adaptation/icap/ModXact.h' --- src/adaptation/icap/ModXact.h 2010-09-13 00:34:44 +0000 +++ src/adaptation/icap/ModXact.h 2010-10-04 09:32:59 +0000 @@ -148,40 +148,43 @@ virtual void noteBodyProductionEnded(BodyPipe::Pointer); virtual void noteBodyProducerAborted(BodyPipe::Pointer); // comm handlers virtual void handleCommConnected(); virtual void handleCommWrote(size_t size); virtual void handleCommRead(size_t size); void handleCommWroteHeaders(); void handleCommWroteBody(); // service waiting void noteServiceReady(); public: InOut virgin; InOut adapted; // bypasses exceptions if needed and possible virtual void callException(const std::exception &e); + /// record error detail in the virgin request if possible + virtual void detailError(int errDetail); + private: virtual void start(); /// locates the request, either as a cause or as a virgin message itself const HttpRequest &virginRequest() const; // Must always be available void estimateVirginBody(); void makeAdaptedBodyPipe(const char *what); void waitForService(); // will not send anything [else] on the adapted pipe bool doneSending() const; void startWriting(); void writeMore(); void writePreviewBody(); void writePrimeBody(); void writeSomeBody(const char *label, size_t size); void decideWritingAfterPreview(const char *previewKind); === modified file 'src/adaptation/icap/Xaction.cc' --- src/adaptation/icap/Xaction.cc 2010-10-04 14:52:38 +0000 +++ src/adaptation/icap/Xaction.cc 2010-10-11 12:51:58 +0000 @@ -1,40 +1,41 @@ /* * DEBUG: section 93 ICAP (RFC 3507) Client */ #include "squid.h" #include "comm.h" #include "CommCalls.h" #include "HttpMsg.h" #include "adaptation/icap/Xaction.h" #include "adaptation/icap/Launcher.h" #include "adaptation/icap/Config.h" #include "base/TextException.h" #include "pconn.h" #include "HttpRequest.h" #include "HttpReply.h" #include "ip/tools.h" #include "acl/FilledChecklist.h" #include "icap_log.h" #include "fde.h" #include "SquidTime.h" +#include "err_detail_type.h" static PconnPool *icapPconnPool = new PconnPool("ICAP Servers"); //CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, Xaction); Adaptation::Icap::Xaction::Xaction(const char *aTypeName, Adaptation::Icap::ServiceRep::Pointer &aService): AsyncJob(aTypeName), Adaptation::Initiate(aTypeName), icapRequest(NULL), icapReply(NULL), attempts(0), connection(-1), theService(aService), commBuf(NULL), commBufSize(0), commEof(false), reuseConnection(true), isRetriable(true), isRepeatable(true), @@ -208,40 +209,41 @@ } // connection with the ICAP service established void Adaptation::Icap::Xaction::noteCommConnected(const CommConnectCbParams &io) { Must(connector != NULL); connector = NULL; if (io.flag != COMM_OK) dieOnConnectionFailure(); // throws fd_table[connection].noteUse(icapPconnPool); handleCommConnected(); } void Adaptation::Icap::Xaction::dieOnConnectionFailure() { debugs(93, 2, HERE << typeName << " failed to connect to " << service().cfg().uri); + detailError(ERR_DETAIL_ICAP_XACT_START); throw TexcHere("cannot connect to the ICAP service"); } void Adaptation::Icap::Xaction::scheduleWrite(MemBuf &buf) { // comm module will free the buffer typedef CommCbMemFunT<Adaptation::Icap::Xaction, CommIoCbParams> Dialer; writer = JobCallback(93,3, Dialer, this, Adaptation::Icap::Xaction::noteCommWrote); comm_write_mbuf(connection, &buf, writer); updateTimeout(); } void Adaptation::Icap::Xaction::noteCommWrote(const CommIoCbParams &io) { Must(writer != NULL); writer = NULL; if (ignoreLastWrite) { @@ -267,40 +269,41 @@ debugs(93, 2, HERE << typeName << " failed: timeout with " << theService->cfg().methodStr() << " " << theService->cfg().uri << status()); reuseConnection = false; const bool whileConnecting = connector != NULL; closeConnection(); // so that late Comm callbacks do not disturb bypass throw TexcHere(whileConnecting ? "timed out while connecting to the ICAP service" : "timed out while talking to the ICAP service"); } // unexpected connection close while talking to the ICAP service void Adaptation::Icap::Xaction::noteCommClosed(const CommCloseCbParams &io) { closer = NULL; handleCommClosed(); } void Adaptation::Icap::Xaction::handleCommClosed() { + detailError(ERR_DETAIL_ICAP_XACT_CLOSE); mustStop("ICAP service connection externally closed"); } void Adaptation::Icap::Xaction::callException(const std::exception &e) { setOutcome(xoError); service().noteFailure(); Adaptation::Initiate::callException(e); } void Adaptation::Icap::Xaction::callEnd() { if (doneWithIo()) { debugs(93, 5, HERE << typeName << " done with I/O" << status()); closeConnection(); } Adaptation::Initiate::callEnd(); // may destroy us } @@ -424,40 +427,41 @@ } bool Adaptation::Icap::Xaction::doneWriting() const { return !writer; } bool Adaptation::Icap::Xaction::doneWithIo() const { return connection >= 0 && // or we could still be waiting to open it !connector && !reader && !writer && // fast checks, some redundant doneReading() && doneWriting(); } // initiator aborted void Adaptation::Icap::Xaction::noteInitiatorAborted() { if (theInitiator.set()) { clearInitiator(); + detailError(ERR_DETAIL_ICAP_INIT_GONE); mustStop("initiator aborted"); } } void Adaptation::Icap::Xaction::setOutcome(const Adaptation::Icap::XactOutcome &xo) { if (al.icap.outcome != xoUnknown) { debugs(93, 3, HERE << "Warning: reseting outcome: from " << al.icap.outcome << " to " << xo); } else { debugs(93, 4, HERE << xo); } al.icap.outcome = xo; } // This 'last chance' method is called before a 'done' transaction is deleted. // It is wrong to call virtual methods from a destructor. Besides, this call // indicates that the transaction will terminate as planned. void Adaptation::Icap::Xaction::swanSong() === modified file 'src/adaptation/icap/Xaction.h' --- src/adaptation/icap/Xaction.h 2010-09-11 23:59:07 +0000 +++ src/adaptation/icap/Xaction.h 2010-10-04 09:54:51 +0000 @@ -79,40 +79,43 @@ void noteCommClosed(const CommCloseCbParams &io); // TODO: create these only when actually sending/receiving HttpRequest *icapRequest; ///< sent (or at least created) ICAP request HttpReply::Pointer icapReply; ///< received ICAP reply, if any /// the number of times we tried to get to the service, including this time int attempts; protected: virtual void start(); virtual void noteInitiatorAborted(); // TODO: move to Adaptation::Initiate // comm hanndlers; called by comm handler wrappers virtual void handleCommConnected() = 0; virtual void handleCommWrote(size_t sz) = 0; virtual void handleCommRead(size_t sz) = 0; virtual void handleCommTimedout(); virtual void handleCommClosed(); + /// record error detail if possible + virtual void detailError(int errDetail) {} + void openConnection(); void closeConnection(); void dieOnConnectionFailure(); void scheduleRead(); void scheduleWrite(MemBuf &buf); void updateTimeout(); void cancelRead(); bool parseHttpMsg(HttpMsg *msg); // true=success; false=needMore; throw=err bool mayReadMore() const; virtual bool doneReading() const; virtual bool doneWriting() const; bool doneWithIo() const; virtual bool doneAll() const; // called just before the 'done' transaction is deleted virtual void swanSong(); === modified file 'src/base/TextException.cc' --- src/base/TextException.cc 2010-03-20 01:53:34 +0000 +++ src/base/TextException.cc 2010-10-19 13:41:42 +0000 @@ -1,58 +1,85 @@ -#include "config.h" +#include "squid.h" #include "base/TextException.h" #include "Debug.h" #include "util.h" TextException::TextException() { message=NULL; theFileName=NULL; theLineNo=0; + theId=0; } TextException::TextException(const TextException& right) : - message((right.message?xstrdup(right.message):NULL)), theFileName(right.theFileName), theLineNo(right.theLineNo) + message((right.message?xstrdup(right.message):NULL)), theFileName(right.theFileName), theLineNo(right.theLineNo), theId(right.theId) { } -TextException::TextException(const char *aMsg, const char *aFileName, int aLineNo): - message(xstrdup(aMsg)), theFileName(aFileName), theLineNo(aLineNo) +TextException::TextException(const char *aMsg, const char *aFileName, int aLineNo, unsigned int anId): + message(xstrdup(aMsg)), theFileName(aFileName), theLineNo(aLineNo), theId(anId) {} TextException::~TextException() throw() { if (message) xfree(message); } TextException& TextException::operator=(const TextException &right) { if (this==&right) return *this; if (message) xfree(message); message=(right.message?xstrdup(right.message):NULL); theFileName=right.theFileName; theLineNo=right.theLineNo; - + theId=right.theId; return *this; } const char *TextException::what() const throw() { /// \todo add file:lineno return message ? message : "TextException without a message"; } -void Throw(const char *message, const char *fileName, int lineNo) +unsigned int TextException::FileNameHash(const char *fname) +{ + const char *s = NULL; + unsigned int n = 0; + unsigned int j = 0; + unsigned int i = 0; + s = strrchr(fname, '/'); + + if (s) + s++; + else + s = fname; + + while (*s) { + j++; + n ^= 271 * (unsigned) *s++; + } + i = n ^ (j * 271); + /*18bits of a 32 bit integer used for filename hash (max hash=262143), + and 14 bits for storing line number (16k max). + If you change this policy remember to update the FileNameHash function + in the scripts/calc-must-ids.pl script + */ + return i % 262143; +} + +void Throw(const char *message, const char *fileName, int lineNo, unsigned int id) { // or should we let the exception recepient print the exception instead? if (fileName) { debugs(0, 3, fileName << ':' << lineNo << ": exception" << (message ? ": " : ".") << (message ? message : "")); } else { debugs(0, 3, "exception" << (message ? ": " : ".") << (message ? message : "")); } - throw TextException(message, fileName, lineNo); + throw TextException(message, fileName, lineNo, id); } === modified file 'src/base/TextException.h' --- src/base/TextException.h 2010-03-20 01:53:34 +0000 +++ src/base/TextException.h 2010-10-19 13:32:38 +0000 @@ -1,52 +1,84 @@ #ifndef SQUID__TEXTEXCEPTION_H #define SQUID__TEXTEXCEPTION_H // Origin: xstd/TextException #include "config.h" #include <exception> +static unsigned int FileNameHashCached(const char *fname); + // simple exception to report custom errors // we may want to change the interface to be able to report system errors class TextException: public std::exception { public: TextException(); - TextException(const char *aMessage, const char *aFileName = 0, int aLineNo = -1); + TextException(const char *aMessage, const char *aFileName = 0, int aLineNo = -1, unsigned int anId =0); TextException(const TextException& right); virtual ~TextException() throw(); + // unique exception ID for transaction error detail logging + unsigned int id() const { return theId; } + virtual const char *what() const throw(); TextException& operator=(const TextException &right); public: char *message; // read-only protected: + /// a small integer hash value to semi-uniquely identify the source file + static unsigned int FileNameHash(const char *fname); + // optional location information const char *theFileName; int theLineNo; + unsigned int theId; + + friend unsigned int FileNameHashCached(const char *fname); }; //inline //ostream &operator <<(ostream &os, const TextException &exx) { // return exx.print(os); //} +/// caches the result of FileNameHash() for each translation unit +static unsigned int +FileNameHashCached(const char *fname) +{ + static const char *lastFname = 0; + static int lastHash = 0; + // __FILE__ changes when we #include files + if (lastFname != fname) { // cheap pointer comparison + lastFname = fname; + lastHash = TextException::FileNameHash(fname); + } + return lastHash; +} + +/// Avoids "defined but not used" warnings for FileNameHashCached +class FileNameHashCacheUser { + bool use(void *ptr=NULL) { return ptr != &FileNameHashCached;} +}; + #if !defined(TexcHere) -# define TexcHere(msg) TextException((msg), __FILE__, __LINE__) +# define TexcHere(msg) TextException((msg), __FILE__, __LINE__, \ + (FileNameHashCached(__FILE__)<<14) | (__LINE__ & 0x3FFF)) #endif -extern void Throw(const char *message, const char *fileName, int lineNo); +extern void Throw(const char *message, const char *fileName, int lineNo, unsigned int id); // Must(condition) is like assert(condition) but throws an exception instead #if !defined(Must) # define Must(cond) ((cond) ? \ (void)0 : \ - (void)Throw(#cond, __FILE__, __LINE__)) + (void)Throw(#cond, __FILE__, __LINE__, \ + (FileNameHashCached(__FILE__)<<14) | (__LINE__ & 0x3FFF))) #endif #endif /* SQUID__TEXTEXCEPTION_H */ === modified file 'src/cf.data.pre' --- src/cf.data.pre 2010-10-06 03:50:45 +0000 +++ src/cf.data.pre 2010-10-11 12:51:58 +0000 @@ -2704,40 +2704,43 @@ Format codes: % a literal % character >a Client source IP address >A Client FQDN >p Client source port <A Server IP address or peer name la Local IP address (http_port) lp Local port number (http_port) <lp Local port number of the last server or peer connection sn Unique sequence number per log line entry ts Seconds since epoch tu subsecond time (milliseconds) tl Local time. Optional strftime format argument default %d/%b/%Y:%H:%M:%S %z tg GMT time. Optional strftime format argument default %d/%b/%Y:%H:%M:%S %z tr Response time (milliseconds) dt Total time spent making DNS lookups (milliseconds) + 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. HTTP cache related format codes: [http::]>h Original request header. Optional header name argument on the format header[:[separator]element] [http::]>ha The HTTP request headers after adaptation and redirection. Optional header name argument as for >h [http::]<h Reply header. Optional header name argument as for >h [http::]un User name [http::]ul User name from authentication [http::]ui User name from ident [http::]us User name from SSL [http::]ue User name from external acl helper [http::]>Hs HTTP status code sent to the client [http::]<Hs HTTP status code received from the next hop [http::]<bs Number of HTTP-equivalent message body bytes received from the next hop, excluding chunked transfer encoding and control messages. Generated FTP/Gopher listings are treated as === modified file 'src/client_side.cc' --- src/client_side.cc 2010-10-01 00:41:19 +0000 +++ src/client_side.cc 2010-10-06 15:44:46 +0000 @@ -568,40 +568,45 @@ #if ICAP_CLIENT if (ih != NULL) aLogEntry->icap.processingTime = ih->processingTime(); #endif aLogEntry->http.method = request->method; aLogEntry->http.version = request->http_ver; aLogEntry->hier = request->hier; if (request->content_length > 0) // negative when no body or unknown length aLogEntry->cache.requestSize += request->content_length; aLogEntry->cache.extuser = request->extacl_user.termedBuf(); if (request->auth_user_request != NULL) { if (request->auth_user_request->username()) aLogEntry->cache.authuser = xstrdup(request->auth_user_request->username()); // WTF?? request->auth_user_request = NULL; } + + if (aLogEntry->request) { + aLogEntry->request->errType = request->errType; + aLogEntry->request->errDetail = request->errDetail; + } } void ClientHttpRequest::logRequest() { if (out.size || logType) { al.icp.opcode = ICP_INVALID; al.url = log_uri; debugs(33, 9, "clientLogRequest: al.url='" << al.url << "'"); if (al.reply) { al.http.code = al.reply->sline.status; al.http.content_type = al.reply->content_type.termedBuf(); } else if (loggingEntry() && loggingEntry()->mem_obj) { al.http.code = loggingEntry()->mem_obj->getReply()->sline.status; al.http.content_type = loggingEntry()->mem_obj->getReply()->content_type.termedBuf(); } debugs(33, 9, "clientLogRequest: http.code='" << al.http.code << "'"); === modified file 'src/client_side_request.cc' --- src/client_side_request.cc 2010-10-06 03:50:45 +0000 +++ src/client_side_request.cc 2010-10-11 12:51:58 +0000 @@ -52,40 +52,41 @@ #if ICAP_CLIENT #include "adaptation/icap/History.h" #endif #endif #include "auth/UserRequest.h" #include "clientStream.h" #include "client_side.h" #include "client_side_reply.h" #include "client_side_request.h" #include "ClientRequestContext.h" #include "compat/inet_pton.h" #include "fde.h" #include "HttpReply.h" #include "HttpRequest.h" #include "ip/QosConfig.h" #include "MemObject.h" #include "ProtoPort.h" #include "Store.h" #include "SquidTime.h" #include "wordlist.h" +#include "err_detail_type.h" #if LINGERING_CLOSE #define comm_close comm_lingering_close #endif static const char *const crlf = "\r\n"; #if FOLLOW_X_FORWARDED_FOR static void clientFollowXForwardedForCheck(int answer, void *data); #endif /* FOLLOW_X_FORWARDED_FOR */ CBDATA_CLASS_INIT(ClientRequestContext); void * ClientRequestContext::operator new (size_t size) { assert (size == sizeof(ClientRequestContext)); CBDATA_INIT_TYPE(ClientRequestContext); @@ -1438,41 +1439,41 @@ storeEntry()->replaceHttpReply(new_rep); storeEntry()->timestampsSet(); if (!adaptedBodySource) // no body storeEntry()->complete(); clientGetMoreData(node, this); } // we are done with getting headers (but may be receiving body) clearAdaptation(virginHeadSource); if (!request_satisfaction_mode) doCallouts(); } void ClientHttpRequest::noteAdaptationQueryAbort(bool final) { clearAdaptation(virginHeadSource); assert(!adaptedBodySource); - handleAdaptationFailure(!final); + handleAdaptationFailure(ERR_DETAIL_ICAP_REQMOD_ABORT, !final); } void ClientHttpRequest::noteMoreBodyDataAvailable(BodyPipe::Pointer) { assert(request_satisfaction_mode); assert(adaptedBodySource != NULL); if (const size_t contentSize = adaptedBodySource->buf().contentSize()) { BodyPipeCheckout bpc(*adaptedBodySource); const StoreIOBuffer ioBuf(&bpc.buf, request_satisfaction_offset); storeEntry()->write(ioBuf); // assume can write everything request_satisfaction_offset += contentSize; bpc.buf.consume(contentSize); bpc.checkIn(); } if (adaptedBodySource->exhausted()) endRequestSatisfaction(); @@ -1491,62 +1492,64 @@ endRequestSatisfaction(); } } void ClientHttpRequest::endRequestSatisfaction() { debugs(85,4, HERE << this << " ends request satisfaction"); assert(request_satisfaction_mode); stopConsumingFrom(adaptedBodySource); // TODO: anything else needed to end store entry formation correctly? storeEntry()->complete(); } void ClientHttpRequest::noteBodyProducerAborted(BodyPipe::Pointer) { assert(!virginHeadSource); stopConsumingFrom(adaptedBodySource); - handleAdaptationFailure(); + handleAdaptationFailure(ERR_DETAIL_ICAP_RESPMOD_CLT_SIDE_BODY); } void -ClientHttpRequest::handleAdaptationFailure(bool bypassable) +ClientHttpRequest::handleAdaptationFailure(int errDetail, bool bypassable) { debugs(85,3, HERE << "handleAdaptationFailure(" << bypassable << ")"); const bool usedStore = storeEntry() && !storeEntry()->isEmpty(); const bool usedPipe = request->body_pipe != NULL && request->body_pipe->consumedSize() > 0; if (bypassable && !usedStore && !usedPipe) { debugs(85,3, HERE << "ICAP REQMOD callout failed, bypassing: " << calloutContext); if (calloutContext) doCallouts(); return; } debugs(85,3, HERE << "ICAP REQMOD callout failed, responding with error"); clientStreamNode *node = (clientStreamNode *)client_stream.tail->prev->data; clientReplyContext *repContext = dynamic_cast<clientReplyContext *>(node->data.getRaw()); assert(repContext); // The original author of the code also wanted to pass an errno to // setReplyToError, but it seems unlikely that the errno reflects the // true cause of the error at this point, so I did not pass it. Ip::Address noAddr; noAddr.SetNoAddr(); ConnStateData * c = getConn(); repContext->setReplyToError(ERR_ICAP_FAILURE, HTTP_INTERNAL_SERVER_ERROR, request->method, NULL, (c != NULL ? c->peer : noAddr), request, NULL, (c != NULL && c->auth_user_request != NULL ? c->auth_user_request : request->auth_user_request)); + request->detailError(ERR_ICAP_FAILURE, errDetail); + node = (clientStreamNode *)client_stream.tail->data; clientStreamRead(node, this, node->readBuffer); } #endif === modified file 'src/client_side_request.h' --- src/client_side_request.h 2010-08-23 23:15:26 +0000 +++ src/client_side_request.h 2010-10-06 08:54:38 +0000 @@ -145,41 +145,41 @@ private: CBDATA_CLASS(ClientHttpRequest); int64_t maxReplyBodySize_; StoreEntry *entry_; StoreEntry *loggingEntry_; ConnStateData * conn_; #if USE_SSL public: bool sslBumpNeeded() const; void sslBumpStart(); void sslBumpEstablish(comm_err_t errflag); #endif #if USE_ADAPTATION public: void startAdaptation(const Adaptation::ServiceGroupPointer &g); // private but exposed for ClientRequestContext - void handleAdaptationFailure(bool bypassable = false); + void handleAdaptationFailure(int errDetail, bool bypassable = false); private: // Adaptation::Initiator API virtual void noteAdaptationAnswer(HttpMsg *message); virtual void noteAdaptationQueryAbort(bool final); // BodyConsumer API, called by BodyPipe virtual void noteMoreBodyDataAvailable(BodyPipe::Pointer); virtual void noteBodyProductionEnded(BodyPipe::Pointer); virtual void noteBodyProducerAborted(BodyPipe::Pointer); void endRequestSatisfaction(); private: CbcPointer<Adaptation::Initiate> virginHeadSource; BodyPipe::Pointer adaptedBodySource; bool request_satisfaction_mode; int64_t request_satisfaction_offset; #endif === added file 'src/err_detail_type.h' --- src/err_detail_type.h 1970-01-01 00:00:00 +0000 +++ src/err_detail_type.h 2010-10-18 20:34:04 +0000 @@ -0,0 +1,37 @@ +#ifndef _SQUID_ERR_DETAIL_H +#define _SQUID_ERR_DETAIL_H + +typedef enum { + ERR_DETAIL_NONE, + ERR_DETAIL_START = 100000, // to avoid clashes with most OS error numbers + ERR_DETAIL_ICAP_REQMOD_ABORT = ERR_DETAIL_START, // transaction abort + ERR_DETAIL_ICAP_RESPMOD_CLT_SIDE_BODY, // client-side detected body abort + ERR_DETAIL_ICAP_RESPMOD_EARLY, // RESPMOD failed w/o store entry + ERR_DETAIL_ICAP_RESPMOD_LATE, // RESPMOD failed with a store entry + ERR_DETAIL_ICAP_XACT_START, // transaction start failure + ERR_DETAIL_ICAP_XACT_BODY_CONSUMER_ABORT, // transaction body consumer gone + ERR_DETAIL_ICAP_INIT_GONE, // initiator gone + ERR_DETAIL_ICAP_XACT_CLOSE, // ICAP connection closed unexpectedly + ERR_DETAIL_ICAP_XACT_OTHER, // other ICAP transaction errors + ERR_DETAIL_EXCEPTION_OTHER, //other errors ( eg std C++ lib errors) + ERR_DETAIL_MAX, + ERR_DETAIL_EXCEPTION_START = 110000 // offset for exception ID details +} err_detail_type; + +extern const char *err_detail_type_str[]; + +inline +const char *errorDetailName(int errDetailId) { + if (errDetailId < ERR_DETAIL_START) + return "SYSERR"; + + if (errDetailId < ERR_DETAIL_MAX) + return err_detail_type_str[errDetailId-ERR_DETAIL_START+2]; + + if (errDetailId >=ERR_DETAIL_EXCEPTION_START) + return "EXCEPTION"; + + return "UNKNOWN"; +} + +#endif === modified file 'src/errorpage.cc' --- src/errorpage.cc 2010-09-20 19:00:02 +0000 +++ src/errorpage.cc 2010-10-08 09:51:47 +0000 @@ -28,40 +28,41 @@ * * 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. * */ #include "config.h" #include "errorpage.h" #include "auth/UserRequest.h" #include "SquidTime.h" #include "Store.h" #include "HttpReply.h" #include "HttpRequest.h" #include "MemObject.h" #include "fde.h" #include "MemBuf.h" #include "rfc1738.h" #include "URLScheme.h" #include "wordlist.h" +#include "err_detail_type.h" /** \defgroup ErrorPageInternal Error Page Internals \ingroup ErrorPageAPI * \section Abstract Abstract: * These routines are used to generate error messages to be * sent to clients. The error type is used to select between * the various message formats. (formats are stored in the * Config.errorDirectory) */ #ifndef DEFAULT_SQUID_ERROR_DIR /** Where to look for errors if config path fails. \note Please use ./configure --datadir=/path instead of patching */ #define DEFAULT_SQUID_ERROR_DIR DEFAULT_SQUID_DATA_DIR"/errors" #endif @@ -351,64 +352,65 @@ return ERR_NONE; } err_type errorReservePageId(const char *page_name) { ErrorDynamicPageInfo *info; int id = errorPageId(page_name); if (id == ERR_NONE) { info = errorDynamicPageInfoCreate(ERR_MAX + ErrorDynamicPages.size(), page_name); ErrorDynamicPages.push_back(info); id = info->id; } return (err_type)id; } /// \ingroup ErrorPageInternal -static const char * +const char * errorPageName(int pageId) { if (pageId >= ERR_NONE && pageId < ERR_MAX) /* common case */ return err_type_str[pageId]; if (pageId >= ERR_MAX && pageId - ERR_MAX < (ssize_t)ErrorDynamicPages.size()) return ErrorDynamicPages.items[pageId - ERR_MAX]->page_name; return "ERR_UNKNOWN"; /* should not happen */ } ErrorState * errorCon(err_type type, http_status status, HttpRequest * request) { ErrorState *err = new ErrorState; err->page_id = type; /* has to be reset manually if needed */ err->err_language = NULL; err->type = type; err->httpStatus = status; if (request != NULL) { err->request = HTTPMSGLOCK(request); err->src_addr = request->client_addr; + request->detailError(type, ERR_DETAIL_NONE); } return err; } void errorAppendEntry(StoreEntry * entry, ErrorState * err) { assert(entry->mem_obj != NULL); assert (entry->isEmpty()); debugs(4, 4, "Creating an error page for entry " << entry << " with errorstate " << err << " page id " << err->page_id); if (entry->store_status != STORE_PENDING) { debugs(4, 2, "Skipping error page due to store_status: " << entry->store_status); /* * If the entry is not STORE_PENDING, then no clients * care about it, and we don't need to generate an * error message @@ -433,41 +435,41 @@ entry->flush(); entry->complete(); entry->negativeCache(); entry->releaseRequest(); entry->unlock(); errorStateFree(err); } void errorSend(int fd, ErrorState * err) { HttpReply *rep; debugs(4, 3, "errorSend: FD " << fd << ", err=" << err); assert(fd >= 0); /* * ugh, this is how we make sure error codes get back to * the client side for logging and error tracking. */ if (err->request) - err->request->errType = err->type; + err->request->detailError(err->type, err->xerrno); /* moved in front of errorBuildBuf @?@ */ err->flags.flag_cbdata = 1; rep = err->BuildHttpReply(); MemBuf *mb = rep->pack(); comm_write_mbuf(fd, mb, errorSendComplete, err); delete mb; delete rep; } /** \ingroup ErrorPageAPI * * Called by commHandleWrite() after data has been written * to the client socket. * \note If there is a callback, the callback is responsible for === modified file 'src/errorpage.h' --- src/errorpage.h 2010-06-27 08:41:35 +0000 +++ src/errorpage.h 2010-10-04 08:01:58 +0000 @@ -208,22 +208,23 @@ * cannot assume that we can immediately write to the socket * for an error. * \param entry ?? \param err This object is destroyed after use in this function. */ SQUIDCEXTERN void errorAppendEntry(StoreEntry *entry, ErrorState *err); /// \ingroup ErrorPageAPI SQUIDCEXTERN void errorStateFree(ErrorState * err); /// \ingroup ErrorPageAPI SQUIDCEXTERN err_type errorReservePageId(const char *page_name); /** \ingroup ErrorPageAPI * * This function creates a ErrorState object. */ SQUIDCEXTERN ErrorState *errorCon(err_type type, http_status, HttpRequest * request); +SQUIDCEXTERN const char *errorPageName(int pageId); ///< error ID to string #endif /* SQUID_ERRORPAGE_H */ === modified file 'src/forward.cc' --- src/forward.cc 2010-10-06 03:50:45 +0000 +++ src/forward.cc 2010-10-11 12:51:58 +0000 @@ -273,40 +273,42 @@ fwd->start(fwd); return; } /* NOTREACHED */ } void FwdState::fail(ErrorState * errorState) { debugs(17, 3, HERE << err_type_str[errorState->type] << " \"" << httpStatusString(errorState->httpStatus) << "\"\n\t" << entry->url() ); if (err) errorStateFree(err); err = errorState; if (!errorState->request) errorState->request = HTTPMSGLOCK(request); + + request->detailError(errorState->type, errorState->xerrno); } /** * Frees fwdState without closing FD or generating an abort */ void FwdState::unregister(int fd) { debugs(17, 3, HERE << entry->url() ); assert(fd == server_fd); assert(fd > -1); comm_remove_close_handler(fd, fwdServerClosedWrapper, this); server_fd = -1; } /** * server-side modules call fwdComplete() when they are done * downloading an object. Then, we either 1) re-forward the * request somewhere else if needed, or 2) call storeComplete() * to finish it off === modified file 'src/ftp.cc' --- src/ftp.cc 2010-10-09 11:20:12 +0000 +++ src/ftp.cc 2010-10-11 12:51:58 +0000 @@ -3620,40 +3620,43 @@ int code = ftpState->ctrl.replycode; http_status http_code; err_type err_code = ERR_NONE; debugs(9, 3, HERE << ftpState->entry->url() << ", code " << code); if (cbdataReferenceValid(ftpState)) debugs(9, 5, HERE << "ftpState (" << ftpState << ") is valid!"); if (code == 226 || code == 250) { err_code = (ftpState->mdtm > 0) ? ERR_FTP_PUT_MODIFIED : ERR_FTP_PUT_CREATED; http_code = (ftpState->mdtm > 0) ? HTTP_ACCEPTED : HTTP_CREATED; } else if (code == 227) { err_code = ERR_FTP_PUT_CREATED; http_code = HTTP_CREATED; } else { err_code = ERR_FTP_PUT_ERROR; http_code = HTTP_INTERNAL_SERVER_ERROR; } + if (ftpState->request) + ftpState->request->detailError(err_code, code); + err = errorCon(err_code, http_code, ftpState->request); if (ftpState->old_request) err->ftp.request = xstrdup(ftpState->old_request); else err->ftp.request = xstrdup(ftpState->ctrl.last_command); if (ftpState->old_reply) err->ftp.reply = xstrdup(ftpState->old_reply); else if (ftpState->ctrl.last_reply) err->ftp.reply = xstrdup(ftpState->ctrl.last_reply); else err->ftp.reply = xstrdup(""); ftpState->entry->replaceHttpReply( err->BuildHttpReply() ); errorStateFree(err); ftpSendQuit(ftpState); } === modified file 'src/http.cc' --- src/http.cc 2010-10-04 15:44:32 +0000 +++ src/http.cc 2010-10-11 12:51:58 +0000 @@ -2285,40 +2285,48 @@ if (flags.headers_parsed && !flags.abuse_detected) { flags.abuse_detected = 1; debugs(11, 1, "http handleMoreRequestBodyAvailable: Likely proxy abuse detected '" << orig_request->client_addr << "' -> '" << entry->url() << "'" ); if (virginReply()->sline.status == HTTP_INVALID_HEADER) { comm_close(fd); return; } } } HttpStateData::handleMoreRequestBodyAvailable(); } // premature end of the request body void HttpStateData::handleRequestBodyProducerAborted() { ServerStateData::handleRequestBodyProducerAborted(); + if (entry->isEmpty()) { + debugs(11, 3, "request body aborted: FD " << fd); + ErrorState *err; + err = errorCon(ERR_READ_ERROR, HTTP_BAD_GATEWAY, fwd->request); + err->xerrno = errno; + fwd->fail(err); + } + abortTransaction("request body producer aborted"); } // called when we wrote request headers(!) or a part of the body void HttpStateData::sentRequestBody(const CommIoCbParams &io) { if (io.size > 0) kb_incr(&statCounter.server.http.kbytes_out, io.size); ServerStateData::sentRequestBody(io); } // Quickly abort the transaction // TODO: destruction should be sufficient as the destructor should cleanup, // including canceling close handlers void HttpStateData::abortTransaction(const char *reason) { debugs(11,5, HERE << "aborting transaction for " << reason << === modified file 'src/log/access_log.cc' --- src/log/access_log.cc 2010-09-28 15:20:36 +0000 +++ src/log/access_log.cc 2010-10-18 20:40:38 +0000 @@ -22,40 +22,42 @@ * (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. * */ #include "squid.h" #include "AccessLogEntry.h" // Store.h Required by configuration directives parsing/dumping only #include "Store.h" +#include "errorpage.h" +#include "err_detail_type.h" #include "acl/Checklist.h" #include "CacheManager.h" #if USE_SQUID_EUI #include "eui/Eui48.h" #include "eui/Eui64.h" #endif #include "hier_code.h" #include "HttpReply.h" #include "HttpRequest.h" #include "log/File.h" #include "MemBuf.h" #include "rfc1738.h" #include "SquidTime.h" static void accessLogSquid(AccessLogEntry * al, Logfile * logfile); static void accessLogCommon(AccessLogEntry * al, Logfile * logfile); static void accessLogCustom(AccessLogEntry * al, customlog * log); #if HEADERS_LOG static Logfile *headerslog = NULL; #endif @@ -366,41 +368,42 @@ LFT_ADAPTED_REQUEST_ALL_HEADERS, LFT_REPLY_HEADER, LFT_REPLY_HEADER_ELEM, LFT_REPLY_ALL_HEADERS, LFT_USER_NAME, LFT_USER_LOGIN, LFT_USER_IDENT, /*LFT_USER_REALM, */ /*LFT_USER_SCHEME, */ LFT_USER_EXTERNAL, LFT_HTTP_SENT_STATUS_CODE_OLD_30, LFT_HTTP_SENT_STATUS_CODE, LFT_HTTP_RECEIVED_STATUS_CODE, /*LFT_HTTP_STATUS, */ LFT_HTTP_BODY_BYTES_READ, LFT_SQUID_STATUS, - /*LFT_SQUID_ERROR, */ + LFT_SQUID_ERROR, + LFT_SQUID_ERROR_DETAIL, LFT_SQUID_HIERARCHY, LFT_MIME_TYPE, LFT_REQUEST_METHOD, LFT_REQUEST_URI, LFT_REQUEST_URLPATH, /*LFT_REQUEST_QUERY, * // * this is not needed. see strip_query_terms */ LFT_REQUEST_VERSION, LFT_REQUEST_SIZE_TOTAL, /*LFT_REQUEST_SIZE_LINE, */ LFT_REQUEST_SIZE_HEADERS, /*LFT_REQUEST_SIZE_BODY, */ /*LFT_REQUEST_SIZE_BODY_NO_TE, */ LFT_REPLY_SIZE_TOTAL, LFT_REPLY_HIGHOFFSET, LFT_REPLY_OBJECTSIZE, /*LFT_REPLY_SIZE_LINE, */ @@ -525,41 +528,42 @@ {">ha", LFT_ADAPTED_REQUEST_ALL_HEADERS}, {">h", LFT_REQUEST_HEADER}, {">h", LFT_REQUEST_ALL_HEADERS}, {"<h", LFT_REPLY_HEADER}, {"<h", LFT_REPLY_ALL_HEADERS}, {"un", LFT_USER_NAME}, {"ul", LFT_USER_LOGIN}, /*{ "ur", LFT_USER_REALM }, */ /*{ "us", LFT_USER_SCHEME }, */ {"ui", LFT_USER_IDENT}, {"ue", LFT_USER_EXTERNAL}, {"Hs", LFT_HTTP_SENT_STATUS_CODE_OLD_30}, {">Hs", LFT_HTTP_SENT_STATUS_CODE}, {"<Hs", LFT_HTTP_RECEIVED_STATUS_CODE}, /*{ "Ht", LFT_HTTP_STATUS }, */ {"<bs", LFT_HTTP_BODY_BYTES_READ}, {"Ss", LFT_SQUID_STATUS}, - /*{ "Se", LFT_SQUID_ERROR }, */ + { "err_code", LFT_SQUID_ERROR }, + { "err_detail", LFT_SQUID_ERROR_DETAIL }, {"Sh", LFT_SQUID_HIERARCHY}, {"mt", LFT_MIME_TYPE}, {"rm", LFT_REQUEST_METHOD}, {"ru", LFT_REQUEST_URI}, /* doesn't include the query-string */ {"rp", LFT_REQUEST_URLPATH}, /* doesn't include the host */ /* { "rq", LFT_REQUEST_QUERY }, * / / * the query-string, INCLUDING the leading ? */ {">v", LFT_REQUEST_VERSION}, {"rv", LFT_REQUEST_VERSION}, { ">st", LFT_REQUEST_SIZE_TOTAL }, /*{ ">sl", LFT_REQUEST_SIZE_LINE }, * / / * the request line "GET ... " */ { ">sh", LFT_REQUEST_SIZE_HEADERS }, /*{ ">sb", LFT_REQUEST_SIZE_BODY }, */ /*{ ">sB", LFT_REQUEST_SIZE_BODY_NO_TE }, */ {"<st", LFT_REPLY_SIZE_TOTAL}, {"<sH", LFT_REPLY_HIGHOFFSET}, {"<sS", LFT_REPLY_OBJECTSIZE}, @@ -1107,41 +1111,61 @@ if (al->hier.bodyBytesRead >= 0) { outoff = al->hier.bodyBytesRead; dooff = 1; } // else if hier.bodyBytesRead < 0 we did not have any data exchange with // a peer server so just print a "-" (eg requests served from cache, // or internal error messages). break; case LFT_SQUID_STATUS: if (al->http.timedout || al->http.aborted) { snprintf(tmp, sizeof(tmp), "%s%s", log_tags[al->cache.code], al->http.statusSfx()); out = tmp; } else { out = log_tags[al->cache.code]; } break; - /* case LFT_SQUID_ERROR: */ + case LFT_SQUID_ERROR: + if (al->request && al->request->errType != ERR_NONE) + out = errorPageName(al->request->errType); + break; + + case LFT_SQUID_ERROR_DETAIL: + if (al->request && al->request->errDetail != ERR_DETAIL_NONE) { + if (al->request->errDetail > ERR_DETAIL_START && + al->request->errDetail < ERR_DETAIL_MAX) + out = errorDetailName(al->request->errDetail); + else { + if (al->request->errDetail >= ERR_DETAIL_EXCEPTION_START) + snprintf(tmp, sizeof(tmp), "%s=0x%X", + errorDetailName(al->request->errDetail), (uint32_t) al->request->errDetail); + else + snprintf(tmp, sizeof(tmp), "%s=%d", + errorDetailName(al->request->errDetail), al->request->errDetail); + out = tmp; + } + } + break; case LFT_SQUID_HIERARCHY: if (al->hier.ping.timedout) mb.append("TIMEOUT_", 8); out = hier_code_str[al->hier.code]; break; case LFT_MIME_TYPE: out = al->http.content_type; break; case LFT_REQUEST_METHOD: out = al->_private.method_str; break; case LFT_REQUEST_URI: