Resolver bug fixes

- A DNSAttempt/dns_attempt value of 0 was ambiguous: either there was no
  successful attempt, or the first attempt succeeded. Now, the first attempt
  has index 1 and 0 means no successful attempt.

- Don't emit DNSAttempt in pre-dial notices.

- Don't redact preresolved IPs or alternate DNS server IPs in diagnostics.

- Also apply non-redaction to meek resolver IP address, including it only in
  fronted cases.

- Fix missing/0 TTL handling.

- Use more explicit "unset" logic for minRTT metrics.

- Fix comment typos.

psiphon/common/redact.go

@@ -102,6 +102,19 @@ func RedactIPAddressesString(s string) string {
 	return redactIPAddressAndPortRegex.ReplaceAllString(s, "[redacted]")
 }
 
+// EscapeRedactIPAddressString escapes the IP or IP:port addresses in the
+// input in such a way that they won't be redacted when part of the input to
+// RedactIPAddresses.
+//
+// The escape encoding is not guaranteed to be reversable or suitable for
+// machine processing; the goal is to simply ensure the original value is
+// human readable.
+func EscapeRedactIPAddressString(address string) string {
+	address = strings.ReplaceAll(address, ".", "\\.")
+	address = strings.ReplaceAll(address, ":", "\\:")
+	return address
+}
+
 var redactFilePathRegex = regexp.MustCompile(
 	// File path
 	`(` +

psiphon/common/redact_test.go

@@ -31,72 +31,101 @@ func TestRedactIPAddresses(t *testing.T) {
 		description    string
 		input          string
 		expectedOutput string
+		escape         bool
 	}{
 		{
 			"IPv4 address",
 			"prefix 192.168.0.1 suffix",
 			"prefix [redacted] suffix",
+			false,
 		},
 		{
 			"IPv6 address",
 			"prefix 2001:0db8:0000:0000:0000:ff00:0042:8329 suffix",
 			"prefix [redacted] suffix",
+			false,
 		},
 		{
 			"Remove leading zeros IPv6 address",
 			"prefix 2001:db8:0:0:0:ff00:42:8329 suffix",
 			"prefix [redacted] suffix",
+			false,
 		},
 		{
 			"Omit consecutive zeros sections IPv6 address",
 			"prefix 2001:db8::ff00:42:8329 suffix",
 			"prefix [redacted] suffix",
+			false,
 		},
 		{
 			"IPv4 mapped/translated/embedded address",
 			"prefix 0::ffff:192.168.0.1, 0::ffff:0:192.168.0.1, 64:ff9b::192.168.0.1 suffix",
 			"prefix [redacted], [redacted], [redacted] suffix",
+			false,
 		},
 		{
 			"IPv4 address and port",
 			"read tcp 127.0.0.1:1025->127.0.0.1:8000: use of closed network connection",
 			"read tcp [redacted]->[redacted]: use of closed network connection",
+			false,
 		},
 		{
 			"IPv6 address and port",
 			"read tcp [2001:db8::ff00:42:8329]:1025->[2001:db8::ff00:42:8329]:8000: use of closed network connection",
 			"read tcp [redacted]->[redacted]: use of closed network connection",
+			false,
 		},
 		{
 			"Loopback IPv6 address and invalid port number",
 			"dial tcp [::1]:88888: network is unreachable",
 			"dial tcp [redacted]: network is unreachable",
+			false,
 		},
 		{
 			"Numbers and periods",
 			"prefix 192. 168. 0. 1 suffix",
 			"prefix 192. 168. 0. 1 suffix",
+			false,
 		},
 		{
 			"Hex string and colon",
 			"prefix 0123456789abcdef: suffix",
 			"prefix 0123456789abcdef: suffix",
+			false,
 		},
 		{
 			"Colons",
 			"prefix :: suffix",
 			"prefix :: suffix",
+			false,
 		},
 		{
 			"Notice",
 			`{"data":{"SSHClientVersion":"SSH-2.0-C","candidateNumber":0,"diagnosticID":"se0XVQ/4","dialPortNumber":"4000","establishedTunnelsCount":0,"isReplay":false,"networkLatencyMultiplier":2.8284780852763953,"networkType":"WIFI","protocol":"OSSH","region":"US","upstream_ossh_padding":7077},"noticeType":"ConnectedServer","timestamp":"2020-12-16T14:07:02.030Z"}`,
 			`{"data":{"SSHClientVersion":"SSH-2.0-C","candidateNumber":0,"diagnosticID":"se0XVQ/4","dialPortNumber":"4000","establishedTunnelsCount":0,"isReplay":false,"networkLatencyMultiplier":2.8284780852763953,"networkType":"WIFI","protocol":"OSSH","region":"US","upstream_ossh_padding":7077},"noticeType":"ConnectedServer","timestamp":"2020-12-16T14:07:02.030Z"}`,
+			false,
+		},
+		{
+			"escape IPv4 address and port",
+			"prefix 192.168.0.1:443 suffix",
+			"prefix 192\\.168\\.0\\.1\\:443 suffix",
+			true,
+		},
+		{
+			"escape IPv6 address and port",
+			"prefix [2001:db8::ff00:42:8329]:443 suffix",
+			"prefix [2001\\:db8\\:\\:ff00\\:42\\:8329]\\:443 suffix",
+			true,
 		},
 	}
 
 	for _, testCase := range testCases {
 		t.Run(testCase.description, func(t *testing.T) {
-			output := RedactIPAddressesString(testCase.input)
+			input := testCase.input
+			if testCase.escape {
+				input = EscapeRedactIPAddressString(input)
+			}
+			output := RedactIPAddressesString(input)
 			if output != testCase.expectedOutput {
 				t.Errorf("unexpected output: %s", output)
 			}

psiphon/common/resolver/resolver.go

@@ -153,10 +153,11 @@ type ResolveParameters struct {
 	firstAttemptWithAnswer int32
 }
 
-// GetFirstAttemptWithAnswer returns the zero-based index of the first request
-// attempt that received a valid response, for the most recent ResolveIP call
-// using this ResolveParameters. This information is used for logging
-// metrics.
+// GetFirstAttemptWithAnswer returns the index of the first request attempt
+// that received a valid response, for the most recent ResolveIP call using
+// this ResolveParameters. This information is used for logging metrics. The
+// first attempt has index 1. GetFirstAttemptWithAnswer return 0 when no
+// request attempt has reported a valid response.
 //
 // The caller is responsible for synchronizing use of a ResolveParameters
 // instance (e.g, use a distinct ResolveParameters per ResolveIP to ensure
@@ -208,11 +209,16 @@ type resolverMetrics struct {
 	maxRTT        time.Duration
 }
 
+func newResolverMetrics() resolverMetrics {
+	return resolverMetrics{minRTT: -1}
+}
+
 // NewResolver creates a new Resolver instance.
 func NewResolver(networkConfig *NetworkConfig, networkID string) *Resolver {
 
 	r := &Resolver{
 		networkConfig: networkConfig,
+		metrics:       newResolverMetrics(),
 	}
 
 	// updateNetworkState will initialize the cache and network state,
@@ -237,7 +243,7 @@ func (r *Resolver) Stop() {
 	r.hasIPv6Route = false
 	r.systemServers = nil
 	r.cache.Flush()
-	r.metrics = resolverMetrics{}
+	r.metrics = newResolverMetrics()
 }
 
 // MakeResolveParameters generates ResolveParameters using the input tactics
@@ -669,17 +675,16 @@ func (r *Resolver) ResolveIP(
 					questionType,
 					hostname)
 
-				// Update the min/max RTT metric as long as the reported RTT >
-				// 0, even if the result is an error -- i.e., the even if
-				// there was an invalid response --  unless the resolveCtx is
-				// done (we don't want to consider the RTT in the case of
-				// cancellation). This assumes no actual RTT will be 0 nanoseconds
+				// Update the min/max RTT metric when reported (>=0) even if
+				// the result is an error -- i.e., the even if there was an
+				// invalid response --  unless the resolveCtx is done
+				// (we don't want to consider the RTT in the case of cancellation).
 				//
 				// Limitation: since individual requests aren't cancelled
 				// after requestTimeout, RTT metrics won't reflect
 				// no-response cases, although request and response count
 				// disparities will still show up in the metrics.
-				if RTT > 0 && resolveCtx.Err() == nil {
+				if RTT >= 0 && resolveCtx.Err() == nil {
 					r.updateMetricRTT(RTT)
 				}
 
@@ -709,7 +714,7 @@ func (r *Resolver) ResolveIP(
 				default:
 				}
 
-			}(i, questionType, useProtocolTransform)
+			}(i+1, questionType, useProtocolTransform)
 		}
 
 		resetTimer(requestTimeout)
@@ -822,7 +827,15 @@ func (r *Resolver) GetMetrics() string {
 	r.mutex.Lock()
 	defer r.mutex.Unlock()
 
-	return fmt.Sprintf("resolves %d | hit %d | req v4/v6 %d/%d | resp %d/%d | peak %d | rtt %d - %d ms.",
+	// When r.metrics.minRTT < 0, min/maxRTT is unset.
+	minRTT := "n/a"
+	maxRTT := minRTT
+	if r.metrics.minRTT >= 0 {
+		minRTT = fmt.Sprintf("%d", r.metrics.minRTT/time.Millisecond)
+		maxRTT = fmt.Sprintf("%d", r.metrics.maxRTT/time.Millisecond)
+	}
+
+	return fmt.Sprintf("resolves %d | hit %d | req v4/v6 %d/%d | resp %d/%d | peak %d | rtt %s - %s ms.",
 		r.metrics.resolves,
 		r.metrics.cacheHits,
 		r.metrics.requestsIPv4,
@@ -830,8 +843,8 @@ func (r *Resolver) GetMetrics() string {
 		r.metrics.responsesIPv4,
 		r.metrics.responsesIPv6,
 		r.metrics.peakInFlight,
-		r.metrics.minRTT/time.Millisecond,
-		r.metrics.maxRTT/time.Millisecond)
+		minRTT,
+		maxRTT)
 }
 
 // updateNetworkState updates the system DNS server list, IPv6 state, and the
@@ -971,10 +984,11 @@ func (r *Resolver) setCache(hostname string, IPs []net.IP, TTLs []time.Duration)
 	r.mutex.Lock()
 	defer r.mutex.Unlock()
 
-	// In case TTL is zero, use a default. The shortest TTL is used.
+	// The shortest TTL is used. In some cases, a DNS server may omit the TTL
+	// or set a 0 TTL, in which case the default is used.
 	TTL := resolverDefaultAnswerTTL
 	for _, answerTTL := range TTLs {
-		if answerTTL < TTL {
+		if answerTTL > 0 && answerTTL < TTL {
 			TTL = answerTTL
 		}
 	}
@@ -1103,8 +1117,13 @@ func (r *Resolver) updateMetricRTT(rtt time.Duration) {
 	r.mutex.Lock()
 	defer r.mutex.Unlock()
 
-	// This assumes no actual RTT will be 0 nanoseconds
-	if r.metrics.minRTT == 0 || rtt < r.metrics.minRTT {
+	if rtt < 0 {
+		// Ignore invalid input.
+		return
+	}
+
+	// When r.metrics.minRTT < 0, min/maxRTT is unset.
+	if r.metrics.minRTT < 0 || rtt < r.metrics.minRTT {
 		r.metrics.minRTT = rtt
 	}
 
@@ -1152,7 +1171,7 @@ func generateIPAddressFromCIDR(CIDR string) (net.IP, error) {
 	}
 	// A retry is required, since a CIDR may include broadcast IPs (a.b.c.0) or
 	// other invalid values. The number of retries is limited to ensure we
-	// don't hanging case of a misconfiguration
+	// don't hang in the case of a misconfiguration.
 	for i := 0; i < 10; i++ {
 		randBytes := prng.Bytes(len(IPNet.IP))
 		IP := make(net.IP, len(IPNet.IP))
@@ -1187,13 +1206,13 @@ func performDNSQuery(
 	if useProtocolTransform {
 		if params.ProtocolTransformSpec == nil ||
 			params.ProtocolTransformSeed == nil {
-			return nil, nil, 0, errors.TraceNew("invalid protocol transform configuration")
+			return nil, nil, -1, errors.TraceNew("invalid protocol transform configuration")
 		}
 		// miekg/dns expects conn to be a net.PacketConn or else it writes the
 		// TCP length prefix
 		udpConn, ok := conn.(*net.UDPConn)
 		if !ok {
-			return nil, nil, 0, errors.TraceNew("conn is not a *net.UDPConn")
+			return nil, nil, -1, errors.TraceNew("conn is not a *net.UDPConn")
 		}
 		conn = &transformDNSPacketConn{
 			UDPConn:   udpConn,
@@ -1219,7 +1238,7 @@ func performDNSQuery(
 	case resolverQuestionTypeAAAA:
 		request.SetQuestion(dns.Fqdn(hostname), dns.TypeAAAA)
 	default:
-		return nil, nil, 0, errors.TraceNew("unknown DNS request question type")
+		return nil, nil, -1, errors.TraceNew("unknown DNS request question type")
 	}
 	if params.IncludeEDNS0 {
 		// miekg/dns: "RFC 6891, Section 6.1.1 allows the OPT record to appear
@@ -1269,13 +1288,13 @@ func performDNSQuery(
 		// will still abort after resolveCtx is done, or RequestTimeout
 		// expires for maxAttempts).
 		//
-		// For IPv6, we should also expect RCodeSucess even if there is no
+		// For IPv6, we should also expect RCodeSuccess even if there is no
 		// AAAA record, as long as the domain exists and has an A record.
 		// However, per RFC 6147 section 5.1.2, we may receive
 		// NXDOMAIN: "...some servers respond with RCODE=3 to a AAAA query
 		// even if there is an A record available for that owner name. Those
 		// servers are in clear violation of the meaning of RCODE 3...". In
-		// this case, we coalese NXDOMAIN into success to treat the response
+		// this case, we coalesce NXDOMAIN into success to treat the response
 		// the same as success with no AAAA record.
 		//
 		// All other RCodes, which are unexpected, lead to a read retry.

psiphon/notice.go

@@ -446,7 +446,7 @@ func NoticeAvailableEgressRegions(regions []string) {
 		"AvailableEgressRegions", 0, "regions", sortedRegions)
 }
 
-func noticeWithDialParameters(noticeType string, dialParams *DialParameters) {
+func noticeWithDialParameters(noticeType string, dialParams *DialParameters, postDial bool) {
 
 	args := []interface{}{
 		"diagnosticID", dialParams.ServerEntry.GetDiagnosticID(),
@@ -486,9 +486,12 @@ func noticeWithDialParameters(noticeType string, dialParams *DialParameters) {
 			args = append(args, "meekDialAddress", dialParams.MeekDialAddress)
 		}
 
-		meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
-		if meekResolvedIPAddress != "" {
-			args = append(args, "meekResolvedIPAddress", meekResolvedIPAddress)
+		if protocol.TunnelProtocolUsesFrontedMeek(dialParams.TunnelProtocol) {
+			meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
+			if meekResolvedIPAddress != "" {
+				nonredacted := common.EscapeRedactIPAddressString(meekResolvedIPAddress)
+				args = append(args, "meekResolvedIPAddress", nonredacted)
+			}
 		}
 
 		if dialParams.MeekSNIServerName != "" {
@@ -556,21 +559,25 @@ func noticeWithDialParameters(noticeType string, dialParams *DialParameters) {
 		if dialParams.ResolveParameters != nil {
 
 			if dialParams.ResolveParameters.PreresolvedIPAddress != "" {
-				args = append(args, "DNSPreresolved", dialParams.ResolveParameters.PreresolvedIPAddress)
+				nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.PreresolvedIPAddress)
+				args = append(args, "DNSPreresolved", nonredacted)
 
 			} else {
 
 				// See dialParams.ResolveParameters comment in getBaseAPIParameters.
 
 				if dialParams.ResolveParameters.PreferAlternateDNSServer {
-					args = append(args, "DNSPreferred", dialParams.ResolveParameters.AlternateDNSServer)
+					nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.AlternateDNSServer)
+					args = append(args, "DNSPreferred", nonredacted)
 				}
 
 				if dialParams.ResolveParameters.ProtocolTransformName != "" {
 					args = append(args, "DNSTransform", dialParams.ResolveParameters.ProtocolTransformName)
 				}
 
-				args = append(args, "DNSAttempt", dialParams.ResolveParameters.GetFirstAttemptWithAnswer())
+				if postDial {
+					args = append(args, "DNSAttempt", dialParams.ResolveParameters.GetFirstAttemptWithAnswer())
+				}
 			}
 		}
 
@@ -596,22 +603,22 @@ func noticeWithDialParameters(noticeType string, dialParams *DialParameters) {
 
 // NoticeConnectingServer reports parameters and details for a single connection attempt
 func NoticeConnectingServer(dialParams *DialParameters) {
-	noticeWithDialParameters("ConnectingServer", dialParams)
+	noticeWithDialParameters("ConnectingServer", dialParams, false)
 }
 
 // NoticeConnectedServer reports parameters and details for a single successful connection
 func NoticeConnectedServer(dialParams *DialParameters) {
-	noticeWithDialParameters("ConnectedServer", dialParams)
+	noticeWithDialParameters("ConnectedServer", dialParams, true)
 }
 
 // NoticeRequestingTactics reports parameters and details for a tactics request attempt
 func NoticeRequestingTactics(dialParams *DialParameters) {
-	noticeWithDialParameters("RequestingTactics", dialParams)
+	noticeWithDialParameters("RequestingTactics", dialParams, false)
 }
 
 // NoticeRequestedTactics reports parameters and details for a successful tactics request
 func NoticeRequestedTactics(dialParams *DialParameters) {
-	noticeWithDialParameters("RequestedTactics", dialParams)
+	noticeWithDialParameters("RequestedTactics", dialParams, true)
 }
 
 // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding

psiphon/serverApi.go

@@ -946,9 +946,11 @@ func getBaseAPIParameters(
 			params["meek_dial_address"] = dialParams.MeekDialAddress
 		}
 
-		meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
-		if meekResolvedIPAddress != "" {
-			params["meek_resolved_ip_address"] = meekResolvedIPAddress
+		if protocol.TunnelProtocolUsesFrontedMeek(dialParams.TunnelProtocol) {
+			meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
+			if meekResolvedIPAddress != "" {
+				params["meek_resolved_ip_address"] = meekResolvedIPAddress
+			}
 		}
 
 		if dialParams.MeekSNIServerName != "" {