Instrumentation: add more tracing in the auth context handler. (#34939)

ref https://github.com/grafana/grafana/issues/29489

Signed-off-by: bergquist <carl.bergquist@gmail.com>
This commit is contained in:
Carl Bergquist 2021-05-31 21:39:28 +02:00 committed by GitHub
parent 28ccf2c880
commit f432fbd793
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -22,6 +22,8 @@ import (
"github.com/grafana/grafana/pkg/services/sqlstore" "github.com/grafana/grafana/pkg/services/sqlstore"
"github.com/grafana/grafana/pkg/setting" "github.com/grafana/grafana/pkg/setting"
"github.com/grafana/grafana/pkg/util" "github.com/grafana/grafana/pkg/util"
"github.com/opentracing/opentracing-go"
ol "github.com/opentracing/opentracing-go/log"
cw "github.com/weaveworks/common/middleware" cw "github.com/weaveworks/common/middleware"
"gopkg.in/macaron.v1" "gopkg.in/macaron.v1"
) )
@ -61,9 +63,12 @@ func (h *ContextHandler) Init() error {
} }
// Middleware provides a middleware to initialize the Macaron context. // Middleware provides a middleware to initialize the Macaron context.
func (h *ContextHandler) Middleware(c *macaron.Context) { func (h *ContextHandler) Middleware(mContext *macaron.Context) {
ctx := &models.ReqContext{ span, _ := opentracing.StartSpanFromContext(mContext.Req.Context(), "Auth - Middleware")
Context: c, defer span.Finish()
reqContext := &models.ReqContext{
Context: mContext,
SignedInUser: &models.SignedInUser{}, SignedInUser: &models.SignedInUser{},
IsSignedIn: false, IsSignedIn: false,
AllowAnonymous: false, AllowAnonymous: false,
@ -71,20 +76,20 @@ func (h *ContextHandler) Middleware(c *macaron.Context) {
Logger: log.New("context"), Logger: log.New("context"),
} }
traceID, exists := cw.ExtractTraceID(c.Req.Request.Context()) traceID, exists := cw.ExtractTraceID(mContext.Req.Request.Context())
if exists { if exists {
ctx.Logger = ctx.Logger.New("traceID", traceID) reqContext.Logger = reqContext.Logger.New("traceID", traceID)
} }
const headerName = "X-Grafana-Org-Id" const headerName = "X-Grafana-Org-Id"
orgID := int64(0) orgID := int64(0)
orgIDHeader := ctx.Req.Header.Get(headerName) orgIDHeader := reqContext.Req.Header.Get(headerName)
if orgIDHeader != "" { if orgIDHeader != "" {
id, err := strconv.ParseInt(orgIDHeader, 10, 64) id, err := strconv.ParseInt(orgIDHeader, 10, 64)
if err == nil { if err == nil {
orgID = id orgID = id
} else { } else {
ctx.Logger.Debug("Received invalid header", "header", headerName, "value", orgIDHeader) reqContext.Logger.Debug("Received invalid header", "header", headerName, "value", orgIDHeader)
} }
} }
@ -94,51 +99,59 @@ func (h *ContextHandler) Middleware(c *macaron.Context) {
// then look for api key in session (special case for render calls via api) // then look for api key in session (special case for render calls via api)
// then test if anonymous access is enabled // then test if anonymous access is enabled
switch { switch {
case h.initContextWithRenderAuth(ctx): case h.initContextWithRenderAuth(reqContext):
case h.initContextWithAPIKey(ctx): case h.initContextWithAPIKey(reqContext):
case h.initContextWithBasicAuth(ctx, orgID): case h.initContextWithBasicAuth(reqContext, orgID):
case h.initContextWithAuthProxy(ctx, orgID): case h.initContextWithAuthProxy(reqContext, orgID):
case h.initContextWithToken(ctx, orgID): case h.initContextWithToken(reqContext, orgID):
case h.initContextWithJWT(ctx, orgID): case h.initContextWithJWT(reqContext, orgID):
case h.initContextWithAnonymousUser(ctx): case h.initContextWithAnonymousUser(reqContext):
} }
ctx.Logger = log.New("context", "userId", ctx.UserId, "orgId", ctx.OrgId, "uname", ctx.Login) reqContext.Logger = log.New("context", "userId", reqContext.UserId, "orgId", reqContext.OrgId, "uname", reqContext.Login)
ctx.Data["ctx"] = ctx reqContext.Data["ctx"] = reqContext
c.Map(ctx) span.LogFields(
ol.String("uname", reqContext.Login),
ol.Int64("orgId", reqContext.OrgId),
ol.Int64("userId", reqContext.UserId))
mContext.Map(reqContext)
// update last seen every 5min // update last seen every 5min
if ctx.ShouldUpdateLastSeenAt() { if reqContext.ShouldUpdateLastSeenAt() {
ctx.Logger.Debug("Updating last user_seen_at", "user_id", ctx.UserId) reqContext.Logger.Debug("Updating last user_seen_at", "user_id", reqContext.UserId)
if err := bus.Dispatch(&models.UpdateUserLastSeenAtCommand{UserId: ctx.UserId}); err != nil { if err := bus.Dispatch(&models.UpdateUserLastSeenAtCommand{UserId: reqContext.UserId}); err != nil {
ctx.Logger.Error("Failed to update last_seen_at", "error", err) reqContext.Logger.Error("Failed to update last_seen_at", "error", err)
} }
} }
} }
func (h *ContextHandler) initContextWithAnonymousUser(ctx *models.ReqContext) bool { func (h *ContextHandler) initContextWithAnonymousUser(reqContext *models.ReqContext) bool {
if !h.Cfg.AnonymousEnabled { if !h.Cfg.AnonymousEnabled {
return false return false
} }
span, _ := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithAnonymousUser")
defer span.Finish()
org, err := h.SQLStore.GetOrgByName(h.Cfg.AnonymousOrgName) org, err := h.SQLStore.GetOrgByName(h.Cfg.AnonymousOrgName)
if err != nil { if err != nil {
log.Errorf(3, "Anonymous access organization error: '%s': %s", h.Cfg.AnonymousOrgName, err) log.Errorf(3, "Anonymous access organization error: '%s': %s", h.Cfg.AnonymousOrgName, err)
return false return false
} }
ctx.IsSignedIn = false reqContext.IsSignedIn = false
ctx.AllowAnonymous = true reqContext.AllowAnonymous = true
ctx.SignedInUser = &models.SignedInUser{IsAnonymous: true} reqContext.SignedInUser = &models.SignedInUser{IsAnonymous: true}
ctx.OrgRole = models.RoleType(h.Cfg.AnonymousOrgRole) reqContext.OrgRole = models.RoleType(h.Cfg.AnonymousOrgRole)
ctx.OrgId = org.Id reqContext.OrgId = org.Id
ctx.OrgName = org.Name reqContext.OrgName = org.Name
return true return true
} }
func (h *ContextHandler) initContextWithAPIKey(ctx *models.ReqContext) bool { func (h *ContextHandler) initContextWithAPIKey(reqContext *models.ReqContext) bool {
header := ctx.Req.Header.Get("Authorization") header := reqContext.Req.Header.Get("Authorization")
parts := strings.SplitN(header, " ", 2) parts := strings.SplitN(header, " ", 2)
var keyString string var keyString string
if len(parts) == 2 && parts[0] == "Bearer" { if len(parts) == 2 && parts[0] == "Bearer" {
@ -154,17 +167,20 @@ func (h *ContextHandler) initContextWithAPIKey(ctx *models.ReqContext) bool {
return false return false
} }
span, _ := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithAPIKey")
defer span.Finish()
// base64 decode key // base64 decode key
decoded, err := apikeygen.Decode(keyString) decoded, err := apikeygen.Decode(keyString)
if err != nil { if err != nil {
ctx.JsonApiErr(401, InvalidAPIKey, err) reqContext.JsonApiErr(401, InvalidAPIKey, err)
return true return true
} }
// fetch key // fetch key
keyQuery := models.GetApiKeyByNameQuery{KeyName: decoded.Name, OrgId: decoded.OrgId} keyQuery := models.GetApiKeyByNameQuery{KeyName: decoded.Name, OrgId: decoded.OrgId}
if err := bus.Dispatch(&keyQuery); err != nil { if err := bus.Dispatch(&keyQuery); err != nil {
ctx.JsonApiErr(401, InvalidAPIKey, err) reqContext.JsonApiErr(401, InvalidAPIKey, err)
return true return true
} }
@ -173,11 +189,11 @@ func (h *ContextHandler) initContextWithAPIKey(ctx *models.ReqContext) bool {
// validate api key // validate api key
isValid, err := apikeygen.IsValid(decoded, apikey.Key) isValid, err := apikeygen.IsValid(decoded, apikey.Key)
if err != nil { if err != nil {
ctx.JsonApiErr(500, "Validating API key failed", err) reqContext.JsonApiErr(500, "Validating API key failed", err)
return true return true
} }
if !isValid { if !isValid {
ctx.JsonApiErr(401, InvalidAPIKey, err) reqContext.JsonApiErr(401, InvalidAPIKey, err)
return true return true
} }
@ -187,31 +203,34 @@ func (h *ContextHandler) initContextWithAPIKey(ctx *models.ReqContext) bool {
getTime = time.Now getTime = time.Now
} }
if apikey.Expires != nil && *apikey.Expires <= getTime().Unix() { if apikey.Expires != nil && *apikey.Expires <= getTime().Unix() {
ctx.JsonApiErr(401, "Expired API key", err) reqContext.JsonApiErr(401, "Expired API key", err)
return true return true
} }
ctx.IsSignedIn = true reqContext.IsSignedIn = true
ctx.SignedInUser = &models.SignedInUser{} reqContext.SignedInUser = &models.SignedInUser{}
ctx.OrgRole = apikey.Role reqContext.OrgRole = apikey.Role
ctx.ApiKeyId = apikey.Id reqContext.ApiKeyId = apikey.Id
ctx.OrgId = apikey.OrgId reqContext.OrgId = apikey.OrgId
return true return true
} }
func (h *ContextHandler) initContextWithBasicAuth(ctx *models.ReqContext, orgID int64) bool { func (h *ContextHandler) initContextWithBasicAuth(reqContext *models.ReqContext, orgID int64) bool {
if !h.Cfg.BasicAuthEnabled { if !h.Cfg.BasicAuthEnabled {
return false return false
} }
header := ctx.Req.Header.Get("Authorization") header := reqContext.Req.Header.Get("Authorization")
if header == "" { if header == "" {
return false return false
} }
span, ctx := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithBasicAuth")
defer span.Finish()
username, password, err := util.DecodeBasicAuthHeader(header) username, password, err := util.DecodeBasicAuthHeader(header)
if err != nil { if err != nil {
ctx.JsonApiErr(401, "Invalid Basic Auth Header", err) reqContext.JsonApiErr(401, "Invalid Basic Auth Header", err)
return true return true
} }
@ -221,7 +240,7 @@ func (h *ContextHandler) initContextWithBasicAuth(ctx *models.ReqContext, orgID
Cfg: h.Cfg, Cfg: h.Cfg,
} }
if err := bus.Dispatch(&authQuery); err != nil { if err := bus.Dispatch(&authQuery); err != nil {
ctx.Logger.Debug( reqContext.Logger.Debug(
"Failed to authorize the user", "Failed to authorize the user",
"username", username, "username", username,
"err", err, "err", err,
@ -230,63 +249,66 @@ func (h *ContextHandler) initContextWithBasicAuth(ctx *models.ReqContext, orgID
if errors.Is(err, models.ErrUserNotFound) { if errors.Is(err, models.ErrUserNotFound) {
err = login.ErrInvalidCredentials err = login.ErrInvalidCredentials
} }
ctx.JsonApiErr(401, InvalidUsernamePassword, err) reqContext.JsonApiErr(401, InvalidUsernamePassword, err)
return true return true
} }
user := authQuery.User user := authQuery.User
query := models.GetSignedInUserQuery{UserId: user.Id, OrgId: orgID} query := models.GetSignedInUserQuery{UserId: user.Id, OrgId: orgID}
if err := bus.DispatchCtx(ctx.Req.Context(), &query); err != nil { if err := bus.DispatchCtx(ctx, &query); err != nil {
ctx.Logger.Error( reqContext.Logger.Error(
"Failed at user signed in", "Failed at user signed in",
"id", user.Id, "id", user.Id,
"org", orgID, "org", orgID,
) )
ctx.JsonApiErr(401, InvalidUsernamePassword, err) reqContext.JsonApiErr(401, InvalidUsernamePassword, err)
return true return true
} }
ctx.SignedInUser = query.Result reqContext.SignedInUser = query.Result
ctx.IsSignedIn = true reqContext.IsSignedIn = true
return true return true
} }
func (h *ContextHandler) initContextWithToken(ctx *models.ReqContext, orgID int64) bool { func (h *ContextHandler) initContextWithToken(reqContext *models.ReqContext, orgID int64) bool {
if h.Cfg.LoginCookieName == "" { if h.Cfg.LoginCookieName == "" {
return false return false
} }
rawToken := ctx.GetCookie(h.Cfg.LoginCookieName) rawToken := reqContext.GetCookie(h.Cfg.LoginCookieName)
if rawToken == "" { if rawToken == "" {
return false return false
} }
token, err := h.AuthTokenService.LookupToken(ctx.Req.Context(), rawToken) span, ctx := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithToken")
defer span.Finish()
token, err := h.AuthTokenService.LookupToken(ctx, rawToken)
if err != nil { if err != nil {
ctx.Logger.Error("Failed to look up user based on cookie", "error", err) reqContext.Logger.Error("Failed to look up user based on cookie", "error", err)
ctx.Data["lookupTokenErr"] = err reqContext.Data["lookupTokenErr"] = err
return false return false
} }
query := models.GetSignedInUserQuery{UserId: token.UserId, OrgId: orgID} query := models.GetSignedInUserQuery{UserId: token.UserId, OrgId: orgID}
if err := bus.DispatchCtx(ctx.Req.Context(), &query); err != nil { if err := bus.DispatchCtx(ctx, &query); err != nil {
ctx.Logger.Error("Failed to get user with id", "userId", token.UserId, "error", err) reqContext.Logger.Error("Failed to get user with id", "userId", token.UserId, "error", err)
return false return false
} }
ctx.SignedInUser = query.Result reqContext.SignedInUser = query.Result
ctx.IsSignedIn = true reqContext.IsSignedIn = true
ctx.UserToken = token reqContext.UserToken = token
// Rotate the token just before we write response headers to ensure there is no delay between // Rotate the token just before we write response headers to ensure there is no delay between
// the new token being generated and the client receiving it. // the new token being generated and the client receiving it.
ctx.Resp.Before(h.rotateEndOfRequestFunc(ctx, h.AuthTokenService, token)) reqContext.Resp.Before(h.rotateEndOfRequestFunc(reqContext, h.AuthTokenService, token))
return true return true
} }
func (h *ContextHandler) rotateEndOfRequestFunc(ctx *models.ReqContext, authTokenService models.UserTokenService, func (h *ContextHandler) rotateEndOfRequestFunc(reqContext *models.ReqContext, authTokenService models.UserTokenService,
token *models.UserToken) macaron.BeforeFunc { token *models.UserToken) macaron.BeforeFunc {
return func(w macaron.ResponseWriter) { return func(w macaron.ResponseWriter) {
// if response has already been written, skip. // if response has already been written, skip.
@ -296,48 +318,54 @@ func (h *ContextHandler) rotateEndOfRequestFunc(ctx *models.ReqContext, authToke
// if the request is cancelled by the client we should not try // if the request is cancelled by the client we should not try
// to rotate the token since the client would not accept any result. // to rotate the token since the client would not accept any result.
if errors.Is(ctx.Context.Req.Context().Err(), context.Canceled) { if errors.Is(reqContext.Context.Req.Context().Err(), context.Canceled) {
return return
} }
addr := ctx.RemoteAddr() span, ctx := opentracing.StartSpanFromContext(reqContext.Req.Context(), "rotateEndOfRequestFunc")
defer span.Finish()
addr := reqContext.RemoteAddr()
ip, err := network.GetIPFromAddress(addr) ip, err := network.GetIPFromAddress(addr)
if err != nil { if err != nil {
ctx.Logger.Debug("Failed to get client IP address", "addr", addr, "err", err) reqContext.Logger.Debug("Failed to get client IP address", "addr", addr, "err", err)
ip = nil ip = nil
} }
rotated, err := authTokenService.TryRotateToken(ctx.Req.Context(), token, ip, ctx.Req.UserAgent()) rotated, err := authTokenService.TryRotateToken(ctx, token, ip, reqContext.Req.UserAgent())
if err != nil { if err != nil {
ctx.Logger.Error("Failed to rotate token", "error", err) reqContext.Logger.Error("Failed to rotate token", "error", err)
return return
} }
if rotated { if rotated {
cookies.WriteSessionCookie(ctx, h.Cfg, token.UnhashedToken, h.Cfg.LoginMaxLifetime) cookies.WriteSessionCookie(reqContext, h.Cfg, token.UnhashedToken, h.Cfg.LoginMaxLifetime)
} }
} }
} }
func (h *ContextHandler) initContextWithRenderAuth(ctx *models.ReqContext) bool { func (h *ContextHandler) initContextWithRenderAuth(reqContext *models.ReqContext) bool {
key := ctx.GetCookie("renderKey") key := reqContext.GetCookie("renderKey")
if key == "" { if key == "" {
return false return false
} }
span, _ := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithRenderAuth")
defer span.Finish()
renderUser, exists := h.RenderService.GetRenderUser(key) renderUser, exists := h.RenderService.GetRenderUser(key)
if !exists { if !exists {
ctx.JsonApiErr(401, "Invalid Render Key", nil) reqContext.JsonApiErr(401, "Invalid Render Key", nil)
return true return true
} }
ctx.IsSignedIn = true reqContext.IsSignedIn = true
ctx.SignedInUser = &models.SignedInUser{ reqContext.SignedInUser = &models.SignedInUser{
OrgId: renderUser.OrgID, OrgId: renderUser.OrgID,
UserId: renderUser.UserID, UserId: renderUser.UserID,
OrgRole: models.RoleType(renderUser.OrgRole), OrgRole: models.RoleType(renderUser.OrgRole),
} }
ctx.IsRenderCall = true reqContext.IsRenderCall = true
ctx.LastSeenAt = time.Now() reqContext.LastSeenAt = time.Now()
return true return true
} }
@ -371,11 +399,11 @@ func (h *ContextHandler) handleError(ctx *models.ReqContext, err error, statusCo
} }
} }
func (h *ContextHandler) initContextWithAuthProxy(ctx *models.ReqContext, orgID int64) bool { func (h *ContextHandler) initContextWithAuthProxy(reqContext *models.ReqContext, orgID int64) bool {
username := ctx.Req.Header.Get(h.Cfg.AuthProxyHeaderName) username := reqContext.Req.Header.Get(h.Cfg.AuthProxyHeaderName)
auth := authproxy.New(h.Cfg, &authproxy.Options{ auth := authproxy.New(h.Cfg, &authproxy.Options{
RemoteCache: h.RemoteCache, RemoteCache: h.RemoteCache,
Ctx: ctx, Ctx: reqContext,
OrgID: orgID, OrgID: orgID,
}) })
@ -391,9 +419,12 @@ func (h *ContextHandler) initContextWithAuthProxy(ctx *models.ReqContext, orgID
return false return false
} }
span, _ := opentracing.StartSpanFromContext(reqContext.Req.Context(), "initContextWithAuthProxy")
defer span.Finish()
// Check if allowed to continue with this IP // Check if allowed to continue with this IP
if err := auth.IsAllowedIP(); err != nil { if err := auth.IsAllowedIP(); err != nil {
h.handleError(ctx, err, 407, func(details error) { h.handleError(reqContext, err, 407, func(details error) {
logger.Error("Failed to check whitelisted IP addresses", "message", err.Error(), "error", details) logger.Error("Failed to check whitelisted IP addresses", "message", err.Error(), "error", details)
}) })
return true return true
@ -401,7 +432,7 @@ func (h *ContextHandler) initContextWithAuthProxy(ctx *models.ReqContext, orgID
id, err := logUserIn(auth, username, logger, false) id, err := logUserIn(auth, username, logger, false)
if err != nil { if err != nil {
h.handleError(ctx, err, 407, nil) h.handleError(reqContext, err, 407, nil)
return true return true
} }
@ -422,13 +453,13 @@ func (h *ContextHandler) initContextWithAuthProxy(ctx *models.ReqContext, orgID
} }
id, err = logUserIn(auth, username, logger, true) id, err = logUserIn(auth, username, logger, true)
if err != nil { if err != nil {
h.handleError(ctx, err, 407, nil) h.handleError(reqContext, err, 407, nil)
return true return true
} }
user, err = auth.GetSignedInUser(id) user, err = auth.GetSignedInUser(id)
if err != nil { if err != nil {
h.handleError(ctx, err, 407, nil) h.handleError(reqContext, err, 407, nil)
return true return true
} }
} }
@ -436,12 +467,12 @@ func (h *ContextHandler) initContextWithAuthProxy(ctx *models.ReqContext, orgID
logger.Debug("Successfully got user info", "userID", user.UserId, "username", user.Login) logger.Debug("Successfully got user info", "userID", user.UserId, "username", user.Login)
// Add user info to context // Add user info to context
ctx.SignedInUser = user reqContext.SignedInUser = user
ctx.IsSignedIn = true reqContext.IsSignedIn = true
// Remember user data in cache // Remember user data in cache
if err := auth.Remember(id); err != nil { if err := auth.Remember(id); err != nil {
h.handleError(ctx, err, 500, func(details error) { h.handleError(reqContext, err, 500, func(details error) {
logger.Error( logger.Error(
"Failed to store user in cache", "Failed to store user in cache",
"username", username, "username", username,