Re: [squid-dev] [PATCH] Incorrect logging of request size
On 16/09/2016 7:21 a.m., Alex Rousskov wrote: > On 09/15/2016 12:25 PM, Eduard Bagdasaryan wrote: >> 2016-09-13 20:42 GMT+03:00 Alex Rousskov >> : >>> Committed to trunk (r14838) >> >> I am attaching v3.5 port of this r14838 and also r14839 and r14840, >> containing several related fixes. > > Amos, are you willing to include this fix in v3.5? It is fairly small, > but ModXact::finalizeLogInfo() changes are difficult (for me) to check. > > Alex. > I was hoping to let it slide. But since you ask, it is applied as 3.5 rev.14082 Amos ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 09/15/2016 12:25 PM, Eduard Bagdasaryan wrote: > 2016-09-13 20:42 GMT+03:00 Alex Rousskov > : >> Committed to trunk (r14838) > > I am attaching v3.5 port of this r14838 and also r14839 and r14840, > containing several related fixes. Amos, are you willing to include this fix in v3.5? It is fairly small, but ModXact::finalizeLogInfo() changes are difficult (for me) to check. Alex. ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
2016-09-13 20:42 GMT+03:00 Alex Rousskov :
> Committed to trunk (r14838)
I am attaching v3.5 port of this r14838 and also r14839 and r14840,
containing several related fixes.
Eduard.
Fix logged request size (%http::>st) and other size-related %codes.
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 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::" 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::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.
This is a v3.5 port of trunk r14838, r14839 and r14840.
=== modified file 'src/adaptation/icap/ModXact.cc'
--- src/adaptation/icap/ModXact.cc 2016-01-01 00:14:27 +
+++ src/adaptation/icap/ModXact.cc 2016-09-15 10:48:05 +
@@ -1232,125 +1232,130 @@
}
Adaptation::Icap::ModXact::~ModXact()
{
delete bodyParser;
}
// internal cleanup
void Adaptation::Icap::ModXact::swanSong()
{
debugs(93, 5, HERE << "swan sings" << status());
stopWriting(false);
stopSending(false);
if (theInitiator.set()) // we have not sent the answer to the initiator
detailError(ERR_DETAIL_ICAP_XACT_OTHER);
// update adaptation history if start was called and we reserved a slot
Adaptation::History::Pointer ah = virginRequest().adaptLogHistory();
if (ah != NULL && adaptHistoryId >= 0)
ah->recordXactFinish(adaptHistoryId);
Adaptation::Icap::Xaction::swanSong();
}
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(virgin.header));
+HttpRequest *adapted_request_ = nullptr;
+HttpReply *adapted_reply_ = nullptr;
+HttpRequest *virgin_request_ = (virgin.cause ? virgin.cause : dynamic_cast(virgin.header));
if (!(adapted_request_ = dynamic_cast(adapted.header))) {
-adapted_request_ = request_;
-reply_ = dynamic_cast(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(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;
if (h->rfc931.size())
al.cache.rfc931 = h->rfc931.termedBuf();
#if USE_OPENSSL
if (h->ssluser.size())
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(virgin.header);
+if (!virgin_msg)
+
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 09/13/2016 10:02 AM, Amos Jeffries wrote: > On 14/09/2016 2:52 a.m., Alex Rousskov wrote: >>> http::>h >>> To-be-adapted HTTP message headers sent by Squid to >>> the ICAP service (HTTP request headers in REQMOD; HTTP >>> response headers in RESPMOD). Please note that Squid >>> currently does not support logging of HTTP response >>> headers in RESPMOD for this format code. >> I will clarify that when committing: >> >> http::>h To-be-adapted HTTP message headers sent by Squid to the ICAP >> service (i.e., HTTP request headers in REQMOD or HTTP response headers >> in RESPMOD). However, Squid cannot currently log HTTP response headers >> sent to the ICAP service (i.e., %http::>h will expand to "-" for RESPMOD >> transactions). >> >> Does that sound better? > Better, but I think remove the words "or HTTP response headers in > RESPMOD" from that first statement. The second sentence now explains the > RESPMOD clearly all by itself. Committed to trunk (r14838) with the following text: > 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). Thank you, Alex. ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 14/09/2016 2:52 a.m., Alex Rousskov wrote: > On 09/12/2016 10:06 PM, Amos Jeffries wrote: >> Just the new cf.data.pre docs for icap_log contradicting itself: >> >> " >> http::>h ... >> HTTP response headers in RESPMOD) ... >> currently does not support logging of HTTP response headers in >> RESPMOD ... >> " >> >> I think that should probably be saying it does not support HTTP >> *request* headers in RESPMOD. > > I assume you are talking about this blob: Yes. > >> http::>h >> To-be-adapted HTTP message headers sent by Squid to >> the ICAP service (HTTP request headers in REQMOD; HTTP >> response headers in RESPMOD). Please note that Squid >> currently does not support logging of HTTP response >> headers in RESPMOD for this format code. > > I will clarify that when committing: > > http::>h To-be-adapted HTTP message headers sent by Squid to the ICAP > service (i.e., HTTP request headers in REQMOD or HTTP response headers > in RESPMOD). However, Squid cannot currently log HTTP response headers > sent to the ICAP service (i.e., %http::>h will expand to "-" for RESPMOD > transactions). > > Does that sound better? > Better, but I think remove the words "or HTTP response headers in RESPMOD" from that first statement. The second sentence now explains the RESPMOD clearly all by itself. Amos ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 09/12/2016 10:06 PM, Amos Jeffries wrote: > Just the new cf.data.pre docs for icap_log contradicting itself: > > " > http::>h... > HTTP response headers in RESPMOD) ... > currently does not support logging of HTTP response headers in > RESPMOD ... > " > > I think that should probably be saying it does not support HTTP > *request* headers in RESPMOD. I assume you are talking about this blob: > http::>h > To-be-adapted HTTP message headers sent by Squid to > the ICAP service (HTTP request headers in REQMOD; HTTP > response headers in RESPMOD). Please note that Squid > currently does not support logging of HTTP response > headers in RESPMOD for this format code. I will clarify that when committing: http::>h To-be-adapted HTTP message headers sent by Squid to the ICAP service (i.e., HTTP request headers in REQMOD or HTTP response headers in RESPMOD). However, Squid cannot currently log HTTP response headers sent to the ICAP service (i.e., %http::>h will expand to "-" for RESPMOD transactions). Does that sound better? If the above polished version does not clarify things enough, here is what is going on: * The logformat %code is for logging HTTP message headers sent by Squid to the ICAP service. That will not change and is now properly documented. What are those to-be-adapted HTTP headers? They are HTTP request headers in REQMOD and HTTP response headers in RESPMOD. We did not have to say that, but providing that detail is helpful IMO. * However, currently, Squid cannot log HTTP response headers sent by Squid to the ICAP service. The admin will always see "-" in that specific case. Hopefully, that support will be added in the future. For now, we just document the lack of support in that particular case. Thank you, Alex. ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 13/09/2016 12:11 p.m., Alex Rousskov wrote: > On 09/01/2016 03:44 PM, Eduard Bagdasaryan wrote: >> Hello, >> >> This patch fixes logged request size (%http::>st) and other size-related >> %codes. >> >> 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::> 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::> 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::> 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::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. > > > I cannot track the effects of all the proposed low-level fixes, of > course, but no changes jumped at me as wrong. IIRC, Eduard tried quite a > few test cases in hope to weed out the bugs. The underlying code was in > poor shape, on several levels. This patch does not solve all the > problems, but at least Squid should stop lying about several sizes that > folks are often monitoring (and some icap.log codes should be > interpreted in a more consistent/orderly fashion). > > I have not seen any public reviews for this patch. If there are no > last-minute objections, I will commit these important fixes to trunk soon. I've also not had time to do any thorough check, but with a quick read-through nothing stands out as broken. Just the new cf.data.pre docs for icap_log contradicting itself: " http::>h ... HTTP response headers in RESPMOD) ... currently does not support logging of HTTP response headers in RESPMOD ... " I think that should probably be saying it does not support HTTP *request* headers in RESPMOD. Amos ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
Re: [squid-dev] [PATCH] Incorrect logging of request size
On 09/01/2016 03:44 PM, Eduard Bagdasaryan wrote: > Hello, > > This patch fixes logged request size (%http::>st) and other size-related > %codes. > > 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:: 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:: 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:: 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::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. I cannot track the effects of all the proposed low-level fixes, of course, but no changes jumped at me as wrong. IIRC, Eduard tried quite a few test cases in hope to weed out the bugs. The underlying code was in poor shape, on several levels. This patch does not solve all the problems, but at least Squid should stop lying about several sizes that folks are often monitoring (and some icap.log codes should be interpreted in a more consistent/orderly fashion). I have not seen any public reviews for this patch. If there are no last-minute objections, I will commit these important fixes to trunk soon. Cheers, Alex. ___ squid-dev mailing list squid-dev@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-dev
