Re: Associating accesses with cache.log entries

On 28/11/2008, at 7:19 AM, Henrik Nordstrom wrote:

> On tor, 2008-11-27 at 14:21 +1100, Mark Nottingham wrote:
>> I've been playing around with associating specific requests with the
>> debug output they generate, with a simple patch to _db_print along
>> these lines:
>>
>> if (Config.Log.accesslogs && Config.Log.accesslogs->logfile) {
>> seqnum = LOGFILE_SEQNO(Config.Log.accesslogs->logfile);
>> }
>> snprintf(f, BUFSIZ, "%s %i| %s",
>> debugLogTime(squid_curtime),
>> seqnum,
>> format);
>
> Hmm.. I don't really see how this implementation is different from a
> detailed timestamp.
>
> a) It's not associated with the current request, just the last request
> logged (or perhaps the next).
>
> b) There is no direct correlation between cache.log and access.log
> timing. Requests may well have notices in cache.log long before when
> they are logged.

Argh, yes, I should have realised this.

>> * Is it reasonable to hardcode this to associate the numbers with the
>> first configured access_log?
>
> I would argue that there needs to be a "request sequence number"
> associated early in the request processing, not related to access.log.
> Available for logging in access.log but not derived from there.

Agreed. How would you pass it into debug()? It looks like _db_print
already takes variable length args,

     _db_print_file(f, args1);
     _db_print_stderr(f, args2);
#if HAVE_SYSLOG
     _db_print_syslog(format, args3);
#endif

but I can't see anywhere where args2 or args3 is used in a casual
search. Is this just a historical thing, or have I missed some?

If there aren't any places where debug is actually doing different
things on file, stderr and syslog, we could change it where the target
log location(s) could be specified, perhaps by a bitmask; that would
least to something like

debug(format, req_seq?, target?)

>> * To make this really useful, it would be necessary to be able to
>> trigger debug_options (or just all debugging) based upon an ACL
>> match.
>> However, this looks like it would require changing how debug is
>> #defined. Any comments on this?
>
> Time to add some lua hooks? (or similar)

I'm not against them as such, but wonder if the overhead on every
debug call (even after the filtering currently done) will be
acceptable, in this case. I was just wondering what the impact of
slotting a fast acl check in at the top of _db_print would be...

--
Mark Nottingham       mnot_at_yahoo-inc.com