Auth proxy: Ignore stale cache entries (#23979)

* Auth proxy: Retry without cache if failing to get user

pkg/bus/bus.go

@@ -174,20 +174,20 @@ func (b *InProcBus) AddEventListener(handler HandlerFunc) {
 	b.listeners[eventName] = append(b.listeners[eventName], handler)
 }
 
-// AddHandler attach a handler function to the global bus
+// AddHandler attaches a handler function to the global bus.
-// Package level function
+// Package level function.
 func AddHandler(implName string, handler HandlerFunc) {
 	globalBus.AddHandler(handler)
 }
 
-// AddHandlerCtx attach a handler function to the global bus context
+// AddHandlerCtx attaches a handler function to the global bus context.
-// Package level functions
+// Package level function.
 func AddHandlerCtx(implName string, handler HandlerFunc) {
 	globalBus.AddHandlerCtx(handler)
 }
 
-// AddEventListener attach a handler function to the event listener
+// AddEventListener attaches a handler function to the event listener.
-// Package level functions
+// Package level function.
 func AddEventListener(handler HandlerFunc) {
 	globalBus.AddEventListener(handler)
 }

pkg/middleware/auth_proxy.go

@@ -1,6 +1,8 @@
 package middleware
 
 import (
+	"errors"
+
 	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/infra/remotecache"
 	authproxy "github.com/grafana/grafana/pkg/middleware/auth_proxy"
@@ -10,6 +12,18 @@ import (
 
 var header = setting.AuthProxyHeaderName
 
+func logUserIn(auth *authproxy.AuthProxy, username string, logger log.Logger, ignoreCache bool) (int64, *authproxy.Error) {
+	logger.Debug("Trying to log user in", "username", username, "ignoreCache", ignoreCache)
+	// Try to log in user via various providers
+	id, err := auth.Login(logger, ignoreCache)
+	if err != nil {
+		logger.Error("Failed to login", "username", username, "message", err.Error(), "error", err.DetailsError,
+			"ignoreCache", ignoreCache)
+		return 0, err
+	}
+	return id, nil
+}
+
 func initContextWithAuthProxy(store *remotecache.RemoteCache, ctx *models.ReqContext, orgID int64) bool {
 	username := ctx.Req.Header.Get(header)
 	auth := authproxy.New(&authproxy.Options{
@@ -25,7 +39,7 @@ func initContextWithAuthProxy(store *remotecache.RemoteCache, ctx *models.ReqCon
 		return false
 	}
 
-	// If the there is no header - we can't move forward
+	// If there is no header - we can't move forward
 	if !auth.HasHeader() {
 		return false
 	}
@@ -41,37 +55,47 @@ func initContextWithAuthProxy(store *remotecache.RemoteCache, ctx *models.ReqCon
 		return true
 	}
 
-	// Try to log in user from various providers
+	id, err := logUserIn(auth, username, logger, false)
-	id, err := auth.Login()
 	if err != nil {
-		logger.Error(
-			"Failed to login",
-			"username", username,
-			"message", err.Error(),
-			"error", err.DetailsError,
-		)
 		ctx.Handle(407, err.Error(), err.DetailsError)
 		return true
 	}
 
-	// Get full user info
+	logger.Debug("Got user ID, getting full user info", "userID", id)
+
 	user, err := auth.GetSignedUser(id)
 	if err != nil {
-		logger.Error(
+		// The reason we couldn't find the user corresponding to the ID might be that the ID was found from a stale
-			"Failed to get signed user",
+		// cache entry. For example, if a user is deleted via the API, corresponding cache entries aren't invalidated
-			"username", username,
+		// because cache keys are computed from request header values and not just the user ID. Meaning that
-			"message", err.Error(),
+		// we can't easily derive cache keys to invalidate when deleting a user. To work around this, we try to
-			"error", err.DetailsError,
+		// log the user in again without the cache.
-		)
+		logger.Debug("Failed to get user info given ID, retrying without cache", "userID", id)
+		if err := auth.RemoveUserFromCache(logger); err != nil {
+			if !errors.Is(err, remotecache.ErrCacheItemNotFound) {
+				logger.Error("Got unexpected error when removing user from auth cache", "error", err)
+			}
+		}
+		id, err = logUserIn(auth, username, logger, true)
+		if err != nil {
 			ctx.Handle(407, err.Error(), err.DetailsError)
 			return true
 		}
 
+		user, err = auth.GetSignedUser(id)
+		if err != nil {
+			ctx.Handle(407, err.Error(), err.DetailsError)
+			return true
+		}
+	}
+
+	logger.Debug("Successfully got user info", "userID", user.UserId, "username", user.Login)
+
 	// Add user info to context
 	ctx.SignedInUser = user
 	ctx.IsSignedIn = true
 
-	// Remember user data it in cache
+	// Remember user data in cache
 	if err := auth.Remember(id); err != nil {
 		logger.Error(
 			"Failed to store user in cache",

pkg/middleware/auth_proxy/auth_proxy.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/grafana/grafana/pkg/bus"
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/infra/remotecache"
 	"github.com/grafana/grafana/pkg/models"
 	"github.com/grafana/grafana/pkg/services/ldap"
@@ -168,27 +169,23 @@ func (auth *AuthProxy) getKey() string {
 	return fmt.Sprintf(CachePrefix, hashedKey)
 }
 
-// Login logs in user id with whatever means possible
+// Login logs in user ID by whatever means possible.
-func (auth *AuthProxy) Login() (int64, *Error) {
+func (auth *AuthProxy) Login(logger log.Logger, ignoreCache bool) (int64, *Error) {
-
+	if !ignoreCache {
-	id, _ := auth.GetUserViaCache()
-	if id != 0 {
 		// Error here means absent cache - we don't need to handle that
+		id, err := auth.GetUserViaCache(logger)
+		if err == nil && id != 0 {
 			return id, nil
 		}
+	}
 
 	if isLDAPEnabled() {
 		id, err := auth.LoginViaLDAP()
-
-		if err == ldap.ErrInvalidCredentials {
-			return 0, newError(
-				"Proxy authentication required",
-				ldap.ErrInvalidCredentials,
-			)
-		}
-
 		if err != nil {
-			return 0, newError("Failed to get the user", err)
+			if err == ldap.ErrInvalidCredentials {
+				return 0, newError("proxy authentication required", ldap.ErrInvalidCredentials)
+			}
+			return 0, newError("failed to get the user", err)
 		}
 
 		return id, nil
@@ -196,29 +193,38 @@ func (auth *AuthProxy) Login() (int64, *Error) {
 
 	id, err := auth.LoginViaHeader()
 	if err != nil {
-		return 0, newError(
+		return 0, newError("failed to log in as user, specified in auth proxy header", err)
-			"Failed to log in as user, specified in auth proxy header",
-			err,
-		)
 	}
 
 	return id, nil
 }
 
-// GetUserViaCache gets user id from cache
+// GetUserViaCache gets user ID from cache.
-func (auth *AuthProxy) GetUserViaCache() (int64, error) {
+func (auth *AuthProxy) GetUserViaCache(logger log.Logger) (int64, error) {
-	var (
+	cacheKey := auth.getKey()
-		cacheKey    = auth.getKey()
+	logger.Debug("Getting user ID via auth cache", "cacheKey", cacheKey)
-		userID, err = auth.store.Get(cacheKey)
+	userID, err := auth.store.Get(cacheKey)
-	)
-
 	if err != nil {
+		logger.Debug("Failed getting user ID via auth cache", "error", err)
 		return 0, err
 	}
 
+	logger.Debug("Successfully got user ID via auth cache", "id", userID)
 	return userID.(int64), nil
 }
 
+// RemoveUserFromCache removes user from cache.
+func (auth *AuthProxy) RemoveUserFromCache(logger log.Logger) error {
+	cacheKey := auth.getKey()
+	logger.Debug("Removing user from auth cache", "cacheKey", cacheKey)
+	if err := auth.store.Delete(cacheKey); err != nil {
+		return err
+	}
+
+	logger.Debug("Successfully removed user from auth cache", "cacheKey", cacheKey)
+	return nil
+}
+
 // LoginViaLDAP logs in user via LDAP request
 func (auth *AuthProxy) LoginViaLDAP() (int64, *Error) {
 	config, err := getLDAPConfig()
@@ -265,7 +271,6 @@ func (auth *AuthProxy) LoginViaHeader() (int64, error) {
 		extUser.Login = auth.header
 	default:
 		return 0, newError("Auth proxy header property invalid", nil)
-
 	}
 
 	auth.headersIterator(func(field string, header string) {
@@ -305,7 +310,7 @@ func (auth *AuthProxy) headersIterator(fn func(field string, header string)) {
 	}
 }
 
-// GetSignedUser get full signed user info
+// GetSignedUser gets full signed user info.
 func (auth *AuthProxy) GetSignedUser(userID int64) (*models.SignedInUser, *Error) {
 	query := &models.GetSignedInUserQuery{
 		OrgId:  auth.orgID,

pkg/middleware/auth_proxy/auth_proxy_test.go

@@ -7,6 +7,7 @@ import (
 	"testing"
 
 	"github.com/grafana/grafana/pkg/bus"
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/infra/remotecache"
 	"github.com/grafana/grafana/pkg/models"
 	"github.com/grafana/grafana/pkg/services/ldap"
@@ -66,8 +67,10 @@ func prepareMiddleware(t *testing.T, req *http.Request, store *remotecache.Remot
 }
 
 func TestMiddlewareContext(t *testing.T) {
+	logger := log.New("test")
 	Convey("auth_proxy helper", t, func() {
-		req, _ := http.NewRequest("POST", "http://example.com", nil)
+		req, err := http.NewRequest("POST", "http://example.com", nil)
+		So(err, ShouldBeNil)
 		setting.AuthProxyHeaderName = "X-Killa"
 		store := remotecache.NewFakeStore(t)
 
@@ -75,7 +78,6 @@ func TestMiddlewareContext(t *testing.T) {
 		req.Header.Add(setting.AuthProxyHeaderName, name)
 
 		Convey("when the cache only contains the main header", func() {
-
 			Convey("with a simple cache key", func() {
 				// Set cache key
 				key := fmt.Sprintf(CachePrefix, HashCacheKey(name))
@@ -84,10 +86,11 @@ func TestMiddlewareContext(t *testing.T) {
 
 				// Set up the middleware
 				auth := prepareMiddleware(t, req, store)
-				id, err := auth.Login()
+				So(auth.getKey(), ShouldEqual, "auth-proxy-sync-ttl:0a7f3374e9659b10980fd66247b0cf2f")
+
+				id, err := auth.Login(logger, false)
 				So(err, ShouldBeNil)
 
-				So(auth.getKey(), ShouldEqual, "auth-proxy-sync-ttl:0a7f3374e9659b10980fd66247b0cf2f")
 				So(id, ShouldEqual, 33)
 			})
 
@@ -101,14 +104,11 @@ func TestMiddlewareContext(t *testing.T) {
 				So(err, ShouldBeNil)
 
 				auth := prepareMiddleware(t, req, store)
-
-				id, err := auth.Login()
-				So(err, ShouldBeNil)
 				So(auth.getKey(), ShouldEqual, "auth-proxy-sync-ttl:14f69b7023baa0ac98c96b31cec07bc0")
-				So(id, ShouldEqual, 33)
-			})
 
-			Convey("when the does not exist", func() {
+				id, err := auth.Login(logger, false)
+				So(err, ShouldBeNil)
+				So(id, ShouldEqual, 33)
 			})
 		})
 
@@ -155,7 +155,7 @@ func TestMiddlewareContext(t *testing.T) {
 
 				auth := prepareMiddleware(t, req, store)
 
-				id, err := auth.Login()
+				id, err := auth.Login(logger, false)
 
 				So(err, ShouldBeNil)
 				So(id, ShouldEqual, 42)
@@ -189,10 +189,10 @@ func TestMiddlewareContext(t *testing.T) {
 					return stub
 				}
 
-				id, err := auth.Login()
+				id, err := auth.Login(logger, false)
 
 				So(err, ShouldNotBeNil)
-				So(err.Error(), ShouldContainSubstring, "Failed to get the user")
+				So(err.Error(), ShouldContainSubstring, "failed to get the user")
 				So(id, ShouldNotEqual, 42)
 				So(stub.loginCalled, ShouldEqual, false)
 			})

pkg/middleware/auth_proxy_test.go

@@ -0,0 +1,88 @@
+package middleware
+
+import (
+	"fmt"
+	"net/http"
+	"testing"
+
+	"github.com/grafana/grafana/pkg/bus"
+	"github.com/grafana/grafana/pkg/infra/log"
+	"github.com/grafana/grafana/pkg/infra/remotecache"
+	authproxy "github.com/grafana/grafana/pkg/middleware/auth_proxy"
+	"github.com/grafana/grafana/pkg/models"
+	"github.com/grafana/grafana/pkg/setting"
+	"github.com/stretchr/testify/require"
+	macaron "gopkg.in/macaron.v1"
+)
+
+// Test initContextWithAuthProxy with a cached user ID that is no longer valid.
+//
+// In this case, the cache entry should be ignored/cleared and another attempt should be done to sign the user
+// in without cache.
+func TestInitContextWithAuthProxy_CachedInvalidUserID(t *testing.T) {
+	const name = "markelog"
+	const userID = int64(1)
+	const orgID = int64(4)
+
+	upsertHandler := func(cmd *models.UpsertUserCommand) error {
+		require.Equal(t, name, cmd.ExternalUser.Login)
+		cmd.Result = &models.User{Id: userID}
+		return nil
+	}
+	getSignedUserHandler := func(cmd *models.GetSignedInUserQuery) error {
+		// Simulate that the cached user ID is stale
+		if cmd.UserId != userID {
+			return models.ErrUserNotFound
+		}
+
+		cmd.Result = &models.SignedInUser{
+			UserId: userID,
+			OrgId:  orgID,
+		}
+		return nil
+	}
+
+	origHeaderName := setting.AuthProxyHeaderName
+	origEnabled := setting.AuthProxyEnabled
+	origHeaderProperty := setting.AuthProxyHeaderProperty
+	bus.AddHandler("", upsertHandler)
+	bus.AddHandler("", getSignedUserHandler)
+	t.Cleanup(func() {
+		setting.AuthProxyHeaderName = origHeaderName
+		setting.AuthProxyEnabled = origEnabled
+		setting.AuthProxyHeaderProperty = origHeaderProperty
+		bus.ClearBusHandlers()
+	})
+
+	setting.AuthProxyHeaderName = "X-Killa"
+	setting.AuthProxyEnabled = true
+	setting.AuthProxyHeaderProperty = "username"
+	req, err := http.NewRequest("POST", "http://example.com", nil)
+	require.NoError(t, err)
+	store := remotecache.NewFakeStore(t)
+	ctx := &models.ReqContext{
+		Context: &macaron.Context{
+			Req: macaron.Request{
+				Request: req,
+			},
+			Data: map[string]interface{}{},
+		},
+		Logger: log.New("Test"),
+	}
+	req.Header.Add(setting.AuthProxyHeaderName, name)
+	key := fmt.Sprintf(authproxy.CachePrefix, authproxy.HashCacheKey(name))
+
+	t.Logf("Injecting stale user ID in cache with key %q", key)
+	err = store.Set(key, int64(33), 0)
+	require.NoError(t, err)
+
+	authEnabled := initContextWithAuthProxy(store, ctx, orgID)
+	require.True(t, authEnabled)
+
+	require.Equal(t, userID, ctx.SignedInUser.UserId)
+	require.True(t, ctx.IsSignedIn)
+
+	i, err := store.Get(key)
+	require.NoError(t, err)
+	require.Equal(t, userID, i.(int64))
+}