Merge pull request #285 from supertokens/logging/enhance-debug-logs

chore: Add additional debug logs for session functions

CHANGELOG.md

@@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [unreleased]
 
+## [0.12.3] - 2023-05-22
+
+### Added
+
+-   Adds additional debug logs whenever the SDK returns a `TryRefreshTokenError` or `UnauthorizedError` to make debugging easier
+
 ## [0.12.2] - 2023-05-19
 
 -   Adds additional tests for the session recipe

recipe/emailverification/api/implementation.go

@@ -38,6 +38,7 @@ func MakeAPIImplementation() evmodels.APIInterface {
 				err := sessionContainer.FetchAndSetClaimWithContext(evclaims.EmailVerificationClaim, userContext)
 				if err != nil {
 					if err.Error() == "UNKNOWN_USER_ID" {
+						supertokens.LogDebugMessage("verifyEmailPOST: Returning UnauthorizedError because the User Id provided is unknown")
 						return evmodels.VerifyEmailPOSTResponse{}, sessErrors.UnauthorizedError{Msg: "Unknown User ID provided"}
 					}
 					return evmodels.VerifyEmailPOSTResponse{}, err
@@ -61,6 +62,7 @@ func MakeAPIImplementation() evmodels.APIInterface {
 		err := sessionContainer.FetchAndSetClaimWithContext(evclaims.EmailVerificationClaim, userContext)
 		if err != nil {
 			if err.Error() == "UNKNOWN_USER_ID" {
+				supertokens.LogDebugMessage("isEmailVerifiedGET: Returning UnauthorizedError because the User Id provided is unknown")
 				return evmodels.IsEmailVerifiedGETResponse{}, sessErrors.UnauthorizedError{Msg: "Unknown User ID provided"}
 			}
 			return evmodels.IsEmailVerifiedGETResponse{}, err
@@ -88,6 +90,7 @@ func MakeAPIImplementation() evmodels.APIInterface {
 			return evmodels.GenerateEmailVerifyTokenPOSTResponse{}, err
 		}
 		if email.UnknownUserIDError != nil {
+			supertokens.LogDebugMessage("generateEmailVerifyTokenPOST: Returning UnauthorizedError because the User Id provided is unknown")
 			return evmodels.GenerateEmailVerifyTokenPOSTResponse{}, sessErrors.UnauthorizedError{Msg: "Unknown User ID provided"}
 		}
 		if email.EmailDoesNotExistError != nil {

recipe/session/accessToken.go

@@ -17,10 +17,12 @@ package session
 
 import (
 	"errors"
+	"fmt"
 	"github.com/MicahParks/keyfunc"
 	"github.com/golang-jwt/jwt/v4"
 	sterrors "github.com/supertokens/supertokens-golang/recipe/session/errors"
 	"github.com/supertokens/supertokens-golang/recipe/session/sessmodels"
+	"github.com/supertokens/supertokens-golang/supertokens"
 	"strings"
 )
 
@@ -41,6 +43,7 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 	if jwtInfo.Version >= 3 {
 		parsedToken, parseError := jwt.Parse(jwtInfo.RawTokenString, jwks.Keyfunc)
 		if parseError != nil {
+			supertokens.LogDebugMessage(fmt.Sprintf("GetInfoFromAccessToken: Returning TryRefreshTokenError because access token parsing failed - %s", parseError))
 			return nil, sterrors.TryRefreshTokenError{
 				Msg: parseError.Error(),
 			}
@@ -49,6 +52,7 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 		if parsedToken.Valid {
 			claims, ok := parsedToken.Claims.(jwt.MapClaims)
 			if !ok {
+				supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because access token claims are invalid")
 				return nil, sterrors.TryRefreshTokenError{
 					Msg: "Invalid JWT claims",
 				}
@@ -81,6 +85,7 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 			}
 
 			if parseErr != nil {
+				supertokens.LogDebugMessage(fmt.Sprintf("GetInfoFromAccessToken: Returning TryRefreshTokenError because access token parsing failed - %s", parseErr))
 				return nil, sterrors.TryRefreshTokenError{
 					Msg: parseErr.Error(),
 				}
@@ -89,6 +94,7 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 			if parsedToken.Valid {
 				claims, ok := parsedToken.Claims.(jwt.MapClaims)
 				if !ok {
+					supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because access token claims are invalid")
 					return nil, sterrors.TryRefreshTokenError{
 						Msg: "Invalid JWT claims",
 					}
@@ -107,13 +113,15 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 	}
 
 	if payload == nil {
+		supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because access token JWT has no payload")
 		return nil, sterrors.TryRefreshTokenError{
 			Msg: "Invalid JWT",
 		}
 	}
 
 	err := ValidateAccessTokenStructure(payload, jwtInfo.Version)
 	if err != nil {
+		supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because ValidateAccessTokenStructure returned an error")
 		return nil, sterrors.TryRefreshTokenError{
 			Msg: err.Error(),
 		}
@@ -142,12 +150,14 @@ func GetInfoFromAccessToken(jwtInfo sessmodels.ParsedJWTInfo, jwks keyfunc.JWKS,
 	antiCsrfToken := sanitizeStringInput(payload["antiCsrfToken"])
 
 	if antiCsrfToken == nil && doAntiCsrfCheck {
+		supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because access does not contain the anti-csrf token.")
 		return nil, sterrors.TryRefreshTokenError{
 			Msg: "Access token does not contain the anti-csrf token.",
 		}
 	}
 
 	if expiryTime < GetCurrTimeInMS() {
+		supertokens.LogDebugMessage("GetInfoFromAccessToken: Returning TryRefreshTokenError because access is expired")
 		return nil, sterrors.TryRefreshTokenError{
 			Msg: "Access token expired",
 		}
@@ -169,41 +179,55 @@ func ValidateAccessTokenStructure(payload map[string]interface{}, version int) e
 	err := errors.New("Access token does not contain all the information. Maybe the structure has changed?")
 
 	if version >= 3 {
+		supertokens.LogDebugMessage("ValidateAccessTokenStructure: Access token is using version >= 3")
 		if _, ok := payload["sessionHandle"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: sessionHandle not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["sub"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: sub claim not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["refreshTokenHash1"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: refreshTokenHash1 not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["exp"].(float64); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: exp claim not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["iat"].(float64); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: iat claim not found in JWT payload")
 			return err
 		}
 	} else {
+		supertokens.LogDebugMessage("ValidateAccessTokenStructure: Access token is using version < 3")
 		if _, ok := payload["sessionHandle"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: sessionHandle not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["userId"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: userId not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["refreshTokenHash1"].(string); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: refreshTokenHash1 not found in JWT payload")
 			return err
 		}
 		if payload["userData"] == nil {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: userData not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["userData"].(map[string]interface{}); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: userData is invalid in JWT payload")
 			return err
 		}
 		if _, ok := payload["expiryTime"].(float64); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: expiryTime not found in JWT payload")
 			return err
 		}
 		if _, ok := payload["timeCreated"].(float64); !ok {
+			supertokens.LogDebugMessage("ValidateAccessTokenStructure: timeCreated not found in JWT payload")
 			return err
 		}
 	}

recipe/session/session.go

@@ -16,6 +16,7 @@
 package session
 
 import (
+	"fmt"
 	"reflect"
 
 	"github.com/supertokens/supertokens-golang/recipe/session/claims"
@@ -90,6 +91,7 @@ func newSessionContainer(config sessmodels.TypeNormalisedInput, session *Session
 			return nil, err
 		}
 		if sessionInformation == nil {
+			supertokens.LogDebugMessage("GetSessionDataInDatabaseWithContext: Returning UnauthorizedError because session does not exist anymore")
 			return nil, errors.UnauthorizedError{Msg: "session does not exist anymore"}
 		}
 		return sessionInformation.SessionDataInDatabase, nil
@@ -101,6 +103,7 @@ func newSessionContainer(config sessmodels.TypeNormalisedInput, session *Session
 			return err
 		}
 		if !updated {
+			supertokens.LogDebugMessage("UpdateSessionDataInDatabaseWithContext: Returning UnauthorizedError because session does not exist anymore")
 			return errors.UnauthorizedError{Msg: "session does not exist anymore"}
 		}
 		return nil
@@ -112,6 +115,7 @@ func newSessionContainer(config sessmodels.TypeNormalisedInput, session *Session
 			return 0, err
 		}
 		if sessionInformation == nil {
+			supertokens.LogDebugMessage("GetTimeCreatedWithContext: Returning UnauthorizedError because session does not exist anymore")
 			return 0, errors.UnauthorizedError{Msg: "session does not exist anymore"}
 		}
 		return sessionInformation.TimeCreated, nil
@@ -123,6 +127,7 @@ func newSessionContainer(config sessmodels.TypeNormalisedInput, session *Session
 			return 0, err
 		}
 		if sessionInformation == nil {
+			supertokens.LogDebugMessage("GetExpiryWithContext: Returning UnauthorizedError because session does not exist anymore")
 			return 0, errors.UnauthorizedError{Msg: "session does not exist anymore"}
 		}
 		return sessionInformation.Expiry, nil
@@ -160,6 +165,7 @@ func newSessionContainer(config sessmodels.TypeNormalisedInput, session *Session
 		response, err := regenerateAccessTokenHelper(*querier, &accessTokenPayload, sessionContainer.GetAccessToken())
 
 		if err != nil {
+			supertokens.LogDebugMessage(fmt.Sprintf("MergeIntoAccessTokenPayloadWithContext: Returning UnauthorizedError because we could not regenerate the session - %s", err))
 			return errors.UnauthorizedError{
 				Msg: errors.UnauthorizedErrorStr,
 			}

recipe/session/sessionFunctions.go

@@ -18,6 +18,7 @@ package session
 import (
 	"encoding/json"
 	defaultErrors "errors"
+	"fmt"
 	"strings"
 
 	"github.com/supertokens/supertokens-golang/recipe/session/errors"
@@ -63,6 +64,7 @@ func getSessionHelper(config sessmodels.TypeNormalisedInput, querier supertokens
 	var err error = nil
 	combinedJwks, jwksError := sessmodels.GetCombinedJWKS()
 	if jwksError != nil {
+		supertokens.LogDebugMessage(fmt.Sprintf("getSessionHelper: Returning TryRefreshTokenError because there was an error fetching JWKs - %s", jwksError))
 		if !defaultErrors.As(jwksError, &errors.TryRefreshTokenError{}) {
 			return sessmodels.GetSessionResponse{}, jwksError
 		}
@@ -71,6 +73,7 @@ func getSessionHelper(config sessmodels.TypeNormalisedInput, querier supertokens
 	accessTokenInfo, err = GetInfoFromAccessToken(parsedAccessToken, *combinedJwks, config.AntiCsrf == AntiCSRF_VIA_TOKEN && doAntiCsrfCheck)
 	if err != nil {
 		if !defaultErrors.As(err, &errors.TryRefreshTokenError{}) {
+			supertokens.LogDebugMessage("getSessionHelper: Returning TryRefreshTokenError because GetInfoFromAccessToken returned an error")
 			return sessmodels.GetSessionResponse{}, err
 		}
 

recipe/session/sessionRequestFunctions.go

@@ -117,6 +117,7 @@ func CreateNewSessionInRequest(req *http.Request, res http.ResponseWriter, confi
 func GetSessionFromRequest(req *http.Request, res http.ResponseWriter, config sessmodels.TypeNormalisedInput, options *sessmodels.VerifySessionOptions, recipeImpl sessmodels.RecipeInterface, userContext supertokens.UserContext) (sessmodels.SessionContainer, error) {
 	idRefreshToken := GetCookieValue(req, legacyIdRefreshTokenCookieName)
 	if idRefreshToken != nil {
+		supertokens.LogDebugMessage("GetSessionFromRequest: Returning TryRefreshTokenError because the request is using a legacy session and should be refreshed")
 		return nil, errors.TryRefreshTokenError{
 			Msg: "using legacy session, please call the refresh API",
 		}
@@ -350,6 +351,10 @@ func RefreshSessionInRequest(req *http.Request, res http.ResponseWriter, config
 			}
 		}
 
+		if isUnauthorisedErr {
+			supertokens.LogDebugMessage("RefreshSessionInRequest: Returning UnauthorizedError because RefreshSession returned an error")
+		}
+
 		return nil, err
 	}
 

supertokens/constants.go

@@ -21,7 +21,7 @@ const (
 )
 
 // VERSION current version of the lib
-const VERSION = "0.12.2"
+const VERSION = "0.12.3"
 
 var (
 	cdiSupported = []string{"2.21"}