Log additional metrics for remote server list downloads

- Log bytes transferred and download duration.
- Add duration to NoticeRemoteServerListResourceDownloadedBytes.
- Additional metrics may be used to calculate transfer
  rates. Logging base values enables excluding outliers.

psiphon/notice.go

@@ -745,14 +745,15 @@ func NoticeExiting() {
 }
 
 // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress.
-func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64) {
+func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64, duration time.Duration) {
 	if !GetEmitNetworkParameters() {
 		url = "[redacted]"
 	}
 	singletonNoticeLogger.outputNotice(
 		"RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic,
 		"url", url,
-		"bytes", bytes)
+		"bytes", bytes,
+		"duration", duration.String())
 }
 
 // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download
@@ -843,7 +844,7 @@ func NoticePruneServerEntry(serverEntryTag string) {
 func NoticeEstablishTunnelTimeout(timeout time.Duration) {
 	singletonNoticeLogger.outputNotice(
 		"EstablishTunnelTimeout", 0,
-		"timeout", timeout)
+		"timeout", timeout.String())
 }
 
 func NoticeFragmentor(diagnosticID string, message string) {

psiphon/remoteServerList.go

@@ -460,7 +460,9 @@ func downloadRemoteServerListFile(
 		return "", nil, errors.Trace(err)
 	}
 
-	n, responseETag, err := ResumeDownload(
+	startTime := time.Now()
+
+	bytes, responseETag, err := ResumeDownload(
 		ctx,
 		httpClient,
 		sourceURL,
@@ -468,7 +470,9 @@ func downloadRemoteServerListFile(
 		destinationFilename,
 		lastETag)
 
-	NoticeRemoteServerListResourceDownloadedBytes(sourceURL, n)
+	duration := time.Since(startTime)
+
+	NoticeRemoteServerListResourceDownloadedBytes(sourceURL, bytes, duration)
 
 	if err != nil {
 		return "", nil, errors.Trace(err)
@@ -482,7 +486,7 @@ func downloadRemoteServerListFile(
 
 	downloadStatRecorder := func(authenticated bool) {
 		_ = RecordRemoteServerListStat(
-			config, tunneled, sourceURL, responseETag, authenticated)
+			config, tunneled, sourceURL, responseETag, bytes, duration, authenticated)
 	}
 
 	return responseETag, downloadStatRecorder, nil

psiphon/server/api.go

@@ -466,6 +466,8 @@ var remoteServerListStatParams = append(
 		{"tunneled", isBooleanFlag, requestParamOptional | requestParamLogFlagAsBool},
 		{"url", isAnyString, 0},
 		{"etag", isAnyString, 0},
+		{"bytes", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"duration", isIntString, requestParamOptional | requestParamLogStringAsInt},
 		{"authenticated", isBooleanFlag, requestParamOptional | requestParamLogFlagAsBool}},
 	baseSessionParams...)
 
@@ -491,12 +493,12 @@ var failedTunnelStatParams = append(
 		{"session_id", isHexDigits, 0},
 		{"last_connected", isLastConnected, 0},
 		{"client_failed_timestamp", isISO8601Date, 0},
-		{"liveness_test_upstream_bytes", isIntString, requestParamOptional},
-		{"liveness_test_sent_upstream_bytes", isIntString, requestParamOptional},
-		{"liveness_test_downstream_bytes", isIntString, requestParamOptional},
-		{"liveness_test_received_downstream_bytes", isIntString, requestParamOptional},
-		{"bytes_up", isIntString, requestParamOptional},
-		{"bytes_down", isIntString, requestParamOptional},
+		{"liveness_test_upstream_bytes", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"liveness_test_sent_upstream_bytes", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"liveness_test_downstream_bytes", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"liveness_test_received_downstream_bytes", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"bytes_up", isIntString, requestParamOptional | requestParamLogStringAsInt},
+		{"bytes_down", isIntString, requestParamOptional | requestParamLogStringAsInt},
 		{"tunnel_error", isAnyString, 0}},
 	baseSessionAndDialParams...)
 

psiphon/serverApi.go

@@ -33,6 +33,7 @@ import (
 	"net/url"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/buildinfo"
@@ -383,9 +384,9 @@ func (serverContext *ServerContext) DoConnectedRequest() error {
 
 	params["last_connected"] = lastConnected
 
-	// serverContext.tunnel.establishDuration is nanoseconds; divide to get to milliseconds
+	// serverContext.tunnel.establishDuration is nanoseconds; report milliseconds
 	params["establishment_duration"] =
-		fmt.Sprintf("%d", serverContext.tunnel.establishDuration/1000000)
+		fmt.Sprintf("%d", serverContext.tunnel.establishDuration/time.Millisecond)
 
 	var response []byte
 	if serverContext.psiphonHttpsClient == nil {
@@ -628,6 +629,8 @@ func RecordRemoteServerListStat(
 	tunneled bool,
 	url string,
 	etag string,
+	bytes int64,
+	duration time.Duration,
 	authenticated bool) error {
 
 	if !config.GetClientParameters().Get().WeightedCoinFlip(
@@ -655,6 +658,11 @@ func RecordRemoteServerListStat(
 	params["tunneled"] = tunneledStr
 	params["url"] = url
 	params["etag"] = etag
+	params["bytes"] = fmt.Sprintf("%d", bytes)
+
+	// duration is nanoseconds; report milliseconds
+	params["duration"] = fmt.Sprintf("%d", duration/time.Millisecond)
+
 	authenticatedStr := "0"
 	if authenticated {
 		authenticatedStr = "1"
@@ -964,8 +972,8 @@ 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)
+		// dialParams.DialDuration is nanoseconds; report milliseconds
+		params["dial_duration"] = fmt.Sprintf("%d", dialParams.DialDuration/time.Millisecond)
 
 		params["candidate_number"] = strconv.Itoa(dialParams.CandidateNumber)