Merge pull request #342 from rod-hynes/master

Make dial stat notices more consistent

psiphon/TCPConn.go

@@ -181,7 +181,7 @@ func proxiedTcpDial(
 		&upstreamproxy.UpstreamProxyConfig{
 			ForwardDialFunc: dialer,
 			ProxyURIString:  config.UpstreamProxyUrl,
-			CustomHeaders:   config.UpstreamProxyCustomHeaders,
+			CustomHeaders:   config.CustomHeaders,
 		})
 	netConn, err := upstreamDialer("tcp", addr)
 	if _, ok := err.(*upstreamproxy.Error); ok {

psiphon/config.go

@@ -238,9 +238,13 @@ type Config struct {
 	// https://github.com/Psiphon-Labs/psiphon-tunnel-core/tree/master/psiphon/upstreamproxy
 	UpstreamProxyUrl string
 
-	// UpstreamProxyCustomHeaders is a set of additional arbitrary HTTP headers that are
-	// added to all requests made through the upstream proxy specified by UpstreamProxyUrl
-	// NOTE: Only HTTP(s) proxies use this if specified
+	// CustomHeaders is a set of additional arbitrary HTTP headers that are
+	// added to all plaintext HTTP requests and requests made through an HTTP
+	// upstream proxy when specified by UpstreamProxyUrl.
+	CustomHeaders http.Header
+
+	// Deprecated: Use CustomHeaders. When CustomHeaders is
+	// not nil, this parameter is ignored.
 	UpstreamProxyCustomHeaders http.Header
 
 	// NetworkConnectivityChecker is an interface that enables the core tunnel to call
@@ -542,6 +546,12 @@ func LoadConfig(configJson []byte) (*Config, error) {
 		config.TunnelPoolSize = TUNNEL_POOL_SIZE
 	}
 
+	if config.CustomHeaders == nil {
+		// Promote legacy parameter
+		config.CustomHeaders = config.UpstreamProxyCustomHeaders
+		config.UpstreamProxyCustomHeaders = nil
+	}
+
 	if config.NetworkConnectivityChecker != nil {
 		return nil, common.ContextError(
 			errors.New("NetworkConnectivityChecker interface must be set at runtime"))

psiphon/controller.go

@@ -96,7 +96,7 @@ func NewController(config *Config) (controller *Controller, err error) {
 	untunneledPendingConns := new(common.Conns)
 	untunneledDialConfig := &DialConfig{
 		UpstreamProxyUrl:              config.UpstreamProxyUrl,
-		UpstreamProxyCustomHeaders:    config.UpstreamProxyCustomHeaders,
+		CustomHeaders:                 config.CustomHeaders,
 		PendingConns:                  untunneledPendingConns,
 		DeviceBinder:                  config.DeviceBinder,
 		DnsServerGetter:               config.DnsServerGetter,

psiphon/controller_test.go

@@ -484,7 +484,7 @@ func controllerRun(t *testing.T, runConfig *controllerRunConfig) {
 		config.UpstreamProxyUrl = disruptorProxyURL
 	} else if runConfig.useUpstreamProxy {
 		config.UpstreamProxyUrl = upstreamProxyURL
-		config.UpstreamProxyCustomHeaders = upstreamProxyCustomHeaders
+		config.CustomHeaders = upstreamProxyCustomHeaders
 	}
 
 	if runConfig.transformHostNames {

psiphon/feedback.go

@@ -110,7 +110,7 @@ func SendFeedback(configJson, diagnosticsJson, b64EncodedPublicKey, uploadServer
 
 	untunneledDialConfig := &DialConfig{
 		UpstreamProxyUrl:              config.UpstreamProxyUrl,
-		UpstreamProxyCustomHeaders:    config.UpstreamProxyCustomHeaders,
+		CustomHeaders:                 config.CustomHeaders,
 		PendingConns:                  nil,
 		DeviceBinder:                  nil,
 		IPv6Synthesizer:               nil,

psiphon/meekConn.go

@@ -251,7 +251,7 @@ func DialMeek(
 		}
 		if proxyUrl != nil {
 			// Wrap transport with a transport that can perform HTTP proxy auth negotiation
-			transport, err = upstreamproxy.NewProxyAuthTransport(httpTransport, meekDialConfig.UpstreamProxyCustomHeaders)
+			transport, err = upstreamproxy.NewProxyAuthTransport(httpTransport, meekDialConfig.CustomHeaders)
 			if err != nil {
 				return nil, common.ContextError(err)
 			}
@@ -278,7 +278,7 @@ func DialMeek(
 		}
 	} else {
 		if proxyUrl == nil {
-			additionalHeaders = meekDialConfig.UpstreamProxyCustomHeaders
+			additionalHeaders = meekDialConfig.CustomHeaders
 		}
 	}
 

psiphon/net.go

@@ -55,10 +55,10 @@ type DialConfig struct {
 	// supported, those protocols will not connect.
 	UpstreamProxyUrl string
 
-	// UpstreamProxyCustomHeader is a set of additional arbitrary HTTP headers that are
-	// added to all HTTP requests made through the upstream proxy specified by UpstreamProxyUrl
-	// in case of HTTP proxy
-	UpstreamProxyCustomHeaders http.Header
+	// CustomHeaders is a set of additional arbitrary HTTP headers that are
+	// added to all plaintext HTTP requests and requests made through an HTTP
+	// upstream proxy when specified by UpstreamProxyUrl.
+	CustomHeaders http.Header
 
 	ConnectTimeout time.Duration
 

psiphon/notice.go

@@ -167,27 +167,40 @@ func NoticeAvailableEgressRegions(regions []string) {
 		"AvailableEgressRegions", 0, "regions", sortedRegions)
 }
 
-// NoticeConnectingServer is details on a connection attempt
-func NoticeConnectingServer(ipAddress, region, protocol, directTCPDialAddress string, meekConfig *MeekConfig) {
-	if meekConfig == nil {
-		outputNotice("ConnectingServer", noticeIsDiagnostic,
+func noticeServerDialStats(noticeType, ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
+	if tunnelDialStats != nil {
+		outputNotice(noticeType, noticeIsDiagnostic,
 			"ipAddress", ipAddress,
 			"region", region,
 			"protocol", protocol,
-			"directTCPDialAddress", directTCPDialAddress)
+			"upstreamProxyType", tunnelDialStats.UpstreamProxyType,
+			"upstreamProxyCustomHeaderNames", strings.Join(tunnelDialStats.UpstreamProxyCustomHeaderNames, ","),
+			"meekDialAddress", tunnelDialStats.MeekDialAddress,
+			"meekDialAddress", tunnelDialStats.MeekDialAddress,
+			"meekResolvedIPAddress", tunnelDialStats.MeekResolvedIPAddress,
+			"meekSNIServerName", tunnelDialStats.MeekSNIServerName,
+			"meekHostHeader", tunnelDialStats.MeekHostHeader,
+			"meekTransformedHostName", tunnelDialStats.MeekTransformedHostName,
+			"selectedUserAgent", tunnelDialStats.SelectedUserAgent,
+			"userAgent", tunnelDialStats.UserAgent)
 	} else {
-		outputNotice("ConnectingServer", noticeIsDiagnostic,
+		outputNotice(noticeType, noticeIsDiagnostic,
 			"ipAddress", ipAddress,
 			"region", region,
-			"protocol", protocol,
-			"meekDialAddress", meekConfig.DialAddress,
-			"meekUseHTTPS", meekConfig.UseHTTPS,
-			"meekSNIServerName", meekConfig.SNIServerName,
-			"meekHostHeader", meekConfig.HostHeader,
-			"meekTransformedHostName", meekConfig.TransformedHostName)
+			"protocol", protocol)
 	}
 }
 
+// NoticeConnectingServer reports parameters and details for a single connection attempt
+func NoticeConnectingServer(ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
+	noticeServerDialStats("ConnectingServer", ipAddress, region, protocol, tunnelDialStats)
+}
+
+// NoticeConnectedServer reports parameters and details for a single successful connection
+func NoticeConnectedServer(ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
+	noticeServerDialStats("ConnectedServer", ipAddress, region, protocol, tunnelDialStats)
+}
+
 // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding
 func NoticeActiveTunnel(ipAddress, protocol string) {
 	outputNotice("ActiveTunnel", noticeIsDiagnostic, "ipAddress", ipAddress, "protocol", protocol)
@@ -340,22 +353,6 @@ func NoticeLocalProxyError(proxyType string, err error) {
 		"LocalProxyError", noticeIsDiagnostic, "message", err.Error())
 }
 
-// NoticeConnectedTunnelDialStats reports extra network details for tunnel connections that required extra configuration.
-func NoticeConnectedTunnelDialStats(ipAddress string, tunnelDialStats *TunnelDialStats) {
-	outputNotice("ConnectedTunnelDialStats", noticeIsDiagnostic,
-		"ipAddress", ipAddress,
-		"upstreamProxyType", tunnelDialStats.UpstreamProxyType,
-		"upstreamProxyCustomHeaderNames", strings.Join(tunnelDialStats.UpstreamProxyCustomHeaderNames, ","),
-		"meekDialAddress", tunnelDialStats.MeekDialAddress,
-		"meekDialAddress", tunnelDialStats.MeekDialAddress,
-		"meekResolvedIPAddress", tunnelDialStats.MeekResolvedIPAddress,
-		"meekSNIServerName", tunnelDialStats.MeekSNIServerName,
-		"meekHostHeader", tunnelDialStats.MeekHostHeader,
-		"meekTransformedHostName", tunnelDialStats.MeekTransformedHostName,
-		"selectedUserAgent", tunnelDialStats.SelectedUserAgent,
-		"userAgent", tunnelDialStats.UserAgent)
-}
-
 // NoticeBuildInfo reports build version info.
 func NoticeBuildInfo() {
 	outputNotice("BuildInfo", 0, "buildInfo", common.GetBuildInfo())

psiphon/tunnel.go

@@ -584,7 +584,7 @@ func dialSsh(
 	// So depending on which protocol is used, multiple layers are initialized.
 
 	useObfuscatedSsh := false
-	dialHeaders := config.UpstreamProxyCustomHeaders
+	dialCustomHeaders := config.CustomHeaders
 	var directTCPDialAddress string
 	var meekConfig *MeekConfig
 	var selectedUserAgent bool
@@ -606,12 +606,7 @@ func dialSsh(
 		}
 	}
 
-	NoticeConnectingServer(
-		serverEntry.IpAddress,
-		serverEntry.Region,
-		selectedProtocol,
-		directTCPDialAddress,
-		meekConfig)
+	dialCustomHeaders, selectedUserAgent = common.UserAgentIfUnset(config.CustomHeaders)
 
 	// Use an asynchronous callback to record the resolved IP address when
 	// dialing a domain name. Note that DialMeek doesn't immediately
@@ -625,12 +620,9 @@ func dialSsh(
 		resolvedIPAddress.Store(IPAddress)
 	}
 
-	dialHeaders, selectedUserAgent = common.UserAgentIfUnset(config.UpstreamProxyCustomHeaders)
-
-	// Create the base transport: meek or direct connection
 	dialConfig := &DialConfig{
 		UpstreamProxyUrl:              config.UpstreamProxyUrl,
-		UpstreamProxyCustomHeaders:    dialHeaders,
+		CustomHeaders:                 dialCustomHeaders,
 		ConnectTimeout:                time.Duration(*config.TunnelConnectTimeoutSeconds) * time.Second,
 		PendingConns:                  pendingConns,
 		DeviceBinder:                  config.DeviceBinder,
@@ -641,6 +633,55 @@ func dialSsh(
 		DeviceRegion:                  config.DeviceRegion,
 		ResolvedIPCallback:            setResolvedIPAddress,
 	}
+
+	// Gather dial parameters for diagnostic logging and stats reporting
+
+	var dialStats *TunnelDialStats
+
+	if dialConfig.UpstreamProxyUrl != "" || meekConfig != nil {
+		dialStats = &TunnelDialStats{}
+
+		if selectedUserAgent {
+			dialStats.SelectedUserAgent = true
+			dialStats.UserAgent = dialConfig.CustomHeaders.Get("User-Agent")
+		}
+
+		if dialConfig.UpstreamProxyUrl != "" {
+
+			// Note: UpstreamProxyUrl will be validated in the dial
+			proxyURL, err := url.Parse(dialConfig.UpstreamProxyUrl)
+			if err == nil {
+				dialStats.UpstreamProxyType = proxyURL.Scheme
+			}
+
+			dialStats.UpstreamProxyCustomHeaderNames = make([]string, 0)
+			for name, _ := range dialConfig.CustomHeaders {
+				if selectedUserAgent && name == "User-Agent" {
+					continue
+				}
+				dialStats.UpstreamProxyCustomHeaderNames = append(dialStats.UpstreamProxyCustomHeaderNames, name)
+			}
+		}
+
+		if meekConfig != nil {
+			// Note: dialStats.MeekResolvedIPAddress isn't set until the dial begins,
+			// so it will always be blank in NoticeConnectingServer.
+			dialStats.MeekDialAddress = meekConfig.DialAddress
+			dialStats.MeekResolvedIPAddress = ""
+			dialStats.MeekSNIServerName = meekConfig.SNIServerName
+			dialStats.MeekHostHeader = meekConfig.HostHeader
+			dialStats.MeekTransformedHostName = meekConfig.TransformedHostName
+		}
+	}
+
+	NoticeConnectingServer(
+		serverEntry.IpAddress,
+		serverEntry.Region,
+		selectedProtocol,
+		dialStats)
+
+	// Create the base transport: meek or direct connection
+
 	var dialConn net.Conn
 	if meekConfig != nil {
 		dialConn, err = DialMeek(meekConfig, dialConfig)
@@ -755,44 +796,18 @@ func dialSsh(
 		return nil, common.ContextError(result.err)
 	}
 
-	var dialStats *TunnelDialStats
-
-	if dialConfig.UpstreamProxyUrl != "" || meekConfig != nil {
-		dialStats = &TunnelDialStats{}
-
-		if selectedUserAgent {
-			dialStats.SelectedUserAgent = true
-			dialStats.UserAgent = dialConfig.UpstreamProxyCustomHeaders.Get("User-Agent")
-		}
-
-		if dialConfig.UpstreamProxyUrl != "" {
-
-			// Note: UpstreamProxyUrl should have parsed correctly in the dial
-			proxyURL, err := url.Parse(dialConfig.UpstreamProxyUrl)
-			if err == nil {
-				dialStats.UpstreamProxyType = proxyURL.Scheme
-			}
-
-			dialStats.UpstreamProxyCustomHeaderNames = make([]string, 0)
-			for name, _ := range dialConfig.UpstreamProxyCustomHeaders {
-				if selectedUserAgent && name == "User-Agent" {
-					continue
-				}
-				dialStats.UpstreamProxyCustomHeaderNames = append(dialStats.UpstreamProxyCustomHeaderNames, name)
-			}
-		}
-
-		if meekConfig != nil {
-			dialStats.MeekDialAddress = meekConfig.DialAddress
-			dialStats.MeekResolvedIPAddress = resolvedIPAddress.Load().(string)
-			dialStats.MeekSNIServerName = meekConfig.SNIServerName
-			dialStats.MeekHostHeader = meekConfig.HostHeader
-			dialStats.MeekTransformedHostName = meekConfig.TransformedHostName
-		}
+	// Update dial parameters determined during dial
 
-		NoticeConnectedTunnelDialStats(serverEntry.IpAddress, dialStats)
+	if dialStats != nil && meekConfig != nil {
+		dialStats.MeekResolvedIPAddress = resolvedIPAddress.Load().(string)
 	}
 
+	NoticeConnectedServer(
+		serverEntry.IpAddress,
+		serverEntry.Region,
+		selectedProtocol,
+		dialStats)
+
 	cleanupConn = nil
 
 	// Note: dialConn may be used to close the underlying network connection

psiphon/userAgent_test.go

@@ -31,7 +31,6 @@ import (
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/server"
 )
 
-// TODO: test that emitted NoticeConnectedTunnelDialStats reports correct userAgent value
 // TODO: test that server receives and records correct user_agent value
 
 func TestOSSHUserAgent(t *testing.T) {
@@ -66,7 +65,7 @@ func resetUserAgentCounts() {
 	userAgentCounts = make(map[string]int)
 }
 
-func countUserAgent(headers http.Header, isCONNECT bool) {
+func countHTTPUserAgent(headers http.Header, isCONNECT bool) {
 	userAgentCountsMutex.Lock()
 	defer userAgentCountsMutex.Unlock()
 	if _, ok := headers["User-Agent"]; !ok {
@@ -78,6 +77,12 @@ func countUserAgent(headers http.Header, isCONNECT bool) {
 	}
 }
 
+func countNoticeUserAgent(userAgent string) {
+	userAgentCountsMutex.Lock()
+	defer userAgentCountsMutex.Unlock()
+	userAgentCounts["NOTICE-"+userAgent]++
+}
+
 func checkUserAgentCounts(t *testing.T, isCONNECT bool) {
 	userAgentCountsMutex.Lock()
 	defer userAgentCountsMutex.Unlock()
@@ -96,6 +101,11 @@ func checkUserAgentCounts(t *testing.T, isCONNECT bool) {
 				return
 			}
 		}
+
+		if userAgentCounts["NOTICE-"+userAgent] == 0 {
+			t.Fatalf("unexpected NOTICE user agent count of 0: %+v", userAgentCounts)
+			return
+		}
 	}
 
 	if userAgentCounts["BLANK"] == 0 {
@@ -114,13 +124,13 @@ func initUserAgentCounterUpstreamProxy() {
 
 			proxy.OnRequest().DoFunc(
 				func(r *http.Request, ctx *goproxy.ProxyCtx) (*http.Request, *http.Response) {
-					countUserAgent(r.Header, false)
+					countHTTPUserAgent(r.Header, false)
 					return nil, goproxy.NewResponse(r, goproxy.ContentTypeText, http.StatusUnauthorized, "")
 				})
 
 			proxy.OnRequest().HandleConnectFunc(
 				func(host string, ctx *goproxy.ProxyCtx) (*goproxy.ConnectAction, string) {
-					countUserAgent(ctx.Req.Header, true)
+					countHTTPUserAgent(ctx.Req.Header, true)
 					return goproxy.RejectConnect, host
 				})
 
@@ -199,7 +209,17 @@ func attemptConnectionsWithUserAgent(
 
 	SetNoticeOutput(NewNoticeReceiver(
 		func(notice []byte) {
-			// (inspect notices here)
+			noticeType, payload, err := GetNotice(notice)
+			if err != nil {
+				return
+			}
+			if noticeType == "ConnectingServer" {
+				selectedUserAgent := payload["selectedUserAgent"].(bool)
+				userAgent := payload["userAgent"].(string)
+				if selectedUserAgent {
+					countNoticeUserAgent(userAgent)
+				}
+			}
 		}))
 
 	controller, err := NewController(clientConfig)