Merge branch 'master' into staging-client

psiphon/common/utils.go

@@ -23,10 +23,12 @@ import (
 	"bytes"
 	"compress/zlib"
 	"crypto/rand"
+	std_errors "errors"
 	"fmt"
 	"io"
 	"io/ioutil"
 	"math"
+	"net/url"
 	"os"
 	"time"
 
@@ -237,3 +239,37 @@ func DoFileMigration(migration FileMigration) error {
 
 	return nil
 }
+
+// SafeParseURL wraps url.Parse, stripping the input URL from any error
+// message. This allows logging url.Parse errors without unintentially logging
+// PII that may appear in the input URL.
+func SafeParseURL(rawurl string) (*url.URL, error) {
+	parsedURL, err := url.Parse(rawurl)
+	if err != nil {
+		// Unwrap yields just the url.Error error field without the url.Error URL
+		// and operation fields.
+		err = std_errors.Unwrap(err)
+		if err == nil {
+			err = std_errors.New("SafeParseURL: Unwrap failed")
+		} else {
+			err = fmt.Errorf("url.Parse: %v", err)
+		}
+	}
+	return parsedURL, err
+}
+
+// SafeParseRequestURI wraps url.ParseRequestURI, stripping the input URL from
+// any error message. This allows logging url.ParseRequestURI errors without
+// unintentially logging PII that may appear in the input URL.
+func SafeParseRequestURI(rawurl string) (*url.URL, error) {
+	parsedURL, err := url.ParseRequestURI(rawurl)
+	if err != nil {
+		err = std_errors.Unwrap(err)
+		if err == nil {
+			err = std_errors.New("SafeParseRequestURI: Unwrap failed")
+		} else {
+			err = fmt.Errorf("url.ParseRequestURI: %v", err)
+		}
+	}
+	return parsedURL, err
+}

psiphon/common/utils_test.go

@@ -22,7 +22,9 @@ package common
 import (
 	"bytes"
 	"encoding/json"
+	"net/url"
 	"reflect"
+	"strings"
 	"testing"
 )
 
@@ -90,3 +92,53 @@ func TestFormatByteCount(t *testing.T) {
 		})
 	}
 }
+
+func TestSafeParseURL(t *testing.T) {
+
+	invalidURL := "https://invalid url"
+
+	_, err := url.Parse(invalidURL)
+
+	if err == nil {
+		t.Error("unexpected parse success")
+	}
+
+	if strings.Index(err.Error(), invalidURL) == -1 {
+		t.Error("URL not in error string")
+	}
+
+	_, err = SafeParseURL(invalidURL)
+
+	if err == nil {
+		t.Error("unexpected parse success")
+	}
+
+	if strings.Index(err.Error(), invalidURL) != -1 {
+		t.Error("URL in error string")
+	}
+}
+
+func TestSafeParseRequestURI(t *testing.T) {
+
+	invalidURL := "https://invalid url"
+
+	_, err := url.ParseRequestURI(invalidURL)
+
+	if err == nil {
+		t.Error("unexpected parse success")
+	}
+
+	if strings.Index(err.Error(), invalidURL) == -1 {
+		t.Error("URL not in error string")
+	}
+
+	_, err = SafeParseRequestURI(invalidURL)
+
+	if err == nil {
+		t.Error("unexpected parse success")
+	}
+
+	if strings.Index(err.Error(), invalidURL) != -1 {
+		t.Error("URL in error string")
+	}
+}

psiphon/dialParameters.go

