In the log entries I've seen and the ones below no ident was ever recorded on the access.log. The situation the SQUID FAQ refers to didn't occur here. Cleary, it could have but it didn't.
As for what a tail looked like, you're joking I presume? If not consider what the squid access.log entry contains and when the entry must have been written (ignoring such technical details as buffered IO). -----Original Message----- From: Rick Matthews [mailto:[EMAIL PROTECTED]] Sent: Friday, October 04, 2002 16:36 To: Ian Spare; [EMAIL PROTECTED]; [EMAIL PROTECTED] Subject: RE: ident >From http://www.squid-cache.org/Doc/FAQ/FAQ-15.html: Squid does not delay a request to wait for an ident lookup, unless you use the ident ACLs. Thus, it is very likely that the ident was not available at the time of calling the redirector, but became available by the time the request is complete and logged to access.log If you want to block requests waiting for ident lookup, try something like this: acl foo ident REQUIRED http_access allow foo --------- snip ------------ Adding the REQUIRED line gave me 100% coverage, where I didn't have it before. I guess I had assumed that the record in the access.log accurately reflected what was being sent to squidGuard, an audit trail, if you will. And I never would've have believed that they would go back and alter the log record after it was written! (I wonder what that looks like on a 'tail -f access.log'?) Rick > -----Original Message----- > From: [EMAIL PROTECTED] > [mailto:[EMAIL PROTECTED]]On Behalf Of Ian Spare > Sent: Friday, October 04, 2002 7:07 AM > To: '[EMAIL PROTECTED]'; '[EMAIL PROTECTED]' > Subject: RE: ident > > > > 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 > >
