Inconsistent appconnect_time reporting over HTTP

[1ma]

I did this

# Make 2 HTTPS requests, reusing the connection
$ curl -s -w@curl-format.txt -o /dev/null https://www.google.com/ -o /dev/null https://www.google.com/
    time_namelookup:  0.001085
       time_connect:  0.010285
    time_appconnect:  0.063561
   time_pretransfer:  0.063676
 time_starttransfer:  0.126158
                    ----------
         time_total:  0.128053

    time_namelookup:  0.000031
       time_connect:  0.000032
    time_appconnect:  0.000032
   time_pretransfer:  0.000085
 time_starttransfer:  0.080010
                    ----------
         time_total:  0.082248


# Make 2 HTTP requests, reusing the connection
$ curl -s -w@curl-format.txt -o /dev/null http://www.google.com/ -o /dev/null http://www.google.com/
    time_namelookup:  0.001781
       time_connect:  0.010850
    time_appconnect:  0.000000
   time_pretransfer:  0.010889
 time_starttransfer:  0.072396
                    ----------
         time_total:  0.081564

    time_namelookup:  0.000031
       time_connect:  0.000032
    time_appconnect:  0.000032
   time_pretransfer:  0.000080
 time_starttransfer:  0.068770
                    ----------
         time_total:  0.071535

Contents of curl-format.txt:

    time_namelookup:  %{time_namelookup}\n
       time_connect:  %{time_connect}\n
    time_appconnect:  %{time_appconnect}\n
   time_pretransfer:  %{time_pretransfer}\n
 time_starttransfer:  %{time_starttransfer}\n
                    ----------\n
         time_total:  %{time_total}\n\n

I expected the following

On the second run the appconnect_time of the first request should have been 0.010850 instead of 0.000000.

The documentation states that appconnect_time is "the time, in seconds, it took from the start until the SSL/SSH connect/handshake to the remote host was completed". However, seems that when cURL has to open a new TCP connection and the protocol is plain HTTP the reported timing is just 0.

curl/libcurl version

curl 7.64.0 (x86_64-alpine-linux-musl) libcurl/7.64.0 OpenSSL/1.1.1b zlib/1.2.11 libssh2/1.8.2 nghttp2/1.35.1
Release-Date: 2019-02-06
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy

operating system

Alpine Linux 3.9.3

[bagder]

"the time, in seconds, it took from the start until the SSL/SSH connect/handshake to the remote host was completed". However, seems that when cURL has to open a new TCP connection and the protocol is plain HTTP the reported timing is just 0.

Which is because there was no "SSL/SSH connect/handshake" performed so it never stores any appconnect timestamp then. In the case of reused connections it always stores it since it then doesn't check if the existing connection uses SSL or SSH...

But yeah, maybe we should avoid the zero case and instead just have that use the time_connect time.

[1ma]

Exactly, it's just a matter of consistence. With recycled connections (either HTTP or HTTPS) cURL already behaves like that, and I am calculating the actual SSL handshake time by subtracting time_connect to time_appconnect. I noticed the inconsistency because I was seeing negative timings when doing this subtraction while performing HTTP requests.

[jay]

This doesn't seem like a bug to me or I don't understand the issue. time_appconnect is documented for the "SSL/SSH/etc" [1] handshake and there was none. How about it's wrong for appconnect to be anything other than 0 on a reused connection.

[1]: Note that time_appconnect maps to CURLINFO_APPCONNECT_TIME in libcurl which doesn't have the "etc".

[1ma]

Ok, let me try to elaborate this a bit more (sorry, not a native speaker). My point is that for HTTP requests time_appconnect should always be either exactly 0 or equal to time_connect to be consistent, but not both like in the second sample run.

As far as I know all time_* variables report the time elapsed since the beginning of the request until some operation or stage of the request lifecycle completes. It also seems like the "TLS handshaking stage" (either if it's actually done or not) is something that happens between time_connect (establishing the TCP connection?) and time_pretransfer (cURL ready to push the request bytes over the wire?), because time_connect <= time_appconnect <= time_pretransfer usually holds true. The documentation for curl_easy_getinfo also depicts the different time values like this:

curl_easy_perform()
    |
    |--NAMELOOKUP
    |--|--CONNECT
    |--|--|--APPCONNECT
    |--|--|--|--PRETRANSFER
    |--|--|--|--|--STARTTRANSFER
    |--|--|--|--|--|--TOTAL
    |--|--|--|--|--|--REDIRECT

With this understanding, on my system I was relying on time_appconnect - time_connect to log an approximation of the time actually spent inside the TLS handshake, and expected to get a correct result regardless of the protocol. But then I started to see negative "TLS time" records for some HTTP requests (later I found these were the ones that create a new TCP connection, due to 0 - time_connect), and the correct 0.000000 for most others (the ones that managed to reuse a connection). That's the issue.

[bagder]

I believe this has been addressed since #3773 was merged. Can anyone confirm?