Record individual tunnel dial time for metrics

psiphon/dialParameters.go

@@ -103,6 +103,8 @@ type DialParameters struct {
 	DialConnMetrics          common.MetricsSource `json:"-"`
 	ObfuscatedSSHConnMetrics common.MetricsSource `json:"-"`
 
+	DialDuration time.Duration `json:"-"`
+
 	dialConfig *DialConfig `json:"-"`
 	meekConfig *MeekConfig `json:"-"`
 }

psiphon/server/api.go

@@ -593,6 +593,7 @@ var baseRequestParams = append(
 		{"pad_response", isIntString, requestParamOptional | requestParamLogStringAsInt},
 		{"is_replay", isBooleanFlag, requestParamOptional | requestParamLogFlagAsBool},
 		{"egress_region", isRegionCode, requestParamOptional},
+		{"dial_duration", isIntString, requestParamOptional | requestParamLogStringAsInt},
 	},
 	upstreamFragmentorParams...)
 

psiphon/serverApi.go

@@ -809,6 +809,9 @@ func getBaseAPIParameters(
 		params["egress_region"] = config.EgressRegion
 	}
 
+	// dialParams.DialDuration is nanoseconds; divide to get to milliseconds
+	params["dial_duration"] = fmt.Sprintf("%d", dialParams.DialDuration/1000000)
+
 	if dialParams.DialConnMetrics != nil {
 		metrics := dialParams.DialConnMetrics.GetMetrics()
 		for name, value := range metrics {

psiphon/tunnel.go

@@ -565,6 +565,19 @@ func dialTunnel(
 	ctx, cancelFunc = context.WithTimeout(ctx, timeout)
 	defer cancelFunc()
 
+	// DialDuration is the elapsed time for both successful and failed tunnel
+	// dials. For successful tunnels, it includes any the network protocol
+	// handshake(s), obfuscation protocol handshake(s), SSH handshake, and
+	// liveness test, when performed.
+	//
+	// Note: ensure DialDuration is set before calling any function which logs
+	// dial_duration.
+
+	startDialTime := monotime.Now()
+	defer func() {
+		dialParams.DialDuration = monotime.Since(startDialTime)
+	}()
+
 	// Note: dialParams.MeekResolvedIPAddress isn't set until the dial begins,
 	// so it will always be blank in NoticeConnectingServer.