Add some timestamps to connect/accept failures.

This is in an attempt to debug the Mac flakiness. The timestamps will
hopefully help narrow down the order of operations here.

Bug: 199
Change-Id: I8b8dd7222e3a57a8b055b8bc1b7731334e0fcdf0
Reviewed-on: https://boringssl-review.googlesource.com/17886
Commit-Queue: David Benjamin <davidben@google.com>
Commit-Queue: Steven Valdez <svaldez@google.com>
Reviewed-by: Steven Valdez <svaldez@google.com>
CQ-Verified: CQ bot account: commit-bot@chromium.org <commit-bot@chromium.org>

ssl/test/bssl_shim.cc

@@ -39,6 +39,7 @@ OPENSSL_MSVC_PRAGMA(comment(lib, "Ws2_32.lib"))
 #include <assert.h>
 #include <inttypes.h>
 #include <string.h>
+#include <time.h>
 
 #include <openssl/aead.h>
 #include <openssl/bio.h>
@@ -969,6 +970,7 @@ static int ServerNameCallback(SSL *ssl, int *out_alert, void *arg) {
 // Connect returns a new socket connected to localhost on |port| or -1 on
 // error.
 static int Connect(uint16_t port) {
+  time_t start_time = time(nullptr);
   for (int af : { AF_INET6, AF_INET }) {
     int sock = socket(af, SOCK_STREAM, 0);
     if (sock == -1) {
@@ -1013,7 +1015,13 @@ static int Connect(uint16_t port) {
     }
     closesocket(sock);
   }
+
   PrintSocketError("connect");
+  // TODO(davidben): Remove this logging when https://crbug.com/boringssl/199 is
+  // resolved.
+  fprintf(stderr, "start_time = %lld, end_time = %lld\n",
+          static_cast<long long>(start_time),
+          static_cast<long long>(time(nullptr)));
   return -1;
 }
 

ssl/test/runner/runner.go

@@ -881,18 +881,26 @@ var (
 // exit first.
 func acceptOrWait(listener *net.TCPListener, waitChan chan error) (net.Conn, error) {
 	type connOrError struct {
-		conn net.Conn
-		err  error
+		conn               net.Conn
+		err                error
+		startTime, endTime time.Time
 	}
 	connChan := make(chan connOrError, 1)
 	go func() {
+		startTime := time.Now()
 		listener.SetDeadline(time.Now().Add(*idleTimeout))
 		conn, err := listener.Accept()
-		connChan <- connOrError{conn, err}
+		endTime := time.Now()
+		connChan <- connOrError{conn, err, startTime, endTime}
 		close(connChan)
 	}()
 	select {
 	case result := <-connChan:
+		if result.err != nil {
+			// TODO(davidben): Remove this logging when
+			// https://crbug.com/boringssl/199 is resolved.
+			fmt.Fprintf(os.Stderr, "acceptOrWait failed, startTime=%v, endTime=%v\n", result.startTime, result.endTime)
+		}
 		return result.conn, result.err
 	case childErr := <-waitChan:
 		waitChan <- childErr