auth: adds option to enable verbose logging during sso (#24892)

Co-authored-by: James Rasell <jrasell@users.noreply.github.com>

.changelog/24892.txt

@@ -0,0 +1,3 @@
+```release-note:improvement
+auth: adds `VerboseLogging` option to auth-method config for debugging SSO
+```

api/acl.go

@@ -857,6 +857,9 @@ type ACLAuthMethodConfig struct {
 	// (value).
 	ClaimMappings     map[string]string
 	ListClaimMappings map[string]string
+	// Enables logging of claims and binding-rule evaluations when
+	// debug level logging is enabled.
+	VerboseLogging bool
 }
 
 // MarshalJSON implements the json.Marshaler interface and allows

lib/auth/binder.go

@@ -8,6 +8,7 @@ import (
 	"strings"
 
 	"github.com/hashicorp/go-bexpr"
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-memdb"
 	"github.com/hashicorp/hil"
 	"github.com/hashicorp/hil/ast"
@@ -53,7 +54,7 @@ func (b *Bindings) None() bool {
 }
 
 // Bind collects the ACL roles and policies to be assigned to the created token.
-func (b *Binder) Bind(authMethod *structs.ACLAuthMethod, identity *Identity) (*Bindings, error) {
+func (b *Binder) Bind(vlog hclog.Logger, authMethod *structs.ACLAuthMethod, identity *Identity) (*Bindings, error) {
 	var (
 		bindings Bindings
 		err      error
@@ -75,6 +76,9 @@ func (b *Binder) Bind(authMethod *structs.ACLAuthMethod, identity *Identity) (*B
 		rule := raw.(*structs.ACLBindingRule)
 		if doesSelectorMatch(rule.Selector, identity.Claims) {
 			matchingRules = append(matchingRules, rule)
+			vlog.Debug("binding-rule selector matches an identity claim, will evaluate bind-name", "selector", rule.Selector)
+		} else {
+			vlog.Debug("bind-rule selector did not match any claims", "selector", rule.Selector)
 		}
 	}
 	if len(matchingRules) == 0 {
@@ -103,6 +107,9 @@ func (b *Binder) Bind(authMethod *structs.ACLAuthMethod, identity *Identity) (*B
 				bindings.Roles = append(bindings.Roles, &structs.ACLTokenRoleLink{
 					ID: role.ID,
 				})
+				vlog.Debug("role found with name matching ACL binding-rule", "name", bindName)
+			} else {
+				vlog.Debug("no role found with name matching ACL binding-rule", "name", bindName)
 			}
 		case structs.ACLBindingRuleBindTypePolicy:
 			policy, err := b.store.ACLPolicyByName(nil, bindName)
@@ -112,8 +119,12 @@ func (b *Binder) Bind(authMethod *structs.ACLAuthMethod, identity *Identity) (*B
 
 			if policy != nil {
 				bindings.Policies = append(bindings.Policies, policy.Name)
+				vlog.Debug("policy found with name matching ACL binding-rule", "name", bindName)
+			} else {
+				vlog.Debug("no policy found with name matching ACL binding-rule", "name", bindName)
 			}
 		case structs.ACLBindingRuleBindTypeManagement:
+			vlog.Debug("management ACL binding-rule found", "name", bindName)
 			bindings.Management = true
 			bindings.Policies = nil
 			bindings.Roles = nil

lib/auth/binder_test.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/shoenig/test/must"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/nomad/ci"
 	"github.com/hashicorp/nomad/helper/uuid"
 	"github.com/hashicorp/nomad/nomad/mock"
@@ -115,7 +116,8 @@ func TestBinder_Bind(t *testing.T) {
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			got, err := testBind.Bind(tt.authMethod, tt.identity)
+			l := hclog.NewNullLogger()
+			got, err := testBind.Bind(l, tt.authMethod, tt.identity)
 			if tt.wantErr {
 				must.Error(t, err)
 			} else {

nomad/acl_endpoint.go

@@ -5,6 +5,7 @@ package nomad
 
 import (
 	"context"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"net/http"
@@ -52,6 +53,10 @@ const (
 	// aclLoginRequestExpiryTime is the deadline used when performing HTTP
 	// requests to external APIs during the validation of bearer tokens.
 	aclLoginRequestExpiryTime = 60 * time.Second
+
+	// verboseLoggingMessage is the message displayed to a user when
+	// this auth config is enabled
+	verboseLoggingMessage = "attempting login with verbose logging enabled"
 )
 
 // ACL endpoint is used for manipulating ACL tokens and policies
@@ -2691,6 +2696,14 @@ func (a *ACL) OIDCCompleteAuth(
 		return structs.NewErrRPCCodedf(http.StatusBadRequest, "auth-method %q not found", args.AuthMethodName)
 	}
 
+	// vlog is a verbose logger used for debugging OIDC in test environments
+	vlog := hclog.NewNullLogger()
+	if authMethod.Config.VerboseLogging {
+		vlog = a.logger
+	}
+
+	vlog.Debug(verboseLoggingMessage)
+
 	// If the authentication method generates global ACL tokens, we need to
 	// forward the request onto the authoritative regional leader.
 	if authMethod.TokenLocalityIsGlobal() {
@@ -2761,6 +2774,29 @@ func (a *ACL) OIDCCompleteAuth(
 		return err
 	}
 
+	// No need to do all this marshaling if VerboseLogging is disabled
+	if authMethod.Config.VerboseLogging {
+		idTokenClaimBytes, err := json.MarshalIndent(idTokenClaims, "", " ")
+		if err != nil {
+			vlog.Debug("failed to marshal ID token claims")
+		}
+
+		userClaimBytes, err := json.MarshalIndent(userClaims, "", " ")
+		if err != nil {
+			vlog.Debug("failed to marshal user claims")
+		}
+		vlog.Debug("claims from jwt token and user info endpoint",
+			"token_claims", string(idTokenClaimBytes),
+			"user_claims", string(userClaimBytes),
+		)
+
+		internalClaimBytes, err := json.MarshalIndent(oidcInternalClaims.List, "", " ")
+		if err != nil {
+			vlog.Debug("failed to marshal OIDC internal claims list")
+		}
+		vlog.Debug("claims after mapping to nomad identity attributes", "internal_claims", string(internalClaimBytes))
+	}
+
 	// Create a new binder object based on the current state snapshot to
 	// provide consistency within the RPC handler.
 	oidcBinder := auth.NewBinder(stateSnapshot)
@@ -2768,7 +2804,7 @@ func (a *ACL) OIDCCompleteAuth(
 	// Generate the role and policy bindings that will be assigned to the ACL
 	// token. Ensure we have at least 1 role or policy, otherwise the RPC will
 	// fail anyway.
-	tokenBindings, err := oidcBinder.Bind(authMethod, auth.NewIdentity(authMethod.Config, oidcInternalClaims))
+	tokenBindings, err := oidcBinder.Bind(vlog, authMethod, auth.NewIdentity(authMethod.Config, oidcInternalClaims))
 	if err != nil {
 		return err
 	}
@@ -2910,6 +2946,14 @@ func (a *ACL) Login(args *structs.ACLLoginRequest, reply *structs.ACLLoginRespon
 		)
 	}
 
+	// vlog is a verbose logger used for debugging in test environments
+	vlog := hclog.NewNullLogger()
+	if authMethod.Config.VerboseLogging {
+		vlog = a.logger
+	}
+
+	vlog.Debug(verboseLoggingMessage)
+
 	// Create a new binder object based on the current state snapshot to
 	// provide consistency within the RPC handler.
 	jwtBinder := auth.NewBinder(stateSnapshot)
@@ -2921,7 +2965,22 @@ func (a *ACL) Login(args *structs.ACLLoginRequest, reply *structs.ACLLoginRespon
 		return err
 	}
 
-	tokenBindings, err := jwtBinder.Bind(authMethod, auth.NewIdentity(authMethod.Config, jwtClaims))
+	// No need to do marshaling if VerboseLogging is not enabled
+	if authMethod.Config.VerboseLogging {
+		idTokenClaimBytes, err := json.MarshalIndent(claims, "", " ")
+		if err != nil {
+			vlog.Debug("failed to marshal token claims")
+		}
+		vlog.Debug("jwt token claims", "token_claims", string(idTokenClaimBytes))
+
+		internalClaimBytes, err := json.MarshalIndent(jwtClaims.List, "", " ")
+		if err != nil {
+			vlog.Debug("failed to marshal claims list")
+		}
+		vlog.Debug("claims after mapping to nomad identity attributes", "internal_claims", string(internalClaimBytes))
+	}
+
+	tokenBindings, err := jwtBinder.Bind(vlog, authMethod, auth.NewIdentity(authMethod.Config, jwtClaims))
 	if err != nil {
 		return err
 	}

nomad/acl_endpoint_test.go

@@ -4,15 +4,19 @@
 package nomad
 
 import (
+	"bytes"
 	"fmt"
+	"io"
 	"net/url"
 	"os"
 	"path/filepath"
+	"strings"
 	"testing"
 	"time"
 
 	"github.com/golang-jwt/jwt/v5"
 	capOIDC "github.com/hashicorp/cap/oidc"
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-memdb"
 	msgpackrpc "github.com/hashicorp/net-rpc-msgpackrpc/v2"
 	"github.com/hashicorp/nomad/ci"
@@ -3631,7 +3635,14 @@ func TestACL_OIDCAuthURL(t *testing.T) {
 func TestACL_OIDCCompleteAuth(t *testing.T) {
 	ci.Parallel(t)
 
-	testServer, _, testServerCleanupFn := TestACLServer(t, nil)
+	// setup logging output to test verbose logging
+	var buf bytes.Buffer
+	testServer, _, testServerCleanupFn := TestACLServer(t, func(c *Config) {
+		c.Logger = hclog.NewInterceptLogger(&hclog.LoggerOptions{
+			Level:  hclog.Debug,
+			Output: io.MultiWriter(&buf, os.Stderr),
+		})
+	})
 	defer testServerCleanupFn()
 	codec := rpcClient(t, testServer)
 	testutil.WaitForLeader(t, testServer.RPC)
@@ -3720,6 +3731,12 @@ func TestACL_OIDCCompleteAuth(t *testing.T) {
 	must.Error(t, err)
 	must.ErrorContains(t, err, "400")
 	must.ErrorContains(t, err, "no role or policy bindings matched")
+	must.False(t, strings.Contains(buf.String(), verboseLoggingMessage))
+
+	// Reset buf and enable verbose logging
+	buf.Reset()
+	mockedAuthMethod.Config.VerboseLogging = true
+	must.NoError(t, testServer.fsm.State().UpsertACLAuthMethods(11, []*structs.ACLAuthMethod{mockedAuthMethod}))
 
 	// Upsert an ACL policy and role, so that we can reference this within our
 	// OIDC claims.
@@ -3767,6 +3784,7 @@ func TestACL_OIDCCompleteAuth(t *testing.T) {
 	must.Len(t, 1, completeAuthResp4.ACLToken.Roles)
 	must.Eq(t, mockACLRole.Name, completeAuthResp4.ACLToken.Roles[0].Name)
 	must.Eq(t, mockACLRole.ID, completeAuthResp4.ACLToken.Roles[0].ID)
+	must.True(t, strings.Contains(buf.String(), verboseLoggingMessage))
 
 	// Create a binding rule which generates management tokens. This should
 	// override the other rules, giving us a management token when we next
@@ -3803,7 +3821,14 @@ func TestACL_OIDCCompleteAuth(t *testing.T) {
 func TestACL_Login(t *testing.T) {
 	ci.Parallel(t)
 
-	testServer, _, testServerCleanupFn := TestACLServer(t, nil)
+	// setup logging output to test verbose logging
+	var buf bytes.Buffer
+	testServer, _, testServerCleanupFn := TestACLServer(t, func(c *Config) {
+		c.Logger = hclog.NewInterceptLogger(&hclog.LoggerOptions{
+			Level:  hclog.Debug,
+			Output: io.MultiWriter(&buf, os.Stderr),
+		})
+	})
 	defer testServerCleanupFn()
 	codec := rpcClient(t, testServer)
 	testutil.WaitForLeader(t, testServer.RPC)
@@ -3885,6 +3910,12 @@ func TestACL_Login(t *testing.T) {
 	must.Error(t, err)
 	must.ErrorContains(t, err, "400")
 	must.ErrorContains(t, err, "no role or policy bindings matched")
+	must.False(t, strings.Contains(buf.String(), verboseLoggingMessage))
+
+	// Reset buf and enable verbose logging
+	buf.Reset()
+	mockedAuthMethod.Config.VerboseLogging = true
+	must.NoError(t, testServer.fsm.State().UpsertACLAuthMethods(11, []*structs.ACLAuthMethod{mockedAuthMethod}))
 
 	// Upsert an ACL policy and role, so that we can reference this within our
 	// JWT claims.
@@ -3930,6 +3961,7 @@ func TestACL_Login(t *testing.T) {
 	must.Eq(t, mockACLRole.Name, completeAuthResp4.ACLToken.Roles[0].Name)
 	must.Eq(t, mockACLRole.ID, completeAuthResp4.ACLToken.Roles[0].ID)
 	must.Eq(t, mockedAuthMethod.Type+"-"+mockedAuthMethod.Name, completeAuthResp4.ACLToken.Name)
+	must.True(t, strings.Contains(buf.String(), verboseLoggingMessage))
 
 	// Create a binding rule which generates management tokens. This should
 	// override the other rules, giving us a management token when we next

nomad/mock/acl.go

@@ -283,6 +283,7 @@ func ACLOIDCAuthMethod() *structs.ACLAuthMethod {
 			SigningAlgs:         []string{"RS256"},
 			ClaimMappings:       map[string]string{"foo": "bar"},
 			ListClaimMappings:   map[string]string{"foo": "bar"},
+			VerboseLogging:      false,
 		},
 		CreateTime:  time.Now().UTC(),
 		CreateIndex: 10,

nomad/structs/acl.go

@@ -795,6 +795,7 @@ func (a *ACLAuthMethod) SetHash() []byte {
 		_, _ = hash.Write([]byte(a.Config.OIDCClientID))
 		_, _ = hash.Write([]byte(a.Config.OIDCClientSecret))
 		_, _ = hash.Write([]byte(strconv.FormatBool(a.Config.OIDCDisableUserInfo)))
+		_, _ = hash.Write([]byte(strconv.FormatBool(a.Config.VerboseLogging)))
 		_, _ = hash.Write([]byte(a.Config.ExpirationLeeway.String()))
 		_, _ = hash.Write([]byte(a.Config.NotBeforeLeeway.String()))
 		_, _ = hash.Write([]byte(a.Config.ClockSkewLeeway.String()))
@@ -1043,6 +1044,10 @@ type ACLAuthMethodConfig struct {
 	// (value).
 	ClaimMappings     map[string]string
 	ListClaimMappings map[string]string
+
+	// Enables logging of claims and binding-rule evaluations when
+	// debug level logging is enabled.
+	VerboseLogging bool
 }
 
 func (a *ACLAuthMethodConfig) Copy() *ACLAuthMethodConfig {

website/content/api-docs/acl/auth-methods.mdx

@@ -116,6 +116,10 @@ The table below shows this endpoint's support for
     copied to a metadata field (value). Use this if the claim you are capturing is
     list-like (such as groups).
 
+  - `VerboseLogging` `(bool: false)` - When set to `true`, Nomad will log token claims
+    and information related to binding-rule and role/policy evaluations. Not recommended
+    in production since sensitive information may be present.
+
 ### Sample payload
 
 ```json