multi interface: missed storing connection time

Dirk Manske reported a regression. When connecting with the multi
interface, there were situations where libcurl wouldn't store
connect time correctly as it used to (and is documented to) do.

Using his fine sample program we could repeat it, and I wrote up
test case 573 using that code. The problem does not easily show
itself using the local test suite though.

The fix, also as suggested by Dirk, is a bit on the ugly side as
it adds yet another call to Curl_verboseconnect() and setting the
TIMER_CONNECT time.  That situation is subject for some closer
inspection in the future.

9 files changed, 189 insertions, 12 deletions

diff --git a/CHANGES b/CHANGES
index 1076b015a..8b794c04d 100644
--- a/CHANGES
+++ b/CHANGES
@@ -7,6 +7,18 @@
                                   Changelog
 
 Daniel Stenberg (7 May 2010)
+- Dirk Manske reported a regression. When connecting with the multi interface,
+  there were situations where libcurl wouldn't store connect time correctly as
+  it used to (and is documented to) do.
+
+  Using his fine sample program we could repeat it, and I wrote up test case
+  573 using that code. The problem does not easily show itself using the local
+  test suite though.
+
+  The fix, also as suggested by Dirk, is a bit on the ugly side as it adds yet
+  another call to Curl_verboseconnect() and setting the TIMER_CONNECT time.
+  That situation is subject for some closer inspection in the future.
+
 - Howard Chu split the I/O handling functions into private handlers.
     
   Howard Chu brought the bulk work of this patch that properly moves out the
diff --git a/RELEASE-NOTES b/RELEASE-NOTES
index 01dcd2ee6..b0b94986c 100644
--- a/RELEASE-NOTES
+++ b/RELEASE-NOTES
@@ -24,6 +24,7 @@ This release includes the following bugfixes:
  o MSVC makefiles now use ws2_32.lib instead of wsock32.lib
  o -O crash on windows
  o SSL handshake timeout underflow in libcurl-NSS
+ o multi interface missed storing connection time
 
 This release includes the following known bugs:
 
@@ -33,6 +34,6 @@ This release would not have looked like this without help, code, reports and
 advice from friends like these:
 
  Rainer Canavan, Paul Howarth, Jerome Vouillon, Ruslan Gazizov, Yang Tse,
- Kamil Dudka, Alex Bligh, Ben Greear, Hoi-Ho Chan, Howard Chu
+ Kamil Dudka, Alex Bligh, Ben Greear, Hoi-Ho Chan, Howard Chu, Dirk Manske
 
         Thanks! (and sorry if I forgot to mention someone)
diff --git a/lib/connect.c b/lib/connect.c
index eb6df71d4..4adc7f35a 100644
--- a/lib/connect.c
+++ b/lib/connect.c
@@ -575,6 +575,8 @@ CURLcode Curl_is_connected(struct connectdata *conn,
       /* we are connected, awesome! */
       conn->bits.tcpconnect = TRUE;
       *connected = TRUE;
+      Curl_pgrsTime(data, TIMER_CONNECT); /* connect done */
+      Curl_verboseconnect(conn);
       return CURLE_OK;
     }
     /* nope, not connected for real */
diff --git a/lib/url.c b/lib/url.c
index 9c9e09fbc..c41db0a7c 100644
--- a/lib/url.c
+++ b/lib/url.c
@@ -150,10 +150,6 @@ static long ConnectionKillOne(struct SessionHandle *data);
 static void conn_free(struct connectdata *conn);
 static void signalPipeClose(struct curl_llist *pipeline, bool pipe_broke);
 
-#ifdef CURL_DISABLE_VERBOSE_STRINGS
-#define verboseconnect(x)  do { } while (0)
-#endif
-
 /*
  * Protocol table.
  */
