Determine appropriate timeouts in DNS, HTTP, TLS

[mxsasha]

We have poor information on what current timeouts are, and no information on how they were chosen. Some recent refactorings have at least moved them into clear constants in the code, but those numbers are also just guessed.

This has come up e.g. when they have been accidentally changed in:
#1714 (comment)
#1218 (comment)

Considerations:

• The timeout for the total test is currently 200 seconds (INTERNETNL_CACHE_TTL). Exceeding this will be reported as a test error, but it's not - the frontend just gave up and the job is still running. This is indistinguishable from an actual error (as in uncaught exception in code execution).
• There are separate timeouts in resolving, TLS connections, HTTP requests, probably other unknown places.
• Not every weird case needs to be testable, I think it's fine to just say no reply in 5 seconds means you don't run HTTP or TLS.
• Multiple connections accumulate this, i.e. if we the HTTP request timeout is 20 seconds, 10 sequential requests will push the test over the global timeout, giving a worse user experience.
• We should not hyper-optimise for minimal lookups/queries, just to be able to accommodate servers that respond ridiculously slow.

We should decide what appropriate timeouts are and apply them consistently in new code. This will impact some test results. If we consider the current changes a release blocker, that's a blocker for 1.10, as we already have some of this merged.

[mxsasha]

Kadaster.nl failing with #1218 is also an example of this, they have an AAAA but it's poorly responsive, and it's pushing is over the total test timeout, i.e. our timeouts are too long.

[bwbroersma]

The question is also: should the TLS test wait for a HTTP response for all tests, since it's just the TLS handshake that is tested. Then again: not waiting for a HTTP response could mean it's actually not a HTTP endpoint... It would speed the TLS test up to only do the TLS handshake, and not wait for the HTTP response.

• DNS timeout: time waiting for UDP (or TCP) response
• TCP timeout: timeout waiting for any TCP package (especially relevant when setting up a connection)
• TLS timeout: timeout for the complete TLS handshake (the question: is this just TLS, starting from the first TCP setup until the TLS handshake is complete?)
• HTTP timeout: timeout waiting for the first HTTP response (this could be the complete response, e.g. including TCP setup and TLS setup, or just the time from TCP or TLS setup, until either the first byte response, or the complete response is in)

[mxsasha]

The question is also: should the TLS test wait for a HTTP response for all tests, since it's just the TLS handshake that is tested. Then again: not waiting for a HTTP response could mean it's actually not a HTTP endpoint... It would speed the TLS test up to only do the TLS handshake, and not wait for the HTTP response.

Measuring HTTP requests per IP as: HTTP access log recorded a request, on my IPv6/TLS compliant nginx instance without strange delays.

Total web test:

• 1.9.3: 11 HTTP requests
• main: 12 HTTP requests
• sslyze (includes 47f3d32): 9 HTTP requests

Another datapoint on sslyze branch: tls_web_conn probe does 3 HTTP requests, tls_web_cert does 0.

Conclusion: we barely do HTTP for TLS tests.

Also, the current timeout for TLS is here, which is also the per request timeout passed to requests, our HTTP client lib:

Internet.nl/checks/tasks/tls_connection.py

Line 48 in d3290df

DEFAULT_TIMEOUT = 10

I can't determine whether this is consistently applied in TLS, or to what - looks like just the connect() call.

[bwbroersma]

https://everything.curl.dev/usingcurl/verbose/writeout.html#:~:text=time_appconnect:

Variable	Description
time_appconnect	The time in seconds, it took from the start until the SSL/SSH/etc connect/handshake to the remote host was completed.
time_connect	The time in seconds, it took from the start until the TCP connect to the remote host (or proxy) was completed.
time_namelookup	The time in seconds, it took from the start until the name resolving was completed.
time_pretransfer	The time in seconds, it took from the start until the file transfer was just about to begin. This includes all pre-transfer commands and negotiations that are specific to the particular protocol(s) involved.
time_redirect	The time in seconds, it took for all redirection steps including name lookup, connect, pre-transfer and transfer before the final transaction was started. time_redirect the complete execution time for multiple redirections.
time_starttransfer	The time in seconds, it took from the start until the first byte was just about to be transferred. This includes time_pretransfer and also the time the server needed to calculate the result.
time_total	The total time in seconds, that the full operation lasted. The time is displayed with millisecond resolution.

