]> git.ipfire.org Git - thirdparty/squid.git/commitdiff
Fix logged request size (%http::>st) and other size-related %codes.
authorEduard Bagdasaryan <eduard.bagdasaryan@measurement-factory.com>
Tue, 13 Sep 2016 17:30:03 +0000 (11:30 -0600)
committerAlex Rousskov <rousskov@measurement-factory.com>
Tue, 13 Sep 2016 17:30:03 +0000 (11:30 -0600)
The %[http::]>st logformat code should log the actual number of
[dechunked] bytes received from the client. However, for requests with
Content-Length, Squid was logging the sum of the request header size and
the Content-Length header field value instead. The logged value was
wrong when the client sent fewer than Content-Length body bytes.

Also:

* Fixed %http::>h and %http::<h format codes for icap_log. The old code
  was focusing on preserving the "request header" (i.e. not "response
  header") meaning of the %http::>h logformat code, but since ICAP
  services deal with (and log) both HTTP requests and responses, that
  focus on the HTTP message kind actually complicates ICAP logging
  configuration and will eventually require introduction of new %http
  logformat codes that would be meaningless in access.log context.

  - In ICAP context, %http::>h should log to-be-adapted HTTP message
    headers embedded in an ICAP request (HTTP request headers in REQMOD;
    HTTP response headers in RESPMOD). Before this change, %http::>h
    logged constant/"FYI" HTTP request headers in RESPMOD.

  - Similarly, %http::<h should log adapted HTTP message headers
    embedded in an ICAP response (HTTP request headers in regular
    REQMOD; HTTP response headers in RESPMOD and during request
    satisfaction in REQMOD). Before this change, %http::<h logged "-" in
    REQMOD.

  In other words, in ICAP logging context, the ">" and "<" characters
  should indicate ICAP message kind (where the being-logged HTTP message
  is embedded), not HTTP message kind, even for %http codes.

  TODO: %http::>h code logs "-" in RESPMOD because AccessLogEntry does
  not store virgin HTTP response headers.

* Correctly initialize ICAP ALE HTTP fields related to HTTP message
  sizes for icap_log, including %http::>st, %http::<st, %http::>sh, and
  %http::>sh format codes.

* Initialize HttpMsg::hdr_sz in HTTP header parsing code. Among other
  uses, this field is needed to initialize HTTP fields inside ICAP ALE.

* Synced default icap_log format documentation with the current code.

src/HttpMsg.cc
src/adaptation/icap/ModXact.cc
src/cf.data.pre
src/client_side.cc
src/format/Format.cc

index df95791720c29228317fe37b5daac8392f22b6e9..7f57717a661b560bd44eb581e85b5b5238999d77 100644 (file)
@@ -314,6 +314,8 @@ HttpMsg::parseHeader(Http1::Parser &hp)
         return false;
     }
 
+    // XXX: we are just parsing HTTP headers, not the whole message prefix here
+    hdr_sz = hp.messageHeaderSize();
     pstate = psParsed;
     hdrCacheInit();
     return true;
