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

[Amos Jeffries]

On 19/07/2016 2:52 a.m., Alex Rousskov wrote:
> 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.
> 

It is. But also results in the TODO about implementing logging those
transactions which have not yet reeived reqeust headers / "first byte".
Resolving that TODO is easy and what I'm aiming at here.

> 
>> 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;
> 

That describes the situation better. +1.

> 
> 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().
> 

Logging them by default is something I think we should do.

As for config controlling them, that was what my questions about the
access_log ACLs abilities were for. Since Eduard has confirmed that
approach is useless, we will need a new config option added for this new
function/method to disable those log entries.


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

Yes, PROXY is a case to note.

Is ftp_port traffic another one?

I think thats all the current ways for a TCP client connection to
happen. I'm assuming UDP ones are out of scope here.

Thank you
Amos