feat: log rate-limited external auth token validation (#26754)

When `ValidateToken` keeps a token because the external auth validation
endpoint was rate-limited (a `403` with rate-limit headers or a `429`),
it returns `valid=true` without provider confirmation. Previously this
happened silently, so operators couldn't tell a provider-confirmed token
from one kept optimistically during a rate limit.

This adds a `Logger` to `externalauth.Config` and emits a `Warn` (with
`provider_id`, `provider_type`, `status_code`, and `reason`) on those
rate-limit branches. It also adds a
`coderd_oauth2_external_requests_rate_limited_total{name, source,
status_code}` counter, incremented in the instrumented round tripper
whenever a provider returns a rate-limited response. The rate-limit
detection is the shared `xhttp.IsRateLimited` (in `coderd/util/xhttp`),
used by both the tripper and `ValidateToken` so the metric and the
validation decision share one definition; no extra wiring is needed
since `ValidateToken` already routes through the instrumented client
with `source="ValidateToken"`.

One deliberate behavioral change rides along: rate-limit detection now
also recognizes the unprefixed `RateLimit-Remaining` header (GitLab, and
the IETF draft rate-limit headers), so a `403` with
`RateLimit-Remaining: 0` is treated as optimistically valid where it was
previously treated as revoked. All other valid/invalid decisions are
unchanged. `TestValidateToken` asserts the warning's fields on the
rate-limited cases and no warning for revocations, `401`, and confirmed
responses; `promoauth` and `xhttp` tests cover the detector and the new
counter.

<details>
<summary>Manual testing</summary>

The signals fire on the external-auth status check (`GET
/api/v2/external-auth/{id}`), which calls `ValidateToken`. To force a
rate-limited response, point a provider's `validate_url` at a mock that
returns the rate-limit shape:

1. Run a mock returning `429` on one path and `403` +
`X-RateLimit-Remaining: 0` on another.
2. Start `coder server` with `--prometheus-enable` and external auth
providers whose `validate_url` point at those mock paths (e.g.
`CODER_EXTERNAL_AUTH_0_VALIDATE_URL=http://127.0.0.1:5599/429`).
3. Create a stored link, either complete the OAuth flow, or insert a row
into `external_auth_links` with a future `oauth_expiry` (token contents
are irrelevant; the mock rejects regardless).
4. `curl` the status endpoint with a session token, then check:
- coderd logs for the `Warn` (`reason=status_code` for `429`,
`reason=rate_limit_headers` for `403`),
- the metrics endpoint for
`coderd_oauth2_external_requests_rate_limited_total{...,status_code="429"|"403"}`.

Notes: `scripts/testidp -429` only rate-limits `/oauth2/userinfo`, not
the `/external-auth-validate/...` path, so it does not exercise this;
use a mock `validate_url`. The default Prometheus port `2112` may
already be taken on dogfood workspaces, set `CODER_PROMETHEUS_ADDRESS`
to a free port.

</details>

🤖 Generated with the help of Coder Agents on behalf of @jscottmiller.
This commit is contained in:
J. Scott Miller
2026-08-10 14:43:16 -05:00
committed by GitHub
parent bd693ad4ae
commit 66b065323b
10 changed files with 435 additions and 48 deletions
+63 -28
View File
@@ -12,6 +12,7 @@ import (
"regexp"
"strconv"
"strings"
"sync"
"time"
"github.com/dustin/go-humanize"
@@ -22,11 +23,13 @@ import (
"golang.org/x/sync/singleflight"
"golang.org/x/xerrors"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/database/dbtime"
"github.com/coder/coder/v2/coderd/externalauth/gitprovider"
"github.com/coder/coder/v2/coderd/promoauth"
"github.com/coder/coder/v2/coderd/util/slice"
"github.com/coder/coder/v2/coderd/util/xhttp"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/retry"
)
@@ -63,6 +66,10 @@ type SingleflightGroup interface {
// Config is used for authentication for Git operations.
type Config struct {
promoauth.InstrumentedOAuth2Config
// Logs rate-limited validation warnings. Zero value discards output.
Logger slog.Logger
// rateLimitLogThrottle throttles rate-limited validation warnings.
rateLimitLogThrottle logThrottle
// ID is a unique identifier for the authenticator.
ID string
// Type is the type of provider.
@@ -520,7 +527,8 @@ func (c *Config) ValidateToken(ctx context.Context, link *oauth2.Token) (bool, *
// validation endpoint is rejecting for a transient reason.
// Treat it as optimistically valid rather than discarding
// the token.
if isRateLimited(res) {
if xhttp.IsRateLimited(res) {
c.logRateLimitedValidation(ctx, http.StatusForbidden, "rate_limit_headers")
return true, nil, nil
}
// No rate-limit headers: genuine token revocation or
@@ -532,6 +540,7 @@ func (c *Config) ValidateToken(ctx context.Context, link *oauth2.Token) (bool, *
// Treat 429 the same as a rate-limited 403: optimistically
// valid. The token was likely just issued by the IDP; the
// validation endpoint is transiently overloaded.
c.logRateLimitedValidation(ctx, http.StatusTooManyRequests, "status_code")
return true, nil, nil
case http.StatusOK:
@@ -560,6 +569,57 @@ func (c *Config) ValidateToken(ctx context.Context, link *oauth2.Token) (bool, *
return true, user, nil
}
// rateLimitLogInterval is the minimum time between rate-limited validation
// warnings emitted per Config.
const rateLimitLogInterval = time.Minute
// logRateLimitedValidation warns that a token was kept valid without
// provider confirmation due to a rate-limited response. At most one
// warning is emitted per Config per rateLimitLogInterval; the line
// carries the number of occurrences suppressed since the previous one.
func (c *Config) logRateLimitedValidation(ctx context.Context, statusCode int, reason string) {
suppressed, ok := c.rateLimitLogThrottle.shouldLog(time.Now(), rateLimitLogInterval)
if !ok {
return
}
c.Logger.Warn(ctx, "external auth validation endpoint rate-limited; keeping token without provider confirmation",
slog.F("status_code", statusCode),
slog.F("reason", reason),
slog.F("suppressed", suppressed),
)
}
// logThrottle allows one event per interval and counts the events
// suppressed in between. Safe for concurrent use; the zero value is
// ready for use.
type logThrottle struct {
mu sync.Mutex
lastLog time.Time
suppressed int64
}
// shouldLog reports whether an event occurring at now may be logged,
// allowing at most one event per interval. When it returns true, it also
// returns the number of events suppressed since the last allowed one;
// if two or more intervals have elapsed, the stale count is discarded
// and zero is returned.
func (t *logThrottle) shouldLog(now time.Time, interval time.Duration) (int64, bool) {
t.mu.Lock()
defer t.mu.Unlock()
sinceLast := now.Sub(t.lastLog)
if sinceLast < interval {
t.suppressed++
return 0, false
}
n := t.suppressed
if sinceLast >= 2*interval {
n = 0
}
t.suppressed = 0
t.lastLog = now
return n, true
}
type AppInstallation struct {
ID int
// Login is the username of the installation.
@@ -852,7 +912,7 @@ func (c *DeviceAuth) formatDeviceCodeURL() (string, error) {
// ConvertConfig converts the SDK configuration entry format
// to the parsed and ready-to-consume in coderd provider type.
func ConvertConfig(instrument *promoauth.Factory, entries []codersdk.ExternalAuthConfig, accessURL *url.URL) ([]*Config, error) {
func ConvertConfig(logger slog.Logger, instrument *promoauth.Factory, entries []codersdk.ExternalAuthConfig, accessURL *url.URL) ([]*Config, error) {
ids := map[string]struct{}{}
configs := []*Config{}
for _, entry := range entries {
@@ -936,6 +996,7 @@ func ConvertConfig(instrument *promoauth.Factory, entries []codersdk.ExternalAut
cfg := &Config{
InstrumentedOAuth2Config: instrumented,
Logger: logger.Named("externalauth").With(slog.F("provider_id", entry.ID), slog.F("provider_type", entry.Type)),
ID: entry.ID,
ClientID: entry.ClientID,
ClientSecret: entry.ClientSecret,
@@ -1483,32 +1544,6 @@ func IsGithubDotComURL(str string) bool {
return ghURL.Host == "github.com"
}
// isRateLimited checks whether an HTTP response indicates a rate
// limit rather than a genuine authorization failure. It returns
// true if either X-RateLimit-Remaining is "0" (primary) or
// Retry-After is present (secondary). OR logic is intentional:
// GitHub secondary limits can include Retry-After without
// X-RateLimit-Remaining: 0 (the remaining count tracks the
// primary quota, not secondary).
//
// Does not catch every secondary rate limit. GitHub can return
// 403 with positive X-RateLimit-Remaining and no Retry-After.
// Reliable detection of those requires response body inspection.
// Missing them is not a regression since all 403s were previously
// treated as invalid.
func isRateLimited(resp *http.Response) bool {
if resp == nil {
return false
}
if resp.Header.Get("Retry-After") != "" {
return true
}
if resp.Header.Get("X-RateLimit-Remaining") == "0" {
return true
}
return false
}
// isFailedRefresh returns true if the error returned by the refresh attempt
// is due to a failed refresh. The failure being the refresh token itself.
// If this returns true, no amount of retries will fix the issue.
@@ -1,7 +1,12 @@
package externalauth
import (
"bytes"
"context"
"encoding/json"
"net/http"
"sync"
"sync/atomic"
"testing"
"time"
@@ -9,10 +14,97 @@ import (
"github.com/stretchr/testify/require"
"golang.org/x/oauth2"
"cdr.dev/slog/v3"
"cdr.dev/slog/v3/sloggers/slogjson"
"github.com/coder/coder/v2/coderd/promoauth"
"github.com/coder/coder/v2/codersdk"
)
func TestLogThrottle(t *testing.T) {
t.Parallel()
const interval = time.Minute
var th logThrottle
start := time.Now()
suppressed, ok := th.shouldLog(start, interval)
require.True(t, ok, "the first event should log")
require.EqualValues(t, 0, suppressed)
for i := range 3 {
_, ok := th.shouldLog(start.Add(time.Duration(i+1)*time.Second), interval)
require.False(t, ok, "events within the interval should be suppressed")
}
_, ok = th.shouldLog(start.Add(interval-time.Millisecond), interval)
require.False(t, ok, "an event just inside the interval should be suppressed")
suppressed, ok = th.shouldLog(start.Add(interval), interval)
require.True(t, ok, "the first event after the interval should log")
require.EqualValues(t, 4, suppressed, "suppressed should count events since the last log")
suppressed, ok = th.shouldLog(start.Add(2*interval), interval)
require.True(t, ok)
require.EqualValues(t, 0, suppressed, "suppressed should reset after each log")
// Suppress one event, then let more than two intervals elapse.
_, ok = th.shouldLog(start.Add(2*interval+time.Second), interval)
require.False(t, ok)
suppressed, ok = th.shouldLog(start.Add(5*interval), interval)
require.True(t, ok)
require.EqualValues(t, 0, suppressed, "counts from a burst that ended more than an interval ago are discarded")
}
func TestLogThrottleConcurrent(t *testing.T) {
t.Parallel()
const (
interval = time.Minute
events = 32
)
var th logThrottle
now := time.Now()
var (
wg sync.WaitGroup
logged atomic.Int64
)
for range events {
wg.Go(func() {
if _, ok := th.shouldLog(now, interval); ok {
logged.Add(1)
}
})
}
wg.Wait()
require.EqualValues(t, 1, logged.Load(), "exactly one concurrent event should log")
suppressed, ok := th.shouldLog(now.Add(interval), interval)
require.True(t, ok)
require.EqualValues(t, events-1, suppressed, "every other concurrent event should be counted")
}
// TestLogRateLimitedValidationSuppressed verifies the suppressed count
// reaches the emitted log line.
func TestLogRateLimitedValidationSuppressed(t *testing.T) {
t.Parallel()
logs := &bytes.Buffer{}
c := &Config{Logger: slog.Make(slogjson.Sink(logs)).Leveled(slog.LevelDebug)}
c.rateLimitLogThrottle.lastLog = time.Now().Add(-rateLimitLogInterval - time.Second)
c.rateLimitLogThrottle.suppressed = 5
c.logRateLimitedValidation(context.Background(), http.StatusTooManyRequests, "status_code")
var entry struct {
Fields struct {
Suppressed *int64 `json:"suppressed"`
} `json:"fields"`
}
require.NoError(t, json.Unmarshal(logs.Bytes(), &entry))
require.NotNil(t, entry.Fields.Suppressed, "the log line should carry the suppressed field")
require.EqualValues(t, 5, *entry.Fields.Suppressed)
}
func TestGitlabDefaults(t *testing.T) {
t.Parallel()
+116 -20
View File
@@ -28,6 +28,8 @@ import (
"golang.org/x/sync/singleflight"
"golang.org/x/xerrors"
"cdr.dev/slog/v3"
"cdr.dev/slog/v3/sloggers/slogjson"
"github.com/coder/coder/v2/coderd"
"github.com/coder/coder/v2/coderd/coderdtest/oidctest"
"github.com/coder/coder/v2/coderd/database"
@@ -1074,7 +1076,7 @@ func TestRefreshTokenWithScopes(t *testing.T) {
newConfig := func(t *testing.T, scopes []string) *externalauth.Config {
t.Helper()
instrument := promoauth.NewFactory(prometheus.NewRegistry())
configs, err := externalauth.ConvertConfig(instrument, []codersdk.ExternalAuthConfig{{
configs, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, []codersdk.ExternalAuthConfig{{
ID: "test",
Type: codersdk.EnhancedExternalAuthProviderAzureDevopsEntra.String(),
ClientID: "id",
@@ -1192,16 +1194,67 @@ func TestValidateToken(t *testing.T) {
// (X-RateLimit-Remaining, Retry-After) that the FakeIDP's
// WithDynamicUserInfo hook does not expose.
newValidateConfig := func(t *testing.T, validateURL string) *externalauth.Config {
const providerName = "test-validate"
// newLoggedConfig returns a config plus the buffer capturing its logs.
newLoggedConfig := func(t *testing.T, validateURL string) (*externalauth.Config, *bytes.Buffer) {
t.Helper()
f := promoauth.NewFactory(prometheus.NewRegistry())
return &externalauth.Config{
InstrumentedOAuth2Config: f.New("test-validate", &oauth2.Config{}),
ID: "test-validate",
Type: codersdk.EnhancedExternalAuthProviderGitHub.String(),
ValidateURL: validateURL,
RefreshGroup: new(singleflight.Group),
logs := &bytes.Buffer{}
logger := slog.Make(slogjson.Sink(logs)).Leveled(slog.LevelDebug)
// ConvertConfig wires the named logger as production does.
configs, err := externalauth.ConvertConfig(logger, f, []codersdk.ExternalAuthConfig{{
ID: providerName,
Type: codersdk.EnhancedExternalAuthProviderGitHub.String(),
ClientID: "id",
ClientSecret: "secret",
ValidateURL: validateURL,
}}, &url.URL{})
require.NoError(t, err)
return configs[0], logs
}
type logEntry struct {
Level string `json:"level"`
Msg string `json:"msg"`
Fields struct {
ProviderType string `json:"provider_type"`
StatusCode int `json:"status_code"`
Reason string `json:"reason"`
Suppressed int64 `json:"suppressed"`
} `json:"fields"`
}
// rateLimitWarnings returns only the rate-limited-validation warnings.
rateLimitWarnings := func(t *testing.T, logs string) []logEntry {
t.Helper()
var out []logEntry
for _, line := range strings.Split(strings.TrimSpace(logs), "\n") {
if line == "" {
continue
}
var entry logEntry
require.NoError(t, json.Unmarshal([]byte(line), &entry))
if strings.Contains(entry.Msg, "validation endpoint rate-limited") {
out = append(out, entry)
}
}
return out
}
// requireRateLimitLog asserts exactly one WARN line with the given
// status code and reason.
requireRateLimitLog := func(t *testing.T, logs string, wantStatus int, wantReason string) {
t.Helper()
warnings := rateLimitWarnings(t, logs)
require.Len(t, warnings, 1, "expected exactly one rate-limit warning, got: %q", logs)
entry := warnings[0]
assert.Equal(t, "WARN", entry.Level)
assert.Equal(t, codersdk.EnhancedExternalAuthProviderGitHub.String(), entry.Fields.ProviderType)
assert.Equal(t, wantStatus, entry.Fields.StatusCode)
assert.Equal(t, wantReason, entry.Fields.Reason)
assert.EqualValues(t, 0, entry.Fields.Suppressed,
"a lone warning should report no suppressed occurrences")
}
newToken := func() *oauth2.Token {
@@ -1234,12 +1287,13 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, logs := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.True(t, valid, "rate-limited 403 should be treated as optimistically valid")
assert.Nil(t, user)
requireRateLimitLog(t, logs.String(), http.StatusForbidden, "rate_limit_headers")
})
// RetryAfter: 403 with Retry-After header (secondary rate limit)
@@ -1253,12 +1307,13 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, logs := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.True(t, valid, "rate-limited 403 with Retry-After should be optimistically valid")
assert.Nil(t, user)
requireRateLimitLog(t, logs.String(), http.StatusForbidden, "rate_limit_headers")
})
// Forbidden_WithNonZeroRateLimit: a 403 with non-zero
@@ -1275,12 +1330,13 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, logs := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.False(t, valid, "403 with non-zero rate limit remaining means token is invalid")
assert.Nil(t, user)
assert.Empty(t, rateLimitWarnings(t, logs.String()), "a genuine revocation should not log a rate-limit warning")
})
// Forbidden_NoRateLimitHeaders: a plain 403 without rate-limit
@@ -1293,12 +1349,13 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, logs := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.False(t, valid, "plain 403 without rate-limit headers means token is invalid")
assert.Nil(t, user)
assert.Empty(t, rateLimitWarnings(t, logs.String()), "a plain 403 should not log a rate-limit warning")
})
// Unauthorized: 401 is always a token revocation regardless of
@@ -1311,7 +1368,7 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, _ := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
@@ -1332,7 +1389,7 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, _ := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
@@ -1351,12 +1408,50 @@ func TestValidateToken(t *testing.T) {
}))
t.Cleanup(srv.Close)
config := newValidateConfig(t, srv.URL)
config, logs := newLoggedConfig(t, srv.URL)
valid, user, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.True(t, valid, "429 should be treated as optimistically valid")
assert.Nil(t, user)
requireRateLimitLog(t, logs.String(), http.StatusTooManyRequests, "status_code")
})
// Throttled: repeated rate-limited validations within the throttle
// interval emit a single warning.
t.Run("Throttled", func(t *testing.T) {
t.Parallel()
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusTooManyRequests)
}))
t.Cleanup(srv.Close)
config, logs := newLoggedConfig(t, srv.URL)
ctx := newValidateCtx(t)
for range 3 {
valid, _, err := config.ValidateToken(ctx, newToken())
require.NoError(t, err)
assert.True(t, valid)
}
requireRateLimitLog(t, logs.String(), http.StatusTooManyRequests, "status_code")
})
t.Run("Confirmed", func(t *testing.T) {
t.Parallel()
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
_, _ = w.Write([]byte(`{}`))
}))
t.Cleanup(srv.Close)
config, logs := newLoggedConfig(t, srv.URL)
valid, _, err := config.ValidateToken(newValidateCtx(t), newToken())
require.NoError(t, err)
assert.True(t, valid, "200 means the provider confirmed the token")
assert.Empty(t, rateLimitWarnings(t, logs.String()), "a confirmed validation should not log a rate-limit warning")
})
}
@@ -1513,7 +1608,7 @@ func TestExchangeWithClientSecret(t *testing.T) {
instrument := promoauth.NewFactory(prometheus.NewRegistry())
// This ensures a provider that requires the custom
// client secret exchange works.
configs, err := externalauth.ConvertConfig(instrument, []codersdk.ExternalAuthConfig{{
configs, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, []codersdk.ExternalAuthConfig{{
// JFrog just happens to require this custom type.
Type: codersdk.EnhancedExternalAuthProviderJFrog.String(),
@@ -1645,7 +1740,7 @@ func TestConvertYAML(t *testing.T) {
}} {
t.Run(tc.Name, func(t *testing.T) {
t.Parallel()
output, err := externalauth.ConvertConfig(instrument, tc.Input, &url.URL{})
output, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, tc.Input, &url.URL{})
if tc.Error != "" {
require.Error(t, err)
require.Contains(t, err.Error(), tc.Error)
@@ -1657,7 +1752,7 @@ func TestConvertYAML(t *testing.T) {
t.Run("CustomScopesAndEndpoint", func(t *testing.T) {
t.Parallel()
config, err := externalauth.ConvertConfig(instrument, []codersdk.ExternalAuthConfig{{
config, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, []codersdk.ExternalAuthConfig{{
Type: string(codersdk.EnhancedExternalAuthProviderGitLab),
ClientID: "id",
ClientSecret: "secret",
@@ -1671,7 +1766,7 @@ func TestConvertYAML(t *testing.T) {
t.Run("RevokeTimeoutSet", func(t *testing.T) {
t.Parallel()
configs, err := externalauth.ConvertConfig(instrument, []codersdk.ExternalAuthConfig{{
configs, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, []codersdk.ExternalAuthConfig{{
Type: string(codersdk.EnhancedExternalAuthProviderGitLab),
ClientID: "id",
ClientSecret: "secret",
@@ -1682,7 +1777,7 @@ func TestConvertYAML(t *testing.T) {
t.Run("SelfHostedGitLabAPIBaseURL", func(t *testing.T) {
t.Parallel()
configs, err := externalauth.ConvertConfig(instrument, []codersdk.ExternalAuthConfig{{
configs, err := externalauth.ConvertConfig(testutil.Logger(t), instrument, []codersdk.ExternalAuthConfig{{
Type: string(codersdk.EnhancedExternalAuthProviderGitLab),
ClientID: "id",
ClientSecret: "secret",
@@ -1861,6 +1956,7 @@ func TestApplyDefaultsToConfig_CaseInsensitive(t *testing.T) {
t.Run(tc.Name, func(t *testing.T) {
t.Parallel()
configs, err := externalauth.ConvertConfig(
testutil.Logger(t),
instrument,
[]codersdk.ExternalAuthConfig{{
Type: tc.Type,