Reduce diagnostic log noise due to skipping server entries

- Ensure MakeDialParameters returns nil/nil in all
  "skip" cases.

- When MakeDialParameters indicates that a server entry
  is to be skipped, the tactics caller no longer logs
  an error.

- MakeDialParameters will now emit a limited set of
  diagnostic notices for skip cases.

psiphon/controller.go

@@ -2139,12 +2139,12 @@ loop:
 
 			controller.concurrentEstablishTunnelsMutex.Unlock()
 
-			// dialParams is nil when the server does not support any protocol
-			// that remains after applying the LimitTunnelProtocols parameter
-			// and the excludeIntensive flag.
-			// Silently skip the candidate in this case. Otherwise, emit error.
+			// MakeDialParameters returns nil/nil when the server entry is to
+			// be skipped. See MakeDialParameters for skip cases and skip
+			// logging. Silently fail the candidate in this case. Otherwise,
+			// emit error.
 			if err != nil {
-				NoticeInfo("failed to select protocol for %s: %v",
+				NoticeInfo("failed to make dial parameters for %s: %v",
 					candidateServerEntry.serverEntry.GetDiagnosticID(),
 					errors.Trace(err))
 			}

psiphon/dialParameters.go

@@ -362,21 +362,32 @@ func MakeDialParameters(
 			dialParams.ServerEntry.FrontingProviderID) {
 		if p.WeightedCoinFlip(
 			parameters.RestrictFrontingProviderIDsClientProbability) {
-			return nil, errors.Tracef(
-				"restricted fronting provider ID: %s", dialParams.ServerEntry.FrontingProviderID)
+
+			// When skipping, return nil/nil as no error should be logged.
+			// NoticeSkipServerEntry emits each skip reason, regardless
+			// of server entry, at most once per session.
+
+			NoticeSkipServerEntry(
+				"restricted fronting provider ID: %s",
+				dialParams.ServerEntry.FrontingProviderID)
+
+			return nil, nil
 		}
 	}
 
 	if config.UseUpstreamProxy() {
 
+		// When UpstreamProxy is configured, ServerEntry.GetSupportedProtocols, when
+		// called via selectProtocol, will filter out protocols such that will not
+		// select a protocol incompatible with UpstreamProxy. This additional check
+		// will catch cases where selectProtocol does not apply this filter.
 		if !protocol.TunnelProtocolSupportsUpstreamProxy(dialParams.TunnelProtocol) {
 
-			// When UpstreamProxy is configured, ServerEntry.GetSupportedProtocols, when
-			// called via selectProtocol, will filter out protocols such that will not
-			// select a protocol incompatible with UpstreamProxy. This additional check
-			// will catch cases where selectProtocol does not apply this filter.
-			return nil, errors.Tracef(
-				"protocol does not support upstream proxy: %s", dialParams.TunnelProtocol)
+			NoticeSkipServerEntry(
+				"protocol does not support upstream proxy: %s",
+				dialParams.TunnelProtocol)
+
+			return nil, nil
 		}
 
 		// Skip this candidate when the server entry is not to be used with an
@@ -389,8 +400,12 @@ func MakeDialParameters(
 		source := dialParams.ServerEntry.LocalSource
 		if !protocol.AllowServerEntrySourceWithUpstreamProxy(source) &&
 			!p.Bool(parameters.UpstreamProxyAllowAllServerEntrySources) {
-			return nil, errors.Tracef(
-				"server entry source disallowed with upstream proxy: %s", source)
+
+			NoticeSkipServerEntry(
+				"server entry source disallowed with upstream proxy: %s",
+				source)
+
+			return nil, nil
 		}
 	}
 

psiphon/dialParameters_test.go

@@ -451,7 +451,9 @@ func runDialParametersAndReplay(t *testing.T, tunnelProtocol string) {
 
 	if protocol.TunnelProtocolUsesFrontedMeek(tunnelProtocol) {
 		if err == nil {
-			t.Fatalf("unexpected MakeDialParameters success")
+			if dialParams != nil {
+				t.Fatalf("unexpected MakeDialParameters success")
+			}
 		}
 	} else {
 		if err != nil {

psiphon/notice.go

@@ -951,6 +951,18 @@ func NoticeHoldOffTunnel(diagnosticID string, duration time.Duration) {
 	}
 }
 
+// NoticeSkipServerEntry reports a reason for skipping a server entry when
+// preparing dial parameters. To avoid log noise, the server entry
+// diagnosticID is not emitted and each reason is reported at most once per
+// session.
+func NoticeSkipServerEntry(format string, args ...interface{}) {
+	reason := fmt.Sprintf(format, args...)
+	repetitionKey := fmt.Sprintf("ServerAlert-%+v", reason)
+	outputRepetitiveNotice(
+		repetitionKey, "", 0,
+		"SkipServerEntry", 0, "reason", reason)
+}
+
 type repetitiveNoticeState struct {
 	message string
 	repeats int

psiphon/tactics.go

@@ -21,7 +21,6 @@ package psiphon
 
 import (
 	"context"
-	std_errors "errors"
 	"time"
 
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
@@ -88,6 +87,8 @@ func GetTactics(ctx context.Context, config *Config) {
 		}
 		defer iterator.Close()
 
+		noCapableServers := true
+
 		for iteration := 0; ; iteration++ {
 
 			if !WaitForNetworkConnectivity(
@@ -102,8 +103,11 @@ func GetTactics(ctx context.Context, config *Config) {
 			}
 
 			if serverEntry == nil {
-				if iteration == 0 {
-					NoticeWarning("tactics request skipped: no capable servers")
+				if noCapableServers {
+					// Abort when no capable servers have been found after
+					// a full iteration. Server entries that are skipped are
+					// classified as not capable.
+					NoticeWarning("tactics request aborted: no capable servers")
 					return
 				}
 
@@ -113,8 +117,24 @@ func GetTactics(ctx context.Context, config *Config) {
 
 			tacticsRecord, err = fetchTactics(
 				ctx, config, serverEntry)
+
+			if tacticsRecord != nil || err != nil {
+				// The fetch succeeded or failed but was not skipped.
+				noCapableServers = false
+			}
+
 			if err == nil {
-				break
+				if tacticsRecord != nil {
+					// The fetch succeeded, so exit the fetch loop and apply
+					// the result.
+					break
+				} else {
+					// MakeDialParameters, via fetchTactics, returns nil/nil
+					// when the server entry is to be skipped. See
+					// MakeDialParameters for skip cases and skip logging.
+					// Silently select a new candidate in this case.
+					continue
+				}
 			}
 
 			NoticeWarning("tactics request failed: %s", err)
@@ -166,6 +186,9 @@ func GetTactics(ctx context.Context, config *Config) {
 	emitMemoryMetrics()
 }
 
+// fetchTactics performs a tactics request using the specified server entry.
+// fetchTactics will return nil/nil when the candidate server entry is
+// skipped.
 func fetchTactics(
 	ctx context.Context,
 	config *Config,
@@ -201,15 +224,13 @@ func fetchTactics(
 		0,
 		0)
 	if dialParams == nil {
-		// MakeDialParameters may return nil, nil when the server entry can't
-		// satisfy protocol selection criteria. This case in not expected
-		// since NewTacticsServerEntryIterator should only return tactics-
-		// capable server entries and selectProtocol will select any tactics
-		// protocol.
-		err = std_errors.New("failed to make dial parameters")
+		return nil, nil
 	}
 	if err != nil {
-		return nil, errors.Trace(err)
+		return nil, errors.Tracef(
+			"failed to make dial parameters for %s: %v",
+			serverEntry.GetDiagnosticID(),
+			err)
 	}
 
 	NoticeRequestingTactics(dialParams)