Calculate and report tunnel establishment duration.

psiphon/controller.go

@@ -913,6 +913,11 @@ func (controller *Controller) startEstablishing() {
 		return
 	}
 	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{})
@@ -948,7 +953,7 @@ func (controller *Controller) startEstablishing() {
 
 	for i := 0; i < controller.config.ConnectionWorkerPoolSize; i++ {
 		controller.establishWaitGroup.Add(1)
-		go controller.establishTunnelWorker()
+		go controller.establishTunnelWorker(establishStartTime)
 	}
 
 	controller.establishWaitGroup.Add(1)
@@ -1116,7 +1121,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() {
+func (controller *Controller) establishTunnelWorker(establishStartTime time.Time) {
 	defer controller.establishWaitGroup.Done()
 loop:
 	for candidateServerEntry := range controller.candidateServerEntries {
@@ -1137,6 +1142,7 @@ loop:
 			controller.sessionId,
 			controller.establishPendingConns,
 			candidateServerEntry.serverEntry,
+			establishStartTime,
 			controller) // TunnelOwner
 		if err != nil {
 

psiphon/serverApi.go

@@ -604,13 +604,17 @@ func RecordTunnelStats(
 	sessionId string,
 	tunnelNumber int64,
 	tunnelServerIpAddress string,
-	serverHandshakeTimestamp, duration string,
-	totalBytesSent, totalBytesReceived int64) error {
+	establishmentDuration string,
+	serverHandshakeTimestamp string,
+	tunnelDuration string,
+	totalBytesSent int64,
+	totalBytesReceived int64) error {
 
 	tunnelStats := struct {
 		SessionId                string `json:"session_id"`
 		TunnelNumber             int64  `json:"tunnel_number"`
 		TunnelServerIpAddress    string `json:"tunnel_server_ip_address"`
+		EstablishmentDuration    string `json:"establishmentDuration"`
 		ServerHandshakeTimestamp string `json:"server_handshake_timestamp"`
 		Duration                 string `json:"duration"`
 		TotalBytesSent           int64  `json:"total_bytes_sent"`
@@ -619,8 +623,9 @@ func RecordTunnelStats(
 		sessionId,
 		tunnelNumber,
 		tunnelServerIpAddress,
+		establishmentDuration,
 		serverHandshakeTimestamp,
-		duration,
+		tunnelDuration,
 		totalBytesSent,
 		totalBytesReceived,
 	}

psiphon/tunnel.go

@@ -80,6 +80,7 @@ type Tunnel struct {
 	signalPortForwardFailure     chan struct{}
 	totalPortForwardFailures     int
 	startTime                    time.Time
+	establishDuration            time.Duration
 	dialStats                    *TunnelDialStats
 	newClientVerificationPayload chan string
 }
@@ -116,6 +117,7 @@ func EstablishTunnel(
 	sessionId string,
 	pendingConns *common.Conns,
 	serverEntry *ServerEntry,
+	establishStartTime time.Time,
 	tunnelOwner TunnelOwner) (tunnel *Tunnel, err error) {
 
 	selectedProtocol, err := selectProtocol(config, serverEntry)
@@ -174,6 +176,14 @@ func EstablishTunnel(
 
 	tunnel.startTime = 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 device sleep time.
+	tunnel.establishDuration = tunnel.startTime.Sub(establishStartTime)
+
 	// Now that network operations are complete, cancel interruptibility
 	pendingConns.Remove(conn)
 
@@ -995,6 +1005,7 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 			tunnel.serverContext.sessionId,
 			tunnel.serverContext.tunnelNumber,
 			tunnel.serverEntry.IpAddress,
+			fmt.Sprintf("%d", tunnel.establishDuration),
 			tunnel.serverContext.serverHandshakeTimestamp,
 			fmt.Sprintf("%d", time.Now().Sub(tunnel.startTime)),
 			totalSent,