Merge branch '18808-new-token-race'
[arvados.git] / lib / controller / localdb / login_oidc.go
1 // Copyright (C) The Arvados Authors. All rights reserved.
2 //
3 // SPDX-License-Identifier: AGPL-3.0
4
5 package localdb
6
7 import (
8         "bytes"
9         "context"
10         "crypto/hmac"
11         "crypto/sha256"
12         "database/sql"
13         "encoding/base64"
14         "errors"
15         "fmt"
16         "io"
17         "net/http"
18         "net/url"
19         "strings"
20         "sync"
21         "text/template"
22         "time"
23
24         "git.arvados.org/arvados.git/lib/controller/api"
25         "git.arvados.org/arvados.git/lib/controller/rpc"
26         "git.arvados.org/arvados.git/lib/ctrlctx"
27         "git.arvados.org/arvados.git/sdk/go/arvados"
28         "git.arvados.org/arvados.git/sdk/go/auth"
29         "git.arvados.org/arvados.git/sdk/go/ctxlog"
30         "git.arvados.org/arvados.git/sdk/go/httpserver"
31         "github.com/coreos/go-oidc"
32         lru "github.com/hashicorp/golang-lru"
33         "github.com/jmoiron/sqlx"
34         "github.com/lib/pq"
35         "github.com/sirupsen/logrus"
36         "golang.org/x/oauth2"
37         "google.golang.org/api/option"
38         "google.golang.org/api/people/v1"
39         "gopkg.in/square/go-jose.v2/jwt"
40 )
41
42 var (
43         tokenCacheSize        = 1000
44         tokenCacheNegativeTTL = time.Minute * 5
45         tokenCacheTTL         = time.Minute * 10
46         tokenCacheRaceWindow  = time.Minute
47         pqCodeUniqueViolation = pq.ErrorCode("23505")
48 )
49
50 type oidcLoginController struct {
51         Cluster                *arvados.Cluster
52         Parent                 *Conn
53         Issuer                 string // OIDC issuer URL, e.g., "https://accounts.google.com"
54         ClientID               string
55         ClientSecret           string
56         UseGooglePeopleAPI     bool              // Use Google People API to look up alternate email addresses
57         EmailClaim             string            // OpenID claim to use as email address; typically "email"
58         EmailVerifiedClaim     string            // If non-empty, ensure claim value is true before accepting EmailClaim; typically "email_verified"
59         UsernameClaim          string            // If non-empty, use as preferred username
60         AcceptAccessToken      bool              // Accept access tokens as API tokens
61         AcceptAccessTokenScope string            // If non-empty, don't accept access tokens as API tokens unless they contain this scope
62         AuthParams             map[string]string // Additional parameters to pass with authentication request
63
64         // override Google People API base URL for testing purposes
65         // (normally empty, set by google pkg to
66         // https://people.googleapis.com/)
67         peopleAPIBasePath string
68
69         provider   *oidc.Provider        // initialized by setup()
70         oauth2conf *oauth2.Config        // initialized by setup()
71         verifier   *oidc.IDTokenVerifier // initialized by setup()
72         mu         sync.Mutex            // protects setup()
73 }
74
75 // Initialize ctrl.provider and ctrl.oauth2conf.
76 func (ctrl *oidcLoginController) setup() error {
77         ctrl.mu.Lock()
78         defer ctrl.mu.Unlock()
79         if ctrl.provider != nil {
80                 // already set up
81                 return nil
82         }
83         redirURL, err := (*url.URL)(&ctrl.Cluster.Services.Controller.ExternalURL).Parse("/" + arvados.EndpointLogin.Path)
84         if err != nil {
85                 return fmt.Errorf("error making redirect URL: %s", err)
86         }
87         provider, err := oidc.NewProvider(context.Background(), ctrl.Issuer)
88         if err != nil {
89                 return err
90         }
91         ctrl.oauth2conf = &oauth2.Config{
92                 ClientID:     ctrl.ClientID,
93                 ClientSecret: ctrl.ClientSecret,
94                 Endpoint:     provider.Endpoint(),
95                 Scopes:       []string{oidc.ScopeOpenID, "profile", "email"},
96                 RedirectURL:  redirURL.String(),
97         }
98         ctrl.verifier = provider.Verifier(&oidc.Config{
99                 ClientID: ctrl.ClientID,
100         })
101         ctrl.provider = provider
102         return nil
103 }
104
105 func (ctrl *oidcLoginController) Logout(ctx context.Context, opts arvados.LogoutOptions) (arvados.LogoutResponse, error) {
106         return logout(ctx, ctrl.Cluster, opts)
107 }
108
109 func (ctrl *oidcLoginController) Login(ctx context.Context, opts arvados.LoginOptions) (arvados.LoginResponse, error) {
110         err := ctrl.setup()
111         if err != nil {
112                 return loginError(fmt.Errorf("error setting up OpenID Connect provider: %s", err))
113         }
114         if opts.State == "" {
115                 // Initiate OIDC sign-in.
116                 if opts.ReturnTo == "" {
117                         return loginError(errors.New("missing return_to parameter"))
118                 }
119                 state := ctrl.newOAuth2State([]byte(ctrl.Cluster.SystemRootToken), opts.Remote, opts.ReturnTo)
120                 var authparams []oauth2.AuthCodeOption
121                 for k, v := range ctrl.AuthParams {
122                         authparams = append(authparams, oauth2.SetAuthURLParam(k, v))
123                 }
124                 return arvados.LoginResponse{
125                         RedirectLocation: ctrl.oauth2conf.AuthCodeURL(state.String(), authparams...),
126                 }, nil
127         }
128         // Callback after OIDC sign-in.
129         state := ctrl.parseOAuth2State(opts.State)
130         if !state.verify([]byte(ctrl.Cluster.SystemRootToken)) {
131                 return loginError(errors.New("invalid OAuth2 state"))
132         }
133         oauth2Token, err := ctrl.oauth2conf.Exchange(ctx, opts.Code)
134         if err != nil {
135                 return loginError(fmt.Errorf("error in OAuth2 exchange: %s", err))
136         }
137         ctxlog.FromContext(ctx).WithField("oauth2Token", oauth2Token).Debug("oauth2 exchange succeeded")
138         rawIDToken, ok := oauth2Token.Extra("id_token").(string)
139         if !ok {
140                 return loginError(errors.New("error in OAuth2 exchange: no ID token in OAuth2 token"))
141         }
142         ctxlog.FromContext(ctx).WithField("rawIDToken", rawIDToken).Debug("oauth2Token provided ID token")
143         idToken, err := ctrl.verifier.Verify(ctx, rawIDToken)
144         if err != nil {
145                 return loginError(fmt.Errorf("error verifying ID token: %s", err))
146         }
147         authinfo, err := ctrl.getAuthInfo(ctx, oauth2Token, idToken)
148         if err != nil {
149                 return loginError(err)
150         }
151         ctxRoot := auth.NewContext(ctx, &auth.Credentials{Tokens: []string{ctrl.Cluster.SystemRootToken}})
152         return ctrl.Parent.UserSessionCreate(ctxRoot, rpc.UserSessionCreateOptions{
153                 ReturnTo: state.Remote + "," + state.ReturnTo,
154                 AuthInfo: *authinfo,
155         })
156 }
157
158 func (ctrl *oidcLoginController) UserAuthenticate(ctx context.Context, opts arvados.UserAuthenticateOptions) (arvados.APIClientAuthorization, error) {
159         return arvados.APIClientAuthorization{}, httpserver.ErrorWithStatus(errors.New("username/password authentication is not available"), http.StatusBadRequest)
160 }
161
162 // claimser can decode arbitrary claims into a map. Implemented by
163 // *oauth2.IDToken and *oauth2.UserInfo.
164 type claimser interface {
165         Claims(interface{}) error
166 }
167
168 // Use a person's token to get all of their email addresses, with the
169 // primary address at index 0. The provided defaultAddr is always
170 // included in the returned slice, and is used as the primary if the
171 // Google API does not indicate one.
172 func (ctrl *oidcLoginController) getAuthInfo(ctx context.Context, token *oauth2.Token, claimser claimser) (*rpc.UserSessionAuthInfo, error) {
173         var ret rpc.UserSessionAuthInfo
174         defer ctxlog.FromContext(ctx).WithField("ret", &ret).Debug("getAuthInfo returned")
175
176         var claims map[string]interface{}
177         if err := claimser.Claims(&claims); err != nil {
178                 return nil, fmt.Errorf("error extracting claims from token: %s", err)
179         } else if verified, _ := claims[ctrl.EmailVerifiedClaim].(bool); verified || ctrl.EmailVerifiedClaim == "" {
180                 // Fall back to this info if the People API call
181                 // (below) doesn't return a primary && verified email.
182                 givenName, _ := claims["given_name"].(string)
183                 familyName, _ := claims["family_name"].(string)
184                 if givenName != "" && familyName != "" {
185                         ret.FirstName = givenName
186                         ret.LastName = familyName
187                 } else {
188                         name, _ := claims["name"].(string)
189                         if names := strings.Fields(strings.TrimSpace(name)); len(names) > 1 {
190                                 ret.FirstName = strings.Join(names[0:len(names)-1], " ")
191                                 ret.LastName = names[len(names)-1]
192                         } else if len(names) > 0 {
193                                 ret.FirstName = names[0]
194                         }
195                 }
196                 ret.Email, _ = claims[ctrl.EmailClaim].(string)
197         }
198
199         if ctrl.UsernameClaim != "" {
200                 ret.Username, _ = claims[ctrl.UsernameClaim].(string)
201         }
202
203         if !ctrl.UseGooglePeopleAPI {
204                 if ret.Email == "" {
205                         return nil, fmt.Errorf("cannot log in with unverified email address %q", claims[ctrl.EmailClaim])
206                 }
207                 return &ret, nil
208         }
209
210         svc, err := people.NewService(ctx, option.WithTokenSource(ctrl.oauth2conf.TokenSource(ctx, token)), option.WithScopes(people.UserEmailsReadScope))
211         if err != nil {
212                 return nil, fmt.Errorf("error setting up People API: %s", err)
213         }
214         if p := ctrl.peopleAPIBasePath; p != "" {
215                 // Override normal API endpoint (for testing)
216                 svc.BasePath = p
217         }
218         person, err := people.NewPeopleService(svc).Get("people/me").PersonFields("emailAddresses,names").Do()
219         if err != nil {
220                 if strings.Contains(err.Error(), "Error 403") && strings.Contains(err.Error(), "accessNotConfigured") {
221                         // Log the original API error, but display
222                         // only the "fix config" advice to the user.
223                         ctxlog.FromContext(ctx).WithError(err).WithField("email", ret.Email).Error("People API is not enabled")
224                         return nil, errors.New("configuration error: Login.GoogleAlternateEmailAddresses is true, but Google People API is not enabled")
225                 }
226                 return nil, fmt.Errorf("error getting profile info from People API: %s", err)
227         }
228
229         // The given/family names returned by the People API and
230         // flagged as "primary" (if any) take precedence over the
231         // split-by-whitespace result from above.
232         for _, name := range person.Names {
233                 if name.Metadata != nil && name.Metadata.Primary {
234                         ret.FirstName = name.GivenName
235                         ret.LastName = name.FamilyName
236                         break
237                 }
238         }
239
240         altEmails := map[string]bool{}
241         if ret.Email != "" {
242                 altEmails[ret.Email] = true
243         }
244         for _, ea := range person.EmailAddresses {
245                 if ea.Metadata == nil || !ea.Metadata.Verified {
246                         ctxlog.FromContext(ctx).WithField("address", ea.Value).Info("skipping unverified email address")
247                         continue
248                 }
249                 altEmails[ea.Value] = true
250                 if ea.Metadata.Primary || ret.Email == "" {
251                         ret.Email = ea.Value
252                 }
253         }
254         if len(altEmails) == 0 {
255                 return nil, errors.New("cannot log in without a verified email address")
256         }
257         for ae := range altEmails {
258                 if ae == ret.Email {
259                         continue
260                 }
261                 ret.AlternateEmails = append(ret.AlternateEmails, ae)
262                 if ret.Username == "" {
263                         i := strings.Index(ae, "@")
264                         if i > 0 && strings.ToLower(ae[i+1:]) == strings.ToLower(ctrl.Cluster.Users.PreferDomainForUsername) {
265                                 ret.Username = strings.SplitN(ae[:i], "+", 2)[0]
266                         }
267                 }
268         }
269         return &ret, nil
270 }
271
272 func loginError(sendError error) (resp arvados.LoginResponse, err error) {
273         tmpl, err := template.New("error").Parse(`<h2>Login error:</h2><p>{{.}}</p>`)
274         if err != nil {
275                 return
276         }
277         err = tmpl.Execute(&resp.HTML, sendError.Error())
278         return
279 }
280
281 func (ctrl *oidcLoginController) newOAuth2State(key []byte, remote, returnTo string) oauth2State {
282         s := oauth2State{
283                 Time:     time.Now().Unix(),
284                 Remote:   remote,
285                 ReturnTo: returnTo,
286         }
287         s.HMAC = s.computeHMAC(key)
288         return s
289 }
290
291 type oauth2State struct {
292         HMAC     []byte // hash of other fields; see computeHMAC()
293         Time     int64  // creation time (unix timestamp)
294         Remote   string // remote cluster if requesting a salted token, otherwise blank
295         ReturnTo string // redirect target
296 }
297
298 func (ctrl *oidcLoginController) parseOAuth2State(encoded string) (s oauth2State) {
299         // Errors are not checked. If decoding/parsing fails, the
300         // token will be rejected by verify().
301         decoded, _ := base64.RawURLEncoding.DecodeString(encoded)
302         f := strings.Split(string(decoded), "\n")
303         if len(f) != 4 {
304                 return
305         }
306         fmt.Sscanf(f[0], "%x", &s.HMAC)
307         fmt.Sscanf(f[1], "%x", &s.Time)
308         fmt.Sscanf(f[2], "%s", &s.Remote)
309         fmt.Sscanf(f[3], "%s", &s.ReturnTo)
310         return
311 }
312
313 func (s oauth2State) verify(key []byte) bool {
314         if delta := time.Now().Unix() - s.Time; delta < 0 || delta > 300 {
315                 return false
316         }
317         return hmac.Equal(s.computeHMAC(key), s.HMAC)
318 }
319
320 func (s oauth2State) String() string {
321         var buf bytes.Buffer
322         enc := base64.NewEncoder(base64.RawURLEncoding, &buf)
323         fmt.Fprintf(enc, "%x\n%x\n%s\n%s", s.HMAC, s.Time, s.Remote, s.ReturnTo)
324         enc.Close()
325         return buf.String()
326 }
327
328 func (s oauth2State) computeHMAC(key []byte) []byte {
329         mac := hmac.New(sha256.New, key)
330         fmt.Fprintf(mac, "%x %s %s", s.Time, s.Remote, s.ReturnTo)
331         return mac.Sum(nil)
332 }
333
334 func OIDCAccessTokenAuthorizer(cluster *arvados.Cluster, getdb func(context.Context) (*sqlx.DB, error)) *oidcTokenAuthorizer {
335         // We want ctrl to be nil if the chosen controller is not a
336         // *oidcLoginController, so we can ignore the 2nd return value
337         // of this type cast.
338         ctrl, _ := NewConn(cluster).loginController.(*oidcLoginController)
339         cache, err := lru.New2Q(tokenCacheSize)
340         if err != nil {
341                 panic(err)
342         }
343         return &oidcTokenAuthorizer{
344                 ctrl:  ctrl,
345                 getdb: getdb,
346                 cache: cache,
347         }
348 }
349
350 type oidcTokenAuthorizer struct {
351         ctrl  *oidcLoginController
352         getdb func(context.Context) (*sqlx.DB, error)
353         cache *lru.TwoQueueCache
354 }
355
356 func (ta *oidcTokenAuthorizer) Middleware(w http.ResponseWriter, r *http.Request, next http.Handler) {
357         if ta.ctrl == nil {
358                 // Not using a compatible (OIDC) login controller.
359         } else if authhdr := strings.Split(r.Header.Get("Authorization"), " "); len(authhdr) > 1 && (authhdr[0] == "OAuth2" || authhdr[0] == "Bearer") {
360                 err := ta.registerToken(r.Context(), authhdr[1])
361                 if err != nil {
362                         http.Error(w, err.Error(), http.StatusInternalServerError)
363                         return
364                 }
365         }
366         next.ServeHTTP(w, r)
367 }
368
369 func (ta *oidcTokenAuthorizer) WrapCalls(origFunc api.RoutableFunc) api.RoutableFunc {
370         if ta.ctrl == nil {
371                 // Not using a compatible (OIDC) login controller.
372                 return origFunc
373         }
374         return func(ctx context.Context, opts interface{}) (_ interface{}, err error) {
375                 creds, ok := auth.FromContext(ctx)
376                 if !ok {
377                         return origFunc(ctx, opts)
378                 }
379                 // Check each token in the incoming request. If any
380                 // are valid OAuth2 access tokens, insert/update them
381                 // in the database so RailsAPI's auth code accepts
382                 // them.
383                 for _, tok := range creds.Tokens {
384                         err = ta.registerToken(ctx, tok)
385                         if err != nil {
386                                 return nil, err
387                         }
388                 }
389                 return origFunc(ctx, opts)
390         }
391 }
392
393 // registerToken checks whether tok is a valid OIDC Access Token and,
394 // if so, ensures that an api_client_authorizations row exists so that
395 // RailsAPI will accept it as an Arvados token.
396 func (ta *oidcTokenAuthorizer) registerToken(ctx context.Context, tok string) error {
397         if tok == ta.ctrl.Cluster.SystemRootToken || strings.HasPrefix(tok, "v2/") {
398                 return nil
399         }
400         if cached, hit := ta.cache.Get(tok); !hit {
401                 // Fall through to database and OIDC provider checks
402                 // below
403         } else if exp, ok := cached.(time.Time); ok {
404                 // cached negative result (value is expiry time)
405                 if time.Now().Before(exp) {
406                         return nil
407                 }
408                 ta.cache.Remove(tok)
409         } else {
410                 // cached positive result
411                 aca := cached.(arvados.APIClientAuthorization)
412                 var expiring bool
413                 if !aca.ExpiresAt.IsZero() {
414                         t := aca.ExpiresAt
415                         expiring = t.Before(time.Now().Add(time.Minute))
416                 }
417                 if !expiring {
418                         return nil
419                 }
420         }
421
422         db, err := ta.getdb(ctx)
423         if err != nil {
424                 return err
425         }
426         tx, err := db.Beginx()
427         if err != nil {
428                 return err
429         }
430         defer tx.Rollback()
431         ctx = ctrlctx.NewWithTransaction(ctx, tx)
432
433         // We use hmac-sha256(accesstoken,systemroottoken) as the
434         // secret part of our own token, and avoid storing the auth
435         // provider's real secret in our database.
436         mac := hmac.New(sha256.New, []byte(ta.ctrl.Cluster.SystemRootToken))
437         io.WriteString(mac, tok)
438         hmac := fmt.Sprintf("%x", mac.Sum(nil))
439
440         var expiring bool
441         err = tx.QueryRowContext(ctx, `select (expires_at is not null and expires_at - interval '1 minute' <= current_timestamp at time zone 'UTC') from api_client_authorizations where api_token=$1`, hmac).Scan(&expiring)
442         if err != nil && err != sql.ErrNoRows {
443                 return fmt.Errorf("database error while checking token: %w", err)
444         } else if err == nil && !expiring {
445                 // Token is already in the database as an Arvados
446                 // token, and isn't about to expire, so we can pass it
447                 // through to RailsAPI etc. regardless of whether it's
448                 // an OIDC access token.
449                 return nil
450         }
451         updating := err == nil
452
453         // Check whether the token is a valid OIDC access token. If
454         // so, swap it out for an Arvados token (creating/updating an
455         // api_client_authorizations row if needed) which downstream
456         // server components will accept.
457         err = ta.ctrl.setup()
458         if err != nil {
459                 return fmt.Errorf("error setting up OpenID Connect provider: %s", err)
460         }
461         if ok, err := ta.checkAccessTokenScope(ctx, tok); err != nil || !ok {
462                 ta.cache.Add(tok, time.Now().Add(tokenCacheNegativeTTL))
463                 return err
464         }
465         oauth2Token := &oauth2.Token{
466                 AccessToken: tok,
467         }
468         userinfo, err := ta.ctrl.provider.UserInfo(ctx, oauth2.StaticTokenSource(oauth2Token))
469         if err != nil {
470                 ta.cache.Add(tok, time.Now().Add(tokenCacheNegativeTTL))
471                 return nil
472         }
473         ctxlog.FromContext(ctx).WithField("userinfo", userinfo).Debug("(*oidcTokenAuthorizer)registerToken: got userinfo")
474         authinfo, err := ta.ctrl.getAuthInfo(ctx, oauth2Token, userinfo)
475         if err != nil {
476                 return err
477         }
478
479         // Expiry time for our token is one minute longer than our
480         // cache TTL, so we don't pass it through to RailsAPI just as
481         // it's expiring.
482         exp := time.Now().UTC().Add(tokenCacheTTL + tokenCacheRaceWindow)
483
484         if updating {
485                 _, err = tx.ExecContext(ctx, `update api_client_authorizations set expires_at=$1 where api_token=$2`, exp, hmac)
486                 if err != nil {
487                         return fmt.Errorf("error updating token expiry time: %w", err)
488                 }
489                 ctxlog.FromContext(ctx).WithField("HMAC", hmac).Debug("(*oidcTokenAuthorizer)registerToken: updated api_client_authorizations row")
490         } else {
491                 aca, err := ta.ctrl.Parent.CreateAPIClientAuthorization(ctx, ta.ctrl.Cluster.SystemRootToken, *authinfo)
492                 if err != nil {
493                         return err
494                 }
495                 _, err = tx.ExecContext(ctx, `savepoint upd`)
496                 if err != nil {
497                         return err
498                 }
499                 _, err = tx.ExecContext(ctx, `update api_client_authorizations set api_token=$1, expires_at=$2 where uuid=$3`, hmac, exp, aca.UUID)
500                 if e, ok := err.(*pq.Error); ok && e.Code == pqCodeUniqueViolation {
501                         // unique_violation, given that the above
502                         // query did not find a row with matching
503                         // api_token, means another thread/process
504                         // also received this same token and won the
505                         // race to insert it -- in which case this
506                         // thread doesn't need to update the database.
507                         // Discard the redundant row.
508                         _, err = tx.ExecContext(ctx, `rollback to savepoint upd`)
509                         if err != nil {
510                                 return err
511                         }
512                         _, err = tx.ExecContext(ctx, `delete from api_client_authorizations where uuid=$1`, aca.UUID)
513                         if err != nil {
514                                 return err
515                         }
516                         ctxlog.FromContext(ctx).WithField("HMAC", hmac).Debug("(*oidcTokenAuthorizer)registerToken: api_client_authorizations row inserted by another thread")
517                 } else if err != nil {
518                         ctxlog.FromContext(ctx).Errorf("%#v", err)
519                         return fmt.Errorf("error adding OIDC access token to database: %w", err)
520                 } else {
521                         ctxlog.FromContext(ctx).WithFields(logrus.Fields{"UUID": aca.UUID, "HMAC": hmac}).Debug("(*oidcTokenAuthorizer)registerToken: inserted api_client_authorizations row")
522                 }
523         }
524         err = tx.Commit()
525         if err != nil {
526                 return err
527         }
528         ta.cache.Add(tok, arvados.APIClientAuthorization{ExpiresAt: exp})
529         return nil
530 }
531
532 // Check that the provided access token is a JWT with the required
533 // scope. If it is a valid JWT but missing the required scope, we
534 // return a 403 error, otherwise true (acceptable as an API token) or
535 // false (pass through unmodified).
536 //
537 // Return false if configured not to accept access tokens at all.
538 //
539 // Note we don't check signature or expiry here. We are relying on the
540 // caller to verify those separately (e.g., by calling the UserInfo
541 // endpoint).
542 func (ta *oidcTokenAuthorizer) checkAccessTokenScope(ctx context.Context, tok string) (bool, error) {
543         if !ta.ctrl.AcceptAccessToken {
544                 return false, nil
545         } else if ta.ctrl.AcceptAccessTokenScope == "" {
546                 return true, nil
547         }
548         var claims struct {
549                 Scope string `json:"scope"`
550         }
551         if t, err := jwt.ParseSigned(tok); err != nil {
552                 ctxlog.FromContext(ctx).WithError(err).Debug("error parsing jwt")
553                 return false, nil
554         } else if err = t.UnsafeClaimsWithoutVerification(&claims); err != nil {
555                 ctxlog.FromContext(ctx).WithError(err).Debug("error extracting jwt claims")
556                 return false, nil
557         }
558         for _, s := range strings.Split(claims.Scope, " ") {
559                 if s == ta.ctrl.AcceptAccessTokenScope {
560                         return true, nil
561                 }
562         }
563         ctxlog.FromContext(ctx).WithFields(logrus.Fields{"have": claims.Scope, "need": ta.ctrl.AcceptAccessTokenScope}).Infof("unacceptable access token scope")
564         return false, httpserver.ErrorWithStatus(errors.New("unacceptable access token scope"), http.StatusUnauthorized)
565 }