]> git.ipfire.org Git - thirdparty/squid.git/commitdiff
Cleanup transaction message size logging
authorAmos Jeffries <squid3@treenet.co.nz>
Tue, 29 Oct 2013 02:24:29 +0000 (19:24 -0700)
committerAmos Jeffries <squid3@treenet.co.nz>
Tue, 29 Oct 2013 02:24:29 +0000 (19:24 -0700)
- Add class MessageCounters to track all size properties of a
  transaction message. HTTP-centric for now.

- replaced AccessLogEntry::cache.requestHeadersSize with
  AccessLogEntry::http.clientRequest.headerSz

- replaced AccessLogEntry::cache.requestSize with
  AccessLogEntry::http.clientRequest (total() of all counters)

- replaced AccessLogEntry::cache.replyHeadersSize with
  AccessLogEntry::http.adaptedReply.headerSz

- replaced AccessLogEntry::cache.replySize with
  AccessLogEntry::http.adaptedReply (total() of all counters)

- Rename the logformat byte codes for message size counters to
  form a logical set of details by message type

- reorganize and document logformat option codes more clearly

There are no logic changes in this patch. Several accounting
bugs have been identified and marked for fixing later.

13 files changed:
src/AccessLogEntry.h
src/Makefile.am
src/MessageCounters.h [new file with mode: 0644]
src/adaptation/icap/ModXact.cc
src/cf.data.pre
src/client_side.cc
src/format/ByteCode.h
src/format/Format.cc
src/format/Token.cc
src/icp_v2.cc
src/log/FormatHttpdCombined.cc
src/log/FormatHttpdCommon.cc
src/log/FormatSquidNative.cc

index b3c4908ae3f4c9d9f7fb8ebfb3d66078c4654813..2ee4b73d3454146b3ea4e9f54fa3355aaa31cc16 100644 (file)
@@ -40,6 +40,7 @@
 #include "icp_opcode.h"
 #include "ip/Address.h"
 #include "LogTags.h"
+#include "MessageCounters.h"
 #include "Notes.h"
 #if ICAP_CLIENT
 #include "adaptation/icap/Elements.h"
@@ -84,7 +85,10 @@ public:
 
     public:
         HttpDetails() : method(Http::METHOD_NONE), code(0), content_type(NULL),
-                timedout(false), aborted(false) {}
+                timedout(false),
+                aborted(false),
+                clientRequest()
+            {}
 
         HttpRequestMethod method;
         int code;
@@ -97,6 +101,17 @@ public:
         const char *statusSfx() const {
             return timedout ? "_TIMEDOUT" : (aborted ? "_ABORTED" : "");
         }
+
+        /// counters for the original request received from client
+        // TODO calculate header and payload better (by parser)
+        // XXX payload encoding overheads not calculated at all yet.
+        MessageCounters clientRequest;
+
+        /// counters for the response sent to client
+        // TODO calculate header and payload better (by parser)
+        // XXX payload encoding overheads not calculated at all yet.
+        MessageCounters adaptedReply;
+
     } http;
 
     /** \brief This subclass holds log info for ICP protocol
@@ -144,10 +159,6 @@ public:
 
     public:
         CacheDetails() : caddr(),
-                requestSize(0),
-                replySize(0),
-                requestHeadersSize(0),
-                replyHeadersSize(0),
                 highOffset(0),
                 objectSize(0),
                 code (LOG_TAG_NONE),
@@ -162,10 +173,6 @@ public:
         }
 
         Ip::Address caddr;
-        int64_t requestSize;
-        int64_t replySize;
-        int requestHeadersSize; ///< received, including request line
-        int replyHeadersSize; ///< sent, including status line
         int64_t highOffset;
         int64_t objectSize;
         LogTags code;
index 2a04e3437ee65e95119ba7207fcae5ef1ca78c0f..8f8d5284709e7d35cb200538baa342732500b1d5 100644 (file)
@@ -427,6 +427,7 @@ squid_SOURCES = \
        MemBuf.cc \
        MemObject.cc \
        MemObject.h \
+       MessageCounters.h \
        mime.h \
        mime.cc \
        mime_header.h \
diff --git a/src/MessageCounters.h b/src/MessageCounters.h
new file mode 100644 (file)
index 0000000..b1b86ef
--- /dev/null
@@ -0,0 +1,29 @@
+#ifndef SQUID_SRC_MESSAGECOUNTERS_H
+#define SQUID_SRC_MESSAGECOUNTERS_H
+
+/**
+ * Counters used to collate the traffic size measurements
+ * for a transaction message.
+ */
+class MessageCounters
+{
+public:
+    MessageCounters() : headerSz(0), payloadDataSz(0), payloadTeSz(0) {}
+
+    /// size of message header block (if any)
+    uint64_t headerSz;
+
+    /// total size of payload block(s) excluding transfer encoding overheads
+    uint64_t payloadDataSz;
+
+    /// total size of extra bytes added by transfer encoding
+    uint64_t payloadTeSz;
+
+    // total message size
+    uint64_t total() const {return headerSz + payloadDataSz + payloadTeSz;}
+
+    /// total payload size including transfer encoding overheads
+    uint64_t payloadTotal() const {return payloadDataSz + payloadTeSz;}
+};
+
+#endif  /* SQUID_SRC_MESSAGECOUNTERS_H */
index 71203b4dbd726917fc7333cb5076b27b6beee56b..fc038df289398ea3aa99d793e9eafb611b456f7a 100644 (file)
@@ -1289,7 +1289,8 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
         al.cache.ssluser = h->ssluser.termedBuf();
 #endif
     al.cache.code = h->logType;
