Add logging to the JWT generation for ambient credentials

README.md

@@ -95,8 +95,11 @@ Command Issuer enrolls certificates by submitting a POST request to the Command
     > Documentation for [Version Two Permission Model](https://software.keyfactor.com/Core-OnPrem/Current/Content/ReferenceGuide/SecurityRolePermissions.htm#VersionTwoPermissionModel) and [Version One Permission Model](https://software.keyfactor.com/Core-OnPrem/Current/Content/ReferenceGuide/SecurityRolePermissions.htm#VersionOnePermissionModel)
 
 ![Permission Metadata Read](./docsource/images/security_permission_metadata_read.png)
+
 ![Permission Certificate CSR Enrollment](./docsource/images/security_permission_enrollment_csr.png)
+
 ![Certificate Authority Allowed Requester](./docsource/images/ca_allowed_requester.png)
+
 ![Certificate Template Allowed Requester](./docsource/images/cert_template_allowed_requester.png)
 
 ## Installing Command Issuer

internal/command/client.go

@@ -18,11 +18,14 @@ package command
 
 import (
 	"fmt"
+	"strings"
 
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore"
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
 	"github.com/Azure/azure-sdk-for-go/sdk/azidentity"
 	commandsdk "github.com/Keyfactor/keyfactor-go-client/v3/api"
+	"github.com/go-logr/logr"
+	"github.com/golang-jwt/jwt/v5"
 	"golang.org/x/net/context"
 	"golang.org/x/oauth2"
 	"golang.org/x/oauth2/google"
@@ -95,6 +98,11 @@ type azure struct {
 
 // GetAccessToken implements TokenCredential.
 func (a *azure) GetAccessToken(ctx context.Context) (string, error) {
+	log := log.FromContext(ctx)
+
+	// To prevent clogging logs every time JWT is generated
+	initializing := a.cred == nil
+
 	// Lazily create the credential if needed
 	if a.cred == nil {
 		c, err := azidentity.NewDefaultAzureCredential(nil)
@@ -104,6 +112,8 @@ func (a *azure) GetAccessToken(ctx context.Context) (string, error) {
 		a.cred = c
 	}
 
+	log.Info(fmt.Sprintf("generating Default Azure Credentials with scopes %s", strings.Join(a.scopes, " ")))
+
 	// Request a token with the provided scopes
 	token, err := a.cred.GetToken(ctx, policy.TokenRequestOptions{
 		Scopes: a.scopes,
@@ -112,8 +122,20 @@ func (a *azure) GetAccessToken(ctx context.Context) (string, error) {
 		return "", fmt.Errorf("%w: failed to fetch token: %w", errTokenFetchFailure, err)
 	}
 
-	log.FromContext(ctx).Info("fetched token using Azure DefaultAzureCredential")
-	return token.Token, nil
+	tokenString := token.Token
+
+	if initializing {
+		// Only want to output this once, don't want to output this every time the JWT is generated
+
+		log.Info("==== BEGIN DEBUG: DefaultAzureCredential JWT ======")
+
+		printClaims(log, tokenString, []string{"aud", "azp", "iss", "sub", "oid"})
+
+		log.Info("==== END DEBUG: DefaultAzureCredential JWT ======")
+	}
+
+	log.Info("fetched token using Azure DefaultAzureCredential")
+	return tokenString, nil
 }
 
 func newAzureDefaultCredentialSource(ctx context.Context, scopes []string) (*azure, error) {
@@ -142,17 +164,28 @@ type gcp struct {
 
 // GetAccessToken implements TokenCredential.
 func (g *gcp) GetAccessToken(ctx context.Context) (string, error) {
-	// Lazily create the TokenSource if it's nil.
 	log := log.FromContext(ctx)
+
+	// To prevent clogging logs every time JWT is generated
+	initializing := g.tokenSource == nil
+
+	// Lazily create the TokenSource if it's nil.
 	if g.tokenSource == nil {
+		log.Info(fmt.Sprintf("generating default Google credentials with scopes: %s", strings.Join(g.scopes, " ")))
+
 		credentials, err := google.FindDefaultCredentials(ctx, g.scopes...)
 		if err != nil {
 			return "", fmt.Errorf("%w: failed to find GCP ADC: %w", errTokenFetchFailure, err)
 		}
 		log.Info(fmt.Sprintf("generating a Google OIDC ID token..."))
 
+		// Default audience to "command" if not provided
+		aud := getValueOrDefault(g.audience, "command")
+
+		log.Info(fmt.Sprintf("generating Google id token with audience %s", aud))
+
 		// Use credentials to generate a JWT (requires a service account)
-		tokenSource, err := idtoken.NewTokenSource(ctx, getValueOrDefault(g.audience, "command"), idtoken.WithCredentialsJSON(credentials.JSON))
+		tokenSource, err := idtoken.NewTokenSource(ctx, aud, idtoken.WithCredentialsJSON(credentials.JSON))
 		if err != nil {
 			return "", fmt.Errorf("%w: failed to get GCP ID Token Source: %w", errTokenFetchFailure, err)
 		}
@@ -171,6 +204,14 @@ func (g *gcp) GetAccessToken(ctx context.Context) (string, error) {
 		return "", fmt.Errorf("%w: failed to fetch token from GCP ADC token source: %w", errTokenFetchFailure, err)
 	}
 
+	if initializing {
+		// Only want to output this once, don't want to output this every time the JWT is generated
+
+		log.Info("==== BEGIN DEBUG: Default Google ID Token JWT ======")
+		printClaims(log, token.AccessToken, []string{"aud", "iss", "sub", "email"})
+		log.Info("==== END DEBUG:  Default Google ID Token JWT ======")
+	}
+
 	log.Info("fetched token using GCP ApplicationDefaultCredential")
 
 	return token.AccessToken, nil
@@ -188,3 +229,21 @@ func newGCPDefaultCredentialSource(ctx context.Context, audience string, scopes
 	tokenCredentialSource = source
 	return source, nil
 }
+
+func printClaims(log logr.Logger, token string, claimsToPrint []string) error {
+	tokenRaw, _, err := new(jwt.Parser).ParseUnverified(token, jwt.MapClaims{})
+	if err != nil {
+		log.Error(err, "failed to parse JWT")
+		return fmt.Errorf("failed to parse JWT: %w", err)
+	}
+
+	claims, _ := tokenRaw.Claims.(jwt.MapClaims)
+
+	for _, key := range claimsToPrint {
+		if value, ok := claims[key]; ok {
+			log.Info(fmt.Sprintf("	%s:	%s", key, value))
+		}
+	}
+
+	return nil
+}

internal/command/client_test.go

@@ -0,0 +1,57 @@
+package command
+
+import (
+	"testing"
+
+	"github.com/go-logr/logr/testr"
+	"github.com/golang-jwt/jwt/v5"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestPrintClaims(t *testing.T) {
+	t.Run("valid jwt returns no error", func(t *testing.T) {
+		// Sample JWT with dummy claims (no signature needed for ParseUnverified)
+		claims := jwt.MapClaims{
+			"aud": "api://1234",
+			"iss": "https://sts.windows.net/tenant-id/",
+			"sub": "user-id",
+		}
+		token := createUnsignedJWT(t, claims)
+
+		// Use testr logger
+		testLogger := testr.New(t)
+
+		// Call the function
+		err := printClaims(testLogger, token, []string{"aud", "iss", "sub"})
+		assert.NoError(t, err)
+	})
+
+	t.Run("invalid jwt returns an error", func(t *testing.T) {
+		// Use testr logger
+		testLogger := testr.New(t)
+
+		// Call the function
+		err := printClaims(testLogger, "abcdefghijklmnop", []string{"aud", "iss", "sub"})
+		assert.Error(t, err)
+	})
+
+	t.Run("jwt with no claims returns error", func(t *testing.T) {
+		// Use testr logger
+		testLogger := testr.New(t)
+
+		// Call the function
+		err := printClaims(testLogger, "eyJhbGciOiJub25lIiwidHlwIjoiSldUIn0..", []string{"aud", "iss", "sub"})
+		assert.Error(t, err)
+	})
+}
+
+func createUnsignedJWT(t *testing.T, claims jwt.MapClaims) string {
+	t.Helper()
+
+	token := jwt.NewWithClaims(jwt.SigningMethodNone, claims)
+	str, err := token.SignedString(jwt.UnsafeAllowNoneSignatureType)
+	if err != nil {
+		t.Fatalf("failed to create test token: %v", err)
+	}
+	return str
+}