ATS (8.0.5 + PR 4028) is not handling properly the connect timeout against origin servers when keep alive and parent proxies are being used. Hence 502s are being returned cause ATS wrongly timeouts on connect timeout instead of TTFB timeout
To be able to reproduce it, I had to to generate some traffic in the background, I've used hey with the following options: hey -c 5 -z 10m http://127.0.0.1:3128/ and at the same time I've ran the curl cmd that it's pasted below.
In this example ATS returns a 502 after 14 seconds, the origin server (httpbin) reports that ATS goes away after 3-4 seconds (connect timeout):
willikins:ats vgutierrez$ docker-compose logs httpbin |grep delay
httpbin_2 | time="2020-02-12T13:31:20.5253" status=200 method="GET" uri="/delay/20" size_bytes=0 duration_ms=3301.07
httpbin_2 | time="2020-02-12T13:31:24.5127" status=200 method="GET" uri="/delay/20" size_bytes=0 duration_ms=3985.48
httpbin_1 | time="2020-02-12T13:30:02.1195" status=200 method="GET" uri="/delay/20" size_bytes=0 duration_ms=3841.99
httpbin_1 | time="2020-02-12T13:30:22.1009" status=200 method="GET" uri="/delay/20" size_bytes=503 duration_ms=20002.02
httpbin_1 | time="2020-02-12T13:31:28.501" status=200 method="GET" uri="/delay/20" size_bytes=0 duration_ms=3987.72
httpbin_1 | time="2020-02-12T13:31:31.5108" status=200 method="GET" uri="/delay/20" size_bytes=0 duration_ms=3008.36
client PoV:
root@8994caf57512:/# time curl http://127.0.0.1:3128/delay/20
<HTML>
<HEAD>
<TITLE>Could Not Connect</TITLE>
</HEAD>
<BODY BGCOLOR="white" FGCOLOR="black">
<H1>Could Not Connect</H1>
<HR>
<FONT FACE="Helvetica,Arial"><B>
Description: Could not connect to the requested server host.
</B></FONT>
<HR>
</BODY>
real 0m14.319s
user 0m0.010s
sys 0m0.010s
ATS http debug log can be seen here: https://gist.github.com/jvgutierrez/22d234d4afdbc6017f70f8f3fe0d8665
ATS configuration:
root@8994caf57512:/# cat /etc/trafficserver/parent.config
dest_domain=. parent="ats_httpbin_1:80,ats_httpbin_2:80" parent_is_proxy=false round_robin=strict
root@8994caf57512:/# traffic_ctl config diff
proxy.config.http.server_ports has changed
Current Value : 3128 3128:ipv6
Default Value : 8080 8080:ipv6
proxy.config.ssl.server.cert.path has changed
Current Value : /etc/acmecerts/
Default Value : /etc/trafficserver
proxy.config.ssl.server.private_key.path has changed
Current Value : /etc/acmecerts/
Default Value : /etc/trafficserver
proxy.config.ssl.ocsp.response.path has changed
Current Value : /etc/acmecerts/
Default Value : /etc/trafficserver
proxy.config.ssl.ocsp.enabled has changed
Current Value : 1
Default Value : 0
proxy.config.admin.user_id has changed
Current Value : trafficserver
Default Value : root
proxy.config.http.cache.required_headers has changed
Current Value : 1
Default Value : 2
proxy.config.url_remap.pristine_host_hdr has changed
Current Value : 1
Default Value : 0
proxy.config.disable_configuration_modification has changed
Current Value : 1
Default Value : 0
proxy.config.diags.debug.enabled has changed
Current Value : 2
Default Value : 0
proxy.config.diags.debug.tags has changed
Current Value : http|parent_select
Default Value : http|dns
proxy.config.diags.debug.client_ip has changed
Current Value : 127.0.0.1
Default Value : NULL
proxy.config.diags.output.status has changed
Current Value : O
Default Value : L
proxy.config.diags.output.note has changed
Current Value : O
Default Value : L
proxy.config.diags.output.debug has changed
Current Value : O
Default Value : E
proxy.config.diags.output.diag has changed
Current Value : O
Default Value : E
proxy.config.diags.output.warning has changed
Current Value : O
Default Value : L
proxy.config.diags.output.error has changed
Current Value : O
Default Value : L
proxy.config.diags.output.fatal has changed
Current Value : O
Default Value : L
proxy.config.diags.output.alert has changed
Current Value : O
Default Value : L
proxy.config.diags.output.emergency has changed
Current Value : O
Default Value : L
proxy.config.http.cache.http has changed
Current Value : 0
Default Value : 1
proxy.config.http.parent_proxy_routing_enable has changed
Current Value : 1
Default Value : 0
proxy.config.http.parent_proxy.self_detect has changed
Current Value : 0
Default Value : 2
proxy.config.http.server_session_sharing.match has changed
Current Value : ip
Default Value : both
proxy.config.ssl.session_cache.timeout has changed
Current Value : 7200
Default Value : 0
proxy.config.ssl.server.session_ticket.enable has changed
Current Value : 0
Default Value : 1
proxy.config.http.connect_attempts_timeout has changed
Current Value : 3
Default Value : 30
proxy.config.http.post_connect_attempts_timeout has changed
Current Value : 3
Default Value : 1800
proxy.config.http.parent_proxy.connect_attempts_timeout has changed
Current Value : 3
Default Value : 30
proxy.config.http.keep_alive_no_activity_timeout_in has changed
Current Value : 180
Default Value : 120
proxy.config.http.keep_alive_no_activity_timeout_out has changed
Current Value : 180
Default Value : 120
proxy.config.http.transaction_no_activity_timeout_in has changed
Current Value : 180
Default Value : 30
proxy.config.http.transaction_no_activity_timeout_out has changed
Current Value : 180
Default Value : 30
proxy.config.http2.accept_no_activity_timeout has changed
Current Value : 180
Default Value : 120
proxy.config.http2.no_activity_timeout_in has changed
Current Value : 180
Default Value : 120
proxy.config.http.request_buffer_enabled has changed
Current Value : 1
Default Value : 0
ATS (8.0.5 + PR 4028) is not handling properly the connect timeout against origin servers when keep alive and parent proxies are being used. Hence 502s are being returned cause ATS wrongly timeouts on connect timeout instead of TTFB timeout
To be able to reproduce it, I had to to generate some traffic in the background, I've used hey with the following options:
hey -c 5 -z 10m http://127.0.0.1:3128/and at the same time I've ran the curl cmd that it's pasted below.In this example ATS returns a 502 after 14 seconds, the origin server (httpbin) reports that ATS goes away after 3-4 seconds (connect timeout):
client PoV:
ATS http debug log can be seen here: https://gist.github.com/jvgutierrez/22d234d4afdbc6017f70f8f3fe0d8665
ATS configuration: