Author: Tsantilas Christos <chtsanti@users.sourceforge.net> , Alex Rousskov <roussko...

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 c5862f68032bc6964eefc1dbeb589e0759e31a36..47f81c9d54a1510db93b1a8668e7d70871d36a0b 100644 (file)
--- 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 0f4f158e9bc7224e53069b4a55e7048563d8ff8b..9a0cdae8aba475ddab530f95c2bb6b6d0c57d84d 100644 (file)
--- 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 8597b4e7c78d491db4495bf778b32c6a6340f980..cc98207579c64670511a4a8f5a48d0120775d1a2 100644 (file)
--- 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 814dd0e4a03ba0dcce22ae8256ebd7357bc3ebca..b5a04f2330d8fe7110cfb24a312dbdf706a858f1 100644 (file)
--- 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 6782881022695d4ebd849d79f945740705e42814..c215c0b22434308d26bcd221aad65c30548dbae9 100644 (file)
--- 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 27e722ab9d73accd47242dfde7e430406ad19b96..f9988825eca14d2594ad6bd40f4adcb3734b091c 100644 (file)
--- 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 9fc83837c34e9ed8ca578150bfab51b34f4f40b8..b1b0dabce3ea5dbfd1b3a8bbb6bed73a7809c6b4 100644 (file)
--- 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 1eb5cc7b2436ab99d063361c218e18f36ee0b0a2..07a16ba65c975ae862843a58cb816bbc5b1ee499 100644 (file)
--- 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 dfd9a768b9be31634e9a6a697460812866d7a985..93059718256e579be663b3d0df929aa3a64216bb 100644 (file)
--- 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 df3b1f29015b62a5bcfb9c188aec4a64839b5530..a338fdaf9a207ccfd760a082091daee41d245b82 100644 (file)
--- 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 293059ee46de9f449d2fcee517e3e2dc1dbb9ea3..70e6352f8d90dc5196572bcf5ab278ee4c88cd5b 100644 (file)
--- 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 62b436203fdbeba5f5cbb5a3c1c4009079b353ae..b6be66527ab2b8565b246a47966f272f7d6118ce 100644 (file)
--- 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);