[squid-users] Squid behaviour with external_acl_type

Sat Mar 28 15:55:17 UTC 2015

Hello,

I am faced with a weird situation with an external acl that I have built.

The external acl gets the acl name and the IP information, does a lookup in
a MySQL table if that IP belongs to a group ( read: acl name ) and returns
an output.

The situation is as follows:
 On the first client request coming to the external helper, it performs as
expected, and the correct action is taken. Whereas from the second request
onwards, Squid just waits on the external acl, even though a response was
sent by the acl, and the same was received by Squid.

My acl's are as follows:
external_acl_type grpname ttl=10 children-startup=1 concurrency=1 %SRC %ACL
/usr/local/squid/libexec/grpname_helper
acl two external grpname
acl twoext urlpath_regex
"/usr/local/squid/etc/custom/blacklisted-two-extensions"
deny_info http://192.168.3.11/error.html two
http_access deny twoext two

The debug output for the first request coming in:
2015/03/28 20:11:30.831 kid1| external_acl.cc(868) aclMatchExternal:
grpname("192.168.3.243 two") = lookup needed
2015/03/28 20:11:30.831 kid1| external_acl.cc(871) aclMatchExternal:
"192.168.3.243 two": queueing a call.
2015/03/28 20:11:30.831 kid1| external_acl.cc(1453) Start: fg lookup in
'grpname' for '192.168.3.243 two'
2015/03/28 20:11:30.832 kid1| external_acl.cc(1508) Start:
externalAclLookup: looking up for '192.168.3.243 two' in 'grpname'.
2015/03/28 20:11:30.832 kid1| helper.cc(1208) GetFirstAvailable:
GetFirstAvailable: Running servers 1
2015/03/28 20:11:30.832 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall
helperDispatchWriteDone constructed, this=0x9db91e8 [call2903]
2015/03/28 20:11:30.832 kid1| Write.cc(29) Write: local=[::] remote=[::] FD
22 flags=1: sz 20: asynCall 0x9db91e8*1
2015/03/28 20:11:30.832 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2,
handler=1, client_data=0x970522c, timeout=0
2015/03/28 20:11:30.832 kid1| helper.cc(1350) helperDispatch:
helperDispatch: Request sent to grpname #Hlpr0, 18 bytes
2015/03/28 20:11:30.833 kid1| external_acl.cc(1518) Start:
externalAclLookup: will wait for the result of '192.168.3.243 two' in
'grpname' (ch=0x985f400).
2015/03/28 20:11:30.833 kid1| external_acl.cc(874) aclMatchExternal:
"192.168.3.243 two": return -1.
2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: two = -1 async
2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: http_access#1 =
-1 async
2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: http_access =
-1 async
2015/03/28 20:11:30.834 kid1| Write.cc(60) HandleWrite: local=[::]
remote=[::] FD 22 flags=1: off 0, sz 20.
2015/03/28 20:11:30.834 kid1| Write.cc(100) HandleWrite: write() returns 20
2015/03/28 20:11:30.834 kid1| IoCallback.cc(108) finish: called for
local=[::] remote=[::] FD 22 flags=1 (0, 0)
2015/03/28 20:11:30.834 kid1| AsyncCall.cc(85) ScheduleCall:
IoCallback.cc(127) will call helperDispatchWriteDone(local=[::] remote=[::]
FD 22 flags=1, errno=11, data=0x9b6c4f8, size=20, buf=0x9c9e148) [call2903]
2015/03/28 20:11:30.834 kid1| AsyncCallQueue.cc(51) fireNext: entering
helperDispatchWriteDone(local=[::] remote=[::] FD 22 flags=1, errno=11,
data=0x9b6c4f8, size=20, buf=0x9c9e148)
2015/03/28 20:11:30.835 kid1| AsyncCall.cc(30) make: make call
helperDispatchWriteDone [call2903]
2015/03/28 20:11:30.835 kid1| AsyncCallQueue.cc(53) fireNext: leaving
helperDispatchWriteDone(local=[::] remote=[::] FD 22 flags=1, errno=11,
data=0x9b6c4f8, size=20, buf=0x9c9e148)
2015/03/28 20:11:30.835 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2,
handler=0, client_data=0, timeout=0
2015/03/28 20:11:30.902 kid1| comm.cc(138) commHandleRead: comm_read_try:
FD 22, size 4095, retval 4, errno 0
2015/03/28 20:11:30.902 kid1| IoCallback.cc(108) finish: called for
local=[::] remote=[::] FD 22 flags=1 (0, 0)
2015/03/28 20:11:30.902 kid1| AsyncCall.cc(85) ScheduleCall:
IoCallback.cc(127) will call helperHandleRead(local=[::] remote=[::] FD 22
flags=1, data=0x9b6c4f8, size=4, buf=0x9aa1508) [call980]
2015/03/28 20:11:30.902 kid1| AsyncCallQueue.cc(51) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 22 flags=1, data=0x9b6c4f8,
size=4, buf=0x9aa1508)
2015/03/28 20:11:30.902 kid1| AsyncCall.cc(30) make: make call
helperHandleRead [call980]
2015/03/28 20:11:30.903 kid1| helper.cc(906) helperHandleRead:
helperHandleRead: 4 bytes from grpname #Hlpr0
2015/03/28 20:11:30.903 kid1| helper.cc(932) helperHandleRead:
helperHandleRead: end of reply found
2015/03/28 20:11:30.903 kid1| HelperReply.cc(23) parse: Parsing helper
buffer
2015/03/28 20:11:30.903 kid1| HelperReply.cc(42) parse: Buff length is
larger than 2
2015/03/28 20:11:30.903 kid1| HelperReply.cc(46) parse: helper Result = OK
2015/03/28 20:11:30.903 kid1| external_acl.cc(1375) externalAclHandleReply:
reply={result=OK}
2015/03/28 20:11:30.904 kid1| external_acl.cc(1290) external_acl_cache_add:
external_acl_cache_add: Adding '192.168.3.243 two' = ALLOWED

