Merge pull request #118 from Venafi/adds-more-log-messages

Adds more log messages and fixes bug in setting up token process

CHANGELOG.md

@@ -1,3 +1,11 @@
+# v0.12.1 (January 19, 2023)
+* Added `ignore_local_storage` and `min_cert_time_left` new attributes at `issue` path, which
+bypasses `prevent-reissue-local` feature, if enabled, and requests the certificate, and handles
+certificate time left considered to be valid, respectively
+* Fixes bug that wouldn't let to create `venafi` secret in a Vault cluster environment where refresh tokens were provided
+* Added more logs for refresh token process
+* Starting from release, binaries are signed
+
 # v0.12.0 (December 27, 2022)
 * Added ability to ignore search-certificate in local storage. Fixes behaviour for prevent-reissue features to have certificate default validity.
 * Introduced `proactive refresh` feature, which now relies on handling refreshing the `access_token` by passing two refresh tokens in the `venafi` secret (`refresh_token` and `refresh_token_2`)

plugin/pki/path_venafi_cert_enroll.go

@@ -195,7 +195,7 @@ func (b *backend) pathVenafiCertObtain(ctx context.Context, logicalRequest *logi
 	// here we already filter proper "Zone" to later use with cfg.Zone
 	connector, cfg, err := b.ClientVenafi(ctx, logicalRequest, role)
 	if err != nil {
-		b.Logger().Error("error creating Venafi connector: %s", err.Error())
+		b.Logger().Error(fmt.Sprintf("error creating Venafi connector: %s", err.Error()))
 		return nil, err
 	}
 
@@ -208,6 +208,7 @@ func (b *backend) pathVenafiCertObtain(ctx context.Context, logicalRequest *logi
 		if secretEntry.RefreshToken != "" && secretEntry.RefreshToken2 != "" {
 			connector, err = validateAccessToken(b, ctx, connector, cfg, logicalRequest, role)
 			if err != nil {
+				b.Logger().Error(fmt.Sprintf("error validating access token: %s", err.Error()))
 				return nil, err
 			}
 		}
@@ -1033,27 +1034,29 @@ func validateAccessToken(b *backend, ctx context.Context, connector endpoint.Con
 	}
 	if refreshNeeded {
 		if b.System().ReplicationState().HasState(consts.ReplicationPerformanceStandby | consts.ReplicationPerformanceSecondary) {
-			// only the leader can handle token refreshing
-
+			// only the leader can handle token refreshing, we don't ever want to enter into refreshing process if we are
+			// getting request in vault follower node
 			return nil, logical.ErrReadOnly
 		}
 		b.Logger().Info("Token refresh is needed")
 		if err != nil {
 			return nil, err
 		}
+		b.Logger().Info("Updating access_token")
 		err = updateAccessToken(b, ctx, logReq, cfg, role)
 		if err != nil {
 			return nil, err
 		}
-		// reload the client since the access token changed
+		b.Logger().Info("Successfully updated tokens. Refreshing the connector with new token")
 		var newConnector endpoint.Connector
 		newConnector, cfg, err = b.ClientVenafi(ctx, logReq, role)
 		if err != nil {
-			b.Logger().Debug("got error: token is not ready")
+			b.Logger().Error(fmt.Sprintf("got error when getting new connector: %s", err.Error()))
 			return nil, err
 		}
 		connector = newConnector
 	}
+	b.Logger().Info("Successfully updated connector with new token")
 	return connector, nil
 }
 

plugin/pki/path_venafi_secrets.go

@@ -3,6 +3,7 @@ package pki
 import (
 	"context"
 	"fmt"
+	"github.com/hashicorp/vault/sdk/helper/consts"
 	"time"
 
 	"github.com/hashicorp/vault/sdk/framework"
@@ -165,6 +166,10 @@ func (b *backend) pathVenafiSecretRead(ctx context.Context, req *logical.Request
 }
 
 func (b *backend) pathVenafiSecretDelete(ctx context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) {
+	if b.System().ReplicationState().HasState(consts.ReplicationPerformanceStandby | consts.ReplicationPerformanceSecondary) {
+		// only the leader can handle deletion
+		return nil, logical.ErrReadOnly
+	}
 	err := req.Storage.Delete(ctx, CredentialsRootPath+data.Get("name").(string))
 	if err != nil {
 		return nil, err
@@ -173,9 +178,14 @@ func (b *backend) pathVenafiSecretDelete(ctx context.Context, req *logical.Reque
 }
 
 func (b *backend) pathVenafiSecretCreate(ctx context.Context, req *logical.Request, data *framework.FieldData) (*logical.Response, error) {
+	if b.System().ReplicationState().HasState(consts.ReplicationPerformanceStandby | consts.ReplicationPerformanceSecondary) {
+		// only the leader can handle token creating, we don't ever want to enter into refreshing process if we are
+		// getting request in vault follower node
+		return nil, logical.ErrReadOnly
+	}
 	var err error
 	name := data.Get("name").(string)
-
+	b.Logger().Info(fmt.Sprintf("Creating Venafi secret: %s", name))
 	url := data.Get("url").(string)
 	var tppUrl, cloudUrl string
 
@@ -205,29 +215,35 @@ func (b *backend) pathVenafiSecretCreate(ctx context.Context, req *logical.Reque
 		Fakemode:        data.Get("fakemode").(bool),
 	}
 
+	b.Logger().Info(fmt.Sprintf("Validating data for venafi secret %s", name))
 	err = validateVenafiSecretEntry(entry)
 	if err != nil {
+		b.Logger().Error(fmt.Sprintf("Error with venafi secret data: %s", err.Error()))
 		return logical.ErrorResponse(err.Error()), nil
 	}
-
 	if entry.RefreshToken != "" && !entry.Fakemode {
-
+		b.Logger().Info("Refresh tokens are provided. Setting up data")
 		for i := 0; i < 2; i++ {
 
+			b.Logger().Info("creating config for refreshing tokens")
 			cfg, err := createConfigFromFieldData(entry)
 			if err != nil {
+				b.Logger().Error(fmt.Sprintf("Error during venafi secret creation: creating config error: %s", err.Error()))
 				return logical.ErrorResponse(err.Error()), nil
 			}
 
+			b.Logger().Info("Refreshing tokens during Venafi secret creation")
 			tokenInfo, err := getAccessData(cfg)
 			if err != nil {
+				b.Logger().Error(fmt.Sprintf("Error during venafi secret creation: refreshing tokens error: %s", err.Error()))
 				return logical.ErrorResponse(err.Error()), nil
 			}
 
 			if i == 0 && tokenInfo.Refresh_token != "" {
 				// ensure refresh interval is proactive by not allowing it to be longer than access token is valid
 				maxInterval := time.Until(time.Unix(int64(tokenInfo.Expires), 0)).Round(time.Minute) - time.Duration(30)*time.Second
 				if maxInterval < entry.RefreshInterval {
+					b.Logger().Info("Refresh interval is not correct since is longer than access token validity. Setting up a proper one")
 					entry.RefreshInterval = maxInterval
 				}
 
@@ -245,16 +261,21 @@ func (b *backend) pathVenafiSecretCreate(ctx context.Context, req *logical.Reque
 				}
 			}
 		}
+		b.Logger().Info("Success setting up refresh token data of Venafi secret")
 	}
 
 	//Store it
+	b.Logger().Info("Setting up data for entry of Venafi secret")
 	jsonEntry, err := logical.StorageEntryJSON(CredentialsRootPath+name, entry)
 	if err != nil {
+		b.Logger().Error(fmt.Sprintf("Error during venafi secret creation: error setting up refresh tokens for storage: %s", err.Error()))
 		return nil, err
 	}
 
+	b.Logger().Info("Storing entry of Venafi secret")
 	err = req.Storage.Put(ctx, jsonEntry)
 	if err != nil {
+		b.Logger().Error(fmt.Sprintf("Error during venafi secret creation: error storing refresh tokens: %s", err.Error()))
 		return nil, err
 	}
 
@@ -269,9 +290,10 @@ func (b *backend) pathVenafiSecretCreate(ctx context.Context, req *logical.Reque
 			Redirect: "",
 			Warnings: warnings,
 		}
+		b.Logger().Info(fmt.Sprintf("Sucess on creating Venafi secret %s (with warnings)", name))
 		return logResp, nil
 	}
-
+	b.Logger().Info(fmt.Sprintf("Sucess on creating Venafi secret %s", name))
 	return nil, nil
 }
 

plugin/pki/util.go

@@ -254,11 +254,13 @@ func updateAccessToken(b *backend, ctx context.Context, req *logical.Request, cf
 	b.mux.Lock()
 	defer b.mux.Unlock()
 
+	b.Logger().Info("Verifying again if token still needs refresh")
 	refreshNeeded, refreshToken, err := isTokenRefreshNeeded(b, ctx, req.Storage, role.VenafiSecret)
 	if err != nil {
 		return err
 	}
 	if !refreshNeeded {
+		b.Logger().Info("Refresh is not needed. Another process updated the tokens already")
 		return nil // we're done, another thread beat us to it
 	}
 
@@ -272,46 +274,49 @@ func updateAccessToken(b *backend, ctx context.Context, req *logical.Request, cf
 
 	tppConnector.SetHTTPClient(httpClient)
 
-	b.Logger().Debug("Refreshing token")
+	b.Logger().Info("Refreshing access_token")
 	var resp tpp.OauthRefreshAccessTokenResponse
 	resp, err = tppConnector.RefreshAccessToken(&endpoint.Authentication{
 		RefreshToken: refreshToken,
 		ClientId:     "hashicorp-vault-by-venafi",
 		Scope:        "certificate:manage,revoke",
 	})
 	if resp.Access_token != "" && resp.Refresh_token != "" {
-		err = storeAccessData(b, ctx, req, role.Name, resp)
+		b.Logger().Info("Storing new token")
+		err = storeAccessData(b, ctx, req, role, resp)
 	}
 	return err
 }
 
-func storeAccessData(b *backend, ctx context.Context, req *logical.Request, roleName string, resp tpp.OauthRefreshAccessTokenResponse) error {
-	entry, err := b.getRole(ctx, req.Storage, roleName)
+func storeAccessData(b *backend, ctx context.Context, req *logical.Request, role *roleEntry, resp tpp.OauthRefreshAccessTokenResponse) error {
 
-	if err != nil {
-		return err
-	}
-
-	if entry.VenafiSecret == "" {
-		return fmt.Errorf("Role " + roleName + " does not have any Venafi secret associated")
+	if role.VenafiSecret == "" {
+		return fmt.Errorf("Role " + role.Name + " does not have any Venafi secret associated")
 	}
 
-	venafiEntry, err := b.getVenafiSecret(ctx, req.Storage, entry.VenafiSecret)
+	venafiEntry, err := b.getVenafiSecret(ctx, req.Storage, role.VenafiSecret)
 	if err != nil {
 		return err
 	}
 
+	b.Logger().Info("swapping tokens")
 	venafiEntry.RefreshToken2 = venafiEntry.RefreshToken
+	b.Logger().Info("setting new access_token")
 	venafiEntry.AccessToken = resp.Access_token
+	b.Logger().Info("setting new refresh_token")
 	venafiEntry.RefreshToken = resp.Refresh_token
 	venafiEntry.NextRefresh = time.Now().Add(venafiEntry.RefreshInterval)
-
+	b.Logger().Info(fmt.Sprintf("Setting new time refresh: %s", venafiEntry.NextRefresh.String()))
 	// Store it
-	jsonEntry, err := logical.StorageEntryJSON(CredentialsRootPath+entry.VenafiSecret, venafiEntry)
+	b.Logger().Info("preparing tokens for storage")
+	jsonEntry, err := logical.StorageEntryJSON(CredentialsRootPath+role.VenafiSecret, venafiEntry)
 	if err != nil {
+		b.Logger().Error("Error on creating new tokens into venafi secret:", err.Error())
 		return err
 	}
+	b.Logger().Info("storing new tokens")
 	if err := req.Storage.Put(ctx, jsonEntry); err != nil {
+		b.Logger().Error("Error on storing new tokens into Venafi secret:", err.Error())
 		return err
 	}
 	return nil
@@ -438,7 +443,6 @@ func createConfigFromFieldData(data *venafiSecretEntry) (*vcert.Config, error) {
 	cfg.ConnectorType = endpoint.ConnectorTypeTPP
 
 	cfg.Credentials = &endpoint.Authentication{
-
 		AccessToken:  data.AccessToken,
 		RefreshToken: data.RefreshToken,
 	}