From 19a1704abd5d4a681626aa89d82b0a1d5799c07e Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Wed, 18 Mar 2020 13:04:12 -0700 Subject: [PATCH] netcheck: use best DERP server in past 5 minutes to avoid flip-flopping Fixes #162 --- netcheck/netcheck.go | 70 +++++++++++++++++++---- netcheck/netcheck_test.go | 115 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 175 insertions(+), 10 deletions(-) diff --git a/netcheck/netcheck.go b/netcheck/netcheck.go index 9e2ea7880..e7795d7ae 100644 --- a/netcheck/netcheck.go +++ b/netcheck/netcheck.go @@ -65,10 +65,14 @@ type Client struct { // Logf optionally specifies where to log to. Logf logger.Logf + // TimeNow, if non-nil, is used instead of time.Now. + TimeNow func() time.Time + GetSTUNConn4 func() STUNConn GetSTUNConn6 func() STUNConn - mu sync.Mutex // guards following + mu sync.Mutex // guards following + prev map[time.Time]*Report // some previous reports s4 *stunner.Stunner s6 *stunner.Stunner hairTX stun.TxID @@ -218,9 +222,8 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { ret = &Report{ DERPLatency: map[string]time.Duration{}, } - gotEP = map[string]string{} // server -> ipPort - gotEP4 string - bestDerpLatency time.Duration + gotEP = map[string]string{} // server -> ipPort + gotEP4 string ) anyV6 := func() bool { mu.Lock() @@ -266,11 +269,6 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { } } gotEP[server] = ipPort - - if ret.PreferredDERP == 0 || d < bestDerpLatency { - bestDerpLatency = d - ret.PreferredDERP = c.DERP.NodeIDOfSTUNServer(server) - } } var pc4, pc6 STUNConn @@ -409,5 +407,57 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { // the other side of the planet? Or try ICMP? (likely also // blocked?) - return ret.Clone(), nil + report := ret.Clone() + + c.addReportHistoryAndSetPreferredDERP(report) + + return report, nil +} + +func (c *Client) timeNow() time.Time { + if c.TimeNow != nil { + return c.TimeNow() + } + return time.Now() +} + +// addReportHistoryAndSetPreferredDERP adds r to the set of recent Reports +// and mutates r.PreferredDERP to contain the best recent one. +func (c *Client) addReportHistoryAndSetPreferredDERP(r *Report) { + c.mu.Lock() + defer c.mu.Unlock() + + if c.prev == nil { + c.prev = map[time.Time]*Report{} + } + now := c.timeNow() + c.prev[now] = r + + const maxAge = 5 * time.Minute + + // STUN host:port => its best recent latency in last maxAge + bestRecent := map[string]time.Duration{} + + for t, pr := range c.prev { + if now.Sub(t) > maxAge { + delete(c.prev, t) + continue + } + for hp, d := range pr.DERPLatency { + if bd, ok := bestRecent[hp]; !ok || d < bd { + bestRecent[hp] = d + } + } + } + + // Then, pick which currently-alive DERP server from the + // current report has the best latency over the past maxAge. + var bestAny time.Duration + for hp := range r.DERPLatency { + best := bestRecent[hp] + if r.PreferredDERP == 0 || best < bestAny { + bestAny = best + r.PreferredDERP = c.DERP.NodeIDOfSTUNServer(hp) + } + } } diff --git a/netcheck/netcheck_test.go b/netcheck/netcheck_test.go index b56a176d9..0f58e5f3e 100644 --- a/netcheck/netcheck_test.go +++ b/netcheck/netcheck_test.go @@ -6,6 +6,7 @@ package netcheck import ( "context" + "fmt" "net" "reflect" "strings" @@ -98,3 +99,117 @@ func TestWorksWhenUDPBlocked(t *testing.T) { t.Errorf("mismatch\n got: %+v\nwant: %+v\n", r, want) } } + +func TestAddReportHistoryAndSetPreferredDERP(t *testing.T) { + derps := derpmap.NewTestWorldWith( + &derpmap.Server{ + ID: 1, + STUN4: "d1", + }, + &derpmap.Server{ + ID: 2, + STUN4: "d2", + }, + &derpmap.Server{ + ID: 3, + STUN4: "d3", + }, + ) + // report returns a *Report from (DERP host, time.Duration)+ pairs. + report := func(a ...interface{}) *Report { + r := &Report{DERPLatency: map[string]time.Duration{}} + for i := 0; i < len(a); i += 2 { + k := a[i].(string) + switch v := a[i+1].(type) { + case time.Duration: + r.DERPLatency[k] = v + case int: + r.DERPLatency[k] = time.Second * time.Duration(v) + default: + panic(fmt.Sprintf("unexpected type %T", v)) + } + } + return r + } + type step struct { + after time.Duration + r *Report + } + tests := []struct { + name string + steps []step + wantDERP int // want PreferredDERP on final step + wantPrevLen int // wanted len(c.prev) + }{ + { + name: "first_reading", + steps: []step{ + {0, report("d1", 2, "d2", 3)}, + }, + wantPrevLen: 1, + wantDERP: 1, + }, + { + name: "with_two", + steps: []step{ + {0, report("d1", 2, "d2", 3)}, + {1 * time.Second, report("d1", 4, "d2", 3)}, + }, + wantPrevLen: 2, + wantDERP: 1, // t0's d1 of 2 is still best + }, + { + name: "but_now_d1_gone", + steps: []step{ + {0, report("d1", 2, "d2", 3)}, + {1 * time.Second, report("d1", 4, "d2", 3)}, + {2 * time.Second, report("d2", 3)}, + }, + wantPrevLen: 3, + wantDERP: 2, // only option + }, + { + name: "d1_is_back", + steps: []step{ + {0, report("d1", 2, "d2", 3)}, + {1 * time.Second, report("d1", 4, "d2", 3)}, + {2 * time.Second, report("d2", 3)}, + {3 * time.Second, report("d1", 4, "d2", 3)}, // same as 2 seconds ago + }, + wantPrevLen: 4, + wantDERP: 1, // t0's d1 of 2 is still best + }, + { + name: "things_clean_up", + steps: []step{ + {0, report("d1", 1, "d2", 2)}, + {1 * time.Second, report("d1", 1, "d2", 2)}, + {2 * time.Second, report("d1", 1, "d2", 2)}, + {3 * time.Second, report("d1", 1, "d2", 2)}, + {10 * time.Minute, report("d3", 3)}, + }, + wantPrevLen: 1, // t=[0123]s all gone. (too old, older than 10 min) + wantDERP: 3, // only option + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + fakeTime := time.Unix(123, 0) + c := &Client{ + DERP: derps, + TimeNow: func() time.Time { return fakeTime }, + } + for _, s := range tt.steps { + fakeTime = fakeTime.Add(s.after) + c.addReportHistoryAndSetPreferredDERP(s.r) + } + lastReport := tt.steps[len(tt.steps)-1].r + if got, want := len(c.prev), tt.wantPrevLen; got != want { + t.Errorf("len(prev) = %v; want %v", got, want) + } + if got, want := lastReport.PreferredDERP, tt.wantDERP; got != want { + t.Errorf("PreferredDERP = %v; want %v", got, want) + } + }) + } +}