Re: Associating accesses with cache.log entries

I've put a basic proof-of-concept into a bug; see <http://bugs.squid-cache.org/show_bug.cgi?id=2835>.

It only logs client FDs, but gives output like this (with debug_options ALL,2):

2009/12/17 22:08:24 client_fd=13 ctx: enter level 0: 'client_fd=13'
2009/12/17 22:08:24 client_fd=13 Parser: retval 1: from 0->47: method 0->2; url 4->36; version 38->46 (1/1)
2009/12/17 22:08:24 client_fd=13 The request GET http://www.mnot.net/test/ is ALLOWED, because it matched 'localhost'
2009/12/17 22:08:24 client_fd=13 clientCacheHit: refreshCheckHTTPStale returned 1
2009/12/17 22:08:24 client_fd=13 peerSourceHashSelectParent: Calculating hash for 127.0.0.1
2009/12/17 22:08:28 client_fd=17 ctx: exit level 0
2009/12/17 22:08:28 client_fd=17 ctx: enter level 0: 'client_fd=17'
2009/12/17 22:08:28 client_fd=17 Parser: retval 1: from 0->35: method 0->2; url 4->24; version 26->34 (1/1)
2009/12/17 22:08:28 client_fd=17 The request GET http://www.apple.com/ is ALLOWED, because it matched 'localhost'
2009/12/17 22:08:28 client_fd=17 clientCacheHit: refreshCheckHTTPStale returned 0
2009/12/17 22:08:28 client_fd=17 clientCacheHit: HIT
2009/12/17 22:08:28 client_fd=17 The reply for GET http://www.apple.com/ is ALLOWED, because it matched 'all'
2009/12/17 22:08:29 ctx: exit level 0
2009/12/17 22:08:29 The reply for GET http://www.mnot.net/test/slow.cgi is ALLOWED, because it matched 'all'

Feedback / sanity checking appreciated.

On 25/02/2009, at 6:40 PM, Henrik Nordstrom wrote:

> ons 2009-02-25 klockan 12:10 +1100 skrev Mark Nottingham:
>
>> What am I missing? The most straightforward way that I can see to do
>> this is to add an identifier to clientHttpRequest and pass that to
>> debug where available...
>
> That is what ctx_enter is about... There is not a single location where
> ctx_enter needs to be called, there is many..
>
> Remember that Squid is a big bunch of event driven state machines, doing
> a little bit of processing at a time interleaved with many other
> unrelated things. ctx_enter indicates which state transition is
> currently being processed, ctx_leave when that state transition has
> completed waiting for next event (even if still at the same state..)
>
> So you need ctx_enter in quite many places, providing a reasonable trace
> of the processing within the state machine so far, based on whatever
> identifier the current small step is about. Each time the processing
> returns to the comm loop you are back at ctx level 0 with no context.
> Sometimes the ctx level may be quite high, having many loosely related
> state transitions in the trace, sometimes even almost completely
> unrelated requests.
>
> Most of the time the state machine starts with something directly
> related to a specific request (read/write on http sockets) however, but
> there is also many other kinds of state transitions like DNS, timers
> etc.
>
> Regards
> Henrik
>

--
Mark Nottingham       mnot_at_yahoo-inc.com