diff --git a/internal/experiment/webconnectivity/analysiscore.go b/internal/experiment/webconnectivity/analysiscore.go index 5327dfe..ebcf69c 100644 --- a/internal/experiment/webconnectivity/analysiscore.go +++ b/internal/experiment/webconnectivity/analysiscore.go @@ -109,7 +109,7 @@ func (tk *TestKeys) analysisToplevel(logger model.Logger) { tk.Blocking = "dns" tk.Accessible = false logger.Warnf( - "ANOMALY: flags=%d accessible=%+v, blocking=%+v", + "ANOMALY: flags=%d, accessible=%+v, blocking=%+v", tk.BlockingFlags, tk.Accessible, tk.Blocking, ) @@ -117,14 +117,14 @@ func (tk *TestKeys) analysisToplevel(logger model.Logger) { tk.Blocking = "tcp_ip" tk.Accessible = false logger.Warnf( - "ANOMALY: flags=%d accessible=%+v, blocking=%+v", + "ANOMALY: flags=%d, accessible=%+v, blocking=%+v", tk.BlockingFlags, tk.Accessible, tk.Blocking, ) case (tk.BlockingFlags & (analysisFlagTLSBlocking | analysisFlagHTTPBlocking)) != 0: tk.Blocking = "http-failure" tk.Accessible = false - logger.Warnf("ANOMALY: flags=%d accessible=%+v, blocking=%+v", + logger.Warnf("ANOMALY: flags=%d, accessible=%+v, blocking=%+v", tk.BlockingFlags, tk.Accessible, tk.Blocking, ) @@ -132,7 +132,7 @@ func (tk *TestKeys) analysisToplevel(logger model.Logger) { tk.Blocking = "http-diff" tk.Accessible = false logger.Warnf( - "ANOMALY: flags=%d accessible=%+v, blocking=%+v", + "ANOMALY: flags=%d, accessible=%+v, blocking=%+v", tk.BlockingFlags, tk.Accessible, tk.Blocking, ) @@ -140,7 +140,7 @@ func (tk *TestKeys) analysisToplevel(logger model.Logger) { tk.Blocking = false tk.Accessible = true logger.Infof( - "ACCESSIBLE: flags=%d accessible=%+v, blocking=%+v", + "ACCESSIBLE: flags=%d, accessible=%+v, blocking=%+v", tk.BlockingFlags, tk.Accessible, tk.Blocking, ) diff --git a/internal/experiment/webconnectivity/analysisdns.go b/internal/experiment/webconnectivity/analysisdns.go index 627cbbc..e32bfc2 100644 --- a/internal/experiment/webconnectivity/analysisdns.go +++ b/internal/experiment/webconnectivity/analysisdns.go @@ -58,6 +58,7 @@ const ( func (tk *TestKeys) analysisDNSToplevel(logger model.Logger) { tk.analysisDNSExperimentFailure() tk.analysisDNSBogon(logger) + tk.analysisDNSDuplicateResponses(logger) tk.analysisDNSUnexpectedFailure(logger) tk.analysisDNSUnexpectedAddrs(logger) if tk.DNSFlags != 0 { @@ -70,6 +71,15 @@ func (tk *TestKeys) analysisDNSToplevel(logger model.Logger) { } } +// analysisDNSDuplicateResponses checks whether we received duplicate +// replies for DNS-over-UDP queries, which is very unexpected. +func (tk *TestKeys) analysisDNSDuplicateResponses(logger model.Logger) { + if length := len(tk.DNSDuplicateResponses); length > 0 { + // TODO(bassosimone): write algorithm to analyze this + logger.Warnf("DNS: got %d unexpected late/duplicate DNS responses", length) + } +} + // analysisDNSExperimentFailure sets the legacy DNSExperimentFailure field. func (tk *TestKeys) analysisDNSExperimentFailure() { for _, query := range tk.Queries { @@ -106,13 +116,23 @@ func (tk *TestKeys) analysisDNSBogon(logger model.Logger) { switch answer.AnswerType { case "A": if net.ParseIP(answer.IPv4) != nil && netxlite.IsBogon(answer.IPv4) { - logger.Warnf("DNS: BOGON %s in #%d", answer.IPv4, query.TransactionID) + logger.Warnf( + "DNS: got BOGON answer %s for domain %s (see #%d)", + answer.IPv4, + query.Hostname, + query.TransactionID, + ) tk.DNSFlags |= AnalysisDNSBogon // continue processing so we print all the bogons we have } case "AAAA": if net.ParseIP(answer.IPv6) != nil && netxlite.IsBogon(answer.IPv6) { - logger.Warnf("DNS: BOGON %s in #%d", answer.IPv6, query.TransactionID) + logger.Warnf( + "DNS: got BOGON answer %s for domain %s (see #%d)", + answer.IPv6, + query.Hostname, + query.TransactionID, + ) tk.DNSFlags |= AnalysisDNSBogon // continue processing so we print all the bogons we have } @@ -255,7 +275,7 @@ func (tk *TestKeys) analysisDNSUnexpectedAddrs(logger model.Logger) { // if the probe has not collected any addr for the same domain, it's // definitely suspicious and counts as a difference if len(probeAddrs) <= 0 { - logger.Warnf("DNS: no IP address resolved by the probe") + logger.Warnf("DNS: the probe did not resolve any IP address") tk.DNSFlags |= AnalysisDNSUnexpectedAddrs return } @@ -266,6 +286,9 @@ func (tk *TestKeys) analysisDNSUnexpectedAddrs(logger model.Logger) { if len(differentAddrs) <= 0 { return } + for _, addr := range differentAddrs { + logger.Infof("DNS: address %s: not resolved by TH", addr) + } // now, let's exclude the differentAddrs for which we successfully // completed a TLS handshake: those should be good addrs @@ -273,19 +296,24 @@ func (tk *TestKeys) analysisDNSUnexpectedAddrs(logger model.Logger) { if len(withoutHandshake) <= 0 { return } + for _, addr := range withoutHandshake { + logger.Infof("DNS: address %s: cannot confirm using TLS handshake", addr) + } // as a last resort, accept the addresses without an handshake whose // ASN overlaps with ASNs resolved by the TH - differentASNs := tk.analysisDNSDiffASN(withoutHandshake, thAddrs) + differentASNs := tk.analysisDNSDiffASN(logger, withoutHandshake, thAddrs) if len(differentASNs) <= 0 { return } // otherwise, conclude we have unexpected probe addrs - logger.Warnf( - "DNSDiff: differentAddrs: %+v; withoutHandshake: %+v; differentASNs: %+v", - differentAddrs, withoutHandshake, differentASNs, - ) + for addr, asn := range differentASNs { + logger.Warnf( + "DNS: address %s has unexpected AS%d and we cannot use TLS to confirm it", + addr, asn, + ) + } tk.DNSFlags |= AnalysisDNSUnexpectedAddrs } @@ -298,6 +326,10 @@ func (tk *TestKeys) analysisDNSDiffAddrs(probeAddrs, thAddrs []string) (diff []s ) mapping := make(map[string]int) for _, addr := range probeAddrs { + if net.ParseIP(addr) != nil && netxlite.IsBogon(addr) { + // we can exclude bogons from the analysis because we already analyzed them + continue + } mapping[addr] |= inProbe } for _, addr := range thAddrs { @@ -313,23 +345,44 @@ func (tk *TestKeys) analysisDNSDiffAddrs(probeAddrs, thAddrs []string) (diff []s // analysisDNSDiffASN returns whether there are IP addresses in the probe's // list with different ASNs from the ones in the TH's list. -func (tk *TestKeys) analysisDNSDiffASN(probeAddrs, thAddrs []string) (asns []uint) { +func (tk *TestKeys) analysisDNSDiffASN( + logger model.Logger, + probeAddrs, + thAddrs []string, +) (result map[string]uint) { const ( inProbe = 1 << iota inTH ) - mapping := make(map[uint]int) + logger.Debugf("DNS: probeAddrs %+v, thAddrs %+v", probeAddrs, thAddrs) + uniqueAddrs := make(map[string]uint) + asnToFlags := make(map[uint]int) for _, addr := range probeAddrs { asn, _, _ := geoipx.LookupASN(addr) - mapping[asn] |= inProbe // including the zero ASN that means unknown + asnToFlags[asn] |= inProbe // including the zero ASN that means unknown + uniqueAddrs[addr] = asn } for _, addr := range thAddrs { asn, _, _ := geoipx.LookupASN(addr) - mapping[asn] |= inTH // including the zero ASN that means unknown + asnToFlags[asn] |= inTH // including the zero ASN that means unknown + uniqueAddrs[addr] = asn } - for asn, where := range mapping { + for addr, asn := range uniqueAddrs { + logger.Infof("DNS: addr %s has AS%d", addr, asn) + } + probeOnlyASNs := make(map[uint]bool) + for asn, where := range asnToFlags { if (where & inTH) == 0 { - asns = append(asns, asn) + probeOnlyASNs[asn] = true + } + } + for asn := range probeOnlyASNs { + logger.Infof("DNS: AS%d: only seen by probe", asn) + } + result = make(map[string]uint) + for addr, asn := range uniqueAddrs { + if probeOnlyASNs[asn] { + result[addr] = asn } } return diff --git a/internal/experiment/webconnectivity/analysishttpcore.go b/internal/experiment/webconnectivity/analysishttpcore.go index 91ea2ff..5bebfda 100644 --- a/internal/experiment/webconnectivity/analysishttpcore.go +++ b/internal/experiment/webconnectivity/analysishttpcore.go @@ -53,10 +53,10 @@ func (tk *TestKeys) analysisHTTPToplevel(logger model.Logger) { netxlite.FailureEOFError: tk.BlockingFlags |= analysisFlagHTTPBlocking logger.Warnf( - "HTTP: endpoint %s is blocked (see #%d): %s", + "HTTP: unexpected failure %s for %s (see #%d)", + *failure, finalRequest.Address, finalRequest.TransactionID, - *failure, ) default: // leave this case for ooni/pipeline diff --git a/internal/experiment/webconnectivity/analysishttpdiff.go b/internal/experiment/webconnectivity/analysishttpdiff.go index f65b388..b8f4258 100644 --- a/internal/experiment/webconnectivity/analysishttpdiff.go +++ b/internal/experiment/webconnectivity/analysishttpdiff.go @@ -53,6 +53,7 @@ func (tk *TestKeys) analysisHTTPDiff(logger model.Logger, tk.BlockingFlags |= analysisFlagSuccess return } + logger.Infof("HTTP: body length: MISMATCH (see #%d)", probe.TransactionID) if tk.HeadersMatch != nil && *tk.HeadersMatch { logger.Infof( "HTTP: statusCodeMatch && headersMatch => #%d is successful", @@ -61,6 +62,7 @@ func (tk *TestKeys) analysisHTTPDiff(logger model.Logger, tk.BlockingFlags |= analysisFlagSuccess return } + logger.Infof("HTTP: uncommon headers: MISMATCH (see #%d)", probe.TransactionID) if tk.TitleMatch != nil && *tk.TitleMatch { logger.Infof( "HTTP: statusCodeMatch && titleMatch => #%d is successful", @@ -69,6 +71,9 @@ func (tk *TestKeys) analysisHTTPDiff(logger model.Logger, tk.BlockingFlags |= analysisFlagSuccess return } + logger.Infof("HTTP: title: MISMATCH (see #%d)", probe.TransactionID) + } else { + logger.Infof("HTTP: status code: MISMATCH (see #%d)", probe.TransactionID) } tk.BlockingFlags |= analysisFlagHTTPDiff diff --git a/internal/experiment/webconnectivity/analysistcpip.go b/internal/experiment/webconnectivity/analysistcpip.go index 4a901df..7181176 100644 --- a/internal/experiment/webconnectivity/analysistcpip.go +++ b/internal/experiment/webconnectivity/analysistcpip.go @@ -71,10 +71,10 @@ func (tk *TestKeys) analysisTCPIPToplevel(logger model.Logger) { continue } logger.Warnf( - "TCP/IP: endpoint %s is blocked (see #%d): %s", + "TCP/IP: unexpected failure %s for %s (see #%d)", + *failure, epnt, entry.TransactionID, - *failure, ) entry.Status.Blocked = &istrue tk.BlockingFlags |= analysisFlagTCPIPBlocking diff --git a/internal/experiment/webconnectivity/analysistls.go b/internal/experiment/webconnectivity/analysistls.go index 6e3c5a9..9a74e85 100644 --- a/internal/experiment/webconnectivity/analysistls.go +++ b/internal/experiment/webconnectivity/analysistls.go @@ -40,10 +40,10 @@ func (tk *TestKeys) analysisTLSToplevel(logger model.Logger) { continue } logger.Warnf( - "TLS: endpoint %s is blocked (see #%d): %s", + "TLS: unexpected failure %s for %s (see #%d)", + *failure, epnt, entry.TransactionID, - *failure, ) tk.BlockingFlags |= analysisFlagTLSBlocking } diff --git a/internal/experiment/webconnectivity/dnsresolvers.go b/internal/experiment/webconnectivity/dnsresolvers.go index 89465f1..f82cbae 100644 --- a/internal/experiment/webconnectivity/dnsresolvers.go +++ b/internal/experiment/webconnectivity/dnsresolvers.go @@ -268,9 +268,6 @@ func (t *DNSResolvers) waitForLateReplies(parentCtx context.Context, trace *meas defer t.WaitGroup.Done() const lateTimeout = 500 * time.Millisecond events := trace.DelayedDNSResponseWithTimeout(parentCtx, lateTimeout) - if length := len(events); length > 0 { - t.Logger.Warnf("got %d late DNS replies", length) - } t.TestKeys.AppendDNSLateReplies(events...) } diff --git a/internal/experiment/webconnectivity/measurer.go b/internal/experiment/webconnectivity/measurer.go index a9a4ca0..3d433e2 100644 --- a/internal/experiment/webconnectivity/measurer.go +++ b/internal/experiment/webconnectivity/measurer.go @@ -36,7 +36,7 @@ func (m *Measurer) ExperimentName() string { // ExperimentVersion implements model.ExperimentMeasurer. func (m *Measurer) ExperimentVersion() string { - return "0.5.16" + return "0.5.17" } // Run implements model.ExperimentMeasurer. diff --git a/internal/experiment/webconnectivity/testkeys.go b/internal/experiment/webconnectivity/testkeys.go index 839f625..37dbc94 100644 --- a/internal/experiment/webconnectivity/testkeys.go +++ b/internal/experiment/webconnectivity/testkeys.go @@ -43,9 +43,9 @@ type TestKeys struct { // Do53 contains ancillary observations collected by Do53 resolvers. Do53 *TestKeysDo53 `json:"x_do53"` - // DNSLateReplies contains late replies we didn't expect to receive from + // DNSDuplicateResponses contains late/duplicate responses we didn't expect to receive from // a resolver (which may raise eyebrows if they're different). - DNSLateReplies []*model.ArchivalDNSLookupResult `json:"x_dns_late_replies"` + DNSDuplicateResponses []*model.ArchivalDNSLookupResult `json:"x_dns_duplicate_responses"` // Queries contains DNS queries. Queries []*model.ArchivalDNSLookupResult `json:"queries"` @@ -202,7 +202,7 @@ func (tk *TestKeys) AppendNetworkEvents(v ...*model.ArchivalNetworkEvent) { // AppendDNSLateReplies appends to DNSLateReplies. func (tk *TestKeys) AppendDNSLateReplies(v ...*model.ArchivalDNSLookupResult) { tk.mu.Lock() - tk.DNSLateReplies = append(tk.DNSLateReplies, v...) + tk.DNSDuplicateResponses = append(tk.DNSDuplicateResponses, v...) tk.mu.Unlock() } @@ -325,7 +325,7 @@ func NewTestKeys() *TestKeys { NetworkEvents: []*model.ArchivalNetworkEvent{}, Queries: []*model.ArchivalDNSLookupResult{}, }, - DNSLateReplies: []*model.ArchivalDNSLookupResult{}, + DNSDuplicateResponses: []*model.ArchivalDNSLookupResult{}, Queries: []*model.ArchivalDNSLookupResult{}, Requests: []*model.ArchivalHTTPRequestResult{}, TCPConnect: []*model.ArchivalTCPConnectResult{},