[squid-users] Unreliable Ident lookups on Squid 3.5?

[Anders Gustafsson]

Hi!

This is my first post to this list so I apologise in advance if I have inadvertently left out something :)

squid-3.5.12-20151128-r13959 running on OpenSuse 13.2 and SuSE 12

What we are trying to do is to implement squid in a school district so that they can get reasonable statistics of web usage and be able to track traffic per user. There will be no filtering or blocking.

Most of the clients are windows boxes so we settled on using ident, with a fallback to LDAP in case the ident daemon is not running. The whole setup worked very well in testing, but when we tried to add more workstations for testing we found that the LDAP authenticator would pop up for some page element on more complex pages, say newspapers and such.

When looking at the logs we saw:

2016/01/15 12:17:13.635 kid1| 28,5| Acl.cc(138) matches: checking http_access#6
2016/01/15 12:17:13.635 kid1| 28,5| Acl.cc(138) matches: checking identhosts
2016/01/15 12:17:13.635 kid1| 28,7| UserData.cc(22) match: user is -, case_insensitive is 0
2016/01/15 12:17:13.635 kid1| 28,3| Acl.cc(158) matches: checked: identhosts = 0
2016/01/15 12:17:13.635 kid1| 28,3| Acl.cc(158) matches: checked: http_access#6 = 0

Even if Squid had gotten an identity just seconds ago:

2016/01/15 12:17:01.470 kid1| 28,5| Acl.cc(138) matches: checking http_access#6
2016/01/15 12:17:01.470 kid1| 28,5| Acl.cc(138) matches: checking identhosts
2016/01/15 12:17:01.470 kid1| 28,3| AclIdent.cc(115) checkForAsync: Doing ident lookup
2016/01/15 12:17:01.470 kid1| 30,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Ident::ConnectDone constructed, this=0x2adab30 [call120992]
2016/01/15 12:17:01.470 kid1| 28,3| AclIdent.cc(69) match: switching to ident lookup state
2016/01/15 12:17:01.470 kid1| 28,3| Acl.cc(158) matches: checked: identhosts = -1 async
2016/01/15 12:17:01.470 kid1| 28,3| Acl.cc(158) matches: checked: http_access#6 = -1 async
2016/01/15 12:17:01.470 kid1| 28,3| Acl.cc(158) matches: checked: http_access = -1 async
2016/01/15 12:17:01.471 kid1| 30,3| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(137) will call Ident::ConnectDone(local=10.0.20.73:50154 remote=10.0.20.50:113 FD 112 flags=1, data=0x1e426f8) [call120992]
2016/01/15 12:17:01.471 kid1| 30,3| AsyncCallQueue.cc(55) fireNext: entering Ident::ConnectDone(local=10.0.20.73:50154 remote=10.0.20.50:113 FD 112 flags=1, data=0x1e426f8)
2016/01/15 12:17:01.471 kid1| 30,3| AsyncCall.cc(38) make: make call Ident::ConnectDone [call120992]
2016/01/15 12:17:01.471 kid1| 30,3| AsyncCallQueue.cc(57) fireNext: leaving Ident::ConnectDone(local=10.0.20.73:50154 remote=10.0.20.50:113 FD 112 flags=1, data=0x1e426f8)
2016/01/15 12:17:01.471 kid1| 30,5| Ident.cc(168) WriteFeedback: local=10.0.20.73:50154 remote=10.0.20.50:113 FD 112 flags=1: Wrote IDENT request 13 bytes.
2016/01/15 12:17:01.479 kid1| 30,5| Ident.cc(206) ReadReply: local=10.0.20.73:50154 remote=10.0.20.50:113 FD 112 flags=1: Read '54451 , 8080 : USERID : WIN32 : Dalton'
2016/01/15 12:17:01.479 kid1| 28,5| InnerNode.cc(94) resumeMatchingAt: checking http_access at 5
2016/01/15 12:17:01.479 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/0is not banned
2016/01/15 12:17:01.479 kid1| 28,5| InnerNode.cc(94) resumeMatchingAt: checking http_access#6 at 0
2016/01/15 12:17:01.479 kid1| 28,5| Acl.cc(138) matches: checking identhosts
2016/01/15 12:17:01.479 kid1| 28,7| UserData.cc(22) match: user is Dalton, case_insensitive is 0
2016/01/15 12:17:01.479 kid1| 28,7| UserData.cc(28) match: aclMatchUser: user REQUIRED and auth-info present.
2016/01/15 12:17:01.479 kid1| 28,3| Acl.cc(158) matches: checked: identhosts = 1

I have looked at the source, but not been able to figure out (yet) by what means acl.cc calls userdata.cc and from where it picks the username.

Any ideas?