Add accessorID of token when ops are denied by ACL system

agent/acl.go

@@ -41,6 +41,36 @@ func (a *Agent) resolveTokenAndDefaultMeta(id string, entMeta *structs.Enterpris
 	return a.delegate.ResolveTokenAndDefaultMeta(id, entMeta, authzContext)
 }
 
+// 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() {
+		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(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
@@ -250,7 +280,8 @@ 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)
+		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--
 	}
@@ -280,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 %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 +347,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

agent/acl_test.go

@@ -130,6 +130,19 @@ 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")
+	}
+
+	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

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
@@ -152,7 +153,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 +310,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 +356,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 +373,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 +1882,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()
@@ -1921,17 +1926,21 @@ 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(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) {
-						a.logger.Printf("[WARN] agent: Coordinate update blocked by ACLs")
+						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)
 					}

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,6 +437,9 @@ func (r *ACLResolver) fetchAndCacheIdentityFromToken(token string, cached *struc
 	return nil, err
 }
 
+// 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) {
 	// Attempt to resolve locally first (local results are not cached)
 	if done, identity, err := r.delegate.ResolveIdentityFromToken(token); done {
@@ -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 accessorID=%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 accessorID=%q", roleID, accessorID)
 			}
 
 			continue

agent/consul/acl_server.go

@@ -164,6 +164,7 @@ func (s *Server) ACLsEnabled() bool {
 	return s.config.ACLsEnabled
 }
 
+// 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
@@ -217,10 +218,12 @@ 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) {
+// 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 {
-		return nil, err
+		return nil, nil, err
 	}
 
 	// Default the EnterpriseMeta based on the Tokens meta or actual defaults
@@ -234,6 +237,12 @@ func (s *Server) ResolveTokenAndDefaultMeta(token string, entMeta *structs.Enter
 	// Use the meta to fill in the ACL authorization context
 	entMeta.FillAuthzContext(authzContext)
 
+	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
 }
 

agent/consul/intention_endpoint.go

@@ -38,9 +38,14 @@ 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()
+		}
+		// 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
 	}
 
@@ -85,9 +90,14 @@ 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()
+		}
+		// 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
 	}
 
@@ -103,7 +113,12 @@ 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()
+		}
+		// 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
 	}
 
@@ -134,7 +149,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 +164,12 @@ 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()
+		}
+		// 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
 	}
 
@@ -179,22 +199,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 +268,9 @@ 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)
+				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
 			}
 
@@ -312,7 +334,9 @@ 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)
+				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
 			}
 		}
@@ -383,7 +407,9 @@ 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)
+			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
 		}
 	}
@@ -438,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()
+}