Re: [RFC] connections logging

On 24/06/2014 12:26 p.m., Alex Rousskov wrote:
> On 06/20/2014 03:04 AM, Amos Jeffries wrote:
>> I am playing with the idea of adding a new log file to record just the
>> connections handled by Squid (rather than the HTTP request/reply
>> transactions).
>>
>> This log would include connections opened but never used, port details,
>> connection lifetimes, re-use counts on persistent connections, SSL/TLS
>> presence/version (or not), and other connection details we find a need
>> for later.
>
>
>> The driver behind this is to help resolve a growing amount of user
>> queries regarding "happy eyeballs" idle connections and broken TLS
>> connections. We are also adding other potentially never-used connections
>> ourselves with the standby pools.
>
> A couple of days ago, I came across another use case for logging
> connections unrelated to Happy Eyeballs. It sounds like this is going to
> be a generally useful feature. My use case is still being clarified, but
> here are the already known non-obvious requirements:
>
> 1. Logging when the connection is received (unlike transactions that are
> logged when the transaction is completed).
>
> 2. Logging client-to-Squid connections.
>
> 3. Introduction of some kind of unique connection ID that can be
> associated with HTTP/etc transactions on that connection, correlating
> access.log and connection.log entries. [ uniqueness scope is being
> clarified, but I hope it would just be a single worker lifetime ]
>

For IDs I was thinking of just emitting the MasterXaction::id value sent
in by TcpAcceptor. Assumign this is defined as the TCP transaction (see
below).

>
> Let's coordinate our efforts!
>

Sure.

>
>> The Squid native access.log appears unsuitable for adjustment given its
>> widely used format and the number of details to be logged.
>
> Agreed. We should support a similarly configurable log format and other
> existing logging knobs but use a different, dedicated log (or logs if we
> want to record from-Squid connections and to-Squid connections
> differently). Reusable logformat codes such as %la and %lp should be
> reused, but new ones will probably be needed as well.
>

Ack.

>
>> There is also a useful side effect of MasterXaction. At present the
>> TcpAcceptor generates a MasterXaction object to record initial
>> connection details for the handler, this creates a bit of complexity in
>> the recipient regarding whether the MasterXactino object applies to a
>> future HTTP request or one which is currently being parsed. This could
>> be simplified if the connection was a transaction and the HTTP requests
>> on it each a different transaction spawned from the connection
>> MasterXaction when parsing a new requst.
>
> I am not sure what you mean by "if the connection was a transaction".

I mean defining the TCP actions of opening a socket/connnection, its
entire lifetime, and close() as being one transaction. With the
TcpAcceptor produced MasterXaction representing that cycle.

HTTP requests arriving on the connection being separate transactions
spawned by the parsing actions. (unfortunately the read(2) does not
always nicely match a parse event identifying the exact HTTP request start).

So we have two new transaction types there. TCP transaction and HTTP
transaction, to go alongside ICAP and eCAP transaction etc.

> The MasterXaction is usually associated with at least one connection
> (via the small "t" transaction using that connection), and one
> connection is usually associated with at least one MasterTransaction,
> but transactions and connections are completely different concepts at
> Squid level IMO. I doubt we should try to merge the concept of a
> transaction and a connection somehow.

Generating the HTTP transaction MasterXaction object (child of
MasterXaction?) by cloning it from the TCP connection one represents
that relationship. The clone could be seeded with the parents id value
to persist that info for later use (eg your start of HTTP transaction
log entry).

>
> MasterTransaction is created at connection acceptance time because that
> is when the first HTTP/etc. transaction starts (parsing headers is not
> the first step) and, hence, that is when the master transaction starts.

Hmm. We have some issue here satisfying the people who want HTTP
transation only to represent the time of request+reply versus browser
happy eyeballs (and now Squid) opening standby connections with long
durations before first byte. That is one reason supporting separate
transaction MasterXaction for TCP and HTTP.

>
> We could make the connection acceptance event itself a transaction (an
> object of some new AcceptXaction class inherited from a generic
> Transaction class and associated with the corresponding Master
> Transaction object just like HTTP and ICAP transactions should be). I do
> not yet see what that would actually buy us except more classes to worry
> about, but, at the very least, it would not be conceptually wrong.
>

I agree accept by itself is probably useless. The longer TCP lifecycle
on the other hand (see above) has some use for stats and reporting.

Amos
Received on Tue Jun 24 2014 - 06:33:12 MDT