Squid behaviour with external_acl_type

Ashish Patil <ashish.patil@xxxxxxxxxxxxxx> · Sat, 28 Mar 2015 21:25:17 +0530

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="" 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="" 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="" 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="" 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="" 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="" 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="" 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="" 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="" 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="" 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.

_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users