From 653f4af8929ba3eccf5b863771254461cdb65094 Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Mon, 13 Jan 2020 16:23:56 -0800
Subject: [PATCH 1/9] agent: add and edit doc comments

---
 agent/agent.go | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/agent/agent.go b/agent/agent.go
index 37f3108eab2d..1c2a10005a66 100644
--- a/agent/agent.go
+++ b/agent/agent.go
@@ -152,7 +152,7 @@ type notifier interface {
 	Notify(string) error
 }
 
-// The agent is the long running process that is run on every machine.
+// Agent is the long running process that is run on every machine.
 // It exposes an RPC interface that is used by the CLI to control the
 // agent. The agent runs the query interfaces like HTTP, DNS, and RPC.
 // However, it can run in either a client, or server mode. In server
@@ -309,6 +309,8 @@ type Agent struct {
 	persistedTokensLock sync.RWMutex
 }
 
+// New verifies the configuration given has a Datacenter and DataDir
+// configured, and maps the remaining config fields to fields on the Agent.
 func New(c *config.RuntimeConfig, logger *log.Logger) (*Agent, error) {
 	if c.Datacenter == "" {
 		return nil, fmt.Errorf("Must configure a Datacenter")
@@ -353,6 +355,7 @@ func New(c *config.RuntimeConfig, logger *log.Logger) (*Agent, error) {
 	return &a, nil
 }
 
+// LocalConfig takes a config.RuntimeConfig and maps the fields to a local.Config
 func LocalConfig(cfg *config.RuntimeConfig) local.Config {
 	lc := local.Config{
 		AdvertiseAddr:       cfg.AdvertiseAddrLAN.String(),
@@ -369,6 +372,7 @@ func LocalConfig(cfg *config.RuntimeConfig) local.Config {
 	return lc
 }
 
+// Start verifies its configuration and runs an agent's various subprocesses.
 func (a *Agent) Start() error {
 	a.stateLock.Lock()
 	defer a.stateLock.Unlock()
@@ -1877,7 +1881,7 @@ func (a *Agent) ResumeSync() {
 	}
 }
 
-// syncPausedCh returns either a channel or nil. If nil sync is not paused. If
+// SyncPausedCh returns either a channel or nil. If nil sync is not paused. If
 // non-nil, the channel will be closed when sync resumes.
 func (a *Agent) SyncPausedCh() <-chan struct{} {
 	a.syncMu.Lock()

From 7d1dcf380efed0e4450d765d9d0695f2fbf36bea Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Tue, 21 Jan 2020 17:33:11 -0800
Subject: [PATCH 2/9] agent: add ACL token accessorID to debugging traces

---
 agent/acl.go                       | 30 +++++++++++--
 agent/agent.go                     | 13 +++++-
 agent/consul/acl.go                | 24 ++++++++---
 agent/consul/acl_endpoint.go       | 15 +++++++
 agent/consul/acl_server.go         | 23 ++++++++++
 agent/consul/intention_endpoint.go | 68 ++++++++++++++++++++++++------
 agent/consul/internal_endpoint.go  | 31 ++++++++++++--
 agent/local/state.go               | 58 +++++++++++++++++++------
 8 files changed, 222 insertions(+), 40 deletions(-)

diff --git a/agent/acl.go b/agent/acl.go
index 30788b96a263..6227024de9ca 100644
--- a/agent/acl.go
+++ b/agent/acl.go
@@ -41,6 +41,21 @@ func (a *Agent) resolveTokenAndDefaultMeta(id string, entMeta *structs.Enterpris
 	return a.delegate.ResolveTokenAndDefaultMeta(id, entMeta, authzContext)
 }
 
+// ResolveIdentityFromToken is used to resolve an ACL token secret a structs.ACLIdentity.
+func (a *Agent) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentity, error) {
+	// ACLs are disabled
+	if !a.delegate.ACLsEnabled() {
+		return false, nil, nil
+	}
+
+	// Disable ACLs if version 8 enforcement isn't enabled.
+	if !a.config.ACLEnforceVersion8 {
+		return false, nil, nil
+	}
+
+	return a.delegate.ResolveIdentityFromToken(token)
+}
+
 func (a *Agent) initializeACLs() error {
 	// Build a policy for the agent master token.
 	// The builtin agent master policy allows reading any node information
@@ -241,6 +256,11 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 		return nil
 	}
 
+	_, tokenIdent, err := a.delegate.ResolveIdentityFromToken(token)
+	if err != nil {
+		a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%v", err)
+	}
+
 	var authzContext acl.AuthorizerContext
 	structs.DefaultEnterpriseMeta().FillAuthzContext(&authzContext)
 	// Filter out members based on the node policy.
@@ -250,7 +270,11 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 		if rule.NodeRead(node, &authzContext) == acl.Allow {
 			continue
 		}
-		a.logger.Printf("[DEBUG] agent: dropping node %q from result due to ACLs", node)
+		var accessorID string
+		if tokenIdent != nil {
+			accessorID = tokenIdent.ID()
+		}
+		a.logger.Printf("[DEBUG] agent: dropping node from result due to ACLs, node=%q accessorID=%v", node, accessorID)
 		m = append(m[:i], m[i+1:]...)
 		i--
 	}
@@ -280,7 +304,7 @@ func (a *Agent) filterServicesWithAuthorizer(authz acl.Authorizer, services *map
 		if authz.ServiceRead(service.Service, &authzContext) == acl.Allow {
 			continue
 		}
-		a.logger.Printf("[DEBUG] agent: dropping service %q from result due to ACLs", id.String())
+		a.logger.Printf("[DEBUG] agent: dropping service from result due to ACLs, service=%q ", id.String())
 		delete(*services, id)
 	}
 	return nil
@@ -316,7 +340,7 @@ func (a *Agent) filterChecksWithAuthorizer(authz acl.Authorizer, checks *map[str
 				continue
 			}
 		}
-		a.logger.Printf("[DEBUG] agent: dropping check %q from result due to ACLs", id.String())
+		a.logger.Printf("[DEBUG] agent: dropping check from result due to ACLs, check=%q ", id.String())
 		delete(*checks, id)
 	}
 	return nil
diff --git a/agent/agent.go b/agent/agent.go
index 1c2a10005a66..0bf71823114f 100644
--- a/agent/agent.go
+++ b/agent/agent.go
@@ -137,6 +137,7 @@ type delegate interface {
 	RemoveFailedNode(node string, prune bool) error
 	ResolveToken(secretID string) (acl.Authorizer, error)
 	ResolveTokenAndDefaultMeta(secretID string, entMeta *structs.EnterpriseMeta, authzContext *acl.AuthorizerContext) (acl.Authorizer, error)
+	ResolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error)
 	RPC(method string, args interface{}, reply interface{}) error
 	ACLsEnabled() bool
 	UseLegacyACLs() bool
@@ -1925,17 +1926,25 @@ OUTER:
 			}
 
 			for segment, coord := range cs {
+				agentToken := a.tokens.AgentToken()
 				req := structs.CoordinateUpdateRequest{
 					Datacenter:   a.config.Datacenter,
 					Node:         a.config.NodeName,
 					Segment:      segment,
 					Coord:        coord,
-					WriteRequest: structs.WriteRequest{Token: a.tokens.AgentToken()},
+					WriteRequest: structs.WriteRequest{Token: agentToken},
 				}
 				var reply struct{}
+				//  todo(mkcp) port all of these logger calls to hclog w/ loglevel configuration
 				if err := a.RPC("Coordinate.Update", &req, &reply); err != nil {
 					if acl.IsErrPermissionDenied(err) {
-						a.logger.Printf("[WARN] agent: Coordinate update blocked by ACLs")
+						_, tokenIdent, err2 := a.ResolveIdentityFromToken(agentToken)
+						if err2 != nil {
+							a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%v", err2)
+						}
+						if tokenIdent != nil {
+							a.logger.Printf("[DEBUG] agent: Coordinate update blocked by ACLs, accessorID=%v", tokenIdent.ID())
+						}
 					} else {
 						a.logger.Printf("[ERR] agent: Coordinate update error: %v", err)
 					}
diff --git a/agent/consul/acl.go b/agent/consul/acl.go
index 1ce52dfa6607..de263cba2699 100644
--- a/agent/consul/acl.go
+++ b/agent/consul/acl.go
@@ -178,7 +178,7 @@ type ACLResolverConfig struct {
 //   - Resolving tokens locally via the ACLResolverDelegate
 //   - Resolving policies locally via the ACLResolverDelegate
 //   - Resolving roles locally via the ACLResolverDelegate
-//   - Resolving legacy tokens remotely via a ACL.GetPolicy RPC
+//   - Resolving legacy tokens remotely via an ACL.GetPolicy RPC
 //   - Resolving tokens remotely via an ACL.TokenRead RPC
 //   - Resolving policies remotely via an ACL.PolicyResolve RPC
 //   - Resolving roles remotely via an ACL.RoleResolve RPC
@@ -437,7 +437,10 @@ func (r *ACLResolver) fetchAndCacheIdentityFromToken(token string, cached *struc
 	return nil, err
 }
 
-func (r *ACLResolver) resolveIdentityFromToken(token string) (structs.ACLIdentity, error) {
+// ResolveIdentityFromToken takes a token as a string and returns an ACLIdentity.
+// We read the value from ACLResolver's cache if available, and if the read misses
+// we initiate an RPC for the value.
+func (r *ACLResolver) ResolveIdentityFromToken(token string) (structs.ACLIdentity, error) {
 	// Attempt to resolve locally first (local results are not cached)
 	if done, identity, err := r.delegate.ResolveIdentityFromToken(token); done {
 		return identity, err
@@ -765,6 +768,11 @@ func (r *ACLResolver) collectPoliciesForIdentity(identity structs.ACLIdentity, p
 	var expired []*structs.ACLPolicy
 	expCacheMap := make(map[string]*structs.PolicyCacheEntry)
 
+	var accessorID string
+	if identity != nil {
+		accessorID = identity.ID()
+	}
+
 	for _, policyID := range policyIDs {
 		if done, policy, err := r.delegate.ResolvePolicyFromID(policyID); done {
 			if err != nil && !acl.IsErrNotFound(err) {
@@ -774,7 +782,7 @@ func (r *ACLResolver) collectPoliciesForIdentity(identity structs.ACLIdentity, p
 			if policy != nil {
 				policies = append(policies, policy)
 			} else {
-				r.logger.Printf("[WARN] acl: policy %q not found for identity %q", policyID, identity.ID())
+				r.logger.Printf("[WARN] acl: policy not found for identity, policy=%q identity=%q", policyID, accessorID)
 			}
 
 			continue
@@ -868,7 +876,11 @@ func (r *ACLResolver) collectRolesForIdentity(identity structs.ACLIdentity, role
 			if role != nil {
 				roles = append(roles, role)
 			} else {
-				r.logger.Printf("[WARN] acl: role %q not found for identity %q", roleID, identity.ID())
+				var accessorID string
+				if identity != nil {
+					accessorID = identity.ID()
+				}
+				r.logger.Printf("[WARN] acl: role not found for identity, role=%q identity=%q", roleID, accessorID)
 			}
 
 			continue
@@ -946,7 +958,7 @@ func (r *ACLResolver) resolveTokenToIdentityAndPolicies(token string) (structs.A
 
 	for i := 0; i < tokenPolicyResolutionMaxRetries; i++ {
 		// Resolve the token to an ACLIdentity
-		identity, err := r.resolveIdentityFromToken(token)
+		identity, err := r.ResolveIdentityFromToken(token)
 		if err != nil {
 			return nil, nil, err
 		} else if identity == nil {
@@ -985,7 +997,7 @@ func (r *ACLResolver) resolveTokenToIdentityAndRoles(token string) (structs.ACLI
 
 	for i := 0; i < tokenRoleResolutionMaxRetries; i++ {
 		// Resolve the token to an ACLIdentity
-		identity, err := r.resolveIdentityFromToken(token)
+		identity, err := r.ResolveIdentityFromToken(token)
 		if err != nil {
 			return nil, nil, err
 		} else if identity == nil {
diff --git a/agent/consul/acl_endpoint.go b/agent/consul/acl_endpoint.go
index aed0262d15c1..4497a96c7c9e 100644
--- a/agent/consul/acl_endpoint.go
+++ b/agent/consul/acl_endpoint.go
@@ -2392,3 +2392,18 @@ func (a *ACL) Authorize(args *structs.RemoteACLAuthorizationRequest, reply *[]st
 	*reply = responses
 	return nil
 }
+
+// ResolveIdentityFromToken passes through a request from the ACL type to the ACL's srv delegate.
+func (a *ACL) ResolveIdentityFromToken(args *structs.ACLRequest, reply *structs.ACLIdentity) error {
+	// fixme(kit): do we need to do any other checks here? Maybe look into the cache or route to another endpoint file?
+	_, ident, err := a.srv.ResolveIdentityFromToken(args.WriteRequest.Token)
+	if err != nil {
+		return err
+	}
+
+	// fixme(kit): what other error cases would we want to handle from ResolveIdentityFromToken?
+
+	// Set our reply and return
+	reply = &ident
+	return nil
+}
diff --git a/agent/consul/acl_server.go b/agent/consul/acl_server.go
index 65292e1af5e7..a814c089bcae 100644
--- a/agent/consul/acl_server.go
+++ b/agent/consul/acl_server.go
@@ -164,6 +164,7 @@ func (s *Server) ACLsEnabled() bool {
 	return s.config.ACLsEnabled
 }
 
+// fixme(kit): write a doc comment for this public function
 func (s *Server) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentity, error) {
 	// only allow remote RPC resolution when token replication is off and
 	// when not in the ACL datacenter
@@ -237,6 +238,28 @@ func (s *Server) ResolveTokenAndDefaultMeta(token string, entMeta *structs.Enter
 	return authz, err
 }
 
+// fixme(mkcp): just ResolveTokenAndDefaultMeta copied but we return the identity too. This is pretty janky, but the fn is called in ~60 places so
+// I'm not ready to refactor it just yet
+func (s *Server) ResolveTokenIdentityAndDefaultMeta(token string, entMeta *structs.EnterpriseMeta, authzContext *acl.AuthorizerContext) (structs.ACLIdentity, acl.Authorizer, error) {
+	identity, authz, err := s.acls.ResolveTokenToIdentityAndAuthorizer(token)
+	if err != nil {
+		return nil, nil, err
+	}
+
+	// Default the EnterpriseMeta based on the Tokens meta or actual defaults
+	// in the case of unknown identity
+	if identity != nil {
+		entMeta.Merge(identity.EnterpriseMetadata())
+	} else {
+		entMeta.Merge(structs.DefaultEnterpriseMeta())
+	}
+
+	// Use the meta to fill in the ACL authorization context
+	entMeta.FillAuthzContext(authzContext)
+
+	return identity, authz, err
+}
+
 func (s *Server) filterACL(token string, subj interface{}) error {
 	return s.acls.filterACL(token, subj)
 }
diff --git a/agent/consul/intention_endpoint.go b/agent/consul/intention_endpoint.go
index b99db7f399e7..6e9e294496cf 100644
--- a/agent/consul/intention_endpoint.go
+++ b/agent/consul/intention_endpoint.go
@@ -38,9 +38,13 @@ func (s *Intention) checkIntentionID(id string) (bool, error) {
 
 // prepareApplyCreate validates that the requester has permissions to create the new intention,
 // generates a new uuid for the intention and generally validates that the request is well-formed
-func (s *Intention) prepareApplyCreate(authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
+func (s *Intention) prepareApplyCreate(ident structs.ACLIdentity, authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
 	if !args.Intention.CanWrite(authz) {
-		s.srv.logger.Printf("[WARN] consul.intention: Intention creation denied due to ACLs")
+		var accessorID string
+		if ident != nil {
+			accessorID = ident.ID()
+		}
+		s.srv.logger.Printf("[WARN] consul.intention: Intention creation denied due to ACLs, accessorID=%v", accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -85,9 +89,13 @@ func (s *Intention) prepareApplyCreate(authz acl.Authorizer, entMeta *structs.En
 
 // prepareApplyUpdate validates that the requester has permissions on both the updated and existing
 // intention as well as generally validating that the request is well-formed
-func (s *Intention) prepareApplyUpdate(authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
+func (s *Intention) prepareApplyUpdate(ident structs.ACLIdentity, authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
 	if !args.Intention.CanWrite(authz) {
-		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention %q denied due to ACLs", args.Intention.ID)
+		var accessorID string
+		if ident != nil {
+			accessorID = ident.ID()
+		}
+		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -103,7 +111,11 @@ func (s *Intention) prepareApplyUpdate(authz acl.Authorizer, entMeta *structs.En
 	// which must be true to perform any rename. This is the only ACL enforcement
 	// done for deletions and a secondary enforcement for updates.
 	if !ixn.CanWrite(authz) {
-		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention %q denied due to ACLs", args.Intention.ID)
+		var accessorID string
+		if ident != nil {
+			accessorID = ident.ID()
+		}
+		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -134,7 +146,7 @@ func (s *Intention) prepareApplyUpdate(authz acl.Authorizer, entMeta *structs.En
 
 // prepareApplyDelete ensures that the intention specified by the ID in the request exists
 // and that the requester is authorized to delete it
-func (s *Intention) prepareApplyDelete(authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
+func (s *Intention) prepareApplyDelete(ident structs.ACLIdentity, authz acl.Authorizer, entMeta *structs.EnterpriseMeta, args *structs.IntentionRequest) error {
 	// If this is not a create, then we have to verify the ID.
 	state := s.srv.fsm.State()
 	_, ixn, err := state.IntentionGet(nil, args.Intention.ID)
@@ -149,7 +161,11 @@ func (s *Intention) prepareApplyDelete(authz acl.Authorizer, entMeta *structs.En
 	// which must be true to perform any rename. This is the only ACL enforcement
 	// done for deletions and a secondary enforcement for updates.
 	if !ixn.CanWrite(authz) {
-		s.srv.logger.Printf("[WARN] consul.intention: Deletion operation on intention %q denied due to ACLs", args.Intention.ID)
+		var accessorID string
+		if ident != nil {
+			accessorID = ident.ID()
+		}
+		s.srv.logger.Printf("[WARN] consul.intention: Deletion operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -179,22 +195,22 @@ func (s *Intention) Apply(
 
 	// Get the ACL token for the request for the checks below.
 	var entMeta structs.EnterpriseMeta
-	authz, err := s.srv.ResolveTokenAndDefaultMeta(args.Token, &entMeta, nil)
+	ident, authz, err := s.srv.ResolveTokenIdentityAndDefaultMeta(args.Token, &entMeta, nil)
 	if err != nil {
 		return err
 	}
 
 	switch args.Op {
 	case structs.IntentionOpCreate:
-		if err := s.prepareApplyCreate(authz, &entMeta, args); err != nil {
+		if err := s.prepareApplyCreate(ident, authz, &entMeta, args); err != nil {
 			return err
 		}
 	case structs.IntentionOpUpdate:
-		if err := s.prepareApplyUpdate(authz, &entMeta, args); err != nil {
+		if err := s.prepareApplyUpdate(ident, authz, &entMeta, args); err != nil {
 			return err
 		}
 	case structs.IntentionOpDelete:
-		if err := s.prepareApplyDelete(authz, &entMeta, args); err != nil {
+		if err := s.prepareApplyDelete(ident, authz, &entMeta, args); err != nil {
 			return err
 		}
 	default:
@@ -248,7 +264,15 @@ func (s *Intention) Get(
 
 			// If ACLs prevented any responses, error
 			if len(reply.Intentions) == 0 {
-				s.srv.logger.Printf("[WARN] consul.intention: Request to get intention '%s' denied due to ACLs", args.IntentionID)
+				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
+				if err != nil {
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+				}
+				var accessorID string
+				if ident != nil {
+					accessorID = ident.ID()
+				}
+				s.srv.logger.Printf("[WARN] consul.intention: Request to get intention denied due to ACLs, intention=%s accessorID=%v", args.IntentionID, accessorID)
 				return acl.ErrPermissionDenied
 			}
 
@@ -312,7 +336,15 @@ func (s *Intention) Match(
 		for _, entry := range args.Match.Entries {
 			entry.FillAuthzContext(&authzContext)
 			if prefix := entry.Name; prefix != "" && rule.IntentionRead(prefix, &authzContext) != acl.Allow {
-				s.srv.logger.Printf("[WARN] consul.intention: Operation on intention prefix '%s' denied due to ACLs", prefix)
+				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
+				if err != nil {
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+				}
+				var accessorID string
+				if ident != nil {
+					accessorID = ident.ID()
+				}
+				s.srv.logger.Printf("[WARN] consul.intention: Operation on intention prefix denied due to ACLs, prefix=%s accessorID=%v", prefix, accessorID)
 				return acl.ErrPermissionDenied
 			}
 		}
@@ -383,7 +415,15 @@ func (s *Intention) Check(
 		var authzContext acl.AuthorizerContext
 		query.FillAuthzContext(&authzContext)
 		if rule != nil && rule.ServiceRead(prefix, &authzContext) != acl.Allow {
-			s.srv.logger.Printf("[WARN] consul.intention: test on intention '%s' denied due to ACLs", prefix)
+			_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
+			if err != nil {
+				s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+			}
+			var accessorID string
+			if ident != nil {
+				accessorID = ident.ID()
+			}
+			s.srv.logger.Printf("[WARN] consul.intention: test on intention denied due to ACLs, intention=%s accessorID=%v", prefix, accessorID)
 			return acl.ErrPermissionDenied
 		}
 	}
diff --git a/agent/consul/internal_endpoint.go b/agent/consul/internal_endpoint.go
index 2549e812fba3..11d058057e20 100644
--- a/agent/consul/internal_endpoint.go
+++ b/agent/consul/internal_endpoint.go
@@ -126,7 +126,16 @@ func (m *Internal) EventFire(args *structs.EventFireRequest,
 	}
 
 	if rule != nil && rule.EventWrite(args.Name, nil) != acl.Allow {
-		m.srv.logger.Printf("[WARN] consul: user event %q blocked by ACLs", args.Name)
+		_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
+		if err != nil {
+			m.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, err=%v", err)
+		}
+		var accessorID string
+		if ident != nil {
+			accessorID = ident.ID()
+		}
+		m.srv.logger.Printf("[DEBUG] consul: user event blocked by ACLs, event=%q accessorID=%q", args.Name, accessorID)
+
 		return acl.ErrPermissionDenied
 	}
 
@@ -163,7 +172,15 @@ func (m *Internal) KeyringOperation(
 		switch args.Operation {
 		case structs.KeyringList:
 			if rule.KeyringRead(nil) != acl.Allow {
-				return fmt.Errorf("Reading keyring denied by ACLs")
+				_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
+				if err != nil {
+					m.srv.logger.Printf("[DEBUG] failed to fetch ACL AccessorID, err=%v", err)
+				}
+				var accessorID string
+				if ident != nil {
+					accessorID = ident.ID()
+				}
+				return fmt.Errorf("Reading keyring denied by ACLs, accessorID=%v", accessorID)
 			}
 		case structs.KeyringInstall:
 			fallthrough
@@ -171,7 +188,15 @@ func (m *Internal) KeyringOperation(
 			fallthrough
 		case structs.KeyringRemove:
 			if rule.KeyringWrite(nil) != acl.Allow {
-				return fmt.Errorf("Modifying keyring denied due to ACLs")
+				_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
+				if err != nil {
+					m.srv.logger.Printf("[DEBUG] failed to fetch ACL AccessorID, err=%v", err)
+				}
+				var accessorID string
+				if ident != nil {
+					accessorID = ident.ID()
+				}
+				return fmt.Errorf("Modifying keyring denied due to ACLs, accessorID=%v", accessorID)
 			}
 		default:
 			panic("Invalid keyring operation")
diff --git a/agent/local/state.go b/agent/local/state.go
index 72393de7016d..9e83167e36d0 100644
--- a/agent/local/state.go
+++ b/agent/local/state.go
@@ -1079,12 +1079,14 @@ func (l *State) deleteService(key structs.ServiceID) error {
 		return fmt.Errorf("ServiceID missing")
 	}
 
+	st := l.serviceToken(key)
+
 	req := structs.DeregisterRequest{
 		Datacenter:     l.config.Datacenter,
 		Node:           l.config.NodeName,
 		ServiceID:      key.ID,
 		EnterpriseMeta: key.EnterpriseMeta,
-		WriteRequest:   structs.WriteRequest{Token: l.serviceToken(key)},
+		WriteRequest:   structs.WriteRequest{Token: st},
 	}
 	var out struct{}
 	err := l.Delegate.RPC("Catalog.Deregister", &req, &out)
@@ -1104,7 +1106,8 @@ func (l *State) deleteService(key structs.ServiceID) error {
 		// todo(fs): mark the service to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.services[key].InSync = true
-		l.logger.Printf("[WARN] agent: Service %q deregistration blocked by ACLs", key)
+		accessorID := l.ACLAccessorID(st)
+		l.logger.Printf("[DEBUG] agent: Service deregistration blocked by ACLs, service=%q accessorID=%v", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "service", "deregistration"}, 1)
 		return nil
 
@@ -1120,12 +1123,13 @@ func (l *State) deleteCheck(key structs.CheckID) error {
 		return fmt.Errorf("CheckID missing")
 	}
 
+	ct := l.checkToken(key)
 	req := structs.DeregisterRequest{
 		Datacenter:     l.config.Datacenter,
 		Node:           l.config.NodeName,
 		CheckID:        key.ID,
 		EnterpriseMeta: key.EnterpriseMeta,
-		WriteRequest:   structs.WriteRequest{Token: l.checkToken(key)},
+		WriteRequest:   structs.WriteRequest{Token: ct},
 	}
 	var out struct{}
 	err := l.Delegate.RPC("Catalog.Deregister", &req, &out)
@@ -1139,7 +1143,8 @@ func (l *State) deleteCheck(key structs.CheckID) error {
 		// todo(fs): mark the check to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
-		l.logger.Printf("[WARN] agent: Check %q deregistration blocked by ACLs", key.String())
+		accessorID := l.ACLAccessorID(ct)
+		l.logger.Printf("[DEBUG] agent: Check deregistration blocked by ACLs, check=%q accessorID=%v", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "deregistration"}, 1)
 		return nil
 
@@ -1159,6 +1164,8 @@ func (l *State) pruneCheck(id structs.CheckID) {
 
 // syncService is used to sync a service to the server
 func (l *State) syncService(key structs.ServiceID) error {
+	st := l.serviceToken(key)
+
 	// If the service has associated checks that are out of sync,
 	// piggyback them on the service sync so they are part of the
 	// same transaction and are registered atomically. We only let
@@ -1174,7 +1181,7 @@ func (l *State) syncService(key structs.ServiceID) error {
 		if !key.Matches(&sid) {
 			continue
 		}
-		if l.serviceToken(key) != l.checkToken(checkKey) {
+		if st != l.checkToken(checkKey) {
 			continue
 		}
 		checks = append(checks, c.Check)
@@ -1189,7 +1196,7 @@ func (l *State) syncService(key structs.ServiceID) error {
 		NodeMeta:        l.metadata,
 		Service:         l.services[key].Service,
 		EnterpriseMeta:  key.EnterpriseMeta,
-		WriteRequest:    structs.WriteRequest{Token: l.serviceToken(key)},
+		WriteRequest:    structs.WriteRequest{Token: st},
 	}
 
 	// Backwards-compatibility for Consul < 0.5
@@ -1224,7 +1231,8 @@ func (l *State) syncService(key structs.ServiceID) error {
 			checkKey.Init(check.CheckID, &check.EnterpriseMeta)
 			l.checks[checkKey].InSync = true
 		}
-		l.logger.Printf("[WARN] agent: Service %q registration blocked by ACLs", key.String())
+		accessorID := l.ACLAccessorID(st)
+		l.logger.Printf("[DEBUG] agent: Service registration blocked by ACLs, check=%q accessorID=%s", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "service", "registration"}, 1)
 		return nil
 
@@ -1237,7 +1245,7 @@ func (l *State) syncService(key structs.ServiceID) error {
 // syncCheck is used to sync a check to the server
 func (l *State) syncCheck(key structs.CheckID) error {
 	c := l.checks[key]
-
+	ct := l.checkToken(key)
 	req := structs.RegisterRequest{
 		Datacenter:      l.config.Datacenter,
 		ID:              l.config.NodeID,
@@ -1247,7 +1255,7 @@ func (l *State) syncCheck(key structs.CheckID) error {
 		NodeMeta:        l.metadata,
 		Check:           c.Check,
 		EnterpriseMeta:  c.Check.EnterpriseMeta,
-		WriteRequest:    structs.WriteRequest{Token: l.checkToken(key)},
+		WriteRequest:    structs.WriteRequest{Token: ct},
 	}
 
 	var serviceKey structs.ServiceID
@@ -1274,7 +1282,8 @@ func (l *State) syncCheck(key structs.CheckID) error {
 		// todo(fs): mark the check to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
-		l.logger.Printf("[WARN] agent: Check %q registration blocked by ACLs", key)
+		accessorID := l.ACLAccessorID(ct)
+		l.logger.Printf("[DEBUG] agent: Check registration blocked by ACLs, check=%q accessorID=%v", key, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "registration"}, 1)
 		return nil
 
@@ -1285,6 +1294,7 @@ func (l *State) syncCheck(key structs.CheckID) error {
 }
 
 func (l *State) syncNodeInfo() error {
+	at := l.tokens.AgentToken()
 	req := structs.RegisterRequest{
 		Datacenter:      l.config.Datacenter,
 		ID:              l.config.NodeID,
@@ -1292,7 +1302,7 @@ func (l *State) syncNodeInfo() error {
 		Address:         l.config.AdvertiseAddr,
 		TaggedAddresses: l.config.TaggedAddresses,
 		NodeMeta:        l.metadata,
-		WriteRequest:    structs.WriteRequest{Token: l.tokens.AgentToken()},
+		WriteRequest:    structs.WriteRequest{Token: at},
 	}
 	var out struct{}
 	err := l.Delegate.RPC("Catalog.Register", &req, &out)
@@ -1306,7 +1316,8 @@ func (l *State) syncNodeInfo() error {
 		// todo(fs): mark the node info to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.nodeInfoInSync = true
-		l.logger.Printf("[WARN] agent: Node info update blocked by ACLs")
+		accessorID := l.ACLAccessorID(at)
+		l.logger.Printf("[DEBUG] agent: Node info update blocked by ACLs, nodeID=%v accessorID=%v", l.config.NodeID, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "node", "registration"}, 1)
 		return nil
 
@@ -1331,3 +1342,26 @@ func (l *State) notifyIfAliased(serviceID structs.ServiceID) {
 		}
 	}
 }
+
+// ACLAccessorID takes an ACL secret token and retrives identity metadata on the
+// token, returning just the accessorID so we can log it here. In the future we
+// may wish to return more fields from structs.ACLIdentity to log out more debug
+// info when ACLs are denied
+func (l *State) ACLAccessorID(token string) string {
+	req := structs.ACLRequest{
+		Datacenter:   l.config.Datacenter,
+		WriteRequest: structs.WriteRequest{Token: token},
+	}
+	var reply structs.ACLIdentity
+	if err := l.Delegate.RPC("ACL.ResolveIdentityFromToken", &req, &reply); err != nil {
+		l.logger.Printf("[DEBUG] agent.local: failed to acquire token identity, err=%v", err)
+		return ""
+	}
+
+	// Sometimes we don't get a reply struct back?
+	if reply == nil {
+		return ""
+	}
+
+	return reply.ID()
+}

From 4e47feb7e1263d552e2997d8f67b6637a77152cc Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Wed, 22 Jan 2020 14:52:10 -0800
Subject: [PATCH 3/9] agent: polish acl debugging

---
 agent/consul/acl_endpoint.go       |  7 +++----
 agent/consul/acl_server.go         | 32 +++++++++---------------------
 agent/consul/intention_endpoint.go |  6 +++---
 agent/local/state.go               |  6 ++----
 4 files changed, 17 insertions(+), 34 deletions(-)

diff --git a/agent/consul/acl_endpoint.go b/agent/consul/acl_endpoint.go
index 4497a96c7c9e..f5e0e2caac2c 100644
--- a/agent/consul/acl_endpoint.go
+++ b/agent/consul/acl_endpoint.go
@@ -2395,15 +2395,14 @@ func (a *ACL) Authorize(args *structs.RemoteACLAuthorizationRequest, reply *[]st
 
 // ResolveIdentityFromToken passes through a request from the ACL type to the ACL's srv delegate.
 func (a *ACL) ResolveIdentityFromToken(args *structs.ACLRequest, reply *structs.ACLIdentity) error {
-	// fixme(kit): do we need to do any other checks here? Maybe look into the cache or route to another endpoint file?
 	_, ident, err := a.srv.ResolveIdentityFromToken(args.WriteRequest.Token)
 	if err != nil {
 		return err
+	} else if ident == nil {
+		return fmt.Errorf("Failed to initialize identity")
 	}
 
-	// fixme(kit): what other error cases would we want to handle from ResolveIdentityFromToken?
-
 	// Set our reply and return
-	reply = &ident
+	*reply = ident
 	return nil
 }
diff --git a/agent/consul/acl_server.go b/agent/consul/acl_server.go
index a814c089bcae..b37caf2f2124 100644
--- a/agent/consul/acl_server.go
+++ b/agent/consul/acl_server.go
@@ -164,7 +164,7 @@ func (s *Server) ACLsEnabled() bool {
 	return s.config.ACLsEnabled
 }
 
-// fixme(kit): write a doc comment for this public function
+// ResolveIdentityFromToken retrieve's a token's full identity given its secretID.
 func (s *Server) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentity, error) {
 	// only allow remote RPC resolution when token replication is off and
 	// when not in the ACL datacenter
@@ -218,28 +218,8 @@ func (s *Server) ResolveTokenToIdentityAndAuthorizer(token string) (structs.ACLI
 	return s.acls.ResolveTokenToIdentityAndAuthorizer(token)
 }
 
-func (s *Server) ResolveTokenAndDefaultMeta(token string, entMeta *structs.EnterpriseMeta, authzContext *acl.AuthorizerContext) (acl.Authorizer, error) {
-	identity, authz, err := s.acls.ResolveTokenToIdentityAndAuthorizer(token)
-	if err != nil {
-		return nil, err
-	}
-
-	// Default the EnterpriseMeta based on the Tokens meta or actual defaults
-	// in the case of unknown identity
-	if identity != nil {
-		entMeta.Merge(identity.EnterpriseMetadata())
-	} else {
-		entMeta.Merge(structs.DefaultEnterpriseMeta())
-	}
-
-	// Use the meta to fill in the ACL authorization context
-	entMeta.FillAuthzContext(authzContext)
-
-	return authz, err
-}
-
-// fixme(mkcp): just ResolveTokenAndDefaultMeta copied but we return the identity too. This is pretty janky, but the fn is called in ~60 places so
-// I'm not ready to refactor it just yet
+// ResolveTokenIdentityAndDefaultMeta retrieves an identity and authorizer for the caller,
+// and populates the EnterpriseMeta based on the AuthorizerContext.
 func (s *Server) ResolveTokenIdentityAndDefaultMeta(token string, entMeta *structs.EnterpriseMeta, authzContext *acl.AuthorizerContext) (structs.ACLIdentity, acl.Authorizer, error) {
 	identity, authz, err := s.acls.ResolveTokenToIdentityAndAuthorizer(token)
 	if err != nil {
@@ -260,6 +240,12 @@ func (s *Server) ResolveTokenIdentityAndDefaultMeta(token string, entMeta *struc
 	return identity, authz, err
 }
 
+// ResolveTokenAndDefaultMeta passes through to ResolveTokenIdentityAndDefaultMeta, eliding the identity from its response.
+func (s *Server) ResolveTokenAndDefaultMeta(token string, entMeta *structs.EnterpriseMeta, authzContext *acl.AuthorizerContext) (acl.Authorizer, error) {
+	_, authz, err := s.ResolveTokenIdentityAndDefaultMeta(token, entMeta, authzContext)
+	return authz, err
+}
+
 func (s *Server) filterACL(token string, subj interface{}) error {
 	return s.acls.filterACL(token, subj)
 }
diff --git a/agent/consul/intention_endpoint.go b/agent/consul/intention_endpoint.go
index 6e9e294496cf..93d08cc0a785 100644
--- a/agent/consul/intention_endpoint.go
+++ b/agent/consul/intention_endpoint.go
@@ -266,7 +266,7 @@ func (s *Intention) Get(
 			if len(reply.Intentions) == 0 {
 				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
 				}
 				var accessorID string
 				if ident != nil {
@@ -338,7 +338,7 @@ func (s *Intention) Match(
 			if prefix := entry.Name; prefix != "" && rule.IntentionRead(prefix, &authzContext) != acl.Allow {
 				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
 				}
 				var accessorID string
 				if ident != nil {
@@ -417,7 +417,7 @@ func (s *Intention) Check(
 		if rule != nil && rule.ServiceRead(prefix, &authzContext) != acl.Allow {
 			_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 			if err != nil {
-				s.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, reason: %v", err)
+				s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
 			}
 			var accessorID string
 			if ident != nil {
diff --git a/agent/local/state.go b/agent/local/state.go
index 9e83167e36d0..987140918d36 100644
--- a/agent/local/state.go
+++ b/agent/local/state.go
@@ -1345,8 +1345,8 @@ func (l *State) notifyIfAliased(serviceID structs.ServiceID) {
 
 // ACLAccessorID takes an ACL secret token and retrives identity metadata on the
 // token, returning just the accessorID so we can log it here. In the future we
-// may wish to return more fields from structs.ACLIdentity to log out more debug
-// info when ACLs are denied
+// may wish to return more of the fields on structs.ACLIdentity to log out more
+// debug info when ACLs are denied in state.go.
 func (l *State) ACLAccessorID(token string) string {
 	req := structs.ACLRequest{
 		Datacenter:   l.config.Datacenter,
@@ -1357,8 +1357,6 @@ func (l *State) ACLAccessorID(token string) string {
 		l.logger.Printf("[DEBUG] agent.local: failed to acquire token identity, err=%v", err)
 		return ""
 	}
-
-	// Sometimes we don't get a reply struct back?
 	if reply == nil {
 		return ""
 	}

From 360edddf9c87e0cd600e8238d46e4b3bbf887901 Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Wed, 22 Jan 2020 16:44:35 -0800
Subject: [PATCH 4/9] agent: minor fix + string fmt over value interp

---
 agent/acl.go                       | 11 ++++++-----
 agent/acl_test.go                  | 15 +++++++++++++++
 agent/agent.go                     |  2 +-
 agent/consul/acl_server.go         |  2 +-
 agent/consul/intention_endpoint.go | 22 +++++++++++-----------
 agent/local/state.go               |  8 ++++----
 6 files changed, 38 insertions(+), 22 deletions(-)

diff --git a/agent/acl.go b/agent/acl.go
index 6227024de9ca..81bb6008cc53 100644
--- a/agent/acl.go
+++ b/agent/acl.go
@@ -41,8 +41,9 @@ func (a *Agent) resolveTokenAndDefaultMeta(id string, entMeta *structs.Enterpris
 	return a.delegate.ResolveTokenAndDefaultMeta(id, entMeta, authzContext)
 }
 
-// ResolveIdentityFromToken is used to resolve an ACL token secret a structs.ACLIdentity.
-func (a *Agent) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentity, error) {
+// resolveIdentityFromToken takes an ACL token's secretID, ensures ACLs are
+// enabled, and retrieves its ACLIdentity.
+func (a *Agent) resolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error) {
 	// ACLs are disabled
 	if !a.delegate.ACLsEnabled() {
 		return false, nil, nil
@@ -53,7 +54,7 @@ func (a *Agent) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentit
 		return false, nil, nil
 	}
 
-	return a.delegate.ResolveIdentityFromToken(token)
+	return a.delegate.ResolveIdentityFromToken(secretID)
 }
 
 func (a *Agent) initializeACLs() error {
@@ -258,7 +259,7 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 
 	_, tokenIdent, err := a.delegate.ResolveIdentityFromToken(token)
 	if err != nil {
-		a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%v", err)
+		a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%q", err)
 	}
 
 	var authzContext acl.AuthorizerContext
@@ -274,7 +275,7 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 		if tokenIdent != nil {
 			accessorID = tokenIdent.ID()
 		}
-		a.logger.Printf("[DEBUG] agent: dropping node from result due to ACLs, node=%q accessorID=%v", node, accessorID)
+		a.logger.Printf("[DEBUG] agent: dropping node from result due to ACLs, node=%q accessorID=%q", node, accessorID)
 		m = append(m[:i], m[i+1:]...)
 		i--
 	}
diff --git a/agent/acl_test.go b/agent/acl_test.go
index 97635208bd7a..dcd9253ba3e9 100644
--- a/agent/acl_test.go
+++ b/agent/acl_test.go
@@ -130,6 +130,21 @@ func (a *TestACLAgent) ResolveTokenAndDefaultMeta(secretID string, entMeta *stru
 	return authz, err
 }
 
+func (a *TestACLAgent) ResolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error) {
+	if a.resolveTokenFn == nil {
+		panic("This agent is useless without providing a token resolution function")
+	}
+
+	// note(kit) This is almost certainly not useful test behavior, but I have no idea how I should be testing this x)
+	//           I've just been getting an infinite loop where i accidentally dispatch right back to the delegate
+	identity, _, err := a.resolveTokenFn(secretID)
+	if err != nil {
+		return true, nil, err
+	}
+
+	return true, identity, nil
+}
+
 // All of these are stubs to satisfy the interface
 func (a *TestACLAgent) Encrypted() bool {
 	return false
diff --git a/agent/agent.go b/agent/agent.go
index 0bf71823114f..002993e2f8d2 100644
--- a/agent/agent.go
+++ b/agent/agent.go
@@ -1938,7 +1938,7 @@ OUTER:
 				//  todo(mkcp) port all of these logger calls to hclog w/ loglevel configuration
 				if err := a.RPC("Coordinate.Update", &req, &reply); err != nil {
 					if acl.IsErrPermissionDenied(err) {
-						_, tokenIdent, err2 := a.ResolveIdentityFromToken(agentToken)
+						_, tokenIdent, err2 := a.resolveIdentityFromToken(agentToken)
 						if err2 != nil {
 							a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%v", err2)
 						}
diff --git a/agent/consul/acl_server.go b/agent/consul/acl_server.go
index b37caf2f2124..4d0ec99a3f68 100644
--- a/agent/consul/acl_server.go
+++ b/agent/consul/acl_server.go
@@ -164,7 +164,7 @@ func (s *Server) ACLsEnabled() bool {
 	return s.config.ACLsEnabled
 }
 
-// ResolveIdentityFromToken retrieve's a token's full identity given its secretID.
+// ResolveIdentityFromToken retrieves a token's full identity given its secretID.
 func (s *Server) ResolveIdentityFromToken(token string) (bool, structs.ACLIdentity, error) {
 	// only allow remote RPC resolution when token replication is off and
 	// when not in the ACL datacenter
diff --git a/agent/consul/intention_endpoint.go b/agent/consul/intention_endpoint.go
index 93d08cc0a785..a783bbde73bc 100644
--- a/agent/consul/intention_endpoint.go
+++ b/agent/consul/intention_endpoint.go
@@ -44,7 +44,7 @@ func (s *Intention) prepareApplyCreate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
-		s.srv.logger.Printf("[WARN] consul.intention: Intention creation denied due to ACLs, accessorID=%v", accessorID)
+		s.srv.logger.Printf("[WARN] consul.intention: Intention creation denied due to ACLs, accessorID=%q", accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -95,7 +95,7 @@ func (s *Intention) prepareApplyUpdate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
-		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
+		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -115,7 +115,7 @@ func (s *Intention) prepareApplyUpdate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
-		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
+		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -151,7 +151,7 @@ func (s *Intention) prepareApplyDelete(ident structs.ACLIdentity, authz acl.Auth
 	state := s.srv.fsm.State()
 	_, ixn, err := state.IntentionGet(nil, args.Intention.ID)
 	if err != nil {
-		return fmt.Errorf("Intention lookup failed: %v", err)
+		return fmt.Errorf("Intention lookup failed: %q", err)
 	}
 	if ixn == nil {
 		return fmt.Errorf("Cannot delete non-existent intention: '%s'", args.Intention.ID)
@@ -165,7 +165,7 @@ func (s *Intention) prepareApplyDelete(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
-		s.srv.logger.Printf("[WARN] consul.intention: Deletion operation on intention denied due to ACLs, intention=%q accessorID=%v", args.Intention.ID, accessorID)
+		s.srv.logger.Printf("[WARN] consul.intention: Deletion operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
 
@@ -266,13 +266,13 @@ func (s *Intention) Get(
 			if len(reply.Intentions) == 0 {
 				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
 				}
 				var accessorID string
 				if ident != nil {
 					accessorID = ident.ID()
 				}
-				s.srv.logger.Printf("[WARN] consul.intention: Request to get intention denied due to ACLs, intention=%s accessorID=%v", args.IntentionID, accessorID)
+				s.srv.logger.Printf("[WARN] consul.intention: Request to get intention denied due to ACLs, intention=%s accessorID=%q", args.IntentionID, accessorID)
 				return acl.ErrPermissionDenied
 			}
 
@@ -338,13 +338,13 @@ func (s *Intention) Match(
 			if prefix := entry.Name; prefix != "" && rule.IntentionRead(prefix, &authzContext) != acl.Allow {
 				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
+					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
 				}
 				var accessorID string
 				if ident != nil {
 					accessorID = ident.ID()
 				}
-				s.srv.logger.Printf("[WARN] consul.intention: Operation on intention prefix denied due to ACLs, prefix=%s accessorID=%v", prefix, accessorID)
+				s.srv.logger.Printf("[WARN] consul.intention: Operation on intention prefix denied due to ACLs, prefix=%s accessorID=%q", prefix, accessorID)
 				return acl.ErrPermissionDenied
 			}
 		}
@@ -417,13 +417,13 @@ func (s *Intention) Check(
 		if rule != nil && rule.ServiceRead(prefix, &authzContext) != acl.Allow {
 			_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
 			if err != nil {
-				s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%v", err)
+				s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
 			}
 			var accessorID string
 			if ident != nil {
 				accessorID = ident.ID()
 			}
-			s.srv.logger.Printf("[WARN] consul.intention: test on intention denied due to ACLs, intention=%s accessorID=%v", prefix, accessorID)
+			s.srv.logger.Printf("[WARN] consul.intention: test on intention denied due to ACLs, intention=%s accessorID=%q", prefix, accessorID)
 			return acl.ErrPermissionDenied
 		}
 	}
diff --git a/agent/local/state.go b/agent/local/state.go
index 987140918d36..2d2e2ef85d84 100644
--- a/agent/local/state.go
+++ b/agent/local/state.go
@@ -1144,7 +1144,7 @@ func (l *State) deleteCheck(key structs.CheckID) error {
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
 		accessorID := l.ACLAccessorID(ct)
-		l.logger.Printf("[DEBUG] agent: Check deregistration blocked by ACLs, check=%q accessorID=%v", key.String(), accessorID)
+		l.logger.Printf("[DEBUG] agent: Check deregistration blocked by ACLs, check=%q accessorID=%q", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "deregistration"}, 1)
 		return nil
 
@@ -1283,7 +1283,7 @@ func (l *State) syncCheck(key structs.CheckID) error {
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
 		accessorID := l.ACLAccessorID(ct)
-		l.logger.Printf("[DEBUG] agent: Check registration blocked by ACLs, check=%q accessorID=%v", key, accessorID)
+		l.logger.Printf("[DEBUG] agent: Check registration blocked by ACLs, check=%q accessorID=%q", key, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "registration"}, 1)
 		return nil
 
@@ -1317,7 +1317,7 @@ func (l *State) syncNodeInfo() error {
 		// todo(fs): some backoff strategy might be a better solution
 		l.nodeInfoInSync = true
 		accessorID := l.ACLAccessorID(at)
-		l.logger.Printf("[DEBUG] agent: Node info update blocked by ACLs, nodeID=%v accessorID=%v", l.config.NodeID, accessorID)
+		l.logger.Printf("[DEBUG] agent: Node info update blocked by ACLs, nodeID=%q accessorID=%q", l.config.NodeID, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "node", "registration"}, 1)
 		return nil
 
@@ -1354,7 +1354,7 @@ func (l *State) ACLAccessorID(token string) string {
 	}
 	var reply structs.ACLIdentity
 	if err := l.Delegate.RPC("ACL.ResolveIdentityFromToken", &req, &reply); err != nil {
-		l.logger.Printf("[DEBUG] agent.local: failed to acquire token identity, err=%v", err)
+		l.logger.Printf("[DEBUG] agent.local: failed to acquire token identity, err=%q", err)
 		return ""
 	}
 	if reply == nil {

From ca97c66e4d1d3dadcd9c3642cc0cdc0fea1e615c Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Wed, 22 Jan 2020 17:10:16 -0800
Subject: [PATCH 5/9] agent: undo export & fix logging field names

---
 agent/consul/acl.go | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/agent/consul/acl.go b/agent/consul/acl.go
index de263cba2699..85f74f52cddf 100644
--- a/agent/consul/acl.go
+++ b/agent/consul/acl.go
@@ -437,10 +437,10 @@ func (r *ACLResolver) fetchAndCacheIdentityFromToken(token string, cached *struc
 	return nil, err
 }
 
-// ResolveIdentityFromToken takes a token as a string and returns an ACLIdentity.
+// resolveIdentityFromToken takes a token as a string and returns an ACLIdentity.
 // We read the value from ACLResolver's cache if available, and if the read misses
 // we initiate an RPC for the value.
-func (r *ACLResolver) ResolveIdentityFromToken(token string) (structs.ACLIdentity, error) {
+func (r *ACLResolver) resolveIdentityFromToken(token string) (structs.ACLIdentity, error) {
 	// Attempt to resolve locally first (local results are not cached)
 	if done, identity, err := r.delegate.ResolveIdentityFromToken(token); done {
 		return identity, err
@@ -782,7 +782,7 @@ func (r *ACLResolver) collectPoliciesForIdentity(identity structs.ACLIdentity, p
 			if policy != nil {
 				policies = append(policies, policy)
 			} else {
-				r.logger.Printf("[WARN] acl: policy not found for identity, policy=%q identity=%q", policyID, accessorID)
+				r.logger.Printf("[WARN] acl: policy not found for identity, policy=%q accessorID=%q", policyID, accessorID)
 			}
 
 			continue
@@ -880,7 +880,7 @@ func (r *ACLResolver) collectRolesForIdentity(identity structs.ACLIdentity, role
 				if identity != nil {
 					accessorID = identity.ID()
 				}
-				r.logger.Printf("[WARN] acl: role not found for identity, role=%q identity=%q", roleID, accessorID)
+				r.logger.Printf("[WARN] acl: role not found for identity, role=%q accessorID=%q", roleID, accessorID)
 			}
 
 			continue
@@ -958,7 +958,7 @@ func (r *ACLResolver) resolveTokenToIdentityAndPolicies(token string) (structs.A
 
 	for i := 0; i < tokenPolicyResolutionMaxRetries; i++ {
 		// Resolve the token to an ACLIdentity
-		identity, err := r.ResolveIdentityFromToken(token)
+		identity, err := r.resolveIdentityFromToken(token)
 		if err != nil {
 			return nil, nil, err
 		} else if identity == nil {
@@ -997,7 +997,7 @@ func (r *ACLResolver) resolveTokenToIdentityAndRoles(token string) (structs.ACLI
 
 	for i := 0; i < tokenRoleResolutionMaxRetries; i++ {
 		// Resolve the token to an ACLIdentity
-		identity, err := r.ResolveIdentityFromToken(token)
+		identity, err := r.resolveIdentityFromToken(token)
 		if err != nil {
 			return nil, nil, err
 		} else if identity == nil {

From 3bba883bd339c41ee5a0ea6541d2660a822158ed Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Thu, 23 Jan 2020 09:42:15 -0800
Subject: [PATCH 6/9] agent: remove note and migrate up to code review

---
 agent/acl_test.go | 2 --
 1 file changed, 2 deletions(-)

diff --git a/agent/acl_test.go b/agent/acl_test.go
index dcd9253ba3e9..6d0d220e9a5f 100644
--- a/agent/acl_test.go
+++ b/agent/acl_test.go
@@ -135,8 +135,6 @@ func (a *TestACLAgent) ResolveIdentityFromToken(secretID string) (bool, structs.
 		panic("This agent is useless without providing a token resolution function")
 	}
 
-	// note(kit) This is almost certainly not useful test behavior, but I have no idea how I should be testing this x)
-	//           I've just been getting an infinite loop where i accidentally dispatch right back to the delegate
 	identity, _, err := a.resolveTokenFn(secretID)
 	if err != nil {
 		return true, nil, err

From e0d0daf79a23bb1e0336301b68d91c93ea66b5dc Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Thu, 23 Jan 2020 12:49:29 -0800
Subject: [PATCH 7/9] Update agent/consul/acl.go

Co-Authored-By: Matt Keeler <mkeeler@users.noreply.github.com>
---
 agent/consul/acl.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/agent/consul/acl.go b/agent/consul/acl.go
index 85f74f52cddf..2b3db01200a5 100644
--- a/agent/consul/acl.go
+++ b/agent/consul/acl.go
@@ -437,7 +437,7 @@ func (r *ACLResolver) fetchAndCacheIdentityFromToken(token string, cached *struc
 	return nil, err
 }
 
-// resolveIdentityFromToken takes a token as a string and returns an ACLIdentity.
+// resolveIdentityFromToken takes a token secret as a string and returns an ACLIdentity.
 // We read the value from ACLResolver's cache if available, and if the read misses
 // we initiate an RPC for the value.
 func (r *ACLResolver) resolveIdentityFromToken(token string) (structs.ACLIdentity, error) {

From 2cc71f5636bba1c4483ad74c70a5a99f83b323a7 Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Fri, 24 Jan 2020 15:41:38 -0800
Subject: [PATCH 8/9] agent: incorporate review feedback

---
 agent/acl.go                       | 32 +++++++++++--------
 agent/agent.go                     | 12 +++----
 agent/consul/acl_endpoint.go       | 14 --------
 agent/consul/intention_endpoint.go | 51 +++++++++++++++---------------
 agent/consul/internal_endpoint.go  | 45 +++++++++++---------------
 agent/local/state.go               | 35 +++++++++-----------
 6 files changed, 82 insertions(+), 107 deletions(-)

diff --git a/agent/acl.go b/agent/acl.go
index 81bb6008cc53..6700b0e1c056 100644
--- a/agent/acl.go
+++ b/agent/acl.go
@@ -41,8 +41,7 @@ func (a *Agent) resolveTokenAndDefaultMeta(id string, entMeta *structs.Enterpris
 	return a.delegate.ResolveTokenAndDefaultMeta(id, entMeta, authzContext)
 }
 
-// resolveIdentityFromToken takes an ACL token's secretID, ensures ACLs are
-// enabled, and retrieves its ACLIdentity.
+// resolveTokenAndDefaultMeta is used to resolve an ACLToken's secretID to a structs.ACLIdentity
 func (a *Agent) resolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error) {
 	// ACLs are disabled
 	if !a.delegate.ACLsEnabled() {
@@ -57,6 +56,21 @@ func (a *Agent) resolveIdentityFromToken(secretID string) (bool, structs.ACLIden
 	return a.delegate.ResolveIdentityFromToken(secretID)
 }
 
+// aclAccessorID is used to convert an ACLToken's secretID to its accessorID for non-
+// critical purposes, such as logging. Therefore we interpret all errors as empty-string
+// so we can safely log it without handling non-critical errors at the usage site.
+func (a *Agent) aclAccessorID(secretID string) string {
+	_, ident, err := a.resolveIdentityFromToken(secretID)
+	if err != nil {
+		a.logger.Printf("[DEBUG] agent.acl: %v", err)
+		return ""
+	}
+	if ident == nil {
+		return ""
+	}
+	return ident.ID()
+}
+
 func (a *Agent) initializeACLs() error {
 	// Build a policy for the agent master token.
 	// The builtin agent master policy allows reading any node information
@@ -257,11 +271,6 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 		return nil
 	}
 
-	_, tokenIdent, err := a.delegate.ResolveIdentityFromToken(token)
-	if err != nil {
-		a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%q", err)
-	}
-
 	var authzContext acl.AuthorizerContext
 	structs.DefaultEnterpriseMeta().FillAuthzContext(&authzContext)
 	// Filter out members based on the node policy.
@@ -271,10 +280,7 @@ func (a *Agent) filterMembers(token string, members *[]serf.Member) error {
 		if rule.NodeRead(node, &authzContext) == acl.Allow {
 			continue
 		}
-		var accessorID string
-		if tokenIdent != nil {
-			accessorID = tokenIdent.ID()
-		}
+		accessorID := a.aclAccessorID(token)
 		a.logger.Printf("[DEBUG] agent: dropping node from result due to ACLs, node=%q accessorID=%q", node, accessorID)
 		m = append(m[:i], m[i+1:]...)
 		i--
@@ -305,7 +311,7 @@ func (a *Agent) filterServicesWithAuthorizer(authz acl.Authorizer, services *map
 		if authz.ServiceRead(service.Service, &authzContext) == acl.Allow {
 			continue
 		}
-		a.logger.Printf("[DEBUG] agent: dropping service from result due to ACLs, service=%q ", id.String())
+		a.logger.Printf("[DEBUG] agent: dropping service from result due to ACLs, service=%q", id.String())
 		delete(*services, id)
 	}
 	return nil
@@ -341,7 +347,7 @@ func (a *Agent) filterChecksWithAuthorizer(authz acl.Authorizer, checks *map[str
 				continue
 			}
 		}
-		a.logger.Printf("[DEBUG] agent: dropping check from result due to ACLs, check=%q ", id.String())
+		a.logger.Printf("[DEBUG] agent: dropping check from result due to ACLs, check=%q", id.String())
 		delete(*checks, id)
 	}
 	return nil
diff --git a/agent/agent.go b/agent/agent.go
index 002993e2f8d2..951dc56c88b0 100644
--- a/agent/agent.go
+++ b/agent/agent.go
@@ -1935,16 +1935,12 @@ OUTER:
 					WriteRequest: structs.WriteRequest{Token: agentToken},
 				}
 				var reply struct{}
-				//  todo(mkcp) port all of these logger calls to hclog w/ loglevel configuration
+				// todo(kit) port all of these logger calls to hclog w/ loglevel configuration
+				// todo(kit) handle acl.ErrNotFound cases here in the future
 				if err := a.RPC("Coordinate.Update", &req, &reply); err != nil {
 					if acl.IsErrPermissionDenied(err) {
-						_, tokenIdent, err2 := a.resolveIdentityFromToken(agentToken)
-						if err2 != nil {
-							a.logger.Printf("[DEBUG] agent: failed to acquire token identity, err=%v", err2)
-						}
-						if tokenIdent != nil {
-							a.logger.Printf("[DEBUG] agent: Coordinate update blocked by ACLs, accessorID=%v", tokenIdent.ID())
-						}
+						accessorID := a.aclAccessorID(agentToken)
+						a.logger.Printf("[DEBUG] agent: Coordinate update blocked by ACLs, accessorID=%v", accessorID)
 					} else {
 						a.logger.Printf("[ERR] agent: Coordinate update error: %v", err)
 					}
diff --git a/agent/consul/acl_endpoint.go b/agent/consul/acl_endpoint.go
index f5e0e2caac2c..aed0262d15c1 100644
--- a/agent/consul/acl_endpoint.go
+++ b/agent/consul/acl_endpoint.go
@@ -2392,17 +2392,3 @@ func (a *ACL) Authorize(args *structs.RemoteACLAuthorizationRequest, reply *[]st
 	*reply = responses
 	return nil
 }
-
-// ResolveIdentityFromToken passes through a request from the ACL type to the ACL's srv delegate.
-func (a *ACL) ResolveIdentityFromToken(args *structs.ACLRequest, reply *structs.ACLIdentity) error {
-	_, ident, err := a.srv.ResolveIdentityFromToken(args.WriteRequest.Token)
-	if err != nil {
-		return err
-	} else if ident == nil {
-		return fmt.Errorf("Failed to initialize identity")
-	}
-
-	// Set our reply and return
-	*reply = ident
-	return nil
-}
diff --git a/agent/consul/intention_endpoint.go b/agent/consul/intention_endpoint.go
index a783bbde73bc..a3ccfea1028a 100644
--- a/agent/consul/intention_endpoint.go
+++ b/agent/consul/intention_endpoint.go
@@ -44,6 +44,7 @@ func (s *Intention) prepareApplyCreate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
+		// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 		s.srv.logger.Printf("[WARN] consul.intention: Intention creation denied due to ACLs, accessorID=%q", accessorID)
 		return acl.ErrPermissionDenied
 	}
@@ -95,6 +96,7 @@ func (s *Intention) prepareApplyUpdate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
+		// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
@@ -115,6 +117,7 @@ func (s *Intention) prepareApplyUpdate(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
+		// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 		s.srv.logger.Printf("[WARN] consul.intention: Update operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
@@ -151,7 +154,7 @@ func (s *Intention) prepareApplyDelete(ident structs.ACLIdentity, authz acl.Auth
 	state := s.srv.fsm.State()
 	_, ixn, err := state.IntentionGet(nil, args.Intention.ID)
 	if err != nil {
-		return fmt.Errorf("Intention lookup failed: %q", err)
+		return fmt.Errorf("Intention lookup failed: %v", err)
 	}
 	if ixn == nil {
 		return fmt.Errorf("Cannot delete non-existent intention: '%s'", args.Intention.ID)
@@ -165,6 +168,7 @@ func (s *Intention) prepareApplyDelete(ident structs.ACLIdentity, authz acl.Auth
 		if ident != nil {
 			accessorID = ident.ID()
 		}
+		// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 		s.srv.logger.Printf("[WARN] consul.intention: Deletion operation on intention denied due to ACLs, intention=%q accessorID=%q", args.Intention.ID, accessorID)
 		return acl.ErrPermissionDenied
 	}
@@ -264,14 +268,8 @@ func (s *Intention) Get(
 
 			// If ACLs prevented any responses, error
 			if len(reply.Intentions) == 0 {
-				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
-				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
-				}
-				var accessorID string
-				if ident != nil {
-					accessorID = ident.ID()
-				}
+				accessorID := s.aclAccessorID(args.Token)
+				// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 				s.srv.logger.Printf("[WARN] consul.intention: Request to get intention denied due to ACLs, intention=%s accessorID=%q", args.IntentionID, accessorID)
 				return acl.ErrPermissionDenied
 			}
@@ -336,14 +334,8 @@ func (s *Intention) Match(
 		for _, entry := range args.Match.Entries {
 			entry.FillAuthzContext(&authzContext)
 			if prefix := entry.Name; prefix != "" && rule.IntentionRead(prefix, &authzContext) != acl.Allow {
-				_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
-				if err != nil {
-					s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
-				}
-				var accessorID string
-				if ident != nil {
-					accessorID = ident.ID()
-				}
+				accessorID := s.aclAccessorID(args.Token)
+				// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 				s.srv.logger.Printf("[WARN] consul.intention: Operation on intention prefix denied due to ACLs, prefix=%s accessorID=%q", prefix, accessorID)
 				return acl.ErrPermissionDenied
 			}
@@ -415,14 +407,8 @@ func (s *Intention) Check(
 		var authzContext acl.AuthorizerContext
 		query.FillAuthzContext(&authzContext)
 		if rule != nil && rule.ServiceRead(prefix, &authzContext) != acl.Allow {
-			_, ident, err := s.srv.ResolveIdentityFromToken(args.Token)
-			if err != nil {
-				s.srv.logger.Printf("[DEBUG] consul.intention: failed to failed to acquire token identity, err=%q", err)
-			}
-			var accessorID string
-			if ident != nil {
-				accessorID = ident.ID()
-			}
+			accessorID := s.aclAccessorID(args.Token)
+			// todo(kit) Migrate intention access denial logging over to audit logging when we implement it
 			s.srv.logger.Printf("[WARN] consul.intention: test on intention denied due to ACLs, intention=%s accessorID=%q", prefix, accessorID)
 			return acl.ErrPermissionDenied
 		}
@@ -478,3 +464,18 @@ func (s *Intention) Check(
 
 	return nil
 }
+
+// aclAccessorID is used to convert an ACLToken's secretID to its accessorID for non-
+// critical purposes, such as logging. Therefore we interpret all errors as empty-string
+// so we can safely log it without handling non-critical errors at the usage site.
+func (s *Intention) aclAccessorID(secretID string) string {
+	_, ident, err := s.srv.ResolveIdentityFromToken(secretID)
+	if err != nil {
+		s.srv.logger.Printf("[DEBUG] consul.intention: %v", err)
+		return ""
+	}
+	if ident == nil {
+		return ""
+	}
+	return ident.ID()
+}
diff --git a/agent/consul/internal_endpoint.go b/agent/consul/internal_endpoint.go
index 11d058057e20..2481148aed20 100644
--- a/agent/consul/internal_endpoint.go
+++ b/agent/consul/internal_endpoint.go
@@ -126,16 +126,8 @@ func (m *Internal) EventFire(args *structs.EventFireRequest,
 	}
 
 	if rule != nil && rule.EventWrite(args.Name, nil) != acl.Allow {
-		_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
-		if err != nil {
-			m.srv.logger.Printf("[DEBUG] consul.intention: failed to fetch ACL AccessorID, err=%v", err)
-		}
-		var accessorID string
-		if ident != nil {
-			accessorID = ident.ID()
-		}
+		accessorID := m.aclAccessorID(args.Token)
 		m.srv.logger.Printf("[DEBUG] consul: user event blocked by ACLs, event=%q accessorID=%q", args.Name, accessorID)
-
 		return acl.ErrPermissionDenied
 	}
 
@@ -172,15 +164,7 @@ func (m *Internal) KeyringOperation(
 		switch args.Operation {
 		case structs.KeyringList:
 			if rule.KeyringRead(nil) != acl.Allow {
-				_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
-				if err != nil {
-					m.srv.logger.Printf("[DEBUG] failed to fetch ACL AccessorID, err=%v", err)
-				}
-				var accessorID string
-				if ident != nil {
-					accessorID = ident.ID()
-				}
-				return fmt.Errorf("Reading keyring denied by ACLs, accessorID=%v", accessorID)
+				return fmt.Errorf("Reading keyring denied by ACLs")
 			}
 		case structs.KeyringInstall:
 			fallthrough
@@ -188,15 +172,7 @@ func (m *Internal) KeyringOperation(
 			fallthrough
 		case structs.KeyringRemove:
 			if rule.KeyringWrite(nil) != acl.Allow {
-				_, ident, err := m.srv.ResolveIdentityFromToken(args.Token)
-				if err != nil {
-					m.srv.logger.Printf("[DEBUG] failed to fetch ACL AccessorID, err=%v", err)
-				}
-				var accessorID string
-				if ident != nil {
-					accessorID = ident.ID()
-				}
-				return fmt.Errorf("Modifying keyring denied due to ACLs, accessorID=%v", accessorID)
+				return fmt.Errorf("Modifying keyring denied due to ACLs")
 			}
 		default:
 			panic("Invalid keyring operation")
@@ -282,3 +258,18 @@ func (m *Internal) executeKeyringOpMgr(
 		Error:      errStr,
 	})
 }
+
+// aclAccessorID is used to convert an ACLToken's secretID to its accessorID for non-
+// critical purposes, such as logging. Therefore we interpret all errors as empty-string
+// so we can safely log it without handling non-critical errors at the usage site.
+func (m *Internal) aclAccessorID(secretID string) string {
+	_, ident, err := m.srv.ResolveIdentityFromToken(secretID)
+	if err != nil {
+		m.srv.logger.Printf("[DEBUG] consul.internal: %v", err)
+		return ""
+	}
+	if ident == nil {
+		return ""
+	}
+	return ident.ID()
+}
diff --git a/agent/local/state.go b/agent/local/state.go
index 2d2e2ef85d84..d485d8afc203 100644
--- a/agent/local/state.go
+++ b/agent/local/state.go
@@ -121,6 +121,7 @@ func (c *CheckState) CriticalFor() time.Duration {
 
 type rpc interface {
 	RPC(method string, args interface{}, reply interface{}) error
+	ResolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error)
 }
 
 // State is used to represent the node's services,
@@ -1106,7 +1107,7 @@ func (l *State) deleteService(key structs.ServiceID) error {
 		// todo(fs): mark the service to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.services[key].InSync = true
-		accessorID := l.ACLAccessorID(st)
+		accessorID := l.aclAccessorID(st)
 		l.logger.Printf("[DEBUG] agent: Service deregistration blocked by ACLs, service=%q accessorID=%v", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "service", "deregistration"}, 1)
 		return nil
@@ -1143,7 +1144,7 @@ func (l *State) deleteCheck(key structs.CheckID) error {
 		// todo(fs): mark the check to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
-		accessorID := l.ACLAccessorID(ct)
+		accessorID := l.aclAccessorID(ct)
 		l.logger.Printf("[DEBUG] agent: Check deregistration blocked by ACLs, check=%q accessorID=%q", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "deregistration"}, 1)
 		return nil
@@ -1231,7 +1232,7 @@ func (l *State) syncService(key structs.ServiceID) error {
 			checkKey.Init(check.CheckID, &check.EnterpriseMeta)
 			l.checks[checkKey].InSync = true
 		}
-		accessorID := l.ACLAccessorID(st)
+		accessorID := l.aclAccessorID(st)
 		l.logger.Printf("[DEBUG] agent: Service registration blocked by ACLs, check=%q accessorID=%s", key.String(), accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "service", "registration"}, 1)
 		return nil
@@ -1282,7 +1283,7 @@ func (l *State) syncCheck(key structs.CheckID) error {
 		// todo(fs): mark the check to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.checks[key].InSync = true
-		accessorID := l.ACLAccessorID(ct)
+		accessorID := l.aclAccessorID(ct)
 		l.logger.Printf("[DEBUG] agent: Check registration blocked by ACLs, check=%q accessorID=%q", key, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "check", "registration"}, 1)
 		return nil
@@ -1316,7 +1317,7 @@ func (l *State) syncNodeInfo() error {
 		// todo(fs): mark the node info to be in sync to prevent excessive retrying before next full sync
 		// todo(fs): some backoff strategy might be a better solution
 		l.nodeInfoInSync = true
-		accessorID := l.ACLAccessorID(at)
+		accessorID := l.aclAccessorID(at)
 		l.logger.Printf("[DEBUG] agent: Node info update blocked by ACLs, nodeID=%q accessorID=%q", l.config.NodeID, accessorID)
 		metrics.IncrCounter([]string{"acl", "blocked", "node", "registration"}, 1)
 		return nil
@@ -1343,23 +1344,17 @@ func (l *State) notifyIfAliased(serviceID structs.ServiceID) {
 	}
 }
 
-// ACLAccessorID takes an ACL secret token and retrives identity metadata on the
-// token, returning just the accessorID so we can log it here. In the future we
-// may wish to return more of the fields on structs.ACLIdentity to log out more
-// debug info when ACLs are denied in state.go.
-func (l *State) ACLAccessorID(token string) string {
-	req := structs.ACLRequest{
-		Datacenter:   l.config.Datacenter,
-		WriteRequest: structs.WriteRequest{Token: token},
-	}
-	var reply structs.ACLIdentity
-	if err := l.Delegate.RPC("ACL.ResolveIdentityFromToken", &req, &reply); err != nil {
-		l.logger.Printf("[DEBUG] agent.local: failed to acquire token identity, err=%q", err)
+// aclAccessorID is used to convert an ACLToken's secretID to its accessorID for non-
+// critical purposes, such as logging. Therefore we interpret all errors as empty-string
+// so we can safely log it without handling non-critical errors at the usage site.
+func (l *State) aclAccessorID(secretID string) string {
+	_, ident, err := l.Delegate.ResolveIdentityFromToken(secretID)
+	if err != nil {
+		l.logger.Printf("[DEBUG] agent.local: %v", err)
 		return ""
 	}
-	if reply == nil {
+	if ident == nil {
 		return ""
 	}
-
-	return reply.ID()
+	return ident.ID()
 }

From 6d801ce84a7fa0dbd4d6e06b317e2defd7a3abd0 Mon Sep 17 00:00:00 2001
From: Kit Patella <kit@jepsen.io>
Date: Mon, 27 Jan 2020 11:50:29 -0800
Subject: [PATCH 9/9] Update agent/acl.go

Co-Authored-By: R.B. Boyer <public@richardboyer.net>
---
 agent/acl.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/agent/acl.go b/agent/acl.go
index 6700b0e1c056..56ada17def8d 100644
--- a/agent/acl.go
+++ b/agent/acl.go
@@ -41,7 +41,7 @@ func (a *Agent) resolveTokenAndDefaultMeta(id string, entMeta *structs.Enterpris
 	return a.delegate.ResolveTokenAndDefaultMeta(id, entMeta, authzContext)
 }
 
-// resolveTokenAndDefaultMeta is used to resolve an ACLToken's secretID to a structs.ACLIdentity
+// resolveIdentityFromToken is used to resolve an ACLToken's secretID to a structs.ACLIdentity
 func (a *Agent) resolveIdentityFromToken(secretID string) (bool, structs.ACLIdentity, error) {
 	// ACLs are disabled
 	if !a.delegate.ACLsEnabled() {