Hi all,
this patch append the _ABORTED or _TIMEDOUT suffixes to the action
access.log field.
The patch also exist for squid3.1 branch.
The development sponsored by the Measurement Factory
Description:
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.
-
Christos
=== modified file 'src/AccessLogEntry.h'
--- src/AccessLogEntry.h 2009-08-23 09:30:49 +0000
+++ src/AccessLogEntry.h 2009-10-19 06:30:43 +0000
@@ -55,12 +55,20 @@
{
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
=== modified file 'src/client_side.cc'
--- src/client_side.cc 2009-11-18 12:37:56 +0000
+++ src/client_side.cc 2009-12-15 18:17:24 +0000
@@ -623,6 +623,15 @@
}
}
+/// 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 @@
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 @@
} 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 @@
* lame half-close detection
*/
if (connReadWasError(io.flag, io.size, io.xerrno)) {
+ notifyAllContexts(io.xerrno);
comm_close(fd);
return;
}
@@ -2937,8 +2961,9 @@
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);
}
=== modified file 'src/client_side.h'
--- src/client_side.h 2009-10-31 10:06:17 +0000
+++ src/client_side.h 2009-12-15 18:17:24 +0000
@@ -114,6 +114,7 @@
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 @@
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;
=== modified file 'src/log/access_log.cc'
--- src/log/access_log.cc 2009-11-22 20:37:27 +0000
+++ src/log/access_log.cc 2009-12-15 18:17:25 +0000
@@ -1047,7 +1047,13 @@
*/
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 @@
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 @@
} 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 @@
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 @@
al->http.code,
al->cache.replySize,
log_tags[al->cache.code],
+ al->http.statusSfx(),
hier_code_str[al->hier.code]);
safe_free(user1);
