From 64f61ec52fbd79944cd67d3cfeb2853606d9be4e Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Fri, 12 Jan 2024 16:19:28 +0100 Subject: [PATCH] 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: https://github.com/ooni/probe/issues/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 https://github.com/ooni/probe/issues/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] Current time: 2024-01-12 14:48:25 UTC [ 0.000125] miniooni home directory: $HOME/.miniooni [ 0.000319] ooniprobe-engine/v3.21.0-alpha 9b035a40dd521df61c7cb305d5253e3bc1c2a88e dirty=false go1.20.12 [ 0.001050] Looking up OONI backends; please be patient... [ 0.001640] httpsDialer: [#1] TCPConnect 162.55.247.208:443... started [ 0.047764] httpsDialer: [#1] TCPConnect 162.55.247.208:443... ok [ 0.047788] httpsDialer: [#1] TLSHandshake with 162.55.247.208:443 SNI=interactive.guim.co.uk ALPN=[h2 http/1.1]... started [ 0.100400] httpsDialer: [#1] TLSHandshake with 162.55.247.208:443 SNI=interactive.guim.co.uk ALPN=[h2 http/1.1]... ok [ 0.100417] httpsDialer: [#1] TLSVerifyCertificateChain api.ooni.io... started [ 0.102877] httpsDialer: [#1] TLSVerifyCertificateChain api.ooni.io... ok [ 0.169226] session: using probe services: {Address:https://api.ooni.io Type:https Front:} [ 0.169246] Looking up your location; please be patient... [ 0.169272] iplookup: using stun_google [ 0.170163] sessionresolver: lookup stun.l.google.com using system:///... started [ 0.172175] sessionresolver: lookup stun.l.google.com using system:///... ok [ 0.190530] - country: IT [ 0.190545] - network: Vodafone Italia S.p.A. (AS30722) [ 0.190549] - resolver's IP: 91.80.36.88 [ 0.190552] - resolver's network: Vodafone Italia S.p.A. (AS30722) [ 0.190587] [1/1] running with input: udp://8.8.8.8:53/ [ 0.190728] DNSPing #0 8.8.8.8:53 thepiratebay.net... started [ 0.190729] DNSPing #0 8.8.8.8:53 www.example.com... started [ 0.201393] DNSPing #0 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 0.212578] DNSPing #0 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 1.191531] DNSPing #1 8.8.8.8:53 thepiratebay.net... started [ 1.191527] DNSPing #1 8.8.8.8:53 www.example.com... started [ 1.199034] DNSPing #1 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 1.208817] DNSPing #1 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 2.191812] DNSPing #2 8.8.8.8:53 thepiratebay.net... started [ 2.191815] DNSPing #2 8.8.8.8:53 www.example.com... started [ 2.228774] DNSPing #2 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 2.228793] DNSPing #2 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 3.191340] DNSPing #3 8.8.8.8:53 thepiratebay.net... started [ 3.191370] DNSPing #3 8.8.8.8:53 www.example.com... started [ 3.197974] DNSPing #3 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 3.211675] DNSPing #3 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 4.191878] DNSPing #4 8.8.8.8:53 www.example.com... started [ 4.191889] DNSPing #4 8.8.8.8:53 thepiratebay.net... started [ 4.203056] DNSPing #4 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 4.211179] DNSPing #4 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 5.191830] DNSPing #5 8.8.8.8:53 www.example.com... started [ 5.191830] DNSPing #5 8.8.8.8:53 thepiratebay.net... started [ 5.233596] DNSPing #5 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 5.261641] DNSPing #5 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 6.191596] DNSPing #6 8.8.8.8:53 thepiratebay.net... started [ 6.191573] DNSPing #6 8.8.8.8:53 www.example.com... started [ 6.200647] DNSPing #6 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 6.208036] DNSPing #6 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 7.191875] DNSPing #7 8.8.8.8:53 thepiratebay.net... started [ 7.191879] DNSPing #7 8.8.8.8:53 www.example.com... started [ 7.200336] DNSPing #7 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 7.213787] DNSPing #7 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 8.191866] DNSPing #8 8.8.8.8:53 thepiratebay.net... started [ 8.191900] DNSPing #8 8.8.8.8:53 www.example.com... started [ 8.204297] DNSPing #8 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 8.214435] DNSPing #8 8.8.8.8:53 thepiratebay.net... 83.224.65.41 [ 9.191857] DNSPing #9 8.8.8.8:53 www.example.com... started [ 9.191863] DNSPing #9 8.8.8.8:53 thepiratebay.net... started [ 9.200628] DNSPing #9 8.8.8.8:53 www.example.com... 93.184.216.34 2606:2800:220:1:248:1893:25c8:1946 [ 9.216799] 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] submitting measurement to OONI collector; please be patient... [ 10.262480] New reportID: 20240112T144835Z_dnsping_IT_30722_n1_qbyxPwKoifjgp6AM [ 10.372279] saving measurement to disk [ 10.373693] experiment: recv 0.00 byte, sent 0.00 byte [ 10.375159] whole session: recv 2.28 kbyte, sent 19.24 kbyte ``` --- internal/experiment/dnsping/dnsping.go | 75 +++++++++-- internal/experiment/dnsping/dnsping_test.go | 33 ++++- internal/experiment/dnsping/summarize.go | 122 ++++++++++++++++++ internal/experiment/dnsping/summarize_test.go | 56 ++++++++ 4 files changed, 275 insertions(+), 11 deletions(-) create mode 100644 internal/experiment/dnsping/summarize.go create mode 100644 internal/experiment/dnsping/summarize_test.go diff --git a/internal/experiment/dnsping/dnsping.go b/internal/experiment/dnsping/dnsping.go index 21c4de876..eb976cf90 100644 --- 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,27 +106,46 @@ 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 } } @@ -131,22 +153,36 @@ func (m *Measurer) dnsPingLoop(ctx context.Context, zeroTime time.Time, logger m // 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 index f24326b04..56c7efedb 100644 --- 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 new file mode 100644 index 000000000..9e1977e22 --- /dev/null +++ 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 new file mode 100644 index 000000000..bb464af42 --- /dev/null +++ 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) + } + }) +}