Exclude network unavailable time from tunnel establishment duration

psiphon/controller.go

@@ -68,6 +68,8 @@ type Controller struct {
 type candidateServerEntry struct {
 	serverEntry               *ServerEntry
 	isServerAffinityCandidate bool
+	establishStartTime        time.Time
+	networkWaitDuration       time.Duration
 }
 
 // NewController initializes a new controller.
@@ -914,10 +916,6 @@ func (controller *Controller) startEstablishing() {
 	}
 	NoticeInfo("start establishing")
 
-	// establishStartTime is used to calculate and report the
-	// client's tunnel establishment duration.
-	establishStartTime := time.Now()
-
 	controller.isEstablishing = true
 	controller.establishWaitGroup = new(sync.WaitGroup)
 	controller.stopEstablishingBroadcast = make(chan struct{})
@@ -953,7 +951,7 @@ func (controller *Controller) startEstablishing() {
 
 	for i := 0; i < controller.config.ConnectionWorkerPoolSize; i++ {
 		controller.establishWaitGroup.Add(1)
-		go controller.establishTunnelWorker(establishStartTime)
+		go controller.establishTunnelWorker()
 	}
 
 	controller.establishWaitGroup.Add(1)
@@ -991,6 +989,16 @@ func (controller *Controller) establishCandidateGenerator(impairedProtocols []st
 	defer controller.establishWaitGroup.Done()
 	defer close(controller.candidateServerEntries)
 
+	// establishStartTime is used to calculate and report the
+	// client's tunnel establishment duration.
+	//
+	// networkWaitDuration is the elapsed time spent waiting
+	// for network connectivity. This duration will be excluded
+	// from reported tunnel establishment duration.
+	// networkWaitDuration may include device sleep time.
+	establishStartTime := time.Now()
+	var networkWaitDuration time.Duration
+
 	iterator, err := NewServerEntryIterator(controller.config)
 	if err != nil {
 		NoticeAlert("failed to iterate over candidates: %s", err)
@@ -1011,6 +1019,8 @@ loop:
 	// Repeat until stopped
 	for i := 0; ; i++ {
 
+		networkWaitStartTime := time.Now()
+
 		if !WaitForNetworkConnectivity(
 			controller.config.NetworkConnectivityChecker,
 			controller.stopEstablishingBroadcast,
@@ -1018,6 +1028,8 @@ loop:
 			break loop
 		}
 
+		networkWaitDuration += time.Since(networkWaitStartTime)
+
 		// Send each iterator server entry to the establish workers
 		startTime := time.Now()
 		for {
@@ -1052,9 +1064,15 @@ loop:
 				}
 			}
 
+			candidate := &candidateServerEntry{
+				serverEntry:               serverEntry,
+				isServerAffinityCandidate: isServerAffinityCandidate,
+				establishStartTime:        establishStartTime,
+				networkWaitDuration:       networkWaitDuration,
+			}
+
 			// Note: there must be only one server affinity candidate, as it
 			// closes the serverAffinityDoneBroadcast channel.
-			candidate := &candidateServerEntry{serverEntry, isServerAffinityCandidate}
 			isServerAffinityCandidate = false
 
 			// TODO: here we could generate multiple candidates from the
@@ -1121,7 +1139,7 @@ loop:
 
 // establishTunnelWorker pulls candidates from the candidate queue, establishes
 // a connection to the tunnel server, and delivers the established tunnel to a channel.
-func (controller *Controller) establishTunnelWorker(establishStartTime time.Time) {
+func (controller *Controller) establishTunnelWorker() {
 	defer controller.establishWaitGroup.Done()
 loop:
 	for candidateServerEntry := range controller.candidateServerEntries {
@@ -1142,7 +1160,8 @@ loop:
 			controller.sessionId,
 			controller.establishPendingConns,
 			candidateServerEntry.serverEntry,
-			establishStartTime,
+			candidateServerEntry.establishStartTime,
+			candidateServerEntry.networkWaitDuration,
 			controller) // TunnelOwner
 		if err != nil {
 

psiphon/tunnel.go

@@ -119,6 +119,7 @@ func EstablishTunnel(
 	pendingConns *common.Conns,
 	serverEntry *ServerEntry,
 	establishStartTime time.Time,
+	establishNetworkWaitDuration time.Duration,
 	tunnelOwner TunnelOwner) (tunnel *Tunnel, err error) {
 
 	selectedProtocol, err := selectProtocol(config, serverEntry)
@@ -181,12 +182,24 @@ func EstablishTunnel(
 	tunnel.establishedTime = time.Now()
 
 	// establishDuration is the elapsed time between the controller starting tunnel
-	// establishment and this tunnel being established. This time period can include
-	// time spent unsuccessfully connecting to other servers. The reported value
-	// represents how long the user waited between starting the client and having
-	// a usable tunnel.
-	// Note: this duration calculation doesn't exclude host or device sleep time.
-	tunnel.establishDuration = tunnel.establishedTime.Sub(establishStartTime)
+	// establishment and this tunnel being established. The reported value represents
+	// how long the user waited between starting the client and having a usable tunnel;
+	// or how long between the client detecting an unexpected tunnel disconnect and
+	// completing automatic reestablishment.
+	//
+	// This time period may include time spent unsuccessfully connecting to other
+	// servers. Time spent waiting for network connectivity is excluded. This duration
+	// calculation doesn't exclude host or device sleep time, except that which is
+	// included in establishNetworkWaitDuration.
+	tunnel.establishDuration =
+		time.Duration(tunnel.establishedTime.Sub(establishStartTime).Nanoseconds() -
+			establishNetworkWaitDuration.Nanoseconds())
+
+	// A negative duration typically shouldn't happen, unless the user changes
+	// the OS clock. Always report 0 in this case.
+	if tunnel.establishDuration < 0 {
+		tunnel.establishDuration = 0
+	}
 
 	// Now that network operations are complete, cancel interruptibility
 	pendingConns.Remove(dialConn)
@@ -1011,7 +1024,7 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 
 	// The stats for this tunnel will be reported via the next successful
 	// status request.
-	//
+
 	// Since client clocks are unreliable, we report the server's timestamp from
 	// the handshake response as the absolute tunnel start time. This time
 	// will be slightly earlier than the actual tunnel activation time, as the
@@ -1024,14 +1037,18 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 	// have resumed after a long sleep. Instead, we use the last data received time
 	// as the estimated tunnel end time.
 	//
-	// One potential issue with using the last rereceived time is a successful read
-	// after a long sleep when the device sleep occured with data still in the OS socket
-	// buffer. This is not expected to happen on Android, as the OS will wake a process
-	// when it has TCP data available to read. (For this reason, the actual long sleep
-	// issue is only with an idle tunnel; in this case the client is responsible for
-	// sending SSH keep alives but a device sleep will delay the golang SSH keep alive
-	// timer.)
+	// One potential issue with using the last received time is receiving data
+	// after an extended sleep because the device sleep occured with data still in
+	// the OS socket read buffer. This is not expected to happen on Android, as the
+	// OS will wake a process when it has TCP data available to read. (For this reason,
+	// the actual long sleep issue is only with an idle tunnel; in this case the client
+	// is responsible for sending SSH keep alives but a device sleep will delay the
+	// golang SSH keep alive timer.)
 	//
+	// Idle tunnels will only read data when a SSH keep alive is sent. As a result,
+	// the last-received-time scheme can undercount tunnel durations by up to
+	// TUNNEL_SSH_KEEP_ALIVE_PERIOD_MAX to idle tunnels.
+
 	// Tunnel does not have a serverContext when DisableApi is set.
 	if tunnel.serverContext != nil && !tunnel.IsDiscarded() {
 		err := RecordTunnelStats(
@@ -1107,6 +1124,8 @@ func sendSshKeepAlive(
 			// Proceed without random padding
 			randomPadding = make([]byte, 0)
 		}
+		// Note: reading a reply is important for last-received-time tunnel
+		// duration calculation.
 		_, _, err = sshClient.SendRequest("keepalive@openssh.com", true, randomPadding)
 		errChannel <- err
 	}()