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.
Regards,
Christos
=== modified file 'src/AccessLogEntry.h'
--- src/AccessLogEntry.h 2010-05-02 19:32:42 +0000
+++ src/AccessLogEntry.h 2010-08-02 07:32:32 +0000
@@ -195,7 +195,7 @@
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,7 @@
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
+ int64_t bodyBytesRead; ///< number of ICAP body bytes read from ICAP server
HttpRequest* request; ///< ICAP request
HttpReply* reply; ///< ICAP reply
=== modified file 'src/HierarchyLogEntry.h'
--- src/HierarchyLogEntry.h 2010-06-03 07:49:20 +0000
+++ src/HierarchyLogEntry.h 2010-08-02 07:33:34 +0000
@@ -65,6 +65,7 @@
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
};
extern void hierarchyNote(HierarchyLogEntry *, hier_code, const char *);
=== modified file 'src/Server.cc'
--- src/Server.cc 2010-05-23 12:00:47 +0000
+++ src/Server.cc 2010-08-02 07:32:32 +0000
@@ -824,9 +824,27 @@
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) {
=== modified file 'src/Server.h'
--- src/Server.h 2010-05-23 12:00:47 +0000
+++ src/Server.h 2010-08-02 07:32:32 +0000
@@ -171,6 +171,8 @@
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 */
=== modified file 'src/adaptation/icap/ModXact.cc'
--- src/adaptation/icap/ModXact.cc 2010-06-15 07:21:57 +0000
+++ src/adaptation/icap/ModXact.cc 2010-08-02 07:32:44 +0000
@@ -45,7 +45,8 @@
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::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 @@
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 @@
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 @@
#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;
=== modified file 'src/adaptation/icap/ModXact.h'
--- src/adaptation/icap/ModXact.h 2010-06-15 07:21:57 +0000
+++ src/adaptation/icap/ModXact.h 2010-08-02 07:32:44 +0000
@@ -273,7 +273,8 @@
bool canStartBypass; // enables bypass of transaction failures
bool protectGroupBypass; // protects ServiceGroup-wide bypass of failures
- uint64_t replyBodySize; ///< dechunked ICAP reply body size
+ int64_t replyHttpHeaderSize; ///< size of HTTP header in ICAP reply
+ int64_t replyHttpBodySize; ///< size of dechunked HTTP body in ICAP reply
int adaptHistoryId; ///< adaptation history slot reservation
=== modified file 'src/adaptation/icap/OptXact.cc'
--- src/adaptation/icap/OptXact.cc 2010-06-14 20:01:59 +0000
+++ src/adaptation/icap/OptXact.cc 2010-08-02 07:32:44 +0000
@@ -109,6 +109,10 @@
{
// 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();
}
=== modified file 'src/cf.data.pre'
--- src/cf.data.pre 2010-07-29 13:04:44 +0000
+++ src/cf.data.pre 2010-08-02 07:42:15 +0000
@@ -2672,6 +2672,10 @@
[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 message body bytes received from the
+ next hop, excluding chunked transfer encoding
+ and control messages. Generated FTP 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
@@ -2847,6 +2851,13 @@
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
=== modified file 'src/log/access_log.cc'
--- src/log/access_log.cc 2010-07-28 17:51:26 +0000
+++ src/log/access_log.cc 2010-08-02 07:34:39 +0000
@@ -379,6 +379,7 @@
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 @@
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 @@
{">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 @@
{"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,13 @@
dooff = 1;
break;
+ case LFT_ICAP_BODY_BYTES_READ:
+ if (al->icap.bodyBytesRead >= 0) {
+ outoff = al->icap.bodyBytesRead;
+ dooff = 1;
+ }
+ break;
+
case LFT_ICAP_REQ_HEADER:
if (NULL != al->icap.request) {
sb = al->icap.request->header.getByName(fmt->data.header.header);
@@ -1089,6 +1100,12 @@
* quote = 1;
* break;
*/
+ case LFT_HTTP_BODY_BYTES_READ:
+ if (al->hier.bodyBytesRead >= 0) {
+ outoff = al->hier.bodyBytesRead;
+ dooff = 1;
+ }
+ break;
case LFT_SQUID_STATUS:
if (al->http.timedout || al->http.aborted) {
@@ -2093,7 +2110,8 @@
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);
