progress: Track total times following redirects

Update the progress timers `t_nslookup`, `t_connect`, `t_appconnect`,
`t_pretransfer`, and `t_starttransfer` to track the total times for
these activities when a redirect is followed. Previously, only the times
for the most recent request would be tracked.

Related changes:

  - Rename `Curl_pgrsResetTimesSizes` to `Curl_pgrsResetTransferSizes`
    now that the function only resets transfer sizes and no longer
    modifies any of the progress timers.

  - Add a bool to the `Progress` struct that is used to prevent
    double-counting `t_starttransfer` times.

Added test case 1399.

Fixes #522 and Known Bug 1.8
Closes #1602
Reported-by: joshhe on github

docs/KNOWN_BUGS

@@ -18,7 +18,6 @@ problems may have been fixed or changed somewhat since this was written!
  1.4 multipart formposts file name encoding
  1.5 Expect-100 meets 417
  1.6 Unnecessary close when 401 received waiting for 100
- 1.8 DNS timing is wrong for HTTP redirects
  1.9 HTTP/2 frames while in the connection pool kill reuse
  1.10 Strips trailing dot from host name
  1.11 CURLOPT_SEEKFUNCTION not called with CURLFORM_STREAM
@@ -140,12 +139,6 @@ problems may have been fixed or changed somewhat since this was written!
  waiting for the the 100-continue response.
  https://curl.haxx.se/mail/lib-2008-08/0462.html
 
-1.8 DNS timing is wrong for HTTP redirects
-
- When extracting timing information after HTTP redirects, only the last
- transfer's results are returned and not the totals:
- https://github.com/curl/curl/issues/522
-
 1.9 HTTP/2 frames while in the connection pool kill reuse
 
  If the server sends HTTP/2 frames (like for example an HTTP/2 PING frame) to

lib/getinfo.c

@@ -54,6 +54,7 @@ CURLcode Curl_initinfo(struct Curl_easy *data)
   pro->t_starttransfer = 0;
   pro->timespent = 0;
   pro->t_redirect = 0;
+  pro->is_t_startransfer_set = false;
 
   info->httpcode = 0;
   info->httpproxycode = 0;

lib/progress.c

@@ -149,14 +149,9 @@ int Curl_pgrsDone(struct connectdata *conn)
   return 0;
 }
 
-/* reset all times except redirect, and reset the known transfer sizes */
+/* reset the known transfer sizes */
-void Curl_pgrsResetTimesSizes(struct Curl_easy *data)
+void Curl_pgrsResetTransferSizes(struct Curl_easy *data)
 {
-  data->progress.t_nslookup = 0;
-  data->progress.t_connect = 0;
-  data->progress.t_pretransfer = 0;
-  data->progress.t_starttransfer = 0;
-
   Curl_pgrsSetDownloadSize(data, -1);
   Curl_pgrsSetUploadSize(data, -1);
 }
@@ -181,6 +176,7 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer)
   case TIMER_STARTSINGLE:
     /* This is set at the start of each single fetch */
     data->progress.t_startsingle = now;
+    data->progress.is_t_startransfer_set = false;
     break;
   case TIMER_STARTACCEPT:
     data->progress.t_acceptdata = now;
@@ -205,10 +201,11 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer)
      * This prevents repeated invocations of the function from incorrectly
      * changing the t_starttransfer time.
      */
-    if (*delta > data->progress.t_redirect) {
+    if(data->progress.is_t_startransfer_set) {
       return;
     }
     else {
+      data->progress.is_t_startransfer_set = true;
       break;
     }
   case TIMER_POSTRANSFER:
@@ -222,7 +219,7 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer)
     time_t us = Curl_tvdiff_us(now, data->progress.t_startsingle);
     if(!us)
       us++; /* make sure at least one microsecond passed */
-    *delta = us;
+    *delta += us;
   }
 }
 