Scrape (done over an IPv4 only connection):

curl -sSfLA '' "https://tranco-list.eu/download_daily/$(curl 'https://tranco-list.eu/latest_list' -sSfA '' -o /dev/null -w "%{redirect_url}\n" | cut -d/ -f5)" | bsdtar -Oxf- | cut -d, -f2 | tr -d '\r' > top-1m.list
cat top-1m.list | sed 's@^@http://@' | xargs --process-slot-var=process -P100 -n1 bash -c 'curl "$0" --dns-servers "9.9.9.9" -sSA "Mozilla/5.0" -o /dev/null --http1.1 -w "%{remote_port}\t%{time_appconnect}\t%{time_connect}\t%{time_namelookup}\t%{time_pretransfer}\t%{time_starttransfer}\t%{time_total}\n" >> /tmp/top1m-http-$process'
cat top-1m.list | sed 's@^@https://@' | xargs --process-slot-var=process -P100 -n1 bash -c 'curl "$0" -k --dns-servers "9.9.9.9" -sSA "Mozilla/5.0" -o /dev/null --http1.1 -w "%{remote_port}\t%{time_appconnect}\t%{time_connect}\t%{time_namelookup}\t%{time_pretransfer}\t%{time_starttransfer}\t%{time_total}\n" >> /tmp/top1m-https-$process'

Stats:

cat top1m-http-* | cut -f1 | sort | uniq -c 
 139215 0
 860769 80
# aborted, but total is 999 984 (99.99%)
cat top1m-https-* | cut -f1 | sort | uniq -c
  85440 0
 417352 443
# still in progress, current progress is 502 792 (50.28%)

(echo -e "port\tappconnect\tconnect\tnamelookup\tpretransfer\tstarttransfer\ttotal";cat top1m-http-*) \
| awk -F '\t' '$1!="0"{print$0}' | cut -f2- | Rscript -e 'options(width=120);summary(read.table("stdin",header=TRUE))'

   appconnect    connect            namelookup        pretransfer        starttransfer           total          
 Min.   :0    Min.   :  0.01377   Min.   : 0.01266   Min.   :  0.01383   Min.   :    0.000   Min.   :    0.022  
 1st Qu.:0    1st Qu.:  0.03806   1st Qu.: 0.02035   1st Qu.:  0.03812   1st Qu.:    0.071   1st Qu.:    0.072  
 Median :0    Median :  0.06777   Median : 0.03042   Median :  0.06783   Median :    0.151   Median :    0.157  
 Mean   :0    Mean   :  0.34013   Mean   : 0.11249   Mean   :  0.34020   Mean   :    0.809   Mean   :    1.534  
 3rd Qu.:0    3rd Qu.:  0.17999   3rd Qu.: 0.08844   3rd Qu.:  0.18006   3rd Qu.:    0.349   3rd Qu.:    0.358  
 Max.   :0    Max.   :299.91006   Max.   :12.31138   Max.   :299.91014   Max.   :22285.453   Max.   :24588.812  

(echo -e "port\tappconnect\tconnect\tnamelookup\tpretransfer\tstarttransfer\ttotal";cat top1m-https-*) \
| awk -F '\t' '$1!="0"{print$0}' | cut -f2- | Rscript -e 'options(width=120);summary(read.table("stdin",header=TRUE))'

   appconnect           connect            namelookup        pretransfer        starttransfer           total         
 Min.   :  0.00000   Min.   :  0.01491   Min.   : 0.01275   Min.   :  0.00000   Min.   :   0.0000   Min.   :   0.019  
 1st Qu.:  0.06081   1st Qu.:  0.03794   1st Qu.: 0.02040   1st Qu.:  0.06085   1st Qu.:   0.1202   1st Qu.:   0.134  
 Median :  0.09723   Median :  0.06001   Median : 0.02913   Median :  0.09728   Median :   0.2976   Median :   0.330  
 Mean   :  0.39756   Mean   :  0.52722   Mean   : 0.11179   Mean   :  0.39761   Mean   :   0.8120   Mean   :   1.920  
 3rd Qu.:  0.30748   3rd Qu.:  0.16918   3rd Qu.: 0.07394   3rd Qu.:  0.30753   3rd Qu.:   0.6035   3rd Qu.:   0.694  
 Max.   :298.77196   Max.   :298.71845   Max.   :11.82154   Max.   :298.77203   Max.   :1979.8077   Max.   :3611.980  

