Re: Associating accesses with cache.log entries

2009-12-17 Thread Mark Nottingham
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   m...@yahoo-inc.com




Re: Associating accesses with cache.log entries

2009-12-17 Thread Mark Nottingham
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   m...@yahoo-inc.com
 
 

--
Mark Nottingham   m...@yahoo-inc.com