From: Amos Jeffries Date: Mon, 21 Dec 2009 12:13:11 +0000 (+1300) Subject: Author: Tsantilas Christos X-Git-Tag: SQUID_3_2_0_1~497 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=f692498bb44b36154c27c634ac4f263a751add9c;p=thirdparty%2Fsquid.git Author: Tsantilas Christos Append the _ABORTED or _TIMEDOUT suffixes to the action access.log field. * When an HTTP connection with a client times out, append _TIMEDOUT suffix to the Squid result code field in access.log. * When an HTTP connection with the client is terminated prematurely by Squid, append _ABORTED suffix to the result code field in access.log. Premature connection termination may happen when, for example, I/O errors or server side-problems force Squid to terminate the master transaction and close all associated connections. The above changes make it possible to identify failed transactions even when they have 200/200 received/send response status codes and a "successful" Squid result code (e.g., TCP_MISS). This is important when one does not want 1-hour "stuck" transactions for 15-byte GIFs to significantly skew the mean response time statistics. Such transactions eventually terminate due to, say, TCP errors, and the old code would record huge response times for successfully-looking transactions. The development sponsored by the Measurement Factory --- diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h index 9410ba2588..1dba711727 100644 --- a/src/AccessLogEntry.h +++ b/src/AccessLogEntry.h @@ -55,12 +55,20 @@ public: { public: - HttpDetails() : method(METHOD_NONE), code(0), content_type(NULL) {} + HttpDetails() : method(METHOD_NONE), code(0), content_type(NULL), + timedout(false), aborted(false) {} HttpRequestMethod method; int code; const char *content_type; HttpVersion version; + bool timedout; ///< terminated due to a lifetime or I/O timeout + bool aborted; ///< other abnormal termination (e.g., I/O error) + + /// compute suffix for the status access.log field + const char *statusSfx() const { + return timedout ? "_TIMEDOUT" : (aborted ? "_ABORTED" : ""); + } } http; class ICPDetails diff --git a/src/client_side.cc b/src/client_side.cc index 45a13d09c9..60a28be441 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -623,6 +623,15 @@ ConnStateData::freeAllContexts() } } +/// propagates abort event to all contexts +void +ConnStateData::notifyAllContexts(int xerrno) +{ + typedef ClientSocketContext::Pointer CSCP; + for (CSCP c = getCurrentContext(); c.getRaw(); c = c->next) + c->noteIoError(xerrno); +} + /* This is a handler normally called by comm_close() */ void ConnStateData::connStateClosed(const CommCloseCbParams &io) { @@ -1622,6 +1631,19 @@ clientWriteComplete(int fd, char *bufnotused, size_t size, comm_err_t errflag, i context->writeComplete (fd, bufnotused, size, errflag); } +/// remembers the abnormal connection termination for logging purposes +void +ClientSocketContext::noteIoError(const int xerrno) +{ + if (http) { + if (xerrno == ETIMEDOUT) + http->al.http.timedout = true; + else // even if xerrno is zero (which means read abort/eof) + http->al.http.aborted = true; + } +} + + void ClientSocketContext::doClose() { @@ -2215,6 +2237,7 @@ ConnStateData::connFinishedWithConn(int size) } else if (!Config.onoff.half_closed_clients) { /* admin doesn't want to support half-closed client sockets */ debugs(33, 3, "connFinishedWithConn: FD " << fd << " aborted (half_closed_clients disabled)"); + notifyAllContexts(0); // no specific error implies abort return 1; } } @@ -2663,6 +2686,7 @@ ConnStateData::clientReadRequest(const CommIoCbParams &io) * lame half-close detection */ if (connReadWasError(io.flag, io.size, io.xerrno)) { + notifyAllContexts(io.xerrno); comm_close(fd); return; } @@ -2937,8 +2961,9 @@ static void clientLifetimeTimeout(int fd, void *data) { ClientHttpRequest *http = (ClientHttpRequest *)data; - debugs(33, 1, "WARNING: Closing client " << http->getConn()->peer << " connection due to lifetime timeout"); + debugs(33, 1, "WARNING: Closing client " << " connection due to lifetime timeout"); debugs(33, 1, "\t" << http->uri); + http->al.http.timedout = true; comm_close(fd); } diff --git a/src/client_side.h b/src/client_side.h index 72fe1195af..412948069d 100644 --- a/src/client_side.h +++ b/src/client_side.h @@ -114,6 +114,7 @@ public: void deferRecipientForLater(clientStreamNode * node, HttpReply * rep, StoreIOBuffer receivedData); bool multipartRangeRequest() const; void registerWithConn(); + void noteIoError(const int xerrno); ///< update state to reflect I/O error private: CBDATA_CLASS(ClientSocketContext); @@ -142,6 +143,7 @@ public: int getAvailableBufferLength() const; bool areAllContextsForThisConnection() const; void freeAllContexts(); + void notifyAllContexts(const int xerrno); ///< tell everybody about the err void readNextRequest(); void makeSpaceAvailable(); ClientSocketContext::Pointer getCurrentContext() const; diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 042627dd1d..eab2f75694 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -1047,7 +1047,13 @@ accessLogCustom(AccessLogEntry * al, customlog * log) */ case LFT_SQUID_STATUS: - out = log_tags[al->cache.code]; + 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; @@ -1725,12 +1731,13 @@ accessLogSquid(AccessLogEntry * al, Logfile * logfile) safe_free(user); if (!Config.onoff.log_mime_hdrs) { - logfilePrintf(logfile, "%9ld.%03d %6d %s %s/%03d %"PRId64" %s %s %s %s%s/%s %s\n", + logfilePrintf(logfile, "%9ld.%03d %6d %s %s%s/%03d %"PRId64" %s %s %s %s%s/%s %s\n", (long int) current_time.tv_sec, (int) current_time.tv_usec / 1000, al->cache.msec, client, log_tags[al->cache.code], + al->http.statusSfx(), al->http.code, al->cache.replySize, al->_private.method_str, @@ -1743,12 +1750,13 @@ accessLogSquid(AccessLogEntry * al, Logfile * logfile) } else { char *ereq = log_quote(al->headers.request); char *erep = log_quote(al->headers.reply); - logfilePrintf(logfile, "%9ld.%03d %6d %s %s/%03d %"PRId64" %s %s %s %s%s/%s %s [%s] [%s]\n", + logfilePrintf(logfile, "%9ld.%03d %6d %s %s%s/%03d %"PRId64" %s %s %s %s%s/%s %s [%s] [%s]\n", (long int) current_time.tv_sec, (int) current_time.tv_usec / 1000, al->cache.msec, client, log_tags[al->cache.code], + al->http.statusSfx(), al->http.code, al->cache.replySize, al->_private.method_str, @@ -1785,7 +1793,7 @@ accessLogCommon(AccessLogEntry * al, Logfile * logfile) user2 = accessLogFormatName(al->cache.rfc931); - logfilePrintf(logfile, "%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %"PRId64" %s:%s", + logfilePrintf(logfile, "%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %"PRId64" %s%s:%s", client, user2 ? user2 : dash_str, user1 ? user1 : dash_str, @@ -1796,6 +1804,7 @@ accessLogCommon(AccessLogEntry * al, Logfile * logfile) al->http.code, al->cache.replySize, log_tags[al->cache.code], + al->http.statusSfx(), hier_code_str[al->hier.code]); safe_free(user1);