-    al.cache.requestSize = h->req_sz;
+    // XXX: should use icap-specific counters instead ?
+    al.http.clientRequest.payloadDataSz = h->req_sz;
 
     // leave al.icap.bodyBytesRead negative if no body
     if (replyHttpHeaderSize >= 0 || replyHttpBodySize >= 0) {
@@ -1302,7 +1303,9 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
         al.http.code = reply_->sline.status();
         al.http.content_type = reply_->content_type.termedBuf();
         if (replyHttpBodySize >= 0) {
-            al.cache.replySize = replyHttpBodySize + reply_->hdr_sz;
+            // XXX: should use icap-specific counters instead ?
+            al.http.adaptedReply.payloadDataSz = replyHttpBodySize;
+            al.http.adaptedReply.headerSz =  reply_->hdr_sz;
             al.cache.highOffset = replyHttpBodySize;
         }
         //don't set al.cache.objectSize because it hasn't exist yet
index 19418e8a2649a492957d4ac1a1eba45b2637057f..6fe072bc3ce797ea0e81eb89f51175e1aed23346 100644 (file)
@@ -3710,6 +3710,21 @@ DOC_START
 
        HTTP related format codes:
 
+           REQUEST
+
+               [http::]rm      Request method (GET/POST etc)
+               [http::]>rm     Request method from client
+               [http::]<rm     Request method sent to server or peer
+               [http::]ru      Request URL from client (historic, filtered for logging)
+               [http::]>ru     Request URL from client
+               [http::]<ru     Request URL sent to server or peer
+               [http::]rp      Request URL-Path excluding hostname
+               [http::]>rp     Request URL-Path excluding hostname from client
+               [http::]<rp     Request URL-Path excluding hostname sent to server or peer
+               [http::]rv      Request protocol version
+               [http::]>rv     Request protocol version from client
+               [http::]<rv     Request protocol version sent to server or peer
+
                [http::]>h      Original received request header. 
                                Usually differs from the request header sent by
                                Squid, although most fields are often preserved.
@@ -3720,37 +3735,41 @@ DOC_START
                                Usually differs from the request header sent by
                                Squid, although most fields are often preserved.
                                Optional header name argument as for >h
+
+
+           RESPONSE
+
+               [http::]<Hs     HTTP status code received from the next hop
+               [http::]>Hs     HTTP status code sent to the client
+
                [http::]<h      Reply header. Optional header name argument
                                as for >h
-               [http::]>Hs     HTTP status code sent to the client
-               [http::]<Hs     HTTP status code received from the next hop
+
+               [http::]mt      MIME content type
+
+
+           SIZE COUNTERS
+
+               [http::]st      Total size of request + reply traffic with client
+               [http::]>st     Total size of request received from client.
+                               Excluding chunked encoding bytes.
+               [http::]<st     Total size of reply sent to client (after adaptation)
+
+               [http::]>sh     Size of request headers received from client
+               [http::]<sh     Size of reply headers sent to client (after adaptation)
+
+               [http::]<sH     Reply high offset sent
+               [http::]<sS     Upstream object size
+
                [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::]mt      MIME content type
-               [http::]rm      Request method (GET/POST etc)
-               [http::]>rm     Request method from client
-               [http::]<rm     Request method sent to server or peer
-               [http::]ru      Request URL from client (historic, filtered for logging)
-               [http::]>ru     Request URL from client
-               [http::]<ru     Request URL sent to server or peer
-               [http::]rp      Request URL-Path excluding hostname
-               [http::]>rp     Request URL-Path excluding hostname from client
-               [http::]<rp     Request URL-Path excluding hostname sento to server or peer
-               [http::]rv      Request protocol version
-               [http::]>rv     Request protocol version from client
-               [http::]<rv     Request protocol version sent to server or peer
-               [http::]<st     Sent reply size including HTTP headers
-               [http::]>st     Received request size including HTTP headers. In the
-                               case of chunked requests the chunked encoding metadata
-                               are not included
-               [http::]>sh     Received HTTP request headers size
-               [http::]<sh     Sent HTTP reply headers size
-               [http::]st      Request+Reply size including HTTP headers
-               [http::]<sH     Reply high offset sent
-               [http::]<sS     Upstream object size
+
+
+           TIMING
+
                [http::]<pt     Peer response time in milliseconds. The timer starts
                                when the last request byte is sent to the next hop
                                and stops when the last response byte is received.
index 7277aca978cb716eafb7fd8362ef0433d4b5843f..cdd086dd14ba32f8c0c60166db4d4a3786312fa6 100644 (file)
@@ -597,7 +597,7 @@ prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry::Pointer &aLo
     aLogEntry->http.version = request->http_ver;
     aLogEntry->hier = request->hier;
     if (request->content_length > 0) // negative when no body or unknown length
-        aLogEntry->cache.requestSize += request->content_length;
+        aLogEntry->http.clientRequest.payloadDataSz += request->content_length; // XXX: actually adaptedRequest payload size ??
     aLogEntry->cache.extuser = request->extacl_user.termedBuf();
 
     // Adapted request, if any, inherits and then collects all the stats, but
@@ -631,7 +631,7 @@ ClientHttpRequest::logRequest()
     debugs(33, 9, "clientLogRequest: http.code='" << al->http.code << "'");
 
     if (loggingEntry() && loggingEntry()->mem_obj)
-        al->cache.objectSize = loggingEntry()->contentLen();
+        al->cache.objectSize = loggingEntry()->contentLen(); // payload duplicate ?? with or without TE ?
 
     al->cache.caddr.setNoAddr();
 
@@ -640,11 +640,10 @@ ClientHttpRequest::logRequest()
         al->cache.port =  cbdataReference(getConn()->port);
     }
 
-    al->cache.requestSize = req_sz;
-    al->cache.requestHeadersSize = req_sz;
-
-    al->cache.replySize = out.size;
-    al->cache.replyHeadersSize = out.headers_sz;
+    al->http.clientRequest.headerSz = req_sz;
+    al->http.adaptedReply.headerSz = out.headers_sz;
+    // XXX: calculate without payload encoding or headers !!
+    al->http.adaptedReply.payloadDataSz = out.size - out.headers_sz; // pretend its all un-encoded data for now.
 
     al->cache.highOffset = out.offset;
 
index 81e33a836f27f8effc325c1c937b636620bd6c83..d32227d6e4bef15f1bb07d9d18bb52b6fb301027 100644 (file)
@@ -88,9 +88,8 @@ typedef enum {
     LFT_SERVER_REQ_VERSION,
 
     /* request meta details */
-    LFT_REQUEST_SIZE_TOTAL,
-    /*LFT_REQUEST_SIZE_LINE, */
-    LFT_REQUEST_SIZE_HEADERS,
+    LFT_CLIENT_REQUEST_SIZE_TOTAL,
+    LFT_CLIENT_REQUEST_SIZE_HEADERS,
     /*LFT_REQUEST_SIZE_BODY, */
     /*LFT_REQUEST_SIZE_BODY_NO_TE, */
 
@@ -118,14 +117,15 @@ typedef enum {
     /* LFT_ADAPTED_REPLY_ALL_HEADERS, */
 
     /* response meta details */
-    LFT_REPLY_SIZE_TOTAL,
+    LFT_ADAPTED_REPLY_SIZE_TOTAL,
     LFT_REPLY_HIGHOFFSET,
     LFT_REPLY_OBJECTSIZE,
-    /*LFT_REPLY_SIZE_LINE, */
-    LFT_REPLY_SIZE_HEADERS,
+    LFT_ADAPTED_REPLY_SIZE_HEADERS,
     /*LFT_REPLY_SIZE_BODY, */
     /*LFT_REPLY_SIZE_BODY_NO_TE, */
 
+    LFT_CLIENT_IO_SIZE_TOTAL,
+
     /* client credentials */
     LFT_USER_NAME,   /* any source will do */
     LFT_USER_LOGIN,
@@ -155,7 +155,6 @@ typedef enum {
 
     LFT_MIME_TYPE,
     LFT_TAG,
-    LFT_IO_SIZE_TOTAL,
     LFT_EXT_LOG,
 
     LFT_SEQUENCE_NUMBER,
index e737280e8e572cd44ef8f2aa76d5fdd47cecea59..353d7119a7262ccf661dc3899886afb3a38b8ce7 100644 (file)
@@ -982,21 +982,21 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             }
             break;
 
-        case LFT_REQUEST_SIZE_TOTAL:
-            outoff = al->cache.requestSize;
+        case LFT_CLIENT_REQUEST_SIZE_TOTAL:
+            outoff = al->http.clientRequest.total();
             dooff = 1;
             break;
 
-            /*case LFT_REQUEST_SIZE_LINE: */
-        case LFT_REQUEST_SIZE_HEADERS:
-            outoff = al->cache.requestHeadersSize;
+        case LFT_CLIENT_REQUEST_SIZE_HEADERS:
+            outoff = al->http.clientRequest.headerSz;
             dooff =1;
             break;
+
             /*case LFT_REQUEST_SIZE_BODY: */
             /*case LFT_REQUEST_SIZE_BODY_NO_TE: */
 
-        case LFT_REPLY_SIZE_TOTAL:
-            outoff = al->cache.replySize;
+        case LFT_ADAPTED_REPLY_SIZE_TOTAL:
+            outoff = al->http.adaptedReply.total();
             dooff = 1;
             break;
 
@@ -1014,14 +1014,20 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-            /*case LFT_REPLY_SIZE_LINE: */
-        case LFT_REPLY_SIZE_HEADERS:
-            outint = al->cache.replyHeadersSize;
+        case LFT_ADAPTED_REPLY_SIZE_HEADERS:
+            outint = al->http.adaptedReply.headerSz;
             doint = 1;
             break;
+
             /*case LFT_REPLY_SIZE_BODY: */
             /*case LFT_REPLY_SIZE_BODY_NO_TE: */
 
+        case LFT_CLIENT_IO_SIZE_TOTAL:
+            outint = al->http.clientRequest.total() + al->http.adaptedReply.total();
+            doint = 1;
+            break;
+        /*case LFT_SERVER_IO_SIZE_TOTAL: */
+
         case LFT_TAG:
             if (al->request)
                 out = al->request->tag.termedBuf();
@@ -1030,11 +1036,6 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-        case LFT_IO_SIZE_TOTAL:
-            outint = al->cache.requestSize + al->cache.replySize;
-            doint = 1;
-            break;
-
         case LFT_EXT_LOG:
             if (al->request)
                 out = al->request->extacl_log.termedBuf();
index 1dd60e6c504efdf730f063552033cea3266ff9b1..af80f95baa48c217ff173671e85eda92b04f7f81 100644 (file)
@@ -96,22 +96,22 @@ static TokenTableEntry TokenTable2C[] = {
     /*{"<rq", LFT_SERVER_REQ_QUERY},*/
     {"<rv", LFT_SERVER_REQ_VERSION},
 
-    {">st", LFT_REQUEST_SIZE_TOTAL },
-    /*{ ">sl", LFT_REQUEST_SIZE_LINE }, * / / * the request line "GET ... " */
-    {">sh", LFT_REQUEST_SIZE_HEADERS },
+    {">st", LFT_CLIENT_REQUEST_SIZE_TOTAL },
+    {">sh", LFT_CLIENT_REQUEST_SIZE_HEADERS },
     /*{ ">sb", LFT_REQUEST_SIZE_BODY }, */
     /*{ ">sB", LFT_REQUEST_SIZE_BODY_NO_TE }, */
 
-    {"<st", LFT_REPLY_SIZE_TOTAL},
+    {"<st", LFT_ADAPTED_REPLY_SIZE_TOTAL}, // XXX: adapted should be code: <sta
     {"<sH", LFT_REPLY_HIGHOFFSET},
     {"<sS", LFT_REPLY_OBJECTSIZE},
-    /*{ "<sl", LFT_REPLY_SIZE_LINE }, * /   / * the reply line (protocol, code, text) */
-    {"<sh", LFT_REPLY_SIZE_HEADERS },
+    {"<sh", LFT_ADAPTED_REPLY_SIZE_HEADERS }, // XXX: adapted should be code: <sha
     /*{ "<sb", LFT_REPLY_SIZE_BODY }, */
     /*{ "<sB", LFT_REPLY_SIZE_BODY_NO_TE }, */
 
+    {"st", LFT_CLIENT_IO_SIZE_TOTAL}, // XXX: total from client should be stC ??
+    /*{"stP", LFT_SERVER_IO_SIZE_TOTAL},*/
+
     {"et", LFT_TAG},
-    {"st", LFT_IO_SIZE_TOTAL},
     {"ea", LFT_EXT_LOG},
     {"sn", LFT_SEQUENCE_NUMBER},
 
index 1eb210e69b8eb01fe9a9751cdbe4379f46fb29be..edd0934c5eadd15f35f2416fd98be25ed8835408 100644 (file)
@@ -222,7 +222,8 @@ icpLogIcp(const Ip::Address &caddr, LogTags logcode, int len, const char *url, i
 
     al->cache.caddr = caddr;
 
-    al->cache.replySize = len;
+    // XXX: move to use icp.clientReply instead
+    al->http.adaptedReply.payloadDataSz = len;
 
     al->cache.code = logcode;
 
index b63dc62132b7e15a8a82779e750627837a965230..efb1a5e3441fd0b9e4c04e9d8115afebf205a09e 100644 (file)
@@ -77,7 +77,7 @@ Log::Format::HttpdCombined(const AccessLogEntry::Pointer &al, Logfile * logfile)
                   AnyP::ProtocolType_str[al->http.version.protocol],
                   al->http.version.major, al->http.version.minor,
                   al->http.code,
-                  al->cache.replySize,
+                  al->http.adaptedReply.total(),
                   referer,
                   agent,
                   LogTags_str[al->cache.code],
index f1c6e9a94febf3f741c2b1d48d40ecbc310f8a28..590882f5a626907af97a3d9c8beaf045c047714f 100644 (file)
@@ -64,7 +64,7 @@ Log::Format::HttpdCommon(const AccessLogEntry::Pointer &al, Logfile * logfile)
                   AnyP::ProtocolType_str[al->http.version.protocol],
                   al->http.version.major, al->http.version.minor,
                   al->http.code,
-                  al->cache.replySize,
+                  al->http.adaptedReply.total(),
                   LogTags_str[al->cache.code],
                   al->http.statusSfx(),
                   hier_code_str[al->hier.code],
index 4fafb6fe51366825c6f28d84db866cb5a4383039..e10a84f866b0d9dc9c34b18873a8a7684b3aa2b8 100644 (file)
@@ -78,7 +78,7 @@ Log::Format::SquidNative(const AccessLogEntry::Pointer &al, Logfile * logfile)
                   LogTags_str[al->cache.code],
                   al->http.statusSfx(),
                   al->http.code,
-                  al->cache.replySize,
+                  al->http.adaptedReply.total(),
                   al->_private.method_str,
                   al->url,
                   user ? user : dash_str,