Re: [squid-users] How to debug external_acl_type

Hello,

Am 27.08.09 00:48, "Amos Jeffries" <squid3_at_treenet.co.nz> schrieb:

> I'd suggest:
> http_access deny !MyAcl
> http_access allow all

Now I got at least a WARNING:

2009/08/26 19:07:14| WARNING: Closing client 192.168.32.1 connection due to
lifetime timeout
2009/08/26 19:07:14| http://www.openbsd.org/

Squid.conf:
-----8<-----
external_acl_type myAclType %SRC %LOGIN /usr/local/bin/foobar
acl MyAcl external myAclType
http_access deny !MyAcl
http_access allow all

http_port 3128
debug_options ALL,1 82,9 4,9 28,9

hosts_file /etc/hosts
access_log /var/log/squid/access.log squid
coredump_dir /var/spool/squid
----->8-----

I return now "ERR" from Perl, but have also tried "OK".

/usr/local/bin/foobar:
-----8<-----
#!/usr/bin/perl

$|=1;

while (<>) {
  print "ERR";
}
----->8-----

Is this a problem: aclMatchExternal: myAclType user not authenticated (-1)
-----8<-----
2009/08/26 19:06:28| aclCheck: checking 'http_access deny !MyAcl'
2009/08/26 19:06:28| aclMatchAclList: checking !MyAcl
2009/08/26 19:06:28| aclMatchAcl: checking 'acl MyAcl external myAclType'
2009/08/26 19:06:28| aclMatchExternal: acl="myAclType"
2009/08/26 19:06:28| authenticateAuthenticate: header Basic Zm9vOmJhcg==.
2009/08/26 19:06:28| authenticateAuthenticate: This is a new checklist test
on FD:22
2009/08/26 19:06:28| authenticateAuthenticate: no connection authentication
type
2009/08/26 19:06:28| authenticateAuthUserRequestLock auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateAuthUserRequestLock auth_user request
'0x9feaf50' now at '1'.
2009/08/26 19:06:28| authenticateDecodeAuth: header = 'Basic Zm9vOmJhcg=='
2009/08/26 19:06:28| authenticateBasicDecodeAuth: cleartext = 'foo:bar'
2009/08/26 19:06:28| authBasicAuthUserFindUsername: Looking for user 'foo'
2009/08/26 19:06:28| authBasicDecodeAuth: Creating new user 'foo'
2009/08/26 19:06:28| authenticateAuthUserLock auth_user '0x9feaf80'.
2009/08/26 19:06:28| authenticateAuthUserLock auth_user '0x9feaf80' now at
'1'.
2009/08/26 19:06:28| authenticateAuthUserLock auth_user '0x9feaf80'.
2009/08/26 19:06:28| authenticateAuthUserLock auth_user '0x9feaf80' now at
'2'.
2009/08/26 19:06:28| authenticateValidateUser: Validating Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateValidateUser: Validated Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateValidateUser: Validating Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateValidateUser: Validated Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| User not authenticated or credentials need rechecking.
2009/08/26 19:06:28| authenticateValidateUser: Validating Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateValidateUser: Validated Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| User not authenticated or credentials need rechecking.
2009/08/26 19:06:28| aclAuthenticated: returning 0 sending credentials to
helper.
2009/08/26 19:06:28| aclMatchExternal: myAclType user not authenticated (-1)
2009/08/26 19:06:28| aclMatchAclList: no match, returning 0
2009/08/26 19:06:28| aclCheck: checking password via authenticator
2009/08/26 19:06:28| authenticateValidateUser: Validating Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateValidateUser: Validated Auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateStart: auth_user_request '0x9feaf50'
2009/08/26 19:06:28| authenticateStart: 'foo:bar'
2009/08/26 19:06:28| cbdataLock: 0x9fe6638
2009/08/26 19:06:28| authenticateAuthUserRequestLock auth_user request
'0x9feaf50'.
2009/08/26 19:06:28| authenticateAuthUserRequestLock auth_user request
'0x9feaf50' now at '2'.
----->8-----

