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 96215396 ./src/adaptation/ecap/MessageRep.cc:356: 96215396 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-11 07:58:49 +0000 @@ -0,0 +1,64 @@ +#!/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 19bits of a 32 bit integer used for filename hash + # (max hash=524287), and 13 bits for storing line number + $i = $i % 524287; + return $i; +} + +sub ComputeMustIds +{ + my($file) = @_; + my($hash) = FileNameHash($file); + if(!open(IN, "<$file")) { + printf STDERR "error opening file $file. Ignore ..."; + return; + } + while() { + my($line) = $_; + my($id); + if ( $line =~ /^\s*Must\s*\(/ || $line =~ /^\s*throw\s*TexcHere\s*\(/){ + $line =~ s/^\s*//; + $id= ($hash <<13) | ($. & 0x1FFF); + $id += ERR_DETAIL_EXCEPTION_START; + print "$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-11 07:53:49 +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 96215396 +# ./src/adaptation/ecap/MessageRep.cc:356: 96215396 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 */ #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-04 05:44:42 +0000 +++ src/Makefile.am 2010-10-05 09:38:30 +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(&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(adapted.header))) { request_ = (virgin.cause? virgin.cause: dynamic_cast(virgin.header)); reply_ = dynamic_cast(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(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(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-09-13 00:19:25 +0000 +++ src/adaptation/icap/Xaction.cc 2010-10-08 09:48:02 +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 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-08 14:51:17 +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 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); + /*19bits of a 32 bit integer used for filename hash (max hash=524287), + and 13 bits for storing line number (8k max). + If you change this policy remember to update the FileNameHash function + in the scripts/calc-must-ids.pl script + */ + return i % 524287; +} + +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-10 15:30:19 +0000 @@ -1,52 +1,80 @@ #ifndef SQUID__TEXTEXCEPTION_H #define SQUID__TEXTEXCEPTION_H // Origin: xstd/TextException #include "config.h" #include // 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: // optional location information const char *theFileName; int theLineNo; + unsigned int theId; }; //inline //ostream &operator <<(ostream &os, const TextException &exx) { // return exx.print(os); //} +/// a small integer hash value to semi-uniquely identify the source file +unsigned int FileNameHash(const char *fname); + +/// 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 = 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__, \ + (FileNameHash(__FILE__)<<13) | (__LINE__ & 0x1FFF)) #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__, \ + (FileNameHash(__FILE__)<<13) | (__LINE__ & 0x1FFF))) #endif #endif /* SQUID__TEXTEXCEPTION_H */ === modified file 'src/cf.data.pre' --- src/cf.data.pre 2010-09-30 01:12:15 +0000 +++ src/cf.data.pre 2010-10-07 08:54:05 +0000 @@ -2638,40 +2638,43 @@ Format codes: % a literal % character >a Client source IP address >A Client FQDN >p Client source port 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 [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::]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-09-22 00:12:12 +0000 +++ src/client_side_request.cc 2010-10-08 09:50:52 +0000 @@ -51,40 +51,41 @@ #include "adaptation/Service.h" #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 "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); @@ -1424,41 +1425,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(); @@ -1477,62 +1478,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(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 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-11 06:34:00 +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_START"; + + 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-09-12 00:05:59 +0000 +++ src/forward.cc 2010-10-04 08:01:58 +0000 @@ -272,40 +272,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-09-19 03:03:02 +0000 +++ src/ftp.cc 2010-10-04 08:01:58 +0000 @@ -3614,40 +3614,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-09-29 00:12:13 +0000 +++ src/http.cc 2010-10-06 08:10:25 +0000 @@ -2279,40 +2279,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-08 09:46:58 +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}, {"Hs", LFT_HTTP_SENT_STATUS_CODE}, {"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 }, */ {"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 { + 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: