fix(dnsping): make output more actionable (#1444)

## Checklist - [x] I have read the [contribution guidelines](https://github.com/ooni/probe-cli/blob/master/CONTRIBUTING.md) - [x] reference issue for this pull request: ooni/probe#2650 - [x] if you changed anything related to how experiments work and you need to reflect these changes in the ooni/spec repository, please link to the related ooni/spec pull request: N/A - [x] if you changed code inside an experiment, make sure you bump its version number ## Description Closes ooni/probe#2650 Here's an example of the output now: ``` % ./miniooni dnsping -i udp://8.8.8.8:53/ -O Domains='www.example.com thepiratebay.net' [ 0.000028] <info> Current time: 2024-01-12 14:48:25 UTC [ 0.000125] <info> miniooni home directory: $HOME/.miniooni [ 0.000319] <info> ooniprobe-engine/v3.21.0-alpha 9b035a4 dirty=false go1.20.12 [ 0.001050] <info> Looking up OONI backends; please be patient... [ 0.001640] <info> httpsDialer: [#1] TCPConnect 162.55.247.208:443... started [ 0.047764] <info> httpsDialer: [#1] TCPConnect 162.55.247.208:443... ok [ 0.047788] <info> httpsDialer: [#1] TLSHandshake with 162.55.247.208:443 SNI=interactive.guim.co.uk ALPN=[h2 http/1.1]... started [ 0.100400] <info> httpsDialer: [#1] TLSHandshake with 162.55.247.208:443 SNI=interactive.guim.co.uk ALPN=[h2 http/1.1]... ok [ 0.100417] <info> httpsDialer: [#1] TLSVerifyCertificateChain api.ooni.io... started [ 0.102877] <info> httpsDialer: [#1] TLSVerifyCertificateChain api.ooni.io... ok [ 0.169226] <info> session: using probe services: {Address:https://api.ooni.io Type:https Front:} [ 0.169246] <info> Looking up your location; please be patient... [ 0.169272] <info> iplookup: using stun_google [ 0.170163] <info> sessionresolver: lookup stun.l.google.com using system:///... started [ 0.172175] <info> sessionresolver: lookup stun.l.google.com using system:///... ok [ 0.190530] <info> - country: IT [ 0.190545] <info> - network: Vodafone Italia S.p.A. (AS30722) [ 0.190549] <info> - resolver's IP: 91.80.36.88 [ 0.190552] <info> - resolver's network: Vodafone Italia S.p.A. (AS30722) [ 0.190587] <info> [1/1] running with input: udp://8.8.8.8:53/ [ 0.190728] <info> DNSPing #0 8.8.8.8:53 thepiratebay.net... started [ 0.190729] <info> DNSPing #0 8.8.8.8:53 www.example.com... started [ 0.201393] <info> DNSPing #0 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 0.212578] <info> DNSPing #0 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 1.191531] <info> DNSPing #1 8.8.8.8:53 thepiratebay.net... started [ 1.191527] <info> DNSPing #1 8.8.8.8:53 www.example.com... started [ 1.199034] <info> DNSPing #1 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 1.208817] <info> DNSPing #1 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 2.191812] <info> DNSPing #2 8.8.8.8:53 thepiratebay.net... started [ 2.191815] <info> DNSPing #2 8.8.8.8:53 www.example.com... started [ 2.228774] <info> DNSPing #2 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 2.228793] <info> DNSPing #2 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 3.191340] <info> DNSPing #3 8.8.8.8:53 thepiratebay.net... started [ 3.191370] <info> DNSPing #3 8.8.8.8:53 www.example.com... started [ 3.197974] <info> DNSPing #3 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 3.211675] <info> DNSPing #3 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 4.191878] <info> DNSPing #4 8.8.8.8:53 www.example.com... started [ 4.191889] <info> DNSPing #4 8.8.8.8:53 thepiratebay.net... started [ 4.203056] <info> DNSPing #4 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 4.211179] <info> DNSPing #4 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 5.191830] <info> DNSPing #5 8.8.8.8:53 www.example.com... started [ 5.191830] <info> DNSPing #5 8.8.8.8:53 thepiratebay.net... started [ 5.233596] <info> DNSPing #5 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 5.261641] <info> DNSPing #5 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 6.191596] <info> DNSPing #6 8.8.8.8:53 thepiratebay.net... started [ 6.191573] <info> DNSPing #6 8.8.8.8:53 www.example.com... started [ 6.200647] <info> DNSPing #6 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 6.208036] <info> DNSPing #6 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 7.191875] <info> DNSPing #7 8.8.8.8:53 thepiratebay.net... started [ 7.191879] <info> DNSPing #7 8.8.8.8:53 www.example.com... started [ 7.200336] <info> DNSPing #7 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 7.213787] <info> DNSPing #7 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 8.191866] <info> DNSPing #8 8.8.8.8:53 thepiratebay.net... started [ 8.191900] <info> DNSPing #8 8.8.8.8:53 www.example.com... started [ 8.204297] <info> DNSPing #8 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 8.214435] <info> DNSPing #8 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 9.191857] <info> DNSPing #9 8.8.8.8:53 www.example.com... started [ 9.191863] <info> DNSPing #9 8.8.8.8:53 thepiratebay.net... started [ 9.200628] <info> DNSPing #9 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 9.216799] <info> DNSPing #9 8.8.8.8:53 thepiratebay.net... 83.224.65.41 Domain IPAddress ASN Org #Seen LateResponse -------------------------------------------------------------------------------------------------------------------------------------------------- www.example.com 2606:2800:220:1:248:1893:25c8:1946 15133 Edgecast Inc. 10 false www.example.com 93.184.216.34 15133 Edgecast Inc. 10 false thepiratebay.net 83.224.65.41 30722 Vodafone Italia S.p.A. 10 false [ 10.193633] <info> submitting measurement to OONI collector; please be patient... [ 10.262480] <info> New reportID: 20240112T144835Z_dnsping_IT_30722_n1_qbyxPwKoifjgp6AM [ 10.372279] <info> saving measurement to disk [ 10.373693] <info> experiment: recv 0.00 byte, sent 0.00 byte [ 10.375159] <info> whole session: recv 2.28 kbyte, sent 19.24 kbyte ```
ooni · Jan 12, 2024 · 64f61ec · 64f61ec
1 parent d16df54
commit 64f61ec
Show file tree

Hide file tree

Showing 4 changed files with 275 additions and 11 deletions.
diff --git a/internal/experiment/dnsping/dnsping.go b/internal/experiment/dnsping/dnsping.go
@@ -20,7 +20,7 @@ import (
 
 const (
 	testName    = "dnsping"
-	testVersion = "0.3.0"
+	testVersion = "0.4.0"
 )
 
 // Config contains the experiment configuration.
@@ -87,12 +87,15 @@ var (
 
 // Run implements ExperimentMeasurer.Run.
 func (m *Measurer) Run(ctx context.Context, args *model.ExperimentArgs) error {
+	// unpack experiment args
 	_ = args.Callbacks
 	measurement := args.Measurement
 	sess := args.Session
 	if measurement.Input == "" {
 		return errNoInputProvided
 	}
+
+	// parse experiment input
 	parsed, err := url.Parse(string(measurement.Input))
 	if err != nil {
 		return fmt.Errorf("%w: %s", errInputIsNotAnURL, err.Error())
@@ -103,50 +106,83 @@ func (m *Measurer) Run(ctx context.Context, args *model.ExperimentArgs) error {
 	if parsed.Port() == "" {
 		return errMissingPort
 	}
+
+	// create the empty measurement test keys
 	tk := NewTestKeys()
 	measurement.TestKeys = tk
+
+	// parse the domains to measure
 	domains := strings.Split(m.config.domains(), " ")
+
+	// spawn a pinger for each domain to measure
 	wg := new(sync.WaitGroup)
 	wg.Add(len(domains))
 	for _, domain := range domains {
 		go m.dnsPingLoop(ctx, measurement.MeasurementStartTimeSaved, sess.Logger(), parsed.Host, domain, wg, tk)
 	}
+
+	// block until all pingers are done
 	wg.Wait()
+
+	// generate textual summary
+	summarize(tk)
+
 	return nil // return nil so we always submit the measurement
 }
 
 // dnsPingLoop sends all the ping requests and emits the results onto the out channel.
 func (m *Measurer) dnsPingLoop(ctx context.Context, zeroTime time.Time, logger model.Logger,
 	address string, domain string, wg *sync.WaitGroup, tk *TestKeys) {
+	// make sure the parent knows when we're done
 	defer wg.Done()
+
+	// create ticker so we know when to send the next DNS ping
 	ticker := time.NewTicker(m.config.delay())
 	defer ticker.Stop()
+
+	// start a goroutine for each ping repetition
 	for i := int64(0); i < m.config.repetitions(); i++ {
 		wg.Add(1)
 		go m.dnsRoundTrip(ctx, i, zeroTime, logger, address, domain, wg, tk)
+
+		// make sure we wait until it's time to send the next ping
 		<-ticker.C
 	}
 }
 
 // dnsRoundTrip performs a round trip and returns the results to the caller.
 func (m *Measurer) dnsRoundTrip(ctx context.Context, index int64, zeroTime time.Time,
 	logger model.Logger, address string, domain string, wg *sync.WaitGroup, tk *TestKeys) {
+	// create context bound to timeout
 	// TODO(bassosimone): make the timeout user-configurable
 	ctx, cancel := context.WithTimeout(ctx, 3*time.Second)
 	defer cancel()
+
+	// make sure we inform the parent when we're done
 	defer wg.Done()
-	pings := []*SinglePing{}
+
+	// create trace for collecting information
 	trace := measurexlite.NewTrace(index, zeroTime)
-	ol := logx.NewOperationLogger(logger, "DNSPing #%d %s %s", index, address, domain)
+
+	// create dialer and resolver
+	//
 	// TODO(bassosimone, DecFox): what should we do if the user passes us a resolver with a
 	// domain name in terms of saving its results? Shall we save also the system resolver's lookups?
 	// Shall we, otherwise, pre-resolve the domain name to IP addresses once and for all? In such
 	// a case, shall we use all the available IP addresses or just some of them?
 	dialer := netxlite.NewDialerWithStdlibResolver(logger)
 	resolver := trace.NewParallelUDPResolver(logger, dialer, address)
-	_, err := resolver.LookupHost(ctx, domain)
-	ol.Stop(err)
-	delayedResp := trace.DelayedDNSResponseWithTimeout(ctx, 250*time.Millisecond)
+
+	// perform the lookup proper
+	ol := logx.NewOperationLogger(logger, "DNSPing #%d %s %s", index, address, domain)
+	addrs, err := resolver.LookupHost(ctx, domain)
+	stopOperationLogger(ol, addrs, err)
+
+	// wait a bit for delayed responses
+	delayedResps := trace.DelayedDNSResponseWithTimeout(ctx, 250*time.Millisecond)
+
+	// assemble the results by inspecting ordinary and late responses
+	pings := []*SinglePing{}
 	for _, lookup := range trace.DNSLookupsFromRoundTrip() {
 		// make sure we only include the query types we care about (in principle, there
 		// should be no other query, so we're doing this just for robustness).
@@ -155,18 +191,37 @@ func (m *Measurer) dnsRoundTrip(ctx context.Context, index int64, zeroTime time.
 				Query:            lookup,
 				DelayedResponses: []*model.ArchivalDNSLookupResult{},
 			}
-			// record the delayed responses of the corresponding query
-			for _, resp := range delayedResp {
-				if resp.QueryType == lookup.QueryType {
-					sp.DelayedResponses = append(sp.DelayedResponses, resp)
+
+			// now take care of delayed responses
+			if len(delayedResps) > 0 {
+				logger.Warnf("DNSPing #%d... received %d delayed responses", index, len(delayedResps))
+				// record the delayed responses of the corresponding query
+				for _, resp := range delayedResps {
+					if resp.QueryType == lookup.QueryType {
+						sp.DelayedResponses = append(sp.DelayedResponses, resp)
+					}
 				}
 			}
+
 			pings = append(pings, sp)
 		}
 	}
+
 	tk.addPings(pings)
 }
 
+type stoppableOperationLogger interface {
+	Stop(value any)
+}
+
+func stopOperationLogger(ol stoppableOperationLogger, addrs []string, err error) {
+	if err == nil {
+		ol.Stop(strings.Join(addrs, " "))
+	} else {
+		ol.Stop(err)
+	}
+}
+
 // NewExperimentMeasurer creates a new ExperimentMeasurer.
 func NewExperimentMeasurer(config Config) model.ExperimentMeasurer {
 	return &Measurer{config: config}

diff --git a/internal/experiment/dnsping/dnsping_test.go b/internal/experiment/dnsping/dnsping_test.go
@@ -3,10 +3,12 @@ package dnsping
 import (
 	"context"
 	"errors"
+	"strings"
 	"testing"
 	"time"
 
 	"github.com/google/go-cmp/cmp"
+	"github.com/google/go-cmp/cmp/cmpopts"
 	"github.com/ooni/netem"
 	"github.com/ooni/probe-cli/v3/internal/mocks"
 	"github.com/ooni/probe-cli/v3/internal/model"
@@ -49,7 +51,7 @@ func TestMeasurer_run(t *testing.T) {
 		if m.ExperimentName() != "dnsping" {
 			t.Fatal("invalid experiment name")
 		}
-		if m.ExperimentVersion() != "0.3.0" {
+		if m.ExperimentVersion() != "0.4.0" {
 			t.Fatal("invalid experiment version")
 		}
 		ctx := context.Background()
@@ -233,3 +235,32 @@ func TestMeasurer_run(t *testing.T) {
 		})
 	})
 }
+
+type mockableStoppableOperationLogger struct {
+	value any
+}
+
+func (ol *mockableStoppableOperationLogger) Stop(value any) {
+	ol.value = value
+}
+
+func TestStopOperationLogger(t *testing.T) {
+	t.Run("in case of success", func(t *testing.T) {
+		ol := &mockableStoppableOperationLogger{}
+		expect := []string{"8.8.8.8", "8.8.4.4"}
+		stopOperationLogger(ol, expect, nil)
+		if diff := cmp.Diff(strings.Join(expect, " "), ol.value); diff != "" {
+			t.Fatal(diff)
+		}
+	})
+
+	t.Run("in case of failure", func(t *testing.T) {
+		ol := &mockableStoppableOperationLogger{}
+		addrs := []string{"8.8.8.8", "8.8.4.4"} // the error should prevail
+		expect := errors.New("antani")
+		stopOperationLogger(ol, addrs, expect)
+		if diff := cmp.Diff(expect, ol.value, cmpopts.EquateErrors()); diff != "" {
+			t.Fatal(diff)
+		}
+	})
+}
diff --git a/internal/experiment/dnsping/summarize.go b/internal/experiment/dnsping/summarize.go
@@ -0,0 +1,122 @@
+package dnsping
+
+import (
+	"fmt"
+	"io"
+	"os"
+
+	"github.com/ooni/probe-cli/v3/internal/geoipx"
+	"github.com/ooni/probe-cli/v3/internal/model"
+)
+
+// summarize summarizes the results.
+func summarize(tk *TestKeys) {
+	// print a summary of the addresses we have seen
+	as := &addressSummarizer{}
+	as.load(tk)
+	as.printf(os.Stdout)
+}
+
+// summarizeAddressStats contains stats about a resolved IP address
+// as generated by the [*addressSummarizer].
+type summarizeAddressStats struct {
+	Domain      string
+	IPAddress   string
+	ASN         uint
+	ASOrg       string
+	NumResolved int
+	Late        bool
+}
+
+// addressSummarizer creates a summary for addresses.
+//
+// The zero value is ready to use.
+type addressSummarizer struct {
+	m map[string]map[string]*summarizeAddressStats
+}
+
+func (as *addressSummarizer) printf(w io.Writer) {
+	fmt.Fprintf(w, "\n\n")
+
+	fmt.Fprintf(
+		w,
+		"%-30s %-48s %-10s %-30s %-10s %-10s\n",
+		"Domain",
+		"IPAddress",
+		"ASN",
+		"Org",
+		"#Seen",
+		"LateResponse",
+	)
+
+	fmt.Fprintf(w, "--------------------------------------------------------------------------------------------------------------------------------------------------\n")
+
+	for _, domainAddresses := range as.m {
+		for _, stats := range domainAddresses {
+			fmt.Fprintf(
+				w,
+				"%-30s %-48s %-10d %-30s %-10d %-10v\n",
+				stats.Domain,
+				stats.IPAddress,
+				stats.ASN,
+				stats.ASOrg,
+				stats.NumResolved,
+				stats.Late,
+			)
+		}
+	}
+
+	fmt.Fprintf(w, "\n\n")
+}
+
+// load loads information from the [*TestKeys].
+//
+// This method MAY MUTATE the [*addressSummarizer] content.
+func (as *addressSummarizer) load(tk *TestKeys) {
+	for _, ping := range tk.Pings {
+		as.loadQuery(ping.Query, false)
+		for _, q := range ping.DelayedResponses {
+			as.loadQuery(q, true)
+		}
+	}
+}
+
+// loadQuery loads a single query result.
+//
+// This method MAY MUTATE the [*addressSummarizer] content.
+func (as *addressSummarizer) loadQuery(query *model.ArchivalDNSLookupResult, late bool) {
+	for _, answer := range query.Answers {
+		switch answer.AnswerType {
+		case "A":
+			as.addAnswer(query.Hostname, answer.IPv4, late)
+
+		case "AAAA":
+			as.addAnswer(query.Hostname, answer.IPv6, late)
+		}
+	}
+}
+
+// addAnswer adds a single answer.
+//
+// This method MAY MUTATE the [*addressSummarizer] content.
+func (as *addressSummarizer) addAnswer(hostname string, ipAddr string, late bool) {
+	if as.m == nil {
+		as.m = make(map[string]map[string]*summarizeAddressStats)
+	}
+	if as.m[hostname] == nil {
+		as.m[hostname] = make(map[string]*summarizeAddressStats)
+	}
+	if as.m[hostname][ipAddr] == nil {
+		asNum, asOrg, _ := geoipx.LookupASN(ipAddr)
+		as.m[hostname][ipAddr] = &summarizeAddressStats{
+			Domain:      hostname,
+			IPAddress:   ipAddr,
+			NumResolved: 0,
+			Late:        late,
+			ASN:         asNum,
+			ASOrg:       asOrg,
+		}
+	}
+	entry := as.m[hostname][ipAddr]
+	entry.NumResolved++
+}
diff --git a/internal/experiment/dnsping/summarize_test.go b/internal/experiment/dnsping/summarize_test.go
@@ -0,0 +1,56 @@
+package dnsping
+
+import (
+	"testing"
+
+	"github.com/google/go-cmp/cmp"
+	"github.com/ooni/probe-cli/v3/internal/model"
+)
+
+func TestAddressSummarizer(t *testing.T) {
+	t.Run("loadQuery", func(t *testing.T) {
+
+		// create a realistic query result with the correct addrs
+		result := &model.ArchivalDNSLookupResult{
+			Answers: []model.ArchivalDNSAnswer{{
+				AnswerType: "A",
+				IPv4:       "8.8.8.8",
+			}, {
+				AnswerType: "AAAA",
+				IPv6:       "2001:4860:4860::8844",
+			}},
+			Engine:    "getaddrinfo",
+			Hostname:  "dns.google",
+			QueryType: "ANY",
+		}
+
+		// ingest result
+		as := &addressSummarizer{}
+		as.loadQuery(result, false)
+
+		// define expectations
+		expect := map[string]map[string]*summarizeAddressStats{
+			"dns.google": {
+				"2001:4860:4860::8844": {
+					Domain:      "dns.google",
+					IPAddress:   "2001:4860:4860::8844",
+					ASN:         15169,
+					ASOrg:       "Google LLC",
+					NumResolved: 1,
+				},
+				"8.8.8.8": {
+					Domain:      "dns.google",
+					IPAddress:   "8.8.8.8",
+					ASN:         15169,
+					ASOrg:       "Google LLC",
+					NumResolved: 1,
+				},
+			},
+		}
+
+		// compare
+		if diff := cmp.Diff(expect, as.m); diff != "" {
+			t.Fatal(diff)
+		}
+	})
+}