<div dir="ltr"><div><div><div><div><div><div><div><div><div>Hello,<br><br></div>I am faced with a weird situation with an external acl that I have built. <br><br></div>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.<br><br></div>The situation is as follows:<br></div> 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.<br><br></div>My acl's are as follows:<br>external_acl_type grpname ttl=10 children-startup=1 concurrency=1 %SRC %ACL /usr/local/squid/libexec/grpname_helper<br>acl two external grpname<br>acl twoext urlpath_regex "/usr/local/squid/etc/custom/blacklisted-two-extensions"<br>deny_info <a href="http://192.168.3.11/error.html">http://192.168.3.11/error.html</a> two<br>http_access deny twoext two<br><br><br></div>The debug output for the first request coming in:<br>2015/03/28 20:11:30.831 kid1| external_acl.cc(868) aclMatchExternal: grpname("192.168.3.243 two") = lookup needed<br>2015/03/28 20:11:30.831 kid1| external_acl.cc(871) aclMatchExternal: "192.168.3.243 two": queueing a call.<br>2015/03/28 20:11:30.831 kid1| external_acl.cc(1453) Start: fg lookup in 'grpname' for '192.168.3.243 two'<br>2015/03/28 20:11:30.832 kid1| external_acl.cc(1508) Start: externalAclLookup: looking up for '192.168.3.243 two' in 'grpname'.<br>2015/03/28 20:11:30.832 kid1| helper.cc(1208) GetFirstAvailable: GetFirstAvailable: Running servers 1<br>2015/03/28 20:11:30.832 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0x9db91e8 [call2903]<br>2015/03/28 20:11:30.832 kid1| Write.cc(29) Write: local=[::] remote=[::] FD 22 flags=1: sz 20: asynCall 0x9db91e8*1<br>2015/03/28 20:11:30.832 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2, handler=1, client_data=0x970522c, timeout=0<br>2015/03/28 20:11:30.832 kid1| helper.cc(1350) helperDispatch: helperDispatch: Request sent to grpname #Hlpr0, 18 bytes<br>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).<br>2015/03/28 20:11:30.833 kid1| external_acl.cc(874) aclMatchExternal: "192.168.3.243 two": return -1.<br>2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: two = -1 async<br>2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: http_access#1 = -1 async<br>2015/03/28 20:11:30.833 kid1| Acl.cc(177) matches: checked: http_access = -1 async<br>2015/03/28 20:11:30.834 kid1| Write.cc(60) HandleWrite: local=[::] remote=[::] FD 22 flags=1: off 0, sz 20.<br>2015/03/28 20:11:30.834 kid1| Write.cc(100) HandleWrite: write() returns 20<br>2015/03/28 20:11:30.834 kid1| IoCallback.cc(108) finish: called for local=[::] remote=[::] FD 22 flags=1 (0, 0)<br>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]<br>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)<br>2015/03/28 20:11:30.835 kid1| AsyncCall.cc(30) make: make call helperDispatchWriteDone [call2903]<br>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)<br>2015/03/28 20:11:30.835 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2, handler=0, client_data=0, timeout=0<br>2015/03/28 20:11:30.902 kid1| comm.cc(138) commHandleRead: comm_read_try: FD 22, size 4095, retval 4, errno 0<br>2015/03/28 20:11:30.902 kid1| IoCallback.cc(108) finish: called for local=[::] remote=[::] FD 22 flags=1 (0, 0)<br>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]<br>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)<br>2015/03/28 20:11:30.902 kid1| AsyncCall.cc(30) make: make call helperHandleRead [call980]<br>2015/03/28 20:11:30.903 kid1| helper.cc(906) helperHandleRead: helperHandleRead: 4 bytes from grpname #Hlpr0<br>2015/03/28 20:11:30.903 kid1| helper.cc(932) helperHandleRead: helperHandleRead: end of reply found<br>2015/03/28 20:11:30.903 kid1| HelperReply.cc(23) parse: Parsing helper buffer<br>2015/03/28 20:11:30.903 kid1| HelperReply.cc(42) parse: Buff length is larger than 2<br>2015/03/28 20:11:30.903 kid1| HelperReply.cc(46) parse: helper Result = OK<br>2015/03/28 20:11:30.903 kid1| external_acl.cc(1375) externalAclHandleReply: reply={result=OK}<br>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<br><br><br></div>Debug Output in the case of the enxt request:<br>2015/03/28 20:11:54.422 kid1| Acl.cc(157) matches: checking two<br>2015/03/28 20:11:54.423 kid1| external_acl.cc(868) aclMatchExternal: grpname("192.168.3.243 two") = lookup needed<br>2015/03/28 20:11:54.423 kid1| external_acl.cc(871) aclMatchExternal: "192.168.3.243 two": queueing a call.<br>2015/03/28 20:11:54.423 kid1| external_acl.cc(1453) Start: fg lookup in 'grpname' for '192.168.3.243 two'<br>2015/03/28 20:11:54.423 kid1| external_acl.cc(1508) Start: externalAclLookup: looking up for '192.168.3.243 two' in 'grpname'.<br>2015/03/28 20:11:54.423 kid1| helper.cc(1208) GetFirstAvailable: GetFirstAvailable: Running servers 1<br>2015/03/28 20:11:54.423 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0xa0505f0 [call4372]<br>2015/03/28 20:11:54.424 kid1| Write.cc(29) Write: local=[::] remote=[::] FD 22 flags=1: sz 20: asynCall 0xa0505f0*1<br>2015/03/28 20:11:54.424 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2, handler=1, client_data=0x970522c, timeout=0<br>2015/03/28 20:11:54.424 kid1| helper.cc(1350) helperDispatch: helperDispatch: Request sent to grpname #Hlpr0, 18 bytes<br>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).<br>2015/03/28 20:11:54.424 kid1| external_acl.cc(874) aclMatchExternal: "192.168.3.243 two": return -1.<br>2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: two = -1 async<br>2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: http_access#1 = -1 async<br>2015/03/28 20:11:54.425 kid1| Acl.cc(177) matches: checked: http_access = -1 async<br>2015/03/28 20:11:54.425 kid1| Write.cc(60) HandleWrite: local=[::] remote=[::] FD 22 flags=1: off 0, sz 20.<br>2015/03/28 20:11:54.425 kid1| Write.cc(100) HandleWrite: write() returns 20<br>2015/03/28 20:11:54.426 kid1| IoCallback.cc(108) finish: called for local=[::] remote=[::] FD 22 flags=1 (0, 0)<br>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]<br>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)<br>2015/03/28 20:11:54.426 kid1| AsyncCall.cc(30) make: make call helperDispatchWriteDone [call4372]<br>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)<br>2015/03/28 20:11:54.427 kid1| comm.cc(138) commHandleRead: comm_read_try: FD 22, size 4094, retval 4, errno 0<br>2015/03/28 20:11:54.427 kid1| IoCallback.cc(108) finish: called for local=[::] remote=[::] FD 22 flags=1 (0, 0)<br>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]<br>2015/03/28 20:11:54.427 kid1| ModEpoll.cc(139) SetSelect: FD 22, type=2, handler=0, client_data=0, timeout=0<br>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)<br>2015/03/28 20:11:54.428 kid1| AsyncCall.cc(30) make: make call helperHandleRead [call2905]<br>2015/03/28 20:11:54.428 kid1| helper.cc(906) helperHandleRead: helperHandleRead: 4 bytes from grpname #Hlpr0<br><br><br></div>To verify Squid was getting the responses from the external acl, I ran a strace on the squid process. Below is the trimmed output:<br><br>write(19, "0 192.168.3.243 two\n", 20)  = 20<br>gettimeofday({1427556227, 22424}, NULL) = 0<br>epoll_wait(6, {{EPOLLOUT, {u32=19, u64=13821314555071954963}}}, 4096, 201) = 1<br>gettimeofday({1427556227, 22698}, NULL) = 0<br>epoll_ctl(6, EPOLL_CTL_MOD, 19, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=19, u64=586827630829895699}}) = 0<br>gettimeofday({1427556227, 22772}, NULL) = 0<br>epoll_wait(6, {{EPOLLIN, {u32=19, u64=586827630829895699}}}, 4096, 201) = 1<br>gettimeofday({1427556227, 22854}, NULL) = 0<br>read(19, "OK\n\0", 4095)                = 4<br><br>write(19, "0 192.168.3.243 two\n", 20)  = 20<br>gettimeofday({1427556242, 856906}, NULL) = 0<br>epoll_wait(6, {{EPOLLOUT, {u32=19, u64=13821314555071954963}}}, 4096, 388) = 1<br>gettimeofday({1427556242, 857085}, NULL) = 0<br>epoll_ctl(6, EPOLL_CTL_MOD, 19, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=19, u64=586827630829895699}}) = 0<br>gettimeofday({1427556242, 857175}, NULL) = 0<br>epoll_wait(6, {{EPOLLIN, {u32=19, u64=586827630829895699}}}, 4096, 388) = 1<br>gettimeofday({1427556242, 857250}, NULL) = 0<br>read(19, "OK\n\0", 4094)                = 4<br><br><br></div>Any suggestions are welcome.<br></div>