@@ -26,7 +26,6 @@ import (
 	"fmt"
 	"net"
 	"net/http"
-	"net/url"
 	"strings"
 	"sync/atomic"
 	"time"
@@ -618,7 +617,7 @@ func MakeDialParameters(
 
 	if config.UseUpstreamProxy() {
 		// Note: UpstreamProxyURL will be validated in the dial
-		proxyURL, err := url.Parse(config.UpstreamProxyURL)
+		proxyURL, err := common.SafeParseURL(config.UpstreamProxyURL)
 		if err == nil {
 			dialParams.UpstreamProxyType = proxyURL.Scheme
 		}

psiphon/httpProxy.go

@@ -316,7 +316,7 @@ func (proxy *HttpProxy) urlProxyHandler(responseWriter http.ResponseWriter, requ
 	}
 
 	// Origin URL must be well-formed, absolute, and have a scheme of "http" or "https"
-	originURL, err := url.ParseRequestURI(originURLString)
+	originURL, err := common.SafeParseRequestURI(originURLString)
 	if err != nil {
 		NoticeWarning("%s", errors.Trace(FilterUrlError(err)))
 		forceClose(responseWriter)
@@ -678,7 +678,7 @@ func (proxy *HttpProxy) serve() {
 
 // toAbsoluteURL takes a base URL and a relative URL and constructs an appropriate absolute URL.
 func toAbsoluteURL(baseURL *url.URL, relativeURLString string) string {
-	relativeURL, err := url.Parse(relativeURLString)
+	relativeURL, err := common.SafeParseURL(relativeURLString)
 
 	if err != nil {
 		return ""

psiphon/meekConn.go

@@ -445,7 +445,7 @@ func DialMeek(
 			(meekConfig.DialAddress == meekConfig.HostHeader ||
 				meekConfig.DialAddress == meekConfig.HostHeader+":80") {
 
-			url, err := url.Parse(dialConfig.UpstreamProxyURL)
+			url, err := common.SafeParseURL(dialConfig.UpstreamProxyURL)
 			if err != nil {
 				return nil, errors.Trace(err)
 			}

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,15 +460,19 @@ func downloadRemoteServerListFile(
 		return "", nil, errors.Trace(err)
 	}
 
-	n, responseETag, err := ResumeDownload(
+	startTime := time.Now()
+
+	bytes, responseETag, err := ResumeDownload(
 		ctx,
 		httpClient,
 		sourceURL,
 		MakePsiphonUserAgent(config),
 		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...)
 
@@ -1066,6 +1068,18 @@ func getRequestLogFields(
 				// value for speed_test_samples via the web API protocol. Omit
 				// the field in this case.
 
+			case "tunnel_error":
+				// net/url.Error, returned from net/url.Parse, contains the original input
+				// URL, which may contain PII. New clients strip this out by using
+				// common.SafeParseURL. Legacy clients will still send the full error
+				// message, so strip it out here. The target substring should be unique to
+				// legacy clients.
+				target := "upstreamproxy error: proxyURI url.Parse: parse "
+				index := strings.Index(strValue, target)
+				if index != -1 {
+					strValue = strValue[:index+len(target)] + "<redacted>"
+				}
+
 			default:
 				if expectedParam.flags&requestParamLogStringAsInt != 0 {
 					intValue, _ := strconv.Atoi(strValue)

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 {
@@ -601,33 +602,38 @@ func confirmStatusRequestPayload(payloadInfo *statusRequestPayloadInfo) {
 	}
 }
 
-// RecordRemoteServerListStat records a completed common or OSL
-// remote server list resource download.
+// RecordRemoteServerListStat records a completed common or OSL remote server
+// list resource download.
 //
-// The RSL download event could occur when the client is unable
-// to immediately send a status request to a server, so these
-// records are stored in the persistent datastore and reported
-// via subsequent status requests sent to any Psiphon server.
+// The RSL download event could occur when the client is unable to immediately
+// send a status request to a server, so these records are stored in the
+// persistent datastore and reported via subsequent status requests sent to
+// any Psiphon server.
 //
-// Note that some common event field values may change between the
-// stat recording and reporting, including client geolocation and
-// host_id.
+// Note that some common event field values may change between the stat
+// recording and reporting, including client geolocation and host_id.
 //
-// Multiple "status" requests may be in flight at once (due
-// to multi-tunnel, asynchronous final status retry, and
-// aggressive status requests for pre-registered tunnels),
-// To avoid duplicate reporting, persistent stats records are
-// "taken-out" by a status request and then "put back" in
-// case the request fails.
+// The bytes/duration fields reflect the size and download time for the _last
+// chunk only_ in the case of a resumed download. The purpose of these fields
+// is to calculate rough data transfer rates. Both bytes and duration are
+// included in the log, to allow for filtering out of small transfers which
+// may not produce accurate rate numbers.
 //
-// Duplicate reporting may also occur when a server receives and
-// processes a status request but the client fails to receive
-// the response.
+// Multiple "status" requests may be in flight at once (due to multi-tunnel,
+// asynchronous final status retry, and aggressive status requests for
+// pre-registered tunnels), To avoid duplicate reporting, persistent stats
+// records are "taken-out" by a status request and then "put back" in case the
+// request fails.
+//
+// Duplicate reporting may also occur when a server receives and processes a
+// status request but the client fails to receive the response.
 func RecordRemoteServerListStat(
 	config *Config,
 	tunneled bool,
 	url string,
 	etag string,
+	bytes int64,
+	duration time.Duration,
 	authenticated bool) error {
 
 	if !config.GetClientParameters().Get().WeightedCoinFlip(
@@ -655,6 +661,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 +975,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)
 

psiphon/upstreamproxy/proxy_http.go

@@ -54,6 +54,7 @@ import (
 	"net/url"
 	"time"
 
+	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"golang.org/x/net/proxy"
 )
 
@@ -131,7 +132,7 @@ type proxyConn struct {
 func (pc *proxyConn) handshake(addr, username, password string) error {
 	// HACK: prefix addr of the form 'hostname:port' with a 'http' scheme
 	// so it could be parsed by url.Parse
-	reqURL, err := url.Parse("http://" + addr)
+	reqURL, err := common.SafeParseURL("http://" + addr)
 	if err != nil {
 		pc.httpClientConn.Close()
 		pc.authState = HTTP_AUTH_STATE_FAILURE