Yeh, in fact let me follow-up on my comment about the missing ident in our log. I hacked out a couple of scripts to line up the Squidguard and squid logs here and my "eyeball" was wrong, there's no case in our log where ident occurred for squid and got lost for Squidguard. Usual caveats about rushed hacks apply of course:-) Further, I glanced at the squid code and I can see no "crack" down which the ident data can fall, i.e. I mean if it makes it to the log I can see no way, sort of catastrophic data corruption, that it won't make it to the redirector interface. I wasn't very convinced by your log extracts since, as far as I can tell, the timestamps aren't aligned.
I'm pretty sure we don't want to get into a discussion about ident (least I don't) but it's a pretty poor mechanism and it's pretty obvious from my logs that it doesn't work all the time especially for fast back-to-back requests. I've never traced it but I assume for back-to-back requests the client refuses the connection. I'm pretty sure your conclusion that ident client is unreliable is about right, I *think* we're processing about 25 million requests a week or thereabouts and ident is running but it's nothing like reliable enough to use for any production reports. Ian -----Original Message----- From: Jay Turner [mailto:[EMAIL PROTECTED]] Sent: Friday, October 04, 2002 10:38 To: Rick Matthews; [EMAIL PROTECTED] Subject: RE: ident It appears there maybe something with Squid not receiving the ident info. Just out of interest, I cleared my logs, disabled squidGuard and started using squid as a proxy only. I then ran Sarg over the logs (which can log ident info). Low and behold: Topsites Report Sites & Users Report NUM USERID CONNECT BYTES %BYTES IN-CACHE-OUT USED TIME MILISEC %TIME 1 date/time jturner 209 755.885 98.66% 1.66% 98.34% 00:01:38 98.888 99.93% 2 date/time 10.20.10.100 29 10.305 1.34% 100.00% 0.00% 00:00:00 66 0.07% TOTAL 238 766.190 2.98% 97.03% 00:01:38 98.954 29 of my 238 hits were recorded as coming from my IP and not my Ident. On examining the access.log for these records, I found that yes, some of these requests had no ident information. There are a number of different reasons why this might be: 1) The ident client on my machine is flaky (I'm using the NT ident service as listed on the Squid Software page) on Win2000 2) Squid is failing for some reason processing the ident information 3) Network issues Obviously some more investigation is required here. I will continue to use squid as a proxy only and re-activate the Ident debugging to see if I can obtain some more information. I am of the opinion that it maybe option number 1, as I would assume that if Squid had a problem with ident, more people would have mentioned it by now. But then again, maybe everyone just assumes it is working correctly and haven't bothered to actually check that it works 100% ?!?!? Heres a quick question for those on the list currently experiencing ident problems, what are the details of the ident clients you are running on your workstations. Maybe there could be some correlation there. Mine is: Identd-1.1.0 NT from http://freeware.teledanmark.no/identd/ Jay -----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED]]On Behalf Of Jay Turner Sent: Friday, 4 October 2002 3:01 PM To: Rick Matthews; [EMAIL PROTECTED] Subject: RE: ident Thanks for the tips Rick.... I have done what you said and below is the result of one request where the ident was not passed. As you can see the identReadReply looks fine but the redirectHandleRead does not include the user. Below this is a request that did work (i have turned off ACL debugging as it adds to much and I didn't think there would be any value in there.... i may be wrong) Ofcourse... I found it difficult to replicate it now that I want it to happen!! I kept pressing F5 until one of my requests returned the ident info then I grabbed the relevant lines from the cache.log. I have included two examples of each: <--------- Not Working ------------> 2002/10/04 14:51:18| redirectStart: 'http://www.porn.com/' 2002/10/04 14:51:18| helperDispatch: Request sent to redirector #1, 42 bytes 2002/10/04 14:51:18| helperHandleRead: 110 bytes from redirector #1. 2002/10/04 14:51:18| helperHandleRead: end of reply found 2002/10/04 14:51:18| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=&ur l=http://www.porn.com/ 10.20.10.100/- - GET} 2002/10/04 14:51:18| identReadReply: FD 18: Read '3159 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:51:18| redirectStart: 'http://10.20.10.223/js/deny.js' 2002/10/04 14:51:18| helperDispatch: Request sent to redirector #1, 54 bytes 2002/10/04 14:51:18| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:18| helperHandleRead: end of reply found 2002/10/04 14:51:18| redirectHandleRead: {} 2002/10/04 14:51:18| identReadReply: FD 18: Read '3160 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:51:18| redirectStart: 'http://10.20.10.223/logo.gif' 2002/10/04 14:51:18| helperDispatch: Request sent to redirector #1, 56 bytes 2002/10/04 14:51:18| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:18| helperHandleRead: end of reply found 2002/10/04 14:51:18| redirectHandleRead: {} 2002/10/04 14:51:18| redirectStart: 'http://10.20.10.223/scout.jpg' 2002/10/04 14:51:18| helperDispatch: Request sent to redirector #1, 51 bytes 2002/10/04 14:51:18| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:18| helperHandleRead: end of reply found 2002/10/04 14:51:18| redirectHandleRead: {} 2002/10/04 14:51:18| identReadReply: FD 19: Read '3161 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:56:19| redirectStart: 'http://www.porn.com/' 2002/10/04 14:56:19| helperDispatch: Request sent to redirector #1, 42 bytes 2002/10/04 14:56:19| helperHandleRead: 110 bytes from redirector #1. 2002/10/04 14:56:19| helperHandleRead: end of reply found 2002/10/04 14:56:19| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=&ur l=http://www.porn.com/ 10.20.10.100/- - GET} 2002/10/04 14:56:19| identReadReply: FD 18: Read '3180 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:56:19| redirectStart: 'http://10.20.10.223/js/deny.js' 2002/10/04 14:56:19| helperDispatch: Request sent to redirector #1, 54 bytes 2002/10/04 14:56:19| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:56:19| helperHandleRead: end of reply found 2002/10/04 14:56:19| redirectHandleRead: {} 2002/10/04 14:56:19| identReadReply: FD 18: Read '3181 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:56:19| redirectStart: 'http://10.20.10.223/logo.gif' 2002/10/04 14:56:19| helperDispatch: Request sent to redirector #1, 56 bytes 2002/10/04 14:56:19| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:56:19| helperHandleRead: end of reply found 2002/10/04 14:56:19| redirectHandleRead: {} 2002/10/04 14:56:19| redirectStart: 'http://10.20.10.223/scout.jpg' 2002/10/04 14:56:19| helperDispatch: Request sent to redirector #1, 51 bytes 2002/10/04 14:56:19| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:56:19| helperHandleRead: end of reply found 2002/10/04 14:56:19| redirectHandleRead: {} 2002/10/04 14:56:19| identReadReply: FD 19: Read '3182 , 8080 : USERID : WIN32 : jturner' <---------------------> <--------------- Working --------------> 002/10/04 14:46:53| redirectStart: 'http://www.porn.com/' 2002/10/04 14:46:53| helperDispatch: Request sent to redirector #1, 48 bytes 2002/10/04 14:46:53| helperHandleRead: 123 bytes from redirector #1. 2002/10/04 14:46:53| helperHandleRead: end of reply found 2002/10/04 14:46:53| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=jtu rner&url=http://www.porn.com/ 10.20.10.100/- jturner GET} 2002/10/04 14:46:53| redirectStart: 'http://10.20.10.223/js/deny.js' 2002/10/04 14:46:53| helperDispatch: Request sent to redirector #1, 54 bytes 2002/10/04 14:46:53| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:46:53| helperHandleRead: end of reply found 2002/10/04 14:46:53| redirectHandleRead: {} 2002/10/04 14:46:53| identReadReply: FD 18: Read '3155 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:46:53| redirectStart: 'http://10.20.10.223/logo.gif' 2002/10/04 14:46:53| helperDispatch: Request sent to redirector #1, 56 bytes 2002/10/04 14:46:53| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:46:53| helperHandleRead: end of reply found 2002/10/04 14:46:53| redirectHandleRead: {} 2002/10/04 14:46:53| redirectStart: 'http://10.20.10.223/scout.jpg' 2002/10/04 14:46:53| helperDispatch: Request sent to redirector #1, 51 bytes 2002/10/04 14:46:53| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:46:53| helperHandleRead: end of reply found 2002/10/04 14:46:53| redirectHandleRead: {} 2002/10/04 14:46:53| identReadReply: FD 19: Read '3156 , 8080 : USERID : WIN32 : jturner' 2002/10/04 14:51:54| redirectStart: 'http://www.porn.com/' 2002/10/04 14:51:54| helperDispatch: Request sent to redirector #1, 48 bytes 2002/10/04 14:51:54| helperHandleRead: 123 bytes from redirector #1. 2002/10/04 14:51:54| helperHandleRead: end of reply found 2002/10/04 14:51:54| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=jtu rner&url=http://www.porn.com/ 10.20.10.100/- jturner GET} 2002/10/04 14:51:54| redirectStart: 'http://10.20.10.223/js/deny.js' 2002/10/04 14:51:54| helperDispatch: Request sent to redirector #1, 60 bytes 2002/10/04 14:51:54| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:54| helperHandleRead: end of reply found 2002/10/04 14:51:54| redirectHandleRead: {} 2002/10/04 14:51:54| redirectStart: 'http://10.20.10.223/logo.gif' 2002/10/04 14:51:54| helperDispatch: Request sent to redirector #1, 56 bytes 2002/10/04 14:51:54| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:54| helperHandleRead: end of reply found 2002/10/04 14:51:54| redirectHandleRead: {} 2002/10/04 14:51:54| redirectStart: 'http://10.20.10.223/scout.jpg' 2002/10/04 14:51:54| helperDispatch: Request sent to redirector #1, 51 bytes 2002/10/04 14:51:54| helperHandleRead: 1 bytes from redirector #1. 2002/10/04 14:51:54| helperHandleRead: end of reply found 2002/10/04 14:51:54| redirectHandleRead: {} 2002/10/04 14:51:54| identReadReply: FD 19: Read '3162 , 8080 : USERID : WIN32 : jturner' <--------------------------> The only things that appear inconsistent are the byte size sent to the redirector 42 vs 48... could this be due to squid sending/not sending the ident info??? And the fact that the ident info is actually missing going to the redirector.. 2002/10/04 14:46:53| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=jtu rner&url=http://www.porn.com/ 10.20.10.100/- **jturner** GET} 2002/10/04 14:56:19| redirectHandleRead: {http://10.20.10.223/denied.php?client=10.20.10.100&user=&ur l=http://www.porn.com/ 10.20.10.100/- **-** GET} What do you make of this Rick? A problem in Squid? Cheers Jay -----Original Message----- From: Rick Matthews [mailto:[EMAIL PROTECTED]] Sent: Friday, 4 October 2002 10:17 AM To: [EMAIL PROTECTED]; [EMAIL PROTECTED] Subject: RE: ident Jay Turner wrote: > -----<snip>------- > Squid logs the ident for every request. By setting up a custom log on a > destination, I see that squidGuard only receives the ident information > sometimes. -----<snip>------- > Any ideas? -----<snip>------- I don't have the answers, but I think I can help. Add the following line to your squid.conf: 'debug_options ALL,1 28,9 29,9 30,9' (Note the spaces) Save the file and run 'squid -k reconfigure'. That will turn on the max debug level for: Section 28 - Access Control Section 29 - Redirector Section 30 - Ident (RFC 931) Fire up your browser and click a couple of links. (A couple of links gave me 2300 lines of debug data.) Comment out the debug_options line and 'squid -k reconfigure'. You'll find the information in your squid cache.log file. I really think this will identify what is happening when, and where the process is breaking down. I'd really like to hear what you find. Rick Matthews
