Fix for issue - Token used before issued

pkg/authenticator/api-key.go

@@ -47,7 +47,7 @@ func (aa *APIKeyAuthenticator) GetToken(freshTokenRequired bool) (string, uint64
 
 	if !freshTokenRequired {
 		// Fetching token life time of the token in cache
-		tokenlifetime, err = token.CheckTokenLifeTime(aa.token)
+		tokenlifetime, err = token.CheckTokenLifeTime(aa.token, aa.logger)
 		if err == nil {
 			aa.logger.Info("Fetched iam token from cache", zap.Uint64("token-life-time-in-seconds", tokenlifetime))
 			return aa.token, tokenlifetime, nil
@@ -75,7 +75,7 @@ func (aa *APIKeyAuthenticator) GetToken(freshTokenRequired bool) (string, uint64
 		return "", tokenlifetime, utils.Error{Description: utils.ErrEmptyTokenResponse}
 	}
 
-	tokenlifetime, err = token.CheckTokenLifeTime(tokenResponse.AccessToken)
+	tokenlifetime, err = token.CheckTokenLifeTime(tokenResponse.AccessToken, aa.logger)
 	if err != nil {
 		aa.logger.Error("Error fetching token lifetime for new token", zap.Error(err))
 		return "", tokenlifetime, utils.Error{Description: "Error fetching token lifetime", BackendError: err.Error()}

pkg/authenticator/pod-identity.go

@@ -46,7 +46,7 @@ func (ca *ComputeIdentityAuthenticator) GetToken(freshTokenRequired bool) (strin
 
 	if !freshTokenRequired {
 		// Fetching token life time of the token in cache
-		tokenlifetime, err = token.CheckTokenLifeTime(ca.token)
+		tokenlifetime, err = token.CheckTokenLifeTime(ca.token, ca.logger)
 		if err == nil {
 			ca.logger.Info("Fetched iam token from cache", zap.Uint64("token-life-time-in-seconds", tokenlifetime))
 			return ca.token, tokenlifetime, nil
@@ -73,7 +73,7 @@ func (ca *ComputeIdentityAuthenticator) GetToken(freshTokenRequired bool) (strin
 		return "", tokenlifetime, utils.Error{Description: utils.ErrEmptyTokenResponse}
 	}
 
-	tokenlifetime, err = token.CheckTokenLifeTime(tokenResponse.AccessToken)
+	tokenlifetime, err = token.CheckTokenLifeTime(tokenResponse.AccessToken, ca.logger)
 	if err != nil {
 		ca.logger.Error("Error fetching token lifetime for new token", zap.Error(err))
 		return "", tokenlifetime, utils.Error{Description: "Error fetching token lifetime", BackendError: err.Error()}

pkg/token/token.go

@@ -22,11 +22,12 @@ import (
 
 	"github.com/IBM/secret-utils-lib/pkg/utils"
 	"github.com/golang-jwt/jwt"
+	"go.uber.org/zap"
 )
 
 // CheckTokenLifeTime checks whether the lifetime of token is valid or not
 // and returns life time of the token
-func CheckTokenLifeTime(tokenString string) (uint64, error) {
+func CheckTokenLifeTime(tokenString string, logger *zap.Logger) (uint64, error) {
 	var tokenLifeTime uint64
 
 	token, err := parseToken(tokenString)
@@ -35,10 +36,11 @@ func CheckTokenLifeTime(tokenString string) (uint64, error) {
 	}
 
 	if claims, ok := token.Claims.(jwt.MapClaims); ok {
+		currentTime := time.Now().Unix()
 		if err := claims.Valid(); err != nil {
+			logger.Warn("Token validation failed", zap.Error(err), zap.Any("current time", currentTime), zap.Any("issued at time", claims["iat"]), zap.Any("expiry time", claims["exp"]))
 			return tokenLifeTime, err
 		}
-		currentTime := time.Now().Unix()
 		var expiryTime interface{}
 		if expiryTime, ok = claims["exp"]; !ok {
 			return tokenLifeTime, errors.New("unable to find expiry time of token")

pkg/token/token_test.go

@@ -17,13 +17,20 @@
 package token
 
 import (
+	"bytes"
 	"errors"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 )
 
 func TestCheckTokenLifeTime(t *testing.T) {
+	// Creating test logger
+	logger, teardown := GetTestLogger(t)
+	defer teardown()
+
 	testcases := []struct {
 		testcasename  string
 		token         string
@@ -37,12 +44,12 @@ func TestCheckTokenLifeTime(t *testing.T) {
 		{
 			testcasename:  "Invalid token string",
 			token:         "Invalid",
-			expectedError: errors.New("Not nil"),
+			expectedError: errors.New("token contains an invalid number of segments"),
 		},
 		{
-			testcasename:  "Valid token string",
+			testcasename:  "Expired token",
 			token:         "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJleHAiOjE2NDUwMzI5MTUsImlhdCI6MTY0NTAzMjU3NH0.P4yzEttdMsKXLNesMJPZNeoIAl93b5LTX2Xf7rJtZ4o",
-			expectedError: nil,
+			expectedError: errors.New("Token is expired"),
 		},
 		{
 			testcasename:  "Valid token string without expiry time",
@@ -53,10 +60,40 @@ func TestCheckTokenLifeTime(t *testing.T) {
 
 	for _, testcase := range testcases {
 		t.Run(testcase.testcasename, func(t *testing.T) {
-			_, err := CheckTokenLifeTime(testcase.token)
+			_, err := CheckTokenLifeTime(testcase.token, logger)
 			if testcase.expectedError != nil {
-				assert.NotNil(t, err)
+				assert.Contains(t, err.Error(), testcase.expectedError.Error())
+			} else {
+				assert.Nil(t, err)
 			}
 		})
 	}
 }
+
+// GetTestLogger ...
+func GetTestLogger(t *testing.T) (logger *zap.Logger, teardown func()) {
+	atom := zap.NewAtomicLevel()
+	atom.SetLevel(zap.DebugLevel)
+	encoderCfg := zap.NewProductionEncoderConfig()
+	encoderCfg.TimeKey = "timestamp"
+	encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder
+
+	buf := &bytes.Buffer{}
+
+	logger = zap.New(
+		zapcore.NewCore(
+			zapcore.NewJSONEncoder(encoderCfg),
+			zapcore.AddSync(buf),
+			atom,
+		),
+		zap.AddCaller(),
+	)
+
+	teardown = func() {
+		_ = logger.Sync()
+		if t.Failed() {
+			t.Log(buf)
+		}
+	}
+	return
+}