Author: Tsantilas Christos <chtsanti@users.sourceforge.net>

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 9410ba25880554210c8149a251de4e3e1780382f..1dba71172771d6be1c593f519daa944413aca749 100644 (file)
--- 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 45a13d09c90bd79cc1f86c9d81a39611bc068028..60a28be44140fe23176b7e20a090e705d80dae50 100644 (file)
--- 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 72fe1195afa09b93f6dd2f7b4bdce9fbb4aa8740..412948069d511d2e39cece7b471d6504d63c895f 100644 (file)
--- 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 042627dd1d3b661f50aa1e6b5c02ff9e71b3e63a..eab2f756944a8f6c8da3f430f221638411dd513d 100644 (file)
--- 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);