Re: Associating accesses with cache.log entries

I've made some progress on this, now adding a request identifier and putting that in the context (see updated patch in bug).

I'm willing to see this through, but I'd like a bit of feedback first -- especially around whether this (i.e., sprinkling ctx_* calls throughout the codebase wherever we have a callback) is the right approach, first.

Cheers,

On 17/12/2009, at 10:24 PM, Mark Nottingham wrote:

> 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
>
>

--
Mark Nottingham       mnot_at_yahoo-inc.com