diff --git a/device/device_flow.go b/device/device_flow.go index 5fe1767..f63a824 100644 --- a/device/device_flow.go +++ b/device/device_flow.go @@ -143,11 +143,44 @@ type WaitOptions struct { // GrantType overrides the default value specified by OAuth 2.0 Device Code. Optional. GrantType string - newPoller pollerFactory + newPoller pollerFactory + calculateTimeDriftRatioF func(tstart, tstop time.Time) float64 } +const ( + primaryIntervalMultiplier = 1.2 + secondaryIntervalMultiplier = 1.4 +) + // Wait polls the server at uri until authorization completes. func Wait(ctx context.Context, c httpClient, uri string, opts WaitOptions) (*api.AccessToken, error) { + // We know that in virtualised environments (e.g. WSL or VMs), the monotonic + // clock, which is the source of time measurements in Go, can run faster than + // real time. So, polling intervals should be adjusted to avoid falling into + // an endless loop of "slow_down" errors. See the following issue in cli/cli + // for more context (especially what's after this particular comment): + // - https://github.com/cli/cli/issues/9370#issuecomment-3759706125 + // + // We've observed ~10% faster ticking, thanks to community, but a chat with + // AI suggests it's typically between 5-15% on WSL, and can get up to 30% in + // worst cases. There are issues reported on the WSL repo, but I couldn't + // find any documented/conclusive data about this. + // + // See more: + // - https://github.com/microsoft/WSL/issues/12583 + // + // What we're doing here is to play on the safe side by applying a default + // 20% increase to the polling interval from the start. That is, instead of + // 5s, we begin with 6s waits. This should resolve most cases without any + // "slow_down" errors. However, upon receiving a "slow_down" from the OAuth + // server, we will bump the safety margin to 40%. This will eliminate further + // "slow_down"s in most cases. + // + // We also bail out if we receive more than two "slow_down" errors, as that's + // probably an indication of severe clock drift. In such cases, we'll check + // the time drift between the monotonic and the wall clocks and report it in + // the error message to hint the user at the root cause. + baseCheckInterval := time.Duration(opts.DeviceCode.Interval) * time.Second expiresIn := time.Duration(opts.DeviceCode.ExpiresIn) * time.Second grantType := opts.GrantType @@ -161,11 +194,23 @@ func Wait(ctx context.Context, c httpClient, uri string, opts WaitOptions) (*api } _, poll := makePoller(ctx, baseCheckInterval, expiresIn) + calculateTimeDriftRatioF := opts.calculateTimeDriftRatioF + if calculateTimeDriftRatioF == nil { + calculateTimeDriftRatioF = calculateTimeDriftRatio + } + + multiplier := primaryIntervalMultiplier + + var slowDowns int for { - if err := poll.Wait(); err != nil { + tstart := time.Now() + + if err := poll.Wait(multiplier); err != nil { return nil, err } + tstop := time.Now() + values := url.Values{ "client_id": {opts.ClientID}, "device_code": {opts.DeviceCode.DeviceCode}, @@ -199,6 +244,18 @@ func Wait(ctx context.Context, c httpClient, uri string, opts WaitOptions) (*api } if apiError.Code == "slow_down" { + slowDowns++ + + // Since we have already added the secondary safety multiplier upon + // receiving the first slow_down, getting a second one is a strong + // indication of a huge clock drift (+40% faster mono). More polling + // is just futile unless we apply some unreasonably large multiplier. + // So, we bail out and inform the user about the potential cause. + if slowDowns > 1 { + driftRatio := calculateTimeDriftRatioF(tstart, tstop) + return nil, fmt.Errorf("too many slow_down responses; detected clock drift of roughly %.0f%% between monotonic and wall clocks; please ensure your system clock is accurate", driftRatio*100) + } + // Based on the RFC spec, we must add 5 seconds to our current polling interval. // (See https://www.rfc-editor.org/rfc/rfc8628#section-3.5) newInterval := poll.GetInterval() + 5*time.Second @@ -213,9 +270,17 @@ func Wait(ctx context.Context, c httpClient, uri string, opts WaitOptions) (*api } poll.SetInterval(newInterval) + multiplier = secondaryIntervalMultiplier continue } return nil, err } } + +func calculateTimeDriftRatio(tstart, tstop time.Time) float64 { + elapsedWall := tstop.UnixNano() - tstart.UnixNano() + elapsedMono := tstop.Sub(tstart).Nanoseconds() + drift := elapsedMono - elapsedWall + return float64(drift) / float64(elapsedWall) +} diff --git a/device/device_flow_test.go b/device/device_flow_test.go index a24de11..327e288 100644 --- a/device/device_flow_test.go +++ b/device/device_flow_test.go @@ -297,6 +297,20 @@ func TestRequestCode(t *testing.T) { } func TestPollToken(t *testing.T) { + repeatPostArgs := func(count int, args postArgs) []postArgs { + posts := make([]postArgs, count) + for i := 0; i < count; i++ { + posts[i] = args + } + return posts + } + + assertWaitMultipliers := func(t *testing.T, want, got []float64) { + if !reflect.DeepEqual(got, want) { + t.Errorf("unexpected wait multipliers; got %#v, want %#v", got, want) + } + } + singletonFakePoller := func(maxWaits int) pollerFactory { var instance *fakePoller return func(ctx context.Context, interval, expiresIn time.Duration) (context.Context, poller) { @@ -312,6 +326,12 @@ func TestPollToken(t *testing.T) { } } + newCalculateTimeDriftRatioStub := func(driftRatio float64) func(tstart, tstop time.Time) float64 { + return func(_, _ time.Time) float64 { + return driftRatio + } + } + type args struct { http apiClient url string @@ -324,7 +344,6 @@ func TestPollToken(t *testing.T) { wantErr string assertFunc func(*testing.T, args) posts []postArgs - slept time.Duration }{ { name: "success", @@ -359,30 +378,21 @@ func TestPollToken(t *testing.T) { want: &api.AccessToken{ Token: "123abc", }, - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, + posts: repeatPostArgs(2, postArgs{ + url: "https://github.com/oauth", + params: url.Values{ + "client_id": {"CLIENT-ID"}, + "device_code": {"DEVIC"}, + "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, }, - }, + }), assertFunc: func(t *testing.T, a args) { // Get the created poller _, poller := a.opts.newPoller(context.Background(), 0, 0) if poller.(*fakePoller).updatedIntervals != nil { t.Errorf("no interval change expected = %v", poller.(*fakePoller).updatedIntervals) } + assertWaitMultipliers(t, []float64{1.2, 1.2}, poller.(*fakePoller).waitMultipliers) }, }, { @@ -423,127 +433,23 @@ func TestPollToken(t *testing.T) { want: &api.AccessToken{ Token: "123abc", }, - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - }, - assertFunc: func(t *testing.T, a args) { - // Get the created poller - _, poller := a.opts.newPoller(context.Background(), 0, 0) - got := poller.(*fakePoller).updatedIntervals - want := []time.Duration{22 * time.Second} - if !reflect.DeepEqual(got, want) { - t.Errorf("unexpected updated intervals = %v, want %v", got, want) - } - }, - }, - { - name: "success with multiple slow down, new interval in returned response", - args: args{ - http: apiClient{ - stubs: []apiStub{ - { - body: "error=authorization_pending", - status: 200, - contentType: "application/x-www-form-urlencoded; charset=utf-8", - }, - { - body: "error=slow_down&error_description=Too+many+requests+have+been+made+in+the+same+timeframe.&error_uri=https%3A%2F%2Fdocs.github.com&interval=22", - status: 200, - contentType: "application/x-www-form-urlencoded; charset=utf-8", - }, - { - body: "error=slow_down&error_description=Too+many+requests+have+been+made+in+the+same+timeframe.&error_uri=https%3A%2F%2Fdocs.github.com&interval=33", - status: 200, - contentType: "application/x-www-form-urlencoded; charset=utf-8", - }, - { - body: "access_token=123abc", - status: 200, - contentType: "application/x-www-form-urlencoded; charset=utf-8", - }, - }, - }, + posts: repeatPostArgs(3, postArgs{ url: "https://github.com/oauth", - opts: WaitOptions{ - ClientID: "CLIENT-ID", - DeviceCode: &CodeResponse{ - DeviceCode: "DEVIC", - UserCode: "123-abc", - VerificationURI: "http://verify.me", - ExpiresIn: 99, - Interval: 5, - }, - newPoller: singletonFakePoller(4), - }, - }, - want: &api.AccessToken{ - Token: "123abc", - }, - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, + params: url.Values{ + "client_id": {"CLIENT-ID"}, + "device_code": {"DEVIC"}, + "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - }, + }), assertFunc: func(t *testing.T, a args) { // Get the created poller _, poller := a.opts.newPoller(context.Background(), 0, 0) got := poller.(*fakePoller).updatedIntervals - want := []time.Duration{22 * time.Second, 33 * time.Second} + want := []time.Duration{22 * time.Second} if !reflect.DeepEqual(got, want) { t.Errorf("unexpected updated intervals = %v, want %v", got, want) } + assertWaitMultipliers(t, []float64{1.2, 1.2, 1.4}, poller.(*fakePoller).waitMultipliers) }, }, { @@ -584,32 +490,14 @@ func TestPollToken(t *testing.T) { want: &api.AccessToken{ Token: "123abc", }, - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, + posts: repeatPostArgs(3, postArgs{ + url: "https://github.com/oauth", + params: url.Values{ + "client_id": {"CLIENT-ID"}, + "device_code": {"DEVIC"}, + "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, }, - }, + }), assertFunc: func(t *testing.T, a args) { // Get the created poller _, poller := a.opts.newPoller(context.Background(), 0, 0) @@ -618,10 +506,11 @@ func TestPollToken(t *testing.T) { if !reflect.DeepEqual(got, want) { t.Errorf("unexpected updated intervals = %v, want %v", got, want) } + assertWaitMultipliers(t, []float64{1.2, 1.2, 1.4}, poller.(*fakePoller).waitMultipliers) }, }, { - name: "success with multiple slow down, no interval in returned response", + name: "failure with exceeding slow downs", args: args{ http: apiClient{ stubs: []apiStub{ @@ -640,11 +529,6 @@ func TestPollToken(t *testing.T) { status: 200, contentType: "application/x-www-form-urlencoded; charset=utf-8", }, - { - body: "access_token=123abc", - status: 200, - contentType: "application/x-www-form-urlencoded; charset=utf-8", - }, }, }, url: "https://github.com/oauth", @@ -657,54 +541,28 @@ func TestPollToken(t *testing.T) { ExpiresIn: 99, Interval: 5, }, - newPoller: singletonFakePoller(4), + newPoller: singletonFakePoller(3), + calculateTimeDriftRatioF: newCalculateTimeDriftRatioStub(0.10), }, }, - want: &api.AccessToken{ - Token: "123abc", - }, - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, + wantErr: `too many slow_down responses; detected clock drift of roughly 10% between monotonic and wall clocks; please ensure your system clock is accurate`, + posts: repeatPostArgs(3, postArgs{ + url: "https://github.com/oauth", + params: url.Values{ + "client_id": {"CLIENT-ID"}, + "device_code": {"DEVIC"}, + "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, }, - }, + }), assertFunc: func(t *testing.T, a args) { // Get the created poller _, poller := a.opts.newPoller(context.Background(), 0, 0) got := poller.(*fakePoller).updatedIntervals - want := []time.Duration{10 * time.Second, 15 * time.Second} + want := []time.Duration{10 * time.Second} if !reflect.DeepEqual(got, want) { t.Errorf("unexpected updated intervals = %v, want %v", got, want) } + assertWaitMultipliers(t, []float64{1.2, 1.2, 1.4}, poller.(*fakePoller).waitMultipliers) }, }, { @@ -780,24 +638,14 @@ func TestPollToken(t *testing.T) { }, }, wantErr: "context deadline exceeded", - posts: []postArgs{ - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, - }, - { - url: "https://github.com/oauth", - params: url.Values{ - "client_id": {"CLIENT-ID"}, - "device_code": {"DEVIC"}, - "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, - }, + posts: repeatPostArgs(2, postArgs{ + url: "https://github.com/oauth", + params: url.Values{ + "client_id": {"CLIENT-ID"}, + "device_code": {"DEVIC"}, + "grant_type": {"urn:ietf:params:oauth:grant-type:device_code"}, }, - }, + }), }, { name: "access denied", @@ -866,6 +714,7 @@ type fakePoller struct { maxWaits int count int updatedIntervals []time.Duration + waitMultipliers []float64 } func (p *fakePoller) GetInterval() time.Duration { @@ -877,10 +726,11 @@ func (p *fakePoller) SetInterval(d time.Duration) { p.updatedIntervals = append(p.updatedIntervals, d) } -func (p *fakePoller) Wait() error { +func (p *fakePoller) Wait(multiplier float64) error { if p.count == p.maxWaits { return errors.New("context deadline exceeded") } + p.waitMultipliers = append(p.waitMultipliers, multiplier) p.count++ return nil } diff --git a/device/poller.go b/device/poller.go index f74399a..a8362be 100644 --- a/device/poller.go +++ b/device/poller.go @@ -2,13 +2,14 @@ package device import ( "context" + "math" "time" ) type poller interface { GetInterval() time.Duration SetInterval(time.Duration) - Wait() error + Wait(multiplier float64) error Cancel() } @@ -37,8 +38,9 @@ func (p *intervalPoller) SetInterval(d time.Duration) { p.interval = d } -func (p *intervalPoller) Wait() error { - t := time.NewTimer(p.interval) +func (p *intervalPoller) Wait(multiplier float64) error { + interval := time.Duration(math.Ceil(float64(p.interval) * multiplier)) + t := time.NewTimer(interval) select { case <-p.ctx.Done(): t.Stop()