Re: Associating accesses with cache.log entries

On Thu, Nov 27, 2008 at 4:21 AM, Mark Nottingham <mnot_at_yahoo-inc.com> 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);
>
> This leverages the sequence number that's available in custom access logs
> (%sn).
>
> It's really useful for debugging requests that are causing problems, etc;
> rather than having to correlate times and URLs, you can just correlate
> sequence numbers. It also makes it possible to automate debug output (which
> is the direction I want to take this in).

Looks interesting to me.

> beyond the obvious cleanup that needs to happen (e.g., outputting '-' or
> blank instead of 0 if there isn't an access log line associated, a few
> questions;
>
> * How do people feel about putting this in cache.log all the time? I don't
> think it'll break any scripts (there aren't many, and those that are tend to
> grep for specific phrases, rather than do an actual parse, AFAICT). Is the
> placement above appropriate?

I'd avoid the | character, but apart from that it makes sense to me

> * The sequence number mechanism doesn't guarantee uniqueness in the log
> file; if squid is started between rotates, it will reset the counters. Has
> fixing this been discussed?

I don't think that uniqueness has much value, correlating seqnum with
the timestamp will address any uncertain cases.

> * Is it reasonable to hardcode this to associate the numbers with the first
> configured access_log?
>
> * 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?

YES! It's something I've been thinking about for some time.
Count me in.

-- 
    /kinkie