From: Christos Tsantilas <chtsanti@users.sourceforge.net>
Date: Sat, 7 Aug 2010 14:51:30 +0000 (+0300)
Subject: Author:  Tsantilas Christos <chtsanti@users.sourceforge.net> , Alex Rousskov <roussko... 
X-Git-Tag: take1~414
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=bae917acf060ee38d25ae0e893b38e33368185da;p=thirdparty%2Fsquid.git

Author:  Tsantilas Christos <chtsanti@users.sourceforge.net> , Alex Rousskov <rousskov@measurement-factory.com>
Added %http::<bs and %icap::<bs logformat codes to HTTP and ICAP body sizes received from the next HTTP hop or the ICAP server.

Logging "received message body" is useful because Squid may receive a lot
more or a lot less than it serves to the client or than the original resource
size, which may happen when handling Range requests and partial responses,
when adapting bodies, and for other reasons.

For HTTP, we define "received message body" as message body bytes that
Squid stores, merges, adapts, and/or forwards. In most cases, they are the
same as body bytes sent by the server to Squid. However, the two bodies may
differ for reasons such as errors (where the start of the body was not found),
HTTP transfer encodings (where Squid strips chunked encoding to find the
message body), and generated FTP directory listings (that were received in
a completely different format on a control connection).

For ICAP, the "received message body" is the Encapsulated sections, after
the encapsulated HTTP body, if any, is dechunked.

This is a Measurement Factory project.
---

diff --git a/doc/release-notes/release-3.3.html b/doc/release-notes/release-3.3.html
index c5862f6803..47f81c9d54 100644
--- a/doc/release-notes/release-3.3.html
+++ b/doc/release-notes/release-3.3.html
@@ -128,7 +128,9 @@ for Applied Network Research and members of the Web Caching community.</EM>
 
 <P>
 <DL>
-
+<DT><B>logformat</B><DD>
+<P><EM>%&gt;bs</EM> Number of HTTP-equivalent message body bytes received from the next hop.</P>
+<P><EM>icap::%&gt;bs</EM> Number of message body bytes received from the ICAP server.</P>
 </DL>
 </P>
 
diff --git a/doc/release-notes/release-3.3.sgml b/doc/release-notes/release-3.3.sgml
index 0f4f158e9b..9a0cdae8ab 100644
--- a/doc/release-notes/release-3.3.sgml
+++ b/doc/release-notes/release-3.3.sgml
@@ -65,7 +65,9 @@ This section gives a thorough account of those changes in three categories:
 <sect1>Changes to existing tags<label id="modifiedtags">
 <p>
 <descrip>
-
+	<tag>logformat</tag>
+	<p><em>%&gt;bs</em> Number of HTTP-equivalent message body bytes received from the next hop.
+	<p><em>icap::%&gt;bs</em> Number of message body bytes received from the ICAP server.
 </descrip>
 
 
diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index 8597b4e7c7..cc98207579 100644
--- a/src/AccessLogEntry.h
+++ b/src/AccessLogEntry.h
@@ -195,7 +195,7 @@ public:
     class IcapLogEntry
     {
     public:
-        IcapLogEntry():request(NULL),reply(NULL),outcome(Adaptation::Icap::xoUnknown),trTime(0),ioTime(0),resStatus(HTTP_STATUS_NONE) {}
+        IcapLogEntry():bodyBytesRead(-1),request(NULL),reply(NULL),outcome(Adaptation::Icap::xoUnknown),trTime(0),ioTime(0),resStatus(HTTP_STATUS_NONE) {}
 
         Ip::Address hostAddr; ///< ICAP server IP address
         String serviceName;        ///< ICAP service name
@@ -203,6 +203,11 @@ public:
         Adaptation::Icap::ICAP::Method reqMethod; ///< ICAP request method
         int64_t bytesSent;       ///< number of bytes sent to ICAP server so far
         int64_t bytesRead;       ///< number of bytes read from ICAP server so far
+        /**
+         * number of ICAP body bytes read from ICAP server or -1 for no encapsulated 
+         * message data in ICAP reply (eg 204 responses)
+         */
+        int64_t bodyBytesRead;
         HttpRequest* request;    ///< ICAP request
         HttpReply* reply;        ///< ICAP reply
 
diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h
index 814dd0e4a0..b5a04f2330 100644
--- a/src/HierarchyLogEntry.h
+++ b/src/HierarchyLogEntry.h
@@ -65,6 +65,7 @@ public:
     timeval first_conn_start; ///< first connection use among all peers
     int64_t total_response_time; ///< cumulative for all peers
     u_short peer_local_port; //< local port of the last server-side connection
+    int64_t bodyBytesRead;  ///< number of body bytes received from the next hop or -1
 };
 
 extern void hierarchyNote(HierarchyLogEntry *, hier_code, const char *);