Debug Output in the case of the enxt request:
2015/03/28 20:11:54.422 kid1| Acl.cc(157) matches: checking two
2015/03/28 20:11:54.423 kid1| external_acl.cc(868) aclMatchExternal:
grpname("192.168.3.243 two") = lookup needed
2015/03/28 20:11:54.423 kid1| external_acl.cc(871) aclMatchExternal:
"192.168.3.243 two": queueing a call.
2015/03/28 20:11:54.423 kid1| external_acl.cc(1453) Start: fg lookup in
'grpname' for '192.168.3.243 two'
2015/03/28 20:11:54.423 kid1| external_acl.cc(1508) Start:
externalAclLookup: looking up for '192.168.3.243 two' in 'grpname'.
2015/03/28 20:11:54.423 kid1| helper.cc(1208) GetFirstAvailable:
GetFirstAvailable: Running servers 1
2015/03/28 20:11:54.423 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall
helperDispatchWriteDone constructed, this=0xa0505f0 [call4372]
2015/03/28 20:11:54.424 kid1| Write.cc(29) Write: local=[::] remote=[::] FD
22 flags=1: sz 20: asynCall 0xa0505f0*1
2015/03/28 20:11:54.424 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2,
handler=1, client_data=0x970522c, timeout=0
2015/03/28 20:11:54.424 kid1| helper.cc(1350) helperDispatch:
helperDispatch: Request sent to grpname #Hlpr0, 18 bytes
2015/03/28 20:11:54.424 kid1| external_acl.cc(1518) Start:
externalAclLookup: will wait for the result of '192.168.3.243 two' in
'grpname' (ch=0x985f400).
2015/03/28 20:11:54.424 kid1| external_acl.cc(874) aclMatchExternal:
"192.168.3.243 two": return -1.
2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: two = -1 async
2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: http_access#1 =
-1 async
2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: http_access =
-1 async
2015/03/28 20:11:54.425 kid1| Write.cc(60) HandleWrite: local=[::]
remote=[::] FD 22 flags=1: off 0, sz 20.
2015/03/28 20:11:54.425 kid1| Write.cc(100) HandleWrite: write() returns 20
2015/03/28 20:11:54.426 kid1| IoCallback.cc(108) finish: called for
local=[::] remote=[::] FD 22 flags=1 (0, 0)
2015/03/28 20:11:54.426 kid1| AsyncCall.cc(85) ScheduleCall:
IoCallback.cc(127) will call helperDispatchWriteDone(local=[::] remote=[::]
FD 22 flags=1, errno=11, data=0x9b6c4f8, size=20, buf=0x9c9e148) [call4372]
2015/03/28 20:11:54.426 kid1| AsyncCallQueue.cc(51) fireNext: entering
helperDispatchWriteDone(local=[::] remote=[::] FD 22 flags=1, errno=11,
data=0x9b6c4f8, size=20, buf=0x9c9e148)
2015/03/28 20:11:54.426 kid1| AsyncCall.cc(30) make: make call
helperDispatchWriteDone [call4372]
2015/03/28 20:11:54.426 kid1| AsyncCallQueue.cc(53) fireNext: leaving
helperDispatchWriteDone(local=[::] remote=[::] FD 22 flags=1, errno=11,
data=0x9b6c4f8, size=20, buf=0x9c9e148)
2015/03/28 20:11:54.427 kid1| comm.cc(138) commHandleRead: comm_read_try:
FD 22, size 4094, retval 4, errno 0
2015/03/28 20:11:54.427 kid1| IoCallback.cc(108) finish: called for
local=[::] remote=[::] FD 22 flags=1 (0, 0)
2015/03/28 20:11:54.427 kid1| AsyncCall.cc(85) ScheduleCall:
IoCallback.cc(127) will call helperHandleRead(local=[::] remote=[::] FD 22
flags=1, data=0x9b6c4f8, size=4, buf=0x9aa1509) [call2905]
2015/03/28 20:11:54.427 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2,
handler=0, client_data=0, timeout=0
2015/03/28 20:11:54.427 kid1| AsyncCallQueue.cc(51) fireNext: entering
helperHandleRead(local=[::] remote=[::] FD 22 flags=1, data=0x9b6c4f8,
size=4, buf=0x9aa1509)
2015/03/28 20:11:54.428 kid1| AsyncCall.cc(30) make: make call
helperHandleRead [call2905]
2015/03/28 20:11:54.428 kid1| helper.cc(906) helperHandleRead:
helperHandleRead: 4 bytes from grpname #Hlpr0

