Re: [PATCH] Enhanced access logging, added ICAP logging, bug #2495 fix.

Alex Rousskov wrote:
> On 07/09/2009 12:06 AM, Amos Jeffries wrote:
>> Tsantilas Christos wrote:
>>> This is the second part of the 3p1-plus patch. This patch include:
>>>
>>> - Enhanced access logging
>>> (<Hs, <sh, >sh, <pt, <tt, icap::total_time, and icap::<last_h)
>>>
>>> - ICAP logging
>>> (see icap_log and log_icap in squid.conf as well as
>>> http://wiki.squid-cache.org/Features/AdaptationLog).
>>>
>>> - ICAP retries based on the ICAP responses status code
>>> (see icap_retry and icap_retry_limit in squid.conf).
>>>
>>> - Support logging resp. times of adaptation transactions to access.log
>>> (%adaptation::sum_trs and %adaptation::all_trs)
>>>
>> IMO full 'adaptation' is too long. Opinions on using the abbreviation
>> 'adapt::' here?
>
> Either way is fine with me. If Christos does not prefer the full
> version, let's change to adapt::
>
>>> - Support logging of total DNS wait time to access.log
>>> (%dt)
>>>
>> +1.
>>
>> The only sightly better but harder way is to make this DnsLookupDetails
>> object the DNS cbdata object itself, and contain the RR being fetched as
>> a sub-field. That would keep the error per-fetch not per transaction.
>> If someone wants to simplify the code later theres a project.
>>
>> Meanwhile go with this.
>
> I think I have started with something similar but then realized that
> different parts of the code (e.g., IP cache and FQDN cache) need
> different objects to store the actual lookup result. They also use
> pointers into caches that may not survive across async calls (because
> the cache may change) so storing the result would require allocating
> memory or locking cache entries for a "long" time.
>
> At some point, I made DnsLookupResult store and then forget the RR-level
> details when crossing the async boundary. That code looked somewhat
> over-engineered to me.
>
> This is why I eventually limited the DnsLookupDetails object to the
> details that need to cross the async call boundaries and are common to
> all lookup users.
>
> I do not mean to discourage others from trying to add RR or derivative
> results to DnsLookupDetails. Just keep the above in mind.
>
>
>>> - Bug #2495 fix
>> Oops; bug is: 2459: dns_error_message global does not work...
>
> My fault. I had it backwards in some of the notes that Christos inherited.
>
>
>> ** Please make fqdncache_entry / ipcache_entry public classes instead
>> of functional structs. Some gcc complain and doxygen won't document
>> their functions properly.
>
> Sorry, I am not sure what you mean. What is a "functional struct"? Do
> you want us to replace "struct fqdncache_entry" with "class
> fqdncache_entry" and add "public:"?

Yes exactly.

>
> No objections, of course, just wanted to minimize merging headaches by
> keeping out-of-scope changes to the minimum...
>
>
>>> I also have some questions to developers:
>>> - In squid.conf documentation I prepend each
>>> HTTP format code with [http::]
>>> Is it OK?
>> Most of them yes.
>>
>> There are a few where http:: does not make sense at all:
>> ts Seconds since epoch
>> tu subsecond time (milliseconds)
>> tl Local time. Optional strftime format argument
>> tg GMT time. Optional strftime format argument
>
> Definitely.
>
>> dt Total time spent making DNS lookups (milliseconds)
>> ui User name from ident
>> us User name from SSL
>
> Yeah, at least for now.
>
>> These are also borderline:
>> >a Client source IP address
>> >A Client FQDN
>> >p Client source port
>> la Local IP address (http_port)
>> lp Local port number (http_port)
>> <A Server IP address or peer name
>
> Agreed.
>
>> I'm fine with ignoring http:: for now if people do enter it for these,
>> so no coding change. But I don't think we should document them that way.
>
> Agreed.
>
>> I'd shift the clearly HTTP ones out to a section like you have ICAP.
>> Leaving the rest prefix-ambiguous until something is done properly.
>
> Or at least remove the http:: prefix in the documentation from those
> mentioned above.

That makes a bit of a mess in the list with mixing prefixed and
non-prefixed. I think the sections look good and are easily
understandable the way Christos did the icap:: and adaptation::

>>> - Should we replace icap::Hs with icap::<Hs ? Any opinion?
>>> (My opinion is we should not because the icap::>Hs does not make
>>> sense)
>> Agreed. Makes no sense at this time.
>
> OK.
>
>> In src/AccessLogEntry.h:
>> struct IpAddress => remove the "struct", it's a class in 3.1+.
>
> OK.
>
>> Where an existing short measure tag I don't think we need to add a new
>> long one yet:
>> icap::total_time / icap::tt
>> icap::>size / icap::>st
>> icap::<size / icap::<st
>
> OK.
>
>> adaptation::sum_trs / adaptation::tt
>
> These are very different! Tt is a single value while adapt::sum_trs is a
> list (of individual tr's). Adapt::sum_trs is also symmetric with
> adapt::all_trs (also a list, but possibly with more entries).

You sure?
   I spent a while trying to figure out what all_trs and sum_trs were
and it looked like all_trs was the list and sum_trs was the single-value
sum of them.

If I did get it wrong, then the tt reduction still applies, but to the
other option...

>
>> Yes they are not ideal, but they are there and what people are used to
>> for now. We can minimize confusion a bit.
>
> OK.
>
>
>> I think at the point you do:
>> + case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
>> + debugs(46, 0, "WARNING: the \"Hs\" formating code is deprecated
>> use the \">Hs\" instead");
>> + break;
>>
>> you could also set
>> "lt->type = LFT_HTTP_SENT_STATUS_CODE;" to reduce the need for that
>> OLD_30 type being used outside the parse. Particularly during the config
>> dump later it is useful to display what its supposed to be.
>
> Sounds good.
>
>> I spy a goto that can die...
>> case CLF_NONE:
>> goto last;
>> @@ -1458,7 +1863,15 @@
>> last:
>> (void)0; /* NULL statement for label */
>> +}
>>
>> ==> equates to "return;". Please check for others in that same function.
>
> Sounds kind of out of scope but no objections if Christos agrees.
>
>
>> I see: "// TODO: should we disable unneeded _parts_ of the history?"
>> the glib answer is yes. By appearances there was some disabling of the
>> logging code already done. If thats all I think the TODO can go. If
>> there is more to be done towards that, leave it and the rest for 3.2+
>
> There is more to be done. IIRC, the current code enables [whole] history
> if it is needed by at least one of the history users. In some (but not
> all) contexts, this will cause other users to update the history even if
> the part they are updating may never be used. I do not think I managed
> to kill all such cases -- the inter-dependencies and multiple levels of
> users/updaters make that relatively complex.
>
> IMO, it is not a big problem for now, but if the history grows, we may
> have to do better. I would leave that TODO.

OK.

>
>> most icap file:
>> Anything including acl/FilledChecklist.h does not need to also
>> include acl/Checklist.h.
>
> OK.
>
> Thanks a lot for reviewing this large patch!
>

Amos

-- 
Please be using
   Current Stable Squid 2.7.STABLE6 or 3.0.STABLE16
   Current Beta Squid 3.1.0.9