diff --git a/src/Server.cc b/src/Server.cc
index 6782881022..c215c0b224 100644
--- a/src/Server.cc
+++ b/src/Server.cc
@@ -824,9 +824,27 @@ ServerStateData::adaptOrFinalizeReply()
     setFinalReply(virginReply());
 }
 
+/// initializes bodyBytesRead stats if needed and applies delta
+void
+ServerStateData::adjustBodyBytesRead(const int64_t delta)
+{
+    int64_t &bodyBytesRead = originalRequest()->hier.bodyBytesRead;
+
+    // if we got here, do not log a dash even if we got nothing from the server
+    if (bodyBytesRead < 0)
+        bodyBytesRead = 0;
+
+    bodyBytesRead += delta; // supports negative and zero deltas
+
+    // check for overflows ("infinite" response?) and undeflows (a bug)
+    Must(bodyBytesRead >= 0);
+}
+
 void
 ServerStateData::addVirginReplyBody(const char *data, ssize_t len)
 {
+    adjustBodyBytesRead(len);
+
 #if USE_ADAPTATION
     assert(!adaptationAccessCheckPending); // or would need to buffer while waiting
     if (startedAdaptation) {
diff --git a/src/Server.h b/src/Server.h
index 27e722ab9d..f9988825ec 100644
--- a/src/Server.h
+++ b/src/Server.h
@@ -171,6 +171,8 @@ protected:
     void storeReplyBody(const char *buf, ssize_t len);
     size_t replyBodySpace(const MemBuf &readBuf, const size_t minSpace) const;
 
+    void adjustBodyBytesRead(const int64_t delta);
+
     // These should be private
     int64_t currentOffset;	/**< Our current offset in the StoreEntry */
     MemBuf *responseBodyBuffer;	/**< Data temporarily buffered for ICAP */
diff --git a/src/adaptation/icap/ModXact.cc b/src/adaptation/icap/ModXact.cc
index 9fc83837c3..b1b0dabce3 100644
--- a/src/adaptation/icap/ModXact.cc
+++ b/src/adaptation/icap/ModXact.cc
@@ -45,7 +45,8 @@ Adaptation::Icap::ModXact::ModXact(Adaptation::Initiator *anInitiator, HttpMsg *
         bodyParser(NULL),
         canStartBypass(false), // too early
         protectGroupBypass(true),
-        replyBodySize(0),
+        replyHttpHeaderSize(-1),
+        replyHttpBodySize(-1),
         adaptHistoryId(-1)
 {
     assert(virginHeader);
@@ -964,11 +965,15 @@ void Adaptation::Icap::ModXact::handleUnknownScode()
 void Adaptation::Icap::ModXact::parseHttpHead()
 {
     if (gotEncapsulated("res-hdr") || gotEncapsulated("req-hdr")) {
+        replyHttpHeaderSize = 0;
         maybeAllocateHttpMsg();
 
         if (!parseHead(adapted.header))
             return; // need more header data
 
+        if (adapted.header)
+            replyHttpHeaderSize = adapted.header->hdr_sz;
+
         if (dynamic_cast<HttpRequest*>(adapted.header)) {
             const HttpRequest *oldR = dynamic_cast<const HttpRequest*>(virgin.header);
             Must(oldR);
@@ -1016,6 +1021,7 @@ void Adaptation::Icap::ModXact::decideOnParsingBody()
     if (gotEncapsulated("res-body") || gotEncapsulated("req-body")) {
         debugs(93, 5, HERE << "expecting a body");
         state.parsing = State::psBody;
+        replyHttpBodySize = 0;
         bodyParser = new ChunkedCodingParser;
         makeAdaptedBodyPipe("adapted response from the ICAP server");
         Must(state.sending == State::sendingAdapted);
@@ -1040,7 +1046,7 @@ void Adaptation::Icap::ModXact::parseBody()
 
     debugs(93, 5, HERE << "have " << readBuf.contentSize() << " body bytes after " <<
            "parse; parsed all: " << parsed);
-    replyBodySize += adapted.body_pipe->buf().contentSize();
+    replyHttpBodySize += adapted.body_pipe->buf().contentSize();
 
     // TODO: expose BodyPipe::putSize() to make this check simpler and clearer
     // TODO: do we really need this if we disable when sending headers?
@@ -1195,11 +1201,21 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
 #endif
     al.cache.code = h->logType;
     al.cache.requestSize = h->req_sz;
+
+    // leave al.icap.bodyBytesRead negative if no body
+    if (replyHttpHeaderSize >= 0 || replyHttpBodySize >= 0) {
+        const int64_t zero = 0; // to make max() argument types the same
+        al.icap.bodyBytesRead =
+            max(zero, replyHttpHeaderSize) + max(zero, replyHttpBodySize);
+    }
+
     if (reply_) {
         al.http.code = reply_->sline.status;
         al.http.content_type = reply_->content_type.termedBuf();
-        al.cache.replySize = replyBodySize + reply_->hdr_sz;
-        al.cache.highOffset = replyBodySize;
+        if (replyHttpBodySize >= 0) {
+            al.cache.replySize = replyHttpBodySize + reply_->hdr_sz;
+            al.cache.highOffset = replyHttpBodySize;
+        }
         //don't set al.cache.objectSize because it hasn't exist yet
 
         Packer p;
diff --git a/src/adaptation/icap/ModXact.h b/src/adaptation/icap/ModXact.h
index 1eb5cc7b24..07a16ba65c 100644
--- a/src/adaptation/icap/ModXact.h
+++ b/src/adaptation/icap/ModXact.h
@@ -273,7 +273,16 @@ private:
     bool canStartBypass; // enables bypass of transaction failures
     bool protectGroupBypass; // protects ServiceGroup-wide bypass of failures
 
-    uint64_t replyBodySize; ///< dechunked ICAP reply body size
+    /**
+     * size of HTTP header in ICAP reply or -1 if there is not any encapsulated
+     * message data
+     */
+    int64_t replyHttpHeaderSize;
+    /**
+     * size of dechunked HTTP body in ICAP reply or -1 if there is not any 
+     * encapsulated message data
+     */
+    int64_t replyHttpBodySize;
 
     int adaptHistoryId; ///< adaptation history slot reservation
 
diff --git a/src/adaptation/icap/OptXact.cc b/src/adaptation/icap/OptXact.cc
index dfd9a768b9..9305971825 100644
--- a/src/adaptation/icap/OptXact.cc
+++ b/src/adaptation/icap/OptXact.cc
@@ -109,6 +109,10 @@ void Adaptation::Icap::OptXact::finalizeLogInfo()
 {
     //    al.cache.caddr = 0;
     al.icap.reqMethod = Adaptation::methodOptions;
+
+    if (icapReply && al.icap.bytesRead > icapReply->hdr_sz)
+        al.icap.bodyBytesRead = al.icap.bytesRead - icapReply->hdr_sz;
+
     Adaptation::Icap::Xaction::finalizeLogInfo();
 }
 
diff --git a/src/cf.data.pre b/src/cf.data.pre
index df3b1f2901..a338fdaf9a 100644
--- a/src/cf.data.pre
+++ b/src/cf.data.pre
@@ -2676,6 +2676,11 @@ DOC_START
 		[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
+				received bodies.
 		[http::]Ss	Squid request status (TCP_MISS etc)
 		[http::]Sh	Squid hierarchy status (DEFAULT_PARENT etc)
 		[http::]mt	MIME content type
@@ -2851,6 +2856,13 @@ DOC_START
 				payload only; i.e., what Squid reads from
 				the socket).
 
+		icap::<bs	Number of message body bytes received from the
+				ICAP server. ICAP message body, if any, usually
+				includes encapsulated HTTP message headers and
+				possibly encapsulated HTTP message body. The
+				HTTP body part is dechunked before its size is
+				computed.
+
 		icap::tr 	Transaction response time (in
 				milliseconds).  The timer starts when
 				the ICAP transaction is created and
diff --git a/src/gopher.cc b/src/gopher.cc
index 293059ee46..70e6352f8d 100644
--- a/src/gopher.cc
+++ b/src/gopher.cc
@@ -820,6 +820,13 @@ gopherReadReply(int fd, char *buf, size_t len, comm_err_t flag, int xerrno, void
             clen >>= 1;
 
         IOStats.Gopher.read_hist[bin]++;
+
+        HttpRequest *req = gopherState->fwd->request;
+        if (req->hier.bodyBytesRead < 0) 
+            req->hier.bodyBytesRead = 0;
+        
+        req->hier.bodyBytesRead += len;
+
     }
 
     if (flag != COMM_OK || len < 0) {
diff --git a/src/log/access_log.cc b/src/log/access_log.cc
index 62b436203f..b6be66527a 100644
--- a/src/log/access_log.cc
+++ b/src/log/access_log.cc
@@ -379,6 +379,7 @@ typedef enum {
     LFT_HTTP_SENT_STATUS_CODE,
     LFT_HTTP_RECEIVED_STATUS_CODE,
     /*LFT_HTTP_STATUS, */
+    LFT_HTTP_BODY_BYTES_READ,
 
     LFT_SQUID_STATUS,
     /*LFT_SQUID_ERROR, */
@@ -430,6 +431,7 @@ typedef enum {
     LFT_ICAP_REQUEST_METHOD,
     LFT_ICAP_BYTES_SENT,
     LFT_ICAP_BYTES_READ,
+    LFT_ICAP_BODY_BYTES_READ,
 
     LFT_ICAP_REQ_HEADER,
     LFT_ICAP_REQ_HEADER_ELEM,
@@ -536,6 +538,7 @@ struct logformat_token_table_entry logformat_token_table[] = {
     {">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 }, */
@@ -586,6 +589,7 @@ struct logformat_token_table_entry logformat_token_table[] = {
     {"icap::rm",  LFT_ICAP_REQUEST_METHOD},
     {"icap::>st",  LFT_ICAP_BYTES_SENT},
     {"icap::<st",  LFT_ICAP_BYTES_READ},
+    {"icap::<bs", LFT_ICAP_BODY_BYTES_READ},
 
     {"icap::>h",  LFT_ICAP_REQ_HEADER},
     {"icap::<h",  LFT_ICAP_REP_HEADER},
@@ -883,6 +887,15 @@ accessLogCustom(AccessLogEntry * al, customlog * log)
             dooff = 1;
             break;
 
+        case LFT_ICAP_BODY_BYTES_READ:
+            if (al->icap.bodyBytesRead >= 0) {
+                outoff = al->icap.bodyBytesRead;
+                dooff = 1;
+            }
+            // else if icap.bodyBytesRead < 0, we do not have any http data,
+            // so just print a "-" (204 responses etc) 
+            break;
+
         case LFT_ICAP_REQ_HEADER:
             if (NULL != al->icap.request) {
                 sb = al->icap.request->header.getByName(fmt->data.header.header);
@@ -1089,6 +1102,15 @@ accessLogCustom(AccessLogEntry * al, customlog * log)
              *     quote = 1;
              *     break;
              */
+        case LFT_HTTP_BODY_BYTES_READ:
+            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) {
@@ -2093,7 +2115,8 @@ HierarchyLogEntry::HierarchyLogEntry() :
         peer_reply_status(HTTP_STATUS_NONE),
         peer_response_time(-1),
         total_response_time(-1),
-        peer_local_port(0)
+        peer_local_port(0),
+        bodyBytesRead(-1)
 {
     memset(host, '\0', SQUIDHOSTNAMELEN);
     memset(cd_host, '\0', SQUIDHOSTNAMELEN);