@@ -3178,7 +3174,7 @@ static CURLcode ConnectPlease(struct SessionHandle *data,
  * verboseconnect() displays verbose information after a connect
  */
 #ifndef CURL_DISABLE_VERBOSE_STRINGS
-static void verboseconnect(struct connectdata *conn)
+void Curl_verboseconnect(struct connectdata *conn)
 {
   if(conn->data->set.verbose)
     infof(conn->data, "Connected to %s (%s) port %ld (#%ld)\n",
@@ -3274,8 +3270,7 @@ CURLcode Curl_protocol_connect(struct connectdata *conn,
   if(!conn->bits.tcpconnect) {
 
     Curl_pgrsTime(data, TIMER_CONNECT); /* connect done */
-
-    verboseconnect(conn);
+    Curl_verboseconnect(conn);
   }
 
   if(!conn->bits.protoconnstart) {
@@ -4997,7 +4992,7 @@ static CURLcode setup_conn(struct connectdata *conn,
       Curl_pgrsTime(data, TIMER_APPCONNECT); /* we're connected already */
       conn->bits.tcpconnect = TRUE;
       *protocol_done = TRUE;
-      verboseconnect(conn);
+      Curl_verboseconnect(conn);
     }
     /* Stop the loop now */
     break;
diff --git a/lib/url.h b/lib/url.h
index cb3dd2f60..63d7f2c48 100644
--- a/lib/url.h
+++ b/lib/url.h
@@ -7,7 +7,7 @@
  *                            | (__| |_| |  _ <| |___
  *                             \___|\___/|_| \_\_____|
  *
- * Copyright (C) 1998 - 2009, Daniel Stenberg, <daniel@haxx.se>, et al.
+ * Copyright (C) 1998 - 2010, Daniel Stenberg, <daniel@haxx.se>, et al.
  *
  * This software is licensed as described in the file COPYING, which
  * you should have received as part of this distribution. The terms
@@ -86,4 +86,11 @@ void Curl_reset_reqproto(struct connectdata *conn);
 
 CURLcode Curl_connected_proxy(struct connectdata *conn);
 
+#ifdef CURL_DISABLE_VERBOSE_STRINGS
+#define Curl_verboseconnect(x)  do { } while (0)
+#else
+void Curl_verboseconnect(struct connectdata *conn);
+#endif
+
+
 #endif
diff --git a/tests/data/Makefile.am b/tests/data/Makefile.am
index b28c5adc2..dabe3d195 100644
--- a/tests/data/Makefile.am
+++ b/tests/data/Makefile.am
@@ -65,7 +65,8 @@ EXTRA_DIST = test1 test108 test117 test127 test20 test27 test34 test46	   \
  test564 test1101 test1102 test1103 test1104 test299 test310 test311       \
  test312 test1105 test565 test800 test1106 test801 test566 test802 test803 \
  test1107 test1108 test1109 test1110 test1111 test1112 test129 test567     \
- test568 test569 test570 test571 test572 test804 test805 test806 test807
+ test568 test569 test570 test571 test572 test804 test805 test806 test807 \
+ test573
 
 filecheck:
 	@mkdir test-place; \
diff --git a/tests/data/test573 b/tests/data/test573
new file mode 100644
index 000000000..909ae3cf7
--- /dev/null
+++ b/tests/data/test573
@@ -0,0 +1,56 @@
+<testcase>
+<info>
+<keywords>
+FILE
+</keywords>
+</info>
+#
+# Server-side
+<reply>
+<data>
+HTTP/1.1 200 OK
+Date: Thu, 09 Nov 2010 14:49:00 GMT
+Server: test-server/fake
+Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
+ETag: "21025-dc7-39462498"
+Accept-Ranges: bytes
+Content-Length: 6
+Connection: close
+Content-Type: text/html
+Funny-head: yesyes
+
+-foo-
+</data>
+</reply>
+
+# Client-side
+<client>
+<server>
+http
+</server>
+# tool is what to use instead of 'curl'
+<tool>
+lib573
+</tool>
+
+ <name>
+verify connect time with multi interface
+ </name>
+ <command>
+http://%HOSTIP:%HTTPPORT/573
+</command>
+</client>
+
+# Verify data after the test has been "shot"
+<verify>
+<strip>
+^User-Agent:.*
+</strip>
+<protocol>
+GET /573 HTTP/1.1

+Host: %HOSTIP:%HTTPPORT

+Accept: */*

+

+</protocol>
+</verify>
+</testcase>
diff --git a/tests/libtest/Makefile.inc b/tests/libtest/Makefile.inc
index 4dc8615a7..58d5d9226 100644
--- a/tests/libtest/Makefile.inc
+++ b/tests/libtest/Makefile.inc
@@ -11,7 +11,7 @@ noinst_PROGRAMS = lib500 lib501 lib502 lib503 lib504 lib505 lib506	\
   lib529 lib530 lib532 lib533 lib536 lib537 lib540 lib541 lib542 lib543 \
   lib544 lib545 lib547 lib548 lib549 lib552 lib553 lib554 lib555 lib556 \
   lib539 lib557 lib558 lib559 lib560 lib562 lib564 lib565 lib566 lib567 \
-  lib568 lib569 lib570 lib571 lib572
+  lib568 lib569 lib570 lib571 lib572 lib573
 
 lib500_SOURCES = lib500.c $(SUPPORTFILES)
 
@@ -145,3 +145,4 @@ lib571_SOURCES = lib571.c $(SUPPORTFILES)
 
 lib572_SOURCES = lib572.c $(SUPPORTFILES)
 
+lib573_SOURCES = lib573.c $(SUPPORTFILES) $(TESTUTIL)
diff --git a/tests/libtest/lib573.c b/tests/libtest/lib573.c
new file mode 100644
index 000000000..e08b6df46
--- /dev/null
+++ b/tests/libtest/lib573.c
@@ -0,0 +1,102 @@
+/*****************************************************************************
+ *                                  _   _ ____  _
+ *  Project                     ___| | | |  _ \| |
+ *                             / __| | | | |_) | |
+ *                            | (__| |_| |  _ <| |___
+ *                             \___|\___/|_| \_\_____|
+ *
+ */
+
+#include "test.h"
+
+#include "testutil.h"
+#include "memdebug.h"
+
+#define MAIN_LOOP_HANG_TIMEOUT     90 * 1000
+#define MULTI_PERFORM_HANG_TIMEOUT 60 * 1000
+
+/*
+ * Get a single URL without select().
+ */
+
+int test(char *URL)
+{
+  CURL *c;
+  CURLM *m = NULL;
+  int res = 0;
+  int running=1;
+  long connect_time = 0;
+  struct timeval mp_start;
+  char mp_timedout = FALSE;
+
+  if (curl_global_init(CURL_GLOBAL_ALL) != CURLE_OK) {
+    fprintf(stderr, "curl_global_init() failed\n");
+    return TEST_ERR_MAJOR_BAD;
+  }
+
+  if ((c = curl_easy_init()) == NULL) {
+    fprintf(stderr, "curl_easy_init() failed\n");
+    curl_global_cleanup();
+    return TEST_ERR_MAJOR_BAD;
+  }
+
+  test_setopt(c, CURLOPT_HEADER, 1L);
+  test_setopt(c, CURLOPT_URL, URL);
+
+  if ((m = curl_multi_init()) == NULL) {
+    fprintf(stderr, "curl_multi_init() failed\n");
+    curl_easy_cleanup(c);
+    curl_global_cleanup();
+    return TEST_ERR_MAJOR_BAD;
+  }
+
+  if ((res = (int)curl_multi_add_handle(m, c)) != CURLM_OK) {
+    fprintf(stderr, "curl_multi_add_handle() failed, "
+            "with code %d\n", res);
+    curl_multi_cleanup(m);
+    curl_easy_cleanup(c);
+    curl_global_cleanup();
+    return TEST_ERR_MAJOR_BAD;
+  }
+
+  mp_timedout = FALSE;
+  mp_start = tutil_tvnow();
+
+  while (running) {
+    res = (int)curl_multi_perform(m, &running);
+    if (tutil_tvdiff(tutil_tvnow(), mp_start) >
+        MULTI_PERFORM_HANG_TIMEOUT) {
+      mp_timedout = TRUE;
+      break;
+    }
+    if (running <= 0) {
+      fprintf(stderr, "nothing left running.\n");
+      break;
+    }
+  }
+
+  if (mp_timedout) {
+    if (mp_timedout) fprintf(stderr, "mp_timedout\n");
+    fprintf(stderr, "ABORTING TEST, since it seems "
+            "that it would have run forever.\n");
+    res = TEST_ERR_RUNS_FOREVER;
+  }
+
+  curl_easy_getinfo(c, CURLINFO_CONNECT_TIME, &connect_time);
+  if (connect_time==0) {
+    fprintf(stderr, "connect time is 0\n");
+    res = TEST_ERR_MAJOR_BAD;
+  }
+
+test_cleanup:
+
+  if(m) {
+    curl_multi_remove_handle(m, c);
+    curl_multi_cleanup(m);
+  }
+  curl_easy_cleanup(c);
+  curl_global_cleanup();
+
+  return res;
+}
+