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

[Alex Rousskov]

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.


Cheers,

Alex.