@@ -230,6 +227,7 @@ void Curl_pgrsStartNow(struct Curl_easy *data)
 {
   data->progress.speeder_c = 0; /* reset the progress meter display */
   data->progress.start = Curl_tvnow();
+  data->progress.is_t_startransfer_set = false;
   data->progress.ul_limit_start.tv_sec = 0;
   data->progress.ul_limit_start.tv_usec = 0;
   data->progress.dl_limit_start.tv_sec = 0;

lib/progress.h

@@ -47,7 +47,7 @@ void Curl_pgrsSetUploadSize(struct Curl_easy *data, curl_off_t size);
 void Curl_pgrsSetDownloadCounter(struct Curl_easy *data, curl_off_t size);
 void Curl_pgrsSetUploadCounter(struct Curl_easy *data, curl_off_t size);
 int Curl_pgrsUpdate(struct connectdata *);
-void Curl_pgrsResetTimesSizes(struct Curl_easy *data);
+void Curl_pgrsResetTransferSizes(struct Curl_easy *data);
 void Curl_pgrsTime(struct Curl_easy *data, timerid timer);
 long Curl_pgrsLimitWaitTime(curl_off_t cursize,
                             curl_off_t startsize,

lib/transfer.c

@@ -1345,7 +1345,7 @@ CURLcode Curl_pretransfer(struct Curl_easy *data)
 #endif
 
     Curl_initinfo(data); /* reset session-specific information "variables" */
-    Curl_pgrsResetTimesSizes(data);
+    Curl_pgrsResetTransferSizes(data);
     Curl_pgrsStartNow(data);
 
     if(data->set.timeout)
@@ -1883,7 +1883,7 @@ CURLcode Curl_follow(struct Curl_easy *data,
     break;
   }
   Curl_pgrsTime(data, TIMER_REDIRECT);
-  Curl_pgrsResetTimesSizes(data);
+  Curl_pgrsResetTransferSizes(data);
 
   return CURLE_OK;
 #endif /* CURL_DISABLE_HTTP */

lib/urldata.h

@@ -1259,6 +1259,8 @@ struct Progress {
   struct curltime t_startop;
   struct curltime t_acceptdata;
 
+  bool is_t_startransfer_set;
+
   /* upload speed limit */
   struct curltime ul_limit_start;
   curl_off_t ul_limit_size;

tests/unit/unit1399.c

@@ -36,6 +36,20 @@ static void unit_stop(void)
 
 }
 
+/*
+ * Invoke Curl_pgrsTime for TIMER_STARTSINGLE to trigger the behavior that
+ * manages is_t_startransfer_set, but fake the t_startsingle time for purposes
+ * of the test.
+ */
+static void fake_t_startsingle_time(struct Curl_easy *data,
+                                    struct curltime fake_now,
+                                    int seconds_offset)
+{
+  Curl_pgrsTime(data, TIMER_STARTSINGLE);
+  data->progress.t_startsingle.tv_sec = fake_now.tv_sec + seconds_offset;
+  data->progress.t_startsingle.tv_usec = fake_now.tv_usec;
+}
+
 static bool usec_matches_seconds(time_t time_usec, int expected_seconds)
 {
   int time_sec = (int)(time_usec / usec_magnitude);
@@ -46,55 +60,58 @@ static bool usec_matches_seconds(time_t time_usec, int expected_seconds)
   return same;
 }
 
+static void expect_timer_seconds(struct Curl_easy *data, int seconds)
+{
+  char msg[64];
+  snprintf(msg, sizeof(msg), "about %d seconds should have passed", seconds);
+  fail_unless(usec_matches_seconds(data->progress.t_nslookup, seconds), msg);
+  fail_unless(usec_matches_seconds(data->progress.t_connect, seconds), msg);
+  fail_unless(usec_matches_seconds(data->progress.t_appconnect, seconds), msg);
+  fail_unless(usec_matches_seconds(data->progress.t_pretransfer, seconds),
+              msg);
+  fail_unless(usec_matches_seconds(data->progress.t_starttransfer, seconds),
+              msg);
+}
+
+/* Scenario: simulate a redirect. When a redirect occurs, t_nslookup,
+ * t_connect, t_appconnect, t_pretransfer, and t_starttransfer are addative.
+ * E.g., if t_starttransfer took 2 seconds initially and took another 1
+ * second for the redirect request, then the resulting t_starttransfer should
+ * be 3 seconds. */
 UNITTEST_START
   struct Curl_easy data;
   struct curltime now = Curl_tvnow();
 
+  data.progress.t_nslookup = 0;
+  data.progress.t_connect = 0;
+  data.progress.t_appconnect = 0;
+  data.progress.t_pretransfer = 0;
   data.progress.t_starttransfer = 0;
   data.progress.t_redirect = 0;
+  data.progress.start.tv_sec = now.tv_sec - 2;
+  data.progress.start.tv_usec = now.tv_usec;
+  fake_t_startsingle_time(&data, now, -2);
 
-  /*
+  Curl_pgrsTime(&data, TIMER_NAMELOOKUP);
-  * Set the startsingle time to a second ago. This time is used by
+  Curl_pgrsTime(&data, TIMER_CONNECT);
-  * Curl_pgrsTime to calculate how much time the events takes.
+  Curl_pgrsTime(&data, TIMER_APPCONNECT);
-  * t_starttransfer should be updated to reflect the difference from this time
+  Curl_pgrsTime(&data, TIMER_PRETRANSFER);
-  * when `Curl_pgrsTime is invoked.
-  */
-  data.progress.t_startsingle.tv_sec = now.tv_sec - 1;
-  data.progress.t_startsingle.tv_usec = now.tv_usec;
-
   Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
 
-  fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 1),
+  expect_timer_seconds(&data, 2);
-              "about 1 second should have passed");
 
-  /*
+  /* now simulate the redirect */
-  * Update the startsingle time to a second ago to simulate another second has
-  * passed.
-  * Now t_starttransfer should not be changed, as t_starttransfer has already
-  * occurred and another invocation of `Curl_pgrsTime` for TIMER_STARTTRANSFER
-  * is superfluous.
-  */
-  data.progress.t_startsingle.tv_sec = now.tv_sec - 2;
-  data.progress.t_startsingle.tv_usec = now.tv_usec;
-
-  Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
-
-  fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 1),
-              "about 1 second should have passed");
-
-  /*
-  * Simulate what happens after a redirect has occurred.
-  *
-  * Since the value of t_starttransfer is set to the value from the first
-  * request, it should be updated when a transfer occurs such that
-  * t_starttransfer is the starttransfer time of the redirect request.
-  */
-  data.progress.t_startsingle.tv_sec = now.tv_sec - 3;
-  data.progress.t_startsingle.tv_usec = now.tv_usec;
   data.progress.t_redirect = data.progress.t_starttransfer + 1;
+  fake_t_startsingle_time(&data, now, -1);
 
+  Curl_pgrsTime(&data, TIMER_NAMELOOKUP);
+  Curl_pgrsTime(&data, TIMER_CONNECT);
+  Curl_pgrsTime(&data, TIMER_APPCONNECT);
+  Curl_pgrsTime(&data, TIMER_PRETRANSFER);
+  /* ensure t_starttransfer is only set on the first invocation by attempting
+   * to set it twice */
+  Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
   Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
 
-  fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 3),
+  expect_timer_seconds(&data, 3);
-              "about 3 second should have passed");
 UNITTEST_STOP