[squid-dev] [PATCH] Some failed transactions are not logged

[Alex Rousskov]

On 07/17/2016 03:34 AM, Amos Jeffries wrote:
> On 16/07/2016 2:40 a.m., Eduard Bagdasaryan wrote:
>> +    // do not log connections that sent us no bytes (TODO: make configurable)
>> +    // do not log connections that closed after a transaction (those are normal)
>> +    // XXX: We assume that all inBuf consumption cases were covered above.
>> +    if (inBuf.isEmpty())
>> +        return;

>  - the if (inBuf.isEmpty()) check is not right for "connections that
> sent us no bytes". 

Connections that sent us no bytes will have an empty inBuf and will not
be logged, just like the comment promises. The fact that some _other_
connections may also have an empty inBuf (and will not be logged) is
already implied by the second "do not log" comment. I agree that the two
comments do not cover all cases and so at least one more comment (or
code restructuring to cover all known cases) is needed, but the existing
comments appear to be correct.


> Squid can reach that test on an idle connection
> between HTTP requests (quite common situation). 

... which is already documented by the second "do not log" comment. The
grouped comments ought to be interpreted together, of course.


> That case also proves the XXX assumption is wrong.

The unsubstantiated (hence XXX) assumption is not about sent-nothing
(after start or after the last request) cases. It is difficult to
formulate it correctly without writing a whole paragraph, but we are
trying to say that if something goes into inBuf, then it can only be
consumed by cases covered by the two if-statements above the XXX. We
should reword or move that XXX to clarify.

Perhaps the following sketch that moves XXX up and details it a little
would work better?

>  // if we are parsing request body, its request is responsible for logging
> if (bodyPipe)
>   return;
> 
> // a request currently using this connection is responsible for logging
> if (!pipeline.empty() && pipeline.back()->mayUseConnection())
>   return;
> 
> /* Either we are waiting for the very first transaction, or
>  * we are done with the Nth transaction and are waiting for N+1st.
>  * XXX: We assume that if anything was added to inBuf, then it could
>  * only be consumed by actions already covered by the above checks.
>  */
> 
> // do not log connections that sent us no bytes (TODO: make configurable)
> // do not log connections that closed after a transaction (those are normal)
> // XXX: TLS bytes are consumed without going through inBuf
> // XXX: PROXY protocol bytes are consumed without going through inBuf
> if (inBuf.isEmpty())
>   return;


We agree that sent-nothing connections should be logged. I am not
against logging them by default (unless others have evidence to prove
that it would create too much noise). However, logging sent-nothing
connections probably requires a configuration option and can be
considered outside this patch scope -- the patch is improving access
logging without claiming to fix all access logging bugs.

If you are sure that logging all sent-nothing connections *without an
option to disable that behavior* is the right thing to do in v4, then
let's ask Eduard to cover that case using receivedFirstByte().


>   + which still leaves not-logging at least the cases where TLS bytes or
> such layered things have occured but no HTTP bytes yet (and the inBuf
> empty right now). That needs an explicit mention, and deserves an XXX or
> TODO (different than the "assumes ..." one.)

I agree that TLS should be either handled or explicitly excluded with an
XXX comment. Another potentially relevant case to handle or explicitly
exclude is the PROXY protocol, right? I added two XXXs to cover those in
the above sketch.


Thank you,

Alex.