cat top1m-http-* | awk -F '\t' '$1!="0"{print$7}' \
| Rscript -e 'options(width=240);quantile(as.numeric(readLines("stdin")),probs=c(0.99, 0.991, 0.992, 0.993, 0.994, 0.995, 0.996, 0.997, 0.998, 0.999, 0.9999, 0.99999))'

        99%       99.1%       99.2%       99.3%       99.4%       99.5%       99.6%       99.7%       99.8%       99.9%      99.99%     99.999%
   4.205359    5.211446    6.598712   11.231018   33.553516   39.148258   58.706513   60.204921  129.312701  297.985262 1009.125516 2849.197299

cat top1m-https-* | awk -F '\t' '$1!="0"{print$7}' \
| Rscript -e 'options(width=240);quantile(as.numeric(readLines("stdin")),probs=c(0.99, 0.991, 0.992, 0.993, 0.994, 0.995, 0.996, 0.997, 0.998, 0.999, 0.9999, 0.99999))'

      99%     99.1%     99.2%     99.3%     99.4%     99.5%     99.6%     99.7%     99.8%     99.9%    99.99%   99.999% 
 12.17900  19.39178  19.63663  19.91345  30.09584  39.13294  61.44696 131.15274 235.38071 300.29814 711.29726 862.80484

In summary:

• the Tranco list includes a lot of untestable domains:
  e.g. the top 100 has 27 domains without an A-record

  head -n100 top-1m.list | sed 's/$/ A/g' | xargs dig +noall +question +answer | awk 'substr($0,1,1)==";"{if(NR!=1&&results==0){print domain};domain=substr($1,2);results=0;next}{results=1}'
  

  root-servers.net.
  akamai.net.
  akamaiedge.net.
  ax-msedge.net.
  akadns.net.
  microsoftonline.com.
  tiktokcdn.com.
  windowsupdate.com.
  t-msedge.net.
  trafficmanager.net.
  apple-dns.net.
  office.net.
  l-msedge.net.
  aaplimg.com.
  a-msedge.net.
  dual-s-msedge.net.
  cloudfront.net.
  gtld-servers.net.
  gvt2.com.
  gvt1.com.
  bytefcdn-oversea.com.
  e2ro.com.
  cdn77.org.
  ytimg.com.
  wac-msedge.net.
  edgekey.net.
  cdninstagram.com.
  

• 2 or more nines (>99%) are not in reach (>10s)
• could we ask https://stats.sidnlabs.nl/nl/web.html for stats?

[bwbroersma]

One DNS corner case to consider:

1. stub resolver timeout (after 5s) with an error for first DNS request
   

   Internet.nl/checks/resolver.py

   Line 16 in 917b821

   DNS_TIMEOUT = 5

2. unbound continues resolving and receives a result within the timeout, unsure what can be set, but it seems at least > 5s is possible:
   https://www.nlnetlabs.nl/documentation/unbound/info-timeout/#probing
3. unbound caches the result (after the response is received) for up to 180s:

   • Internet.nl/docker/resolver/entrypoint-resolver.sh

     Line 16 in 917b821

     DNS_CACHE_TTL=$(echo "0.9 $INTERNETNL_CACHE_TTL" | awk '{printf "%d",$1*$2}')

   • Internet.nl/internetnl/settings.py

     Line 253 in 917b821

     CACHE_TTL = int(os.getenv("INTERNETNL_CACHE_TTL", 200))

   • Internet.nl/docker/resolver/resolver-validating.conf.template

     Lines 19 to 20 in 917b821

     	cache-max-ttl: ${DNS_CACHE_TTL}
     	cache-max-negative-ttl: ${DNS_CACHE_TTL}

4. if unbound queried for the same data, it's cache time dependent*
5. result: test might be flacky

* the retry time, but retry is only bound to a domain + test type, e.g. the result could change if first testing web and then mail (or something that has some common NS / CNAME etc.)