index 1140944b2b74ea5d51c34ba0296304b6ac148267..0bf3c1c77e185d5926b130de8137a3a0978fa487 100644 (file)
@@ -1265,31 +1265,32 @@ void prepareLogWithRequestDetails(HttpRequest *, AccessLogEntry::Pointer &);
 
 void Adaptation::Icap::ModXact::finalizeLogInfo()
 {
-    HttpRequest * request_ = NULL;
-    HttpRequest * adapted_request_ = NULL;
-    HttpReply * reply_ = NULL;
-    request_ = (virgin.cause? virgin.cause: dynamic_cast<HttpRequest*>(virgin.header));
+    HttpRequest *adapted_request_ = nullptr;
+    HttpReply *adapted_reply_ = nullptr;
+    HttpRequest *virgin_request_ = (virgin.cause ? virgin.cause : dynamic_cast<HttpRequest*>(virgin.header));
     if (!(adapted_request_ = dynamic_cast<HttpRequest*>(adapted.header))) {
-        adapted_request_ = request_;
-        reply_ = dynamic_cast<HttpReply*>(adapted.header);
+        // if the request was not adapted, use virgin request to simplify
+        // the code further below
+        adapted_request_ = virgin_request_;
+        adapted_reply_ = dynamic_cast<HttpReply*>(adapted.header);
     }
 
-    Adaptation::Icap::History::Pointer h = (request_ ? request_->icapHistory() : NULL);
+    Adaptation::Icap::History::Pointer h = (virgin_request_ ? virgin_request_->icapHistory() : NULL);
     Must(h != NULL); // ICAPXaction::maybeLog calls only if there is a log
     al.icp.opcode = ICP_INVALID;
     al.url = h->log_uri.termedBuf();
     const Adaptation::Icap::ServiceRep  &s = service();
     al.icap.reqMethod = s.cfg().method;
 
-    al.cache.caddr = request_->client_addr;
+    al.cache.caddr = virgin_request_->client_addr;
 
-    al.request = request_;
+    al.request = virgin_request_;
     HTTPMSGLOCK(al.request);
     al.adapted_request = adapted_request_;
     HTTPMSGLOCK(al.adapted_request);
 
-    if (reply_) {
-        al.reply = reply_;
+    if (adapted_reply_) {
+        al.reply = adapted_reply_;
         HTTPMSGLOCK(al.reply);
     } else
         al.reply = NULL;
@@ -1302,30 +1303,34 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
         al.cache.ssluser = h->ssluser.termedBuf();
 #endif
     al.cache.code = h->logType;
-    // XXX: should use icap-specific counters instead ?
-    al.http.clientRequestSz.payloadData = h->req_sz;
+
+    const HttpMsg *virgin_msg = dynamic_cast<HttpReply*>(virgin.header);
+    if (!virgin_msg)
+        virgin_msg = virgin_request_;
+    assert(virgin_msg != virgin.cause);
+    al.http.clientRequestSz.header = virgin_msg->hdr_sz;
+    al.http.clientRequestSz.payloadData = virgin_msg->body_pipe->producedSize();
 
     // 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);
+        const uint64_t headerSize = max(zero, replyHttpHeaderSize);
+        const uint64_t bodySize =  max(zero, replyHttpBodySize);
+        al.icap.bodyBytesRead = headerSize + bodySize;
+        al.http.clientReplySz.header = headerSize;
+        al.http.clientReplySz.payloadData = bodySize;
     }
 
-    if (reply_) {
-        al.http.code = reply_->sline.status();
-        al.http.content_type = reply_->content_type.termedBuf();
-        if (replyHttpBodySize >= 0) {
-            // XXX: should use icap-specific counters instead ?
-            al.http.clientReplySz.payloadData = replyHttpBodySize;
-            al.http.clientReplySz.header =  reply_->hdr_sz;
+    if (adapted_reply_) {
+        al.http.code = adapted_reply_->sline.status();
+        al.http.content_type = adapted_reply_->content_type.termedBuf();
+        if (replyHttpBodySize >= 0)
             al.cache.highOffset = replyHttpBodySize;
-        }
         //don't set al.cache.objectSize because it hasn't exist yet
 
         MemBuf mb;
         mb.init();
-        reply_->header.packInto(&mb);
+        adapted_reply_->header.packInto(&mb);
         al.headers.reply = xstrdup(mb.buf);
         mb.clean();
     }
index 0209c2289b169b2155c6f12eab74b6dcf945faea..7319ccedcc873b91784bdc16e88c30c9a9fa04a3 100644 (file)
@@ -4519,13 +4519,35 @@ DOC_START
        ICAP transaction log lines will correspond to a single access
        log line.
 
-       ICAP log uses logformat codes that make sense for an ICAP
-       transaction. Header-related codes are applied to the HTTP header
-       embedded in an ICAP server response, with the following caveats:
-       For REQMOD, there is no HTTP response header unless the ICAP
-       server performed request satisfaction. For RESPMOD, the HTTP
-       request header is the header sent to the ICAP server. For
-       OPTIONS, there are no HTTP headers.
+       ICAP log supports many access.log logformat %codes. In ICAP context,
+       HTTP message-related %codes are applied to the HTTP message embedded
+       in an ICAP message. Logformat "%http::>..." codes are used for HTTP
+       messages embedded in ICAP requests while "%http::<..." codes are used
+       for HTTP messages embedded in ICAP responses. For example:
+
+               http::>h        To-be-adapted HTTP message headers sent by Squid to
+                               the ICAP service. For REQMOD transactions, these are
+                               HTTP request headers. For RESPMOD, these are HTTP
+                               response headers, but Squid currently cannot log them
+                               (i.e., %http::>h will expand to "-" for RESPMOD).
+
+               http::<h        Adapted HTTP message headers sent by the ICAP
+                               service to Squid (i.e., HTTP request headers in regular
+                               REQMOD; HTTP response headers in RESPMOD and during
+                               request satisfaction in REQMOD).
+
+       ICAP OPTIONS transactions do not embed HTTP messages.
+
+       Several logformat codes below deal with ICAP message bodies. An ICAP
+       message body, if any, typically includes a complete HTTP message
+       (required HTTP headers plus optional HTTP message body). When
+       computing HTTP message body size for these logformat codes, Squid
+       either includes or excludes chunked encoding overheads; see
+       code-specific documentation for details.
+
+       For Secure ICAP services, all size-related information is currently
+       computed before/after TLS encryption/decryption, as if TLS was not
+       in use at all.
 
        The following format codes are also available for ICAP logs:
 
@@ -4539,19 +4561,16 @@ DOC_START
                icap::rm        ICAP request method (REQMOD, RESPMOD, or 
                                OPTIONS). Similar to existing rm.
 
-               icap::>st       Bytes sent to the ICAP server (TCP payload
-                               only; i.e., what Squid writes to the socket).
+               icap::>st       The total size of the ICAP request sent to the ICAP
+                               server (ICAP headers + ICAP body), including chunking
+                               metadata (if any).
 
-               icap::<st       Bytes received from the ICAP server (TCP
-                               payload only; i.e., what Squid reads from
-                               the socket).
+               icap::<st       The total size of the ICAP response received from the
+                               ICAP server (ICAP headers + ICAP body), including
+                               chunking metadata (if any).
 
-               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::<bs       The size of the ICAP response body received from the
+                               ICAP server, excluding chunking metadata (if any).
 
                icap::tr        Transaction response time (in
                                milliseconds).  The timer starts when
@@ -4581,9 +4600,9 @@ DOC_START
        The default ICAP log format, which can be used without an explicit
        definition, is called icap_squid:
 
-logformat icap_squid %ts.%03tu %6icap::tr %>a %icap::to/%03icap::Hs %icap::<size %icap::rm %icap::ru% %un -/%icap::<A -
+logformat icap_squid %ts.%03tu %6icap::tr %>A %icap::to/%03icap::Hs %icap::<st %icap::rm %icap::ru %un -/%icap::<A -
 
-       See also: logformat, log_icap, and %adapt::<last_h 
+       See also: logformat and %adapt::<last_h
 DOC_END
 
 NAME: logfile_daemon
index 1fa2ea3a7aa47592dbcb4f31b0d43fbef6ce9b57..772bad9f9a995295c69f61505a1055b75ea55e36 100644 (file)
@@ -362,8 +362,6 @@ prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry::Pointer &aLo
     aLogEntry->http.method = request->method;
     aLogEntry->http.version = request->http_ver;
     aLogEntry->hier = request->hier;
-    if (request->content_length > 0) // negative when no body or unknown length
-        aLogEntry->http.clientRequestSz.payloadData += 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
@@ -400,6 +398,9 @@ ClientHttpRequest::logRequest()
         al->cache.objectSize = loggingEntry()->contentLen(); // payload duplicate ?? with or without TE ?
 
     al->http.clientRequestSz.header = req_sz;
+    // the virgin request is saved to al->request
+    if (al->request && al->request->body_pipe)
+        al->http.clientRequestSz.payloadData = al->request->body_pipe->producedSize();
     al->http.clientReplySz.header = out.headers_sz;
     // XXX: calculate without payload encoding or headers !!
     al->http.clientReplySz.payloadData = out.size - out.headers_sz; // pretend its all un-encoded data for now.
index 97484c232a7ad6097326abdcc457adc8c7090716..f007e982c975eaa7007c609c42c8d30a1017f0c0 100644 (file)
@@ -330,6 +330,25 @@ sslErrorName(Security::ErrorCode err, char *buf, size_t size)
 }
 #endif
 
+static const HttpMsg *
+actualReplyHeader(const AccessLogEntry::Pointer &al)
+{
+    const HttpMsg *msg = al->reply;
+    if (!msg && al->icap.reqMethod == Adaptation::methodReqmod)
+        msg = al->adapted_request;
+    return msg;
+}
+
+static const HttpMsg *
+actualRequestHeader(const AccessLogEntry::Pointer &al)
+{
+    if (al->icap.reqMethod == Adaptation::methodRespmod) {
+        // XXX: for now AccessLogEntry lacks virgin response headers
+        return nullptr;
+    }
+    return al->request;
+}
+
 void
 Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logSequenceNumber) const
 {
@@ -593,9 +612,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_REQUEST_HEADER:
-
-            if (al->request)
-                sb = al->request->header.getByName(fmt->data.header.header);
+            if (const HttpMsg *msg = actualRequestHeader(al))
+                sb = msg->header.getByName(fmt->data.header.header);
 
             out = sb.termedBuf();
 
@@ -614,15 +632,15 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-        case LFT_REPLY_HEADER:
-            if (al->reply)
-                sb = al->reply->header.getByName(fmt->data.header.header);
+        case LFT_REPLY_HEADER: {
+            if (const HttpMsg *msg = actualReplyHeader(al))
+                sb = msg->header.getByName(fmt->data.header.header);
 
             out = sb.termedBuf();
 
             quote = 1;
-
-            break;
+        }
+        break;
 
 #if USE_ADAPTATION
         case LFT_ADAPTATION_SUM_XACT_TIMES:
@@ -804,8 +822,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 #endif
         case LFT_REQUEST_HEADER_ELEM:
-            if (al->request)
-                sb = al->request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+            if (const HttpMsg *msg = actualRequestHeader(al))
+                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 
             out = sb.termedBuf();
 
@@ -823,18 +841,24 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-        case LFT_REPLY_HEADER_ELEM:
-            if (al->reply)
-                sb = al->reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+        case LFT_REPLY_HEADER_ELEM: {
+            if (const HttpMsg *msg = actualReplyHeader(al))
+                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 
             out = sb.termedBuf();
 
             quote = 1;
-
-            break;
+        }
+        break;
 
         case LFT_REQUEST_ALL_HEADERS:
-            out = al->headers.request;
+            if (al->icap.reqMethod == Adaptation::methodRespmod) {
+                // XXX: since AccessLogEntry::Headers lacks virgin response
+                // headers, do nothing for now
+                out = nullptr;
+            } else {
+                out = al->headers.request;
+            }
 
             quote = 1;
 
@@ -849,6 +873,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         case LFT_REPLY_ALL_HEADERS:
             out = al->headers.reply;
+            if (!out && al->icap.reqMethod == Adaptation::methodReqmod)
+                out = al->headers.adapted_request;
 
             quote = 1;