[squid-users] forward_max_tries 1 has no effect

Alex Rousskov rousskov at measurement-factory.com
Wed Nov 29 03:12:40 UTC 2017


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.



More information about the squid-users mailing list