Hi all.
I am sending the second version.
Amos Jeffries wrote:
* It took me a long while to see that the -1 values being used as
defaults were intended to be converted to dash in the long. Please
update all the relevant places to document that fact.
OK I add some documentation in various places
src/Server.cc:
ServerStateData::addVirginReplyBody(const char *data, ssize_t len)
{
+ adjustBodyBytesRead(+len);
whats with the +? we don't overload the unary operator anywhere and the
libc default is no-op AIUI. If len is required to be positive here thats
grounds for an abs(), Must() or assert() to prevent data corruption and
highlight the bugs.
the "+" removed
src/adaptation/icap/ModXact.cc:
src/cf.data.pre:
The use of [http::] is a bit congruous here. Since the body data is not
necessarily HTTP protocol from the receiver.
Given that there is no other obvious scope, can you change the docs to
say "HTTP-equivalent body data" from the upstream source? That should
allow then the comment about FTP listings.
OK. I modified a little the comment
As a corollary what about gopher/whois listings, and other internal
loaded/generated objects such as errors and icons?
Unfortunately the patch currently does not handle gopher and whois
protocols. I am not sure if it is useful, but if required, i think we
can include these protocols.
About the internal objects it logs a "-"
* I've been a bit uncomfortable since the beginning about the
de-chunking happening before the body bytes are accounted. This
introduces some loss into the protocol accounting apparently being done.
Are those lots bytes accounted for as headers? or is the total reply
bytes value going to be larger than the sum of headers+body ?
Do we stop at de-chunking? what about un-zipping? etc...
My opinion is that zipped and chunked data are not exactly the same.
Squid does not handle zipped and chunked data with the same way..
It's your implementation but I'm of the opinion this should log the
on-wire data size of the segment used for body. Including the chunking
bytes, and excluding the Squid-added markup bytes on FTP/Gopher listings.
Maybe in the future we will implement a "<rbs" (raw body bytes received)
log formating code...
Amos
=== modified file 'src/AccessLogEntry.h'
--- src/AccessLogEntry.h 2010-05-02 19:32:42 +0000
+++ src/AccessLogEntry.h 2010-08-04 08:03:34 +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,11 @@
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
=== modified file 'src/HierarchyLogEntry.h'
--- src/HierarchyLogEntry.h 2010-06-03 07:49:20 +0000
+++ src/HierarchyLogEntry.h 2010-08-04 07:49:14 +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 or -1
};
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-04 06:59:14 +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-04 07:54:42 +0000
@@ -45,7 +45,8 @@
bodyParser(NULL),
canStartBypass(false), // too early
protectGroupBypass(true),
- replyBodySize(0),
+ replyHttpHeaderSize(-1),// -1 if there is not any encapsulated message in ICAP reply
+ replyHttpBodySize(-1), // -1 if there is not any encapsulated message in ICAP reply
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-04 07:33:33 +0000
@@ -2672,6 +2672,11 @@
[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 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 +2852,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-04 07:21:59 +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,15 @@
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,
+ // (204 or option responses etc) so just print a "-"
+ 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 @@
* 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 (eg requests served from cache, or internal error messages).
+ // In this case just print a "-".
+ break;
case LFT_SQUID_STATUS:
if (al->http.timedout || al->http.aborted) {
@@ -2093,7 +2115,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);
