[squid-dev] [PATCH] Incorrect logging of request size

[Amos Jeffries]

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::<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.
> 
> 
> 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