More log output ...
-----8<-----
2009/08/26 19:07:14| fd_close FD 22 half-closed
2009/08/26 19:07:14| commSetEvents(fd=22)
2009/08/26 19:07:14| commCloseAllSockets: FD 25: Calling timeout handler
2009/08/26 19:07:14| WARNING: Closing client 192.168.32.1 connection due to
lifetime timeout
2009/08/26 19:07:14| http://www.openbsd.org/
2009/08/26 19:07:14| comm_close: FD 25
2009/08/26 19:07:14| commCallCloseHandlers: FD 25
2009/08/26 19:07:14| commCallCloseHandlers: ch->handler=0x806dd30
2009/08/26 19:07:14| cbdataValid: 0x9feb0a8
2009/08/26 19:07:14| connStateFree: FD 25
2009/08/26 19:07:14| httpRequestFree: [null_entry]
2009/08/26 19:07:14| cbdataUnlock: 0x9feb0a8
2009/08/26 19:07:14| cbdataUnlock: 0x9ddeb90
2009/08/26 19:07:14| cbdataUnlock: 0x9fec198
2009/08/26 19:07:14| authenticateAuthUserRequestUnlock auth_user request
'0x9fecf08'.
2009/08/26 19:07:14| authenticateAuthUserRequestUnlock auth_user_request
'0x9fecf08' now at '0'.
2009/08/26 19:07:14| authenticateAuthUserRequestFree: freeing request
0x9fecf08
2009/08/26 19:07:14| authenticateAuthUserUnlock auth_user '0x9feaf80'.
2009/08/26 19:07:14| authenticateAuthUserUnlock auth_user '0x9feaf80' now at
'2'.
2009/08/26 19:07:14| cbdataFree: 0x9feca18
2009/08/26 19:07:14| cbdataFree: 0x9feca18 has 1 locks, not freeing
2009/08/26 19:07:14| cleaning hdr: 0x9fec6ec owner: 2
2009/08/26 19:07:14| destroying entry 0x9fecec0: 'Host: www.openbsd.org'
2009/08/26 19:07:14| destroying entry 0x9fece18: 'User-Agent: Mozilla/5.0
(Macintosh; U; Intel Mac OS X 10_5_8; de-de) AppleWebKit/531.9 (KHTML, like
Gecko) Version/4.0.3 Safari/531.9'
2009/08/26 19:07:14| destroying entry 0x9fecd70: 'Accept:
application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image
/png,*/*;q=0.5'
2009/08/26 19:07:14| destroying entry 0x9fecd28: 'Accept-Language: de-de'
2009/08/26 19:07:14| destroying entry 0x9fecce0: 'Accept-Encoding: gzip,
deflate'
2009/08/26 19:07:14| destroying entry 0x9fecc98: 'Proxy-Authorization: Basic
Zm9vOmJhcg=='
2009/08/26 19:07:14| destroying entry 0x9fecc50: 'Connection: keep-alive'
2009/08/26 19:07:14| destroying entry 0x9fecc08: 'Proxy-Connection:
keep-alive'
2009/08/26 19:07:14| cbdataFree: 0x9fec198
2009/08/26 19:07:14| cbdataFree: Freeing 0x9fec198
2009/08/26 19:07:14| cbdataFree: 0x9feb0a8
2009/08/26 19:07:14| cbdataFree: 0x9feb0a8 has 1 locks, not freeing
2009/08/26 19:07:14| cbdataUnlock: 0x9feb0a8
2009/08/26 19:07:14| cbdataUnlock: Freeing 0x9feb0a8
2009/08/26 19:07:14| fd_close FD 25 Reading next request
2009/08/26 19:07:14| commSetEvents(fd=25)
2009/08/26 19:07:14| authenticateShutdown: shutting down auth schemes
2009/08/26 19:07:14| helperShutdown: basicauthenticator #1 is BUSY.
2009/08/26 19:07:14| comm_close: FD 8
2009/08/26 19:07:14| commCallCloseHandlers: FD 8
----->8-----

Best regards

Maik Kündig
Received on Thu Aug 27 2009 - 09:38:26 MDT