To verify Squid was getting the responses from the external acl, I ran a
strace on the squid process. Below is the trimmed output:

write(19, "0 192.168.3.243 two\n", 20)  = 20
gettimeofday({1427556227, 22424}, NULL) = 0
epoll_wait(6, {{EPOLLOUT, {u32=19, u64=13821314555071954963}}}, 4096, 201)
= 1
gettimeofday({1427556227, 22698}, NULL) = 0
epoll_ctl(6, EPOLL_CTL_MOD, 19, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=19,
u64=586827630829895699}}) = 0
gettimeofday({1427556227, 22772}, NULL) = 0
epoll_wait(6, {{EPOLLIN, {u32=19, u64=586827630829895699}}}, 4096, 201) = 1
gettimeofday({1427556227, 22854}, NULL) = 0
read(19, "OK\n\0", 4095)                = 4

write(19, "0 192.168.3.243 two\n", 20)  = 20
gettimeofday({1427556242, 856906}, NULL) = 0
epoll_wait(6, {{EPOLLOUT, {u32=19, u64=13821314555071954963}}}, 4096, 388)
= 1
gettimeofday({1427556242, 857085}, NULL) = 0
epoll_ctl(6, EPOLL_CTL_MOD, 19, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=19,
u64=586827630829895699}}) = 0
gettimeofday({1427556242, 857175}, NULL) = 0
epoll_wait(6, {{EPOLLIN, {u32=19, u64=586827630829895699}}}, 4096, 388) = 1
gettimeofday({1427556242, 857250}, NULL) = 0
read(19, "OK\n\0", 4094)                = 4

Any suggestions are welcome.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20150328/720c6ef3/attachment.html>