fix: make bootstrap more robust (and slower 😢) (ooni#1351)

This diff ensures that the boostrap is more robust in the scenario
described by ooni/probe#2544.

Because we're close to a release, I did not want to write a heavy
refactor of the boostrap, and specifically of the iplookup part, but I
documented what is needed at ooni/probe#2551.

This diff has been tested in a problematic network under two distinct
conditions:

1. cold bootstrap (i.e., w/o prior knowledge), where the correct fix is
to give the system resolver intermediate priority (i.e., 0.5);

2. hot bootstrap with very f***** up `sessionresolver.state`, where the
correct fix is to use a larger coarse grained timeout, such that
_eventually_ we try the system resolver.

The fix that prevents marking a resolver when the external context has been
canceled is required in both of these scenarios.

As you can see, I removed a "reliability fix", which actually was more
of an optimization. This removal means that the probe bootstrap is now
slower than it could be, hence my choice of documenting in
ooni/probe#2551 what I'd do had I had more
time to work on this topic.

BTW, I had to create an overall 45 seconds timeout for IP lookups
because we have 7 DNS over HTTPS resolvers plus the system resolver.
This means that, in the worst case where the system resolver has the
least priority, we expect 7*4 = 28 seconds of timeout before eventually
using the system resolver. The rest of the 45s timeout accounts for
operations happening after the DNS lookup has completed.

internal/enginelocate/iplookup.go

@@ -77,13 +77,21 @@ func makeSlice() []method {
  return ret
 }
 
+func contextForIPLookupWithTimeout(ctx context.Context) (context.Context, context.CancelFunc) {
+ // TODO(https://github.com/ooni/probe/issues/2551): we must enforce a timeout this
+ // large to ensure we give all resolvers a chance to run. We set this value as part of
+ // an hotfix. The above mentioned issue explains how to improve the situation and
+ // avoid the need of setting such large timeouts here.
+ const timeout = 45 * time.Second
+ return context.WithTimeout(ctx, timeout)
+}
+
 func (c ipLookupClient) doWithCustomFunc(
  ctx context.Context, fn lookupFunc,
 ) (string, error) {
- // Reliability fix: let these mechanisms timeout earlier.
- const timeout = 7 * time.Second
- ctx, cancel := context.WithTimeout(ctx, timeout)
+ ctx, cancel := contextForIPLookupWithTimeout(ctx)
  defer cancel()
+
  // Implementation note: we MUST use an HTTP client that we're
  // sure IS NOT using any proxy. To this end, we construct a
  // client ourself that we know is not proxied.

internal/enginelocate/iplookup_test.go

@@ -5,6 +5,7 @@ import (
  "errors"
  "net"
  "testing"
+ "time"
 
  "github.com/apex/log"
  "github.com/ooni/probe-cli/v3/internal/model"
@@ -55,3 +56,19 @@ func TestIPLookupInvalidIP(t *testing.T) {
  t.Fatal("expected the default IP here")
  }
 }
+
+func TestContextForIPLookupWithTimeout(t *testing.T) {
+ now := time.Now()
+ ctx, cancel := contextForIPLookupWithTimeout(context.Background())
+ defer cancel()
+ deadline, okay := ctx.Deadline()
+ if !okay {
+ t.Fatal("the context does not have a deadline")
+ }
+ delta := deadline.Sub(now)
+ // Note: super conservative check. Assume it may take up to five seconds
+ // for the code to create a context, which is totally unrealistic.
+ if delta < 40*time.Second {
+ t.Fatal("the deadline is too short")
+ }
+}

internal/enginelocate/stun.go

@@ -29,6 +29,7 @@ func stunNewClient(conn net.Conn) (stunClient, error) {
 
 func stunIPLookup(ctx context.Context, config stunConfig) (string, error) {
  config.Logger.Debugf("STUNIPLookup: start using %s", config.Endpoint)
+
  ip, err := func() (string, error) {
  dialer := config.Dialer
  if dialer == nil {
@@ -74,6 +75,7 @@ func stunIPLookup(ctx context.Context, config stunConfig) (string, error) {
  return model.DefaultProbeIP, ctx.Err()
  }
  }()
+
  if err != nil {
  config.Logger.Debugf("STUNIPLookup: failure using %s: %+v", config.Endpoint, err)
  return model.DefaultProbeIP, err

internal/engineresolver/doc.go

@@ -13,8 +13,8 @@
 // have any preferential ordering. The initial resolutions may be slower
 // if there are many issues with resolvers.
 //
-// The system resolver is given the lowest priority at the beginning
-// but it will of course be the most popular resolver if anything else
+// The system resolver is given intermediate priority at the beginning (i.e.,
+// 0.5) but it will of course be the most popular resolver if anything else
 // is failing us. (We will still occasionally probe for other working
 // resolvers and increase their score on success.)
 //

internal/engineresolver/resolver.go

@@ -109,6 +109,16 @@ func (r *Resolver) LookupHost(ctx context.Context, hostname string) ([]string, e
  r.logger().Infof("sessionresolver: skipping with proxy: %+v", e)
  continue // we cannot proxy this URL so ignore it
  }
+
+ // Hotfix: if the context has been canceled from the outside avoid
+ // doing a dnslookup, which would mark the resolver as not WAI.
+ //
+ // See https://github.com/ooni/probe/issues/2544
+ if err := ctx.Err(); err != nil {
+ me.Add(newErrWrapper(err, e.URL))
+ continue
+ }
+
  addrs, err := r.lookupHost(ctx, e, hostname)
  if err == nil {
  return addrs, nil

internal/engineresolver/resolver_test.go

@@ -34,7 +34,7 @@ func TestAddressWorks(t *testing.T) {
  }
 }
 
-func TestTypicalUsageWithFailure(t *testing.T) {
+func TestResolverLookupHostUsingACanceledContext(t *testing.T) {
  ctx, cancel := context.WithCancel(context.Background())
  cancel() // fail immediately
  reso := &Resolver{KVStore: &kvstore.Memory{}}
@@ -47,14 +47,15 @@ func TestTypicalUsageWithFailure(t *testing.T) {
  t.Fatal("cannot convert error")
  }
  for _, child := range me.Children {
+
  // net.DNSError does not include the underlying error
  // but just a string representing the error. This
  // means that we need to go down hunting what's the
  // real error that occurred and use more verbose code.
  {
  var ew *errWrapper
  if !errors.As(child, &ew) {
- t.Fatal("not an instance of errwrapper")
+ t.Fatalf("not an instance of errwrapper: '%v' [%T]", child, child)
  }
  var de *net.DNSError
  if errors.As(ew, &de) {
@@ -64,6 +65,7 @@ func TestTypicalUsageWithFailure(t *testing.T) {
  continue
  }
  }
+
  // otherwise just unwrap and check whether it's
  // a real context.Canceled error.
  if !errors.Is(child, context.Canceled) {
@@ -73,9 +75,22 @@ func TestTypicalUsageWithFailure(t *testing.T) {
  if addrs != nil {
  t.Fatal("expected nil here")
  }
- if len(reso.res) < 1 {
- t.Fatal("expected to see some resolvers here")
+
+ // Since https://github.com/ooni/probe-cli/pull/1351 we avoid
+ // constructing any resolver if we start running with a canceled context
+ // because of https://github.com/ooni/probe/issues/2544.
+ //
+ // In other words, as long as we see zero here we can be confident
+ // that we're not creating a resolver if the context has been canceled,
+ // which should imply we're not changing its score.
+ //
+ // Heavier refactoring of this package should probably more aggressively
+ // ensure that we're not changing the score, but for now this test
+ // is sufficient given that we are committing an hotfix.
+ if len(reso.res) != 0 {
+ t.Fatal("expected to see no resolvers here")
  }
+
  reso.CloseIdleConnections()
  if len(reso.res) != 0 {
  t.Fatal("expected to see no resolvers after CloseIdleConnections")

internal/engineresolver/resolvermaker.go

@@ -43,21 +43,29 @@ var allmakers = []*resolvermaker{{
 }}
 
 // allbyurl contains all the resolvermakers by URL
-var allbyurl map[string]*resolvermaker
+var allbyurl = resolverMakeInitialState()
 
-// init fills allbyname and gives a nonzero initial score
+// resolverMakeInitialState initializes the initial
+// state by giving a nonzero initial score
 // to all resolvers except for the system resolver. We set
-// the system resolver score to zero, so that it's less
+// the system resolver score to be 0.5, so that it's less
 // likely than other resolvers in this list.
-func init() {
- allbyurl = make(map[string]*resolvermaker)
+//
+// We used to set this value to 0, but this proved to
+// create issues when it was the only available resolver,
+// see https://github.com/ooni/probe/issues/2544.
+func resolverMakeInitialState() map[string]*resolvermaker {
+ output := make(map[string]*resolvermaker)
  rng := rand.New(rand.NewSource(time.Now().UnixNano()))
  for _, e := range allmakers {
- allbyurl[e.url] = e
+ output[e.url] = e
  if e.url != systemResolverURL {
  e.score = rng.Float64()
+ } else {
+ e.score = 0.5
  }
  }
+ return output
 }
 
 // logger returns the configured logger or a default

internal/engineresolver/resolvermaker_test.go

@@ -121,3 +121,19 @@ func TestGetResolverHTTP3(t *testing.T) {
  t.Fatal("expected true")
  }
 }
+
+func TestResolverMakeInitialState(t *testing.T) {
+ t.Run("the system resolver has a default score of 0.5", func(t *testing.T) {
+ state := resolverMakeInitialState()
+ var okay bool
+ for URL, entry := range state {
+ t.Logf("entry: %v %v", URL, *entry)
+ if URL == systemResolverURL && entry.score == 0.5 {
+ okay = true
+ }
+ }
+ if !okay {
+ t.Fatal("expected to see the system resolver with 0.5 as its score")
+ }
+ })
+}