From: Tom Clegg <tom@curii.com>
Date: Sun, 15 Jan 2023 22:02:42 +0000 (-0500)
Subject: 19907: Log when caching negative result for OIDC token check.
X-Git-Tag: 2.6.0~50^2~2
X-Git-Url: https://git.arvados.org/arvados.git/commitdiff_plain/ec7e22ab6ad88b0e5930e98760334dc0ef14a5be

19907: Log when caching negative result for OIDC token check.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@curii.com>
---

diff --git a/lib/controller/localdb/login_oidc.go b/lib/controller/localdb/login_oidc.go
index 05e5e243b9..b56f67aa33 100644
--- a/lib/controller/localdb/login_oidc.go
+++ b/lib/controller/localdb/login_oidc.go
@@ -462,6 +462,7 @@ func (ta *oidcTokenAuthorizer) registerToken(ctx context.Context, tok string) er
 		return fmt.Errorf("error setting up OpenID Connect provider: %s", err)
 	}
 	if ok, err := ta.checkAccessTokenScope(ctx, tok); err != nil || !ok {
+		// Note checkAccessTokenScope logs any interesting errors
 		ta.cache.Add(tok, time.Now().Add(tokenCacheNegativeTTL))
 		return err
 	}
@@ -470,6 +471,7 @@ func (ta *oidcTokenAuthorizer) registerToken(ctx context.Context, tok string) er
 	}
 	userinfo, err := ta.ctrl.provider.UserInfo(ctx, oauth2.StaticTokenSource(oauth2Token))
 	if err != nil {
+		ctxlog.FromContext(ctx).WithError(err).WithField("HMAC", hmac).Info("UserInfo failed (not an OIDC token?), caching negative result")
 		ta.cache.Add(tok, time.Now().Add(tokenCacheNegativeTTL))
 		return nil
 	}
@@ -563,6 +565,6 @@ func (ta *oidcTokenAuthorizer) checkAccessTokenScope(ctx context.Context, tok st
 			return true, nil
 		}
 	}
-	ctxlog.FromContext(ctx).WithFields(logrus.Fields{"have": claims.Scope, "need": ta.ctrl.AcceptAccessTokenScope}).Infof("unacceptable access token scope")
+	ctxlog.FromContext(ctx).WithFields(logrus.Fields{"have": claims.Scope, "need": ta.ctrl.AcceptAccessTokenScope}).Info("unacceptable access token scope")
 	return false, httpserver.ErrorWithStatus(errors.New("unacceptable access token scope"), http.StatusUnauthorized)
 }