Merge pull request #618 from rod-hynes/master

Bug fixes

psiphon/common/parameters/parameters.go

@@ -663,7 +663,7 @@ var defaultParameters = map[string]struct {
 	DNSResolverAttemptsPerServer:                {value: 2, minimum: 1},
 	DNSResolverAttemptsPerPreferredServer:       {value: 1, minimum: 1},
 	DNSResolverRequestTimeout:                   {value: 5 * time.Second, minimum: 100 * time.Millisecond, flags: useNetworkLatencyMultiplier},
-	DNSResolverAwaitTimeout:                     {value: 100 * time.Millisecond, minimum: 1 * time.Millisecond, flags: useNetworkLatencyMultiplier},
+	DNSResolverAwaitTimeout:                     {value: 10 * time.Millisecond, minimum: 1 * time.Millisecond, flags: useNetworkLatencyMultiplier},
 	DNSResolverPreresolvedIPAddressCIDRs:        {value: LabeledCIDRs{}},
 	DNSResolverPreresolvedIPAddressProbability:  {value: 0.0, minimum: 0.0},
 	DNSResolverAlternateServers:                 {value: []string{}},

psiphon/common/resolver/resolver.go

@@ -50,7 +50,7 @@ const (
 	resolverServersUpdateTTL         = 5 * time.Second
 	resolverDefaultAttemptsPerServer = 2
 	resolverDefaultRequestTimeout    = 5 * time.Second
-	resolverDefaultAwaitTimeout      = 100 * time.Millisecond
+	resolverDefaultAwaitTimeout      = 10 * time.Millisecond
 	resolverDefaultAnswerTTL         = 1 * time.Minute
 	resolverDNSPort                  = "53"
 	udpPacketBufferSize              = 1232
@@ -168,7 +168,7 @@ type ResolveParameters struct {
 
 	// AwaitTimeout specifies how long to await an additional response after
 	// the first response is received. This additional wait time applies only
-	// when there is no IPv4 or IPv6 response.
+	// when there is either no IPv4 or IPv6 response.
 	AwaitTimeout time.Duration
 
 	// PreresolvedIPAddress specifies an IP address result to be used in place

psiphon/common/resolver/resolver_test.go

@@ -110,7 +110,7 @@ func runTestMakeResolveParameters() error {
 	if resolverParams.AttemptsPerServer != 2 ||
 		resolverParams.AttemptsPerPreferredServer != 1 ||
 		resolverParams.RequestTimeout != 5*time.Second ||
-		resolverParams.AwaitTimeout != 100*time.Millisecond ||
+		resolverParams.AwaitTimeout != 10*time.Millisecond ||
 		!CIDRContainsIP(exampleIPv4CIDR, resolverParams.PreresolvedIPAddress) ||
 		resolverParams.AlternateDNSServer != "" ||
 		resolverParams.PreferAlternateDNSServer != false ||
@@ -153,7 +153,7 @@ func runTestMakeResolveParameters() error {
 	if resolverParams.AttemptsPerServer != 2 ||
 		resolverParams.AttemptsPerPreferredServer != 1 ||
 		resolverParams.RequestTimeout != 5*time.Second ||
-		resolverParams.AwaitTimeout != 100*time.Millisecond ||
+		resolverParams.AwaitTimeout != 10*time.Millisecond ||
 		resolverParams.PreresolvedIPAddress != "" ||
 		resolverParams.AlternateDNSServer != preferredAlternateDNSServerWithPort ||
 		resolverParams.PreferAlternateDNSServer != true ||
@@ -183,7 +183,7 @@ func runTestMakeResolveParameters() error {
 	if resolverParams.AttemptsPerServer != 2 ||
 		resolverParams.AttemptsPerPreferredServer != 1 ||
 		resolverParams.RequestTimeout != 5*time.Second ||
-		resolverParams.AwaitTimeout != 100*time.Millisecond ||
+		resolverParams.AwaitTimeout != 10*time.Millisecond ||
 		resolverParams.PreresolvedIPAddress != "" ||
 		resolverParams.AlternateDNSServer != alternateDNSServerWithPort ||
 		resolverParams.PreferAlternateDNSServer != false ||
@@ -636,11 +636,11 @@ func runTestResolver() error {
 	networkConfig.GetDNSServers = func() []string { return []string{okServer.getAddr()} }
 	networkID = "networkID-6"
 
-	for i := 0; i < 100; i++ {
+	for i := 0; i < 500; i++ {
 		resolver.cache.Flush()
 
 		ctx, cancelFunc := context.WithTimeout(
-			context.Background(), time.Duration(i%10*20)*time.Microsecond)
+			context.Background(), time.Duration((i%10+1)*20)*time.Microsecond)
 		defer cancelFunc()
 
 		_, _ = resolver.ResolveIP(ctx, networkID, params, exampleDomain)

psiphon/notice.go

@@ -952,9 +952,14 @@ func NoticeFragmentor(diagnosticID string, message string) {
 	}
 }
 
+// NoticeApplicationParameters reports application parameters. Each key/value
+// parameter pair is emitted in a distinct notice, and each key/value pair is
+// reported at most once per session for a fixed value.
 func NoticeApplicationParameters(keyValues parameters.KeyValues) {
 	for key, value := range keyValues {
-		singletonNoticeLogger.outputNotice(
+		repetitionKey := fmt.Sprintf("ApplicationParameterKey-%s", key)
+		outputRepetitiveNotice(
+			repetitionKey, string(value), 0,
 			"ApplicationParameter", 0,
 			"key", key,
 			"value", value)
@@ -1007,7 +1012,7 @@ func NoticeHoldOffTunnel(diagnosticID string, duration time.Duration) {
 // session.
 func NoticeSkipServerEntry(format string, args ...interface{}) {
 	reason := fmt.Sprintf(format, args...)
-	repetitionKey := fmt.Sprintf("ServerAlert-%+v", reason)
+	repetitionKey := fmt.Sprintf("SkipServerEntryReason-%+v", reason)
 	outputRepetitiveNotice(
 		repetitionKey, "", 0,
 		"SkipServerEntry", 0, "reason", reason)

psiphon/serverApi.go

@@ -728,7 +728,8 @@ func RecordRemoteServerListStat(
 }
 
 // RecordFailedTunnelStat records metrics for a failed tunnel dial, including
-// dial parameters and error condition (tunnelErr).
+// dial parameters and error condition (tunnelErr). No record is created when
+// tunnelErr is nil.
 //
 // This uses the same reporting facility, with the same caveats, as
 // RecordRemoteServerListStat.
@@ -745,6 +746,16 @@ func RecordFailedTunnelStat(
 		return nil
 	}
 
+	// Callers should not call RecordFailedTunnelStat with a nil tunnelErr, as
+	// this is not a useful stat and it results in a nil pointer dereference.
+	// This check catches potential bug cases. An example edge case, now
+	// fixed, is deferred error handlers, such as the ones in in
+	// dialTunnel/tunnel.Activate, which may be invoked in the case of a
+	// panic, which can occur before any error value is returned.
+	if tunnelErr == nil {
+		return errors.TraceNew("no error")
+	}
+
 	lastConnected, err := getLastConnected()
 	if err != nil {
 		return errors.Trace(err)

psiphon/tunnel.go

@@ -182,16 +182,18 @@ func (tunnel *Tunnel) Activate(
 	defer func() {
 		if !activationSucceeded && baseCtx.Err() != context.Canceled {
 			tunnel.dialParams.Failed(tunnel.config)
-			_ = RecordFailedTunnelStat(
-				tunnel.config,
-				tunnel.dialParams,
-				tunnel.livenessTestMetrics,
-				-1,
-				-1,
-				retErr)
 			if tunnel.extraFailureAction != nil {
 				tunnel.extraFailureAction()
 			}
+			if retErr != nil {
+				_ = RecordFailedTunnelStat(
+					tunnel.config,
+					tunnel.dialParams,
+					tunnel.livenessTestMetrics,
+					-1,
+					-1,
+					retErr)
+			}
 		}
 	}()
 
@@ -704,16 +706,18 @@ func dialTunnel(
 	defer func() {
 		if !dialSucceeded && baseCtx.Err() != context.Canceled {
 			dialParams.Failed(config)
-			_ = RecordFailedTunnelStat(
-				config,
-				dialParams,
-				failedTunnelLivenessTestMetrics,
-				-1,
-				-1,
-				retErr)
 			if extraFailureAction != nil {
 				extraFailureAction()
 			}
+			if retErr != nil {
+				_ = RecordFailedTunnelStat(
+					config,
+					dialParams,
+					failedTunnelLivenessTestMetrics,
+					-1,
+					-1,
+					retErr)
+			}
 		}
 	}()