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 > >> 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> 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> > remote=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> > remote=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> 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> remote=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> remote=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> > remote=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> > remote=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 > > > ---------- _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
