[squid-users] external_acl_type, stops at externalAclLookup ?

Hello,

I'm trying to use external_acl_type with squid3 (debian linux,
3.0.STABLE8-3+lenny2) to get the username from an ip address (I'm
using transparent intercepting), so it can be used in the log (%ue).

Unfortunately it looks like squid3 does not get the result from the
external script.

I shrank the script to a minimum, just to isolate the problem:
##########################################
yankee:/var/log/squid3# cat /usr/local/bin/webl.pl
#!/usr/bin/perl
use warnings;
use strict;
$_=1;
while (<>) {
  print "OK\n";
  chomp;
  open(WEBL, ">>/tmp/webl");
  print WEBL "OK ($_)\n";
  close(WEBL);
}
##########################################

And when a client tries to access the web, /tmp/webl gets correctly written:
##########################################
yankee:/var/log/squid3# cat /tmp/webl
OK (192.168.168.221)
##########################################

The cache.log (I'm using debug ALL,9) shows this:
##########################################
2009/10/24 17:01:55.800| ACLChecklist::preCheck: 0x8d79838 checking
'http_access allow weblogin'
2009/10/24 17:01:55.800| ACLList::matches: checking weblogin
2009/10/24 17:01:55.800| ACL::checklistMatches: checking 'weblogin'
2009/10/24 17:01:55.800| aclMatchExternal: acl="weblogin_getuser"
2009/10/24 17:01:55.800| aclMatchExternal:
weblogin_getuser("192.168.168.221") = lookup needed
2009/10/24 17:01:55.800| aclMatchExternal: "192.168.168.221": entry=@0, age=0
2009/10/24 17:01:55.800| aclMatchExternal: "192.168.168.221": queueing a call.
2009/10/24 17:01:55.800| aclMatchExternal: "192.168.168.221": return -1.
2009/10/24 17:01:55.800| ACL::ChecklistMatches: result for 'weblogin' is -1
2009/10/24 17:01:55.800| ACLList::matches: result is false
2009/10/24 17:01:55.800| aclmatchAclList: 0x8d79838 returning false
(AND list entry failed to match)
2009/10/24 17:01:55.800| ACL::FindByName 'weblogin'
2009/10/24 17:01:55.800| ACLChecklist::asyncInProgress: 0x8d79838 async set to 1
2009/10/24 17:01:55.800| externalAclLookup: lookup in
'weblogin_getuser' for '192.168.168.221'
2009/10/24 17:01:55.800| cbdataLock: 0x8b01b80=2
2009/10/24 17:01:55.800| cbdataLock: 0x8d79838=1
2009/10/24 17:01:55.800| externalAclLookup: looking up for
'192.168.168.221' in 'weblogin_getuser'.
2009/10/24 17:01:55.800| cbdataLock: 0x8d82380=1
2009/10/24 17:01:55.800| cbdataReferenceValid: 0x8d82380
2009/10/24 17:01:55.800| comm_write: FD 9: sz 16: hndl 1: data 0x8b428f8.
2009/10/24 17:01:55.801| cbdataLock: 0x8b428f8=3
2009/10/24 17:01:55.801| commSetSelect(FD
9,type=2,handler=1,client_data=0xb6353458,timeout=0)
2009/10/24 17:01:55.801| helperDispatch: Request sent to
weblogin_getuser #1, 16 bytes
2009/10/24 17:01:55.801| helperSubmit: 192.168.168.221

2009/10/24 17:01:55.801| externalAclLookup: will wait for the result
of '192.168.168.221' in 'weblogin_getuser' (ch=0x8d79838).
##########################################
(yes, there's a blank line; squid3 apparently sends a \n with the %SRC
- if there's other part of the log I should look and/or post, please
let me know)

In a single occasion I could see a "read" from the script in the
cache.log, saying it got 11 bytes (correct, as I was using my
"complete" script and it returned "OK user=jsv". Unfortunately it
didn't include the "\n", which I found in this list is required, and
it did not work either.

On the client side (browser), there is no error; it just hangs waiting
for the site to respond until it timesout.

I tried with squid 2.7 (lenny), with the same results.

Here's the squid.conf:
##########################################
acl localhost src 127.0.0.1/32
acl to_localhost dst 127.0.0.0/8
acl localnet src 10.0.0.0/8
acl localnet src 192.168.0.0/16
acl SSL_ports port 443
acl Safe_ports port 80
acl CONNECT method CONNECT
#external_acl_type weblogin_getuser concurrency=0 children=3 ttl=600
negative_ttl=5 %SRC /usr/local/bin/weblogin_getuser.pl
external_acl_type weblogin_getuser concurrency=0 children=3 ttl=10
negative_ttl=10 %SRC /usr/local/bin/webl.pl
acl weblogin external weblogin_getuser
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
http_access deny to_localhost
http_access allow weblogin
#http_access allow localnet
http_access allow localhost
http_access deny all
icp_access deny all
htcp_access deny all
http_port 192.168.168.1:3128 transparent
http_port 192.168.169.1:3128 transparent
hierarchy_stoplist cgi-bin ?
cache_mem 0 MB
maximum_object_size_in_memory 0 KB
cache_dir null /var/spool/squid3 no-store
debug_options ALL,9
#uses external_acl_type to get %ue (username)
#logformat squid_ext %ts.%03tu %6tr %>a %Ss/%03Hs %<st %rm %ru %ue %Sh/%<A %mt
#access_log /var/log/squid3/access.log squid_ext
access_log /var/log/squid3/access.log squid
cache_store_log none
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern (cgi-bin|\?) 0 0% 0
refresh_pattern . 0 20% 4320
cachemgr_passwd disable all
coredump_dir /var/spool/squid3
##########################################

When I then shutdown squid3, the cache.log says the helper is BUSY,
and just before exiting, says the FD is WRITING.
##########################################
2009/10/24 17:02:43.751| helperShutdown: weblogin_getuser #1 is BUSY.
2009/10/24 17:02:43.751| helperShutdown: weblogin_getuser #2 shutting down.
(#2 and #3 get shutdown correctly...)
2009/10/24 17:02:43.755| fd_close FD 8 /var/log/squid3/access.log
2009/10/24 17:02:43.755| commSetSelect(FD
8,type=1,handler=0,client_data=0,timeout=0)
2009/10/24 17:02:43.755| commSetSelect(FD
8,type=2,handler=0,client_data=0,timeout=0)
2009/10/24 17:02:43.755| Open FD WRITING 9 webl.pl #1
2009/10/24 17:02:43.773| memCleanModule: 1004 items in 55 chunks and
54 pools are left dirty
2009/10/24 17:02:43.773| enter_suid: PID 29248 taking root priveleges
2009/10/24 17:02:43.774| leave_suid: PID 29248 called
2009/10/24 17:02:43.774| leave_suid: PID 29248 giving up root, becoming 'proxy'
2009/10/24 17:02:43.774| Squid Cache (Version 3.0.STABLE8): Exiting normally.
##########################################

Could it be something between the perl script and squid3?
##########################################
yankee:/var/log/squid3# ls -l /usr/local/bin/webl.pl
-rwxr-x--- 1 proxy proxy 160 Oct 24 17:01 /usr/local/bin/webl.pl
yankee:/var/log/squid3# perl --version
This is perl, v5.10.0 built for i486-linux-gnu-thread-multi
##########################################

Do you guys see something wrong?
Thanks!
Joao S Veiga
Received on Sat Oct 24 2009 - 19:23:51 MDT