Thanks Alex. Unfortunately I don't have enough C/C++ skills to fix it.
I've created a bug report – https://bugs.squid-cache.org/show_bug.cgi?id=4788 We've also changed parent behavior so it will not silently close the connection but will return 502 in this exact situation and seems like it fixes unexpected squid re-forward. On Tue, Nov 28, 2017 at 7:12 PM, Alex Rousskov < rouss...@measurement-factory.com> wrote: > On 11/28/2017 02:27 PM, Ivan Larionov wrote: > > > Another interesting fact is that I can't reproduce this issue if squid > > has no other traffic except my testing requests. But it's easy to > > reproduce when server has other traffic. > > I did not check your logs carefully, but I believe that (when things do > not work the way you expect) your Squid is retrying a failed persistent > connection (rather than re-forwarding the request after receiving a bad > response). See the "pconn race happened" line below: > > > 1_retry.log:2017/11/28 12:55:12.731| 17,3| FwdState.cc(416) fail: > ERR_ZERO_SIZE_OBJECT "Bad Gateway" > > 1_retry.log:2017/11/28 12:55:12.731| 17,5| FwdState.cc(430) fail: pconn > race happened > > 1_retry.log:2017/11/28 12:55:12.731| 93,5| AsyncJob.cc(84) mustStop: > HttpStateData will stop, reason: HttpStateData::continueAfterParsingHeader > > 1_retry.log:2017/11/28 12:55:12.731| 17,3| FwdState.cc(618) retryOrBail: > re-forwarding (1 tries, 40 secs) > > 1_retry.log:2017/11/28 12:55:12.731| 17,4| FwdState.cc(621) retryOrBail: > retrying the same destination > > > Assuming you tested with forward_max_tries set to 1, the retryOrBail > lines above confirm the off-by-one problem I was describing in my > previous response. > > AFAICT, compensating by setting forward_max_tries to zero will _not_ > work (for reasons unrelated to the problem at hand). > > > FWIW, your current options include those outlined at > http://wiki.squid-cache.org/SquidFaq/AboutSquid#How_to_ > add_a_new_Squid_feature.2C_enhance.2C_of_fix_something.3F > > > Alex. > > > > On Tue, Nov 28, 2017 at 7:32 AM, Alex Rousskov wrote: > > > > On 11/27/2017 05:19 PM, Ivan Larionov wrote: > > > > > I see retries only when squid config has 2 parents. If I comment > out > > > everything related to "newproxy" I can't reproduce this behavior > anymore. > > > > The posted logs are not detailed enough to confirm or deny that IMO, > but > > I suspect that you are dealing with at least one bug. > > > > > > > https://wiki.squid-cache.org/SquidFaq/InnerWorkings#When_ > does_Squid_re-forward_a_client_request.3F > > <https://wiki.squid-cache.org/SquidFaq/InnerWorkings#When_ > does_Squid_re-forward_a_client_request.3F> > > > > > >> Squid does not try to re-forward a request if at least one of the > following conditions is true: > > >> > > >> The number of forwarding attempts exceeded forward_max_tries. For > > >> example, if you set forward_max_tries to 1 (one), then no requests > > >> will be re-forwarded. > > > > > > AFAICT, there is an off-by-one bug in Squid that violates the above: > > > > > if (n_tries > Config.forward_max_tries) > > > return false; > > > > The n_tries counter is incremented before Squid makes a request > > forwarding attempt. With n_tries and Config.forward_max_tries both > set > > to 1, the quoted FwdState::checkRetry() code will not prevent > > re-forwarding. There is a similar problem in FwdState::reforward(). > This > > reasoning needs confirmation/testing. > > > > Please note that simply changing the ">" operator to ">=" may break > > other things in a difficult-to-detect-by-simple-tests ways. The > correct > > fix may be more complex than it looks and may involve making policy > > decisions regarding forward_max_tries meaning. The best fix would > remove > > checkRetry() and reforward() duplication. This code is difficult to > work > > with; many related code names are misleading. > > > > > > >> Squid has no alternative destinations to try. Please note that > > >> alternative destinations may include multiple next hop IP > addresses > > >> and multiple peers. > > > > The fact that Squid sends two requests to the same peer with only one > > peer address selected suggests that Squid is retrying a failed > > persistent connection rather than re-forwarding after receiving a bad > > response. Again, the logs are not detailed enough to distinguish the > two > > cases. I can only see that a single peer/destination address was > > selected (not two), which is correct/expected behavior. I cannot see > > what happened next with sufficient detail. > > > > Going forward, you have several options, including: > > > > A. Post a link to compressed ALL,7+ logs to confirm bug(s). > > B. Fix the broken condition(s) in FwdState. See above. > > > > HTH, > > > > Alex. > > > > > > > 2017/11/27 15:53:40.542| 5,2| TcpAcceptor.cc(220) doAccept: New > connection on FD 15 > > > 2017/11/27 15:53:40.542| 5,2| TcpAcceptor.cc(295) acceptNext: > connection > > > on local=0.0.0.0:3128 <http://0.0.0.0:3128> <http://0.0.0.0:3128> > > remote=[::] FD 15 flags=9 > > > 2017/11/27 15:53:40.543| 11,2| client_side.cc(2372) > parseHttpRequest: > > > HTTP Client local=127.0.0.1:3128 <http://127.0.0.1:3128> > > <http://127.0.0.1:3128> > > > remote=127.0.0.1:53798 <http://127.0.0.1:53798> > > <http://127.0.0.1:53798> FD 45 flags=1 > > > 2017/11/27 15:53:40.543| 11,2| client_side.cc(2373) > parseHttpRequest: > > > HTTP Client REQUEST: > > > --------- > > > GET http://HOST:12345/ HTTP/1.1 > > > Host: HOST:12345 > > > User-Agent: curl/7.51.0 > > > Accept: */* > > > Proxy-Connection: Keep-Alive > > > > > > > > > ---------- > > > 2017/11/27 15:53:40.543| 85,2| client_side_request.cc(745) > > > clientAccessCheckDone: The request GET http://HOST:12345/ is > ALLOWED; > > > last ACL checked: localhost > > > 2017/11/27 15:53:40.543| 85,2| client_side_request.cc(721) > > > clientAccessCheck2: No adapted_http_access configuration. default: > ALLOW > > > 2017/11/27 15:53:40.543| 85,2| client_side_request.cc(745) > > > clientAccessCheckDone: The request GET http://HOST:12345/ is > ALLOWED; > > > last ACL checked: localhost > > > 2017/11/27 15:53:40.543| 17,2| FwdState.cc(133) FwdState: > Forwarding > > > client request local=127.0.0.1:3128 <http://127.0.0.1:3128> > > <http://127.0.0.1:3128> > > > remote=127.0.0.1:53798 <http://127.0.0.1:53798> > > <http://127.0.0.1:53798> FD 45 flags=1, > > > url=http://HOST:12345/ > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(258) > peerSelectDnsPaths: > > > Find IP destination for: http://HOST:12345/' via 127.0.0.1 > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(280) > peerSelectDnsPaths: > > > Found sources for 'http://HOST:12345/' > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(281) > peerSelectDnsPaths: > > > always_direct = DENIED > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(282) > peerSelectDnsPaths: > > > never_direct = ALLOWED > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(292) > peerSelectDnsPaths: > > > cache_peer = local=127.0.0.3 remote=127.0.0.1:18070 < > http://127.0.0.1:18070> > > > <http://127.0.0.1:18070> flags=1 > > > 2017/11/27 15:53:40.543| 44,2| peer_select.cc(295) > peerSelectDnsPaths: > > > timedout = 0 > > > 2017/11/27 15:53:40.543| 11,2| http.cc(2229) sendRequest: HTTP > Server > > > local=127.0.0.3:57091 <http://127.0.0.3:57091> > > <http://127.0.0.3:57091> remote=127.0.0.1:18070 < > http://127.0.0.1:18070> > > > <http://127.0.0.1:18070> FD 40 flags=1 > > > 2017/11/27 15:53:40.543| 11,2| http.cc(2230) sendRequest: HTTP > Server > > > REQUEST: > > > --------- > > > GET http://HOST:12345/ HTTP/1.1 > > > User-Agent: curl/7.51.0 > > > Accept: */* > > > Host: HOST:12345 > > > Cache-Control: max-age=259200 > > > Connection: keep-alive > > > > > > > > > ---------- > > > > > > [SKIPPED 40 seconds until parent closes TCP connection with > FIN,ACK] > > > > > > 2017/11/27 15:54:20.627| 11,2| http.cc(1299) > continueAfterParsingHeader: > > > WARNING: HTTP: Invalid Response: No object data received for > > > http://HOST:12345/ AKA HOST/ > > > 2017/11/27 15:54:20.627| 17,2| FwdState.cc(655) > > > handleUnregisteredServerEnd: self=0x3e31838*2 err=0x409b338 > > > http://HOST:12345/ > > > 2017/11/27 15:54:20.627| 11,2| http.cc(2229) sendRequest: HTTP > Server > > > local=127.0.0.3:41355 <http://127.0.0.3:41355> > > <http://127.0.0.3:41355> remote=127.0.0.1:18070 < > http://127.0.0.1:18070> > > > <http://127.0.0.1:18070> FD 40 flags=1 > > > 2017/11/27 15:54:20.627| 11,2| http.cc(2230) sendRequest: HTTP > Server > > > REQUEST: > > > --------- > > > GET http://HOST:12345/ HTTP/1.1 > > > User-Agent: curl/7.51.0 > > > Accept: */* > > > Host: HOST:12345 > > > Cache-Control: max-age=259200 > > > Connection: keep-alive > > > > > > > > > ---------- > > > > > > [SKIPPED 40 seconds again until parent closes TCP connection with > FIN,ACK] > > > > > > 2017/11/27 15:55:00.728| ctx: enter level 0: 'http://HOST:12345/' > > > 2017/11/27 15:55:00.728| 11,2| http.cc(719) processReplyHeader: > HTTP > > > Server local=127.0.0.3:41355 <http://127.0.0.3:41355> > > <http://127.0.0.3:41355> > > > remote=127.0.0.1:18070 <http://127.0.0.1:18070> > > <http://127.0.0.1:18070> FD 40 flags=1 > > > 2017/11/27 15:55:00.728| 11,2| http.cc(720) processReplyHeader: > HTTP > > > Server REPLY: > > > --------- > > > HTTP/1.0 502 Bad Gateway > > > Cache-Control: no-cache > > > Connection: close > > > Content-Type: text/html > > > > > > <html><body><h1>502 Bad Gateway</h1> > > > The server returned an invalid or incomplete response. > > > </body></html> > > > > > > ---------- > > > 2017/11/27 15:55:00.728| ctx: exit level 0 > > > 2017/11/27 15:55:00.728| 20,2| store.cc(996) checkCachable: > > > StoreEntry::checkCachable: NO: not cachable > > > 2017/11/27 15:55:00.728| 20,2| store.cc(996) checkCachable: > > > StoreEntry::checkCachable: NO: not cachable > > > 2017/11/27 15:55:00.728| 88,2| client_side_reply.cc(2073) > > > processReplyAccessResult: The reply for GET http://HOST:12345/ is > > > ALLOWED, because it matched (access_log > stdio:/var/log/squid/access.log > > > line) > > > 2017/11/27 15:55:00.728| 11,2| client_side.cc(1409) > sendStartOfMessage: > > > HTTP Client local=127.0.0.1:3128 <http://127.0.0.1:3128> > > <http://127.0.0.1:3128> > > > remote=127.0.0.1:53798 <http://127.0.0.1:53798> > > <http://127.0.0.1:53798> FD 45 flags=1 > > > 2017/11/27 15:55:00.728| 11,2| client_side.cc(1410) > > sendStartOfMessage: > > > HTTP Client REPLY: > > > --------- > > > HTTP/1.1 502 Bad Gateway > > > Date: Mon, 27 Nov 2017 23:54:20 GMT > > > Cache-Control: no-cache > > > Content-Type: text/html > > > X-Cache: MISS from ip-172-23-18-130 > > > X-Cache-Lookup: MISS from ip-172-23-18-130:3128 > > > Transfer-Encoding: chunked > > > Connection: keep-alive > > > > > > > > > ---------- > > > > > > > > > > -- > > With best regards, Ivan Larionov. > > -- With best regards, Ivan Larionov.
_______________________________________________ squid-users mailing list squid-users@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-users