From 0d336edb65b004bcb751ec18342873c348ca41b3 Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Mon, 27 Jan 2020 11:54:32 -0800 Subject: [PATCH] Add accessorID of token when ops are denied by ACL system (#7117) * agent: add and edit doc comments * agent: add ACL token accessorID to debugging traces * agent: polish acl debugging * agent: minor fix + string fmt over value interp * agent: undo export & fix logging field names * agent: remove note and migrate up to code review * Update agent/consul/acl.go Co-Authored-By: Matt Keeler * agent: incorporate review feedback * Update agent/acl.go Co-Authored-By: R.B. Boyer Co-authored-by: Matt Keeler Co-authored-by: R.B. Boyer --- agent/acl.go | 37 ++++++++++++++-- agent/acl_test.go | 13 ++++++ agent/agent.go | 17 ++++++-- agent/consul/acl.go | 18 ++++++-- agent/consul/acl_server.go | 13 +++++- agent/consul/intention_endpoint.go | 69 ++++++++++++++++++++++++------ agent/consul/internal_endpoint.go | 18 +++++++- agent/local/state.go | 51 ++++++++++++++++------ 8 files changed, 197 insertions(+), 39 deletions(-) diff --git a/agent/acl.go b/agent/acl.go index 30788b96a2..56ada17def 100644 --- a/agent/acl.go +++ b/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 diff --git a/agent/acl_test.go b/agent/acl_test.go index 97635208bd..6d0d220e9a 100644 --- a/agent/acl_test.go +++ b/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 diff --git a/agent/agent.go b/agent/agent.go index 37f3108eab..951dc56c88 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 @@ -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) } diff --git a/agent/consul/acl.go b/agent/consul/acl.go index 1ce52dfa66..2b3db01200 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,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 diff --git a/agent/consul/acl_server.go b/agent/consul/acl_server.go index 65292e1af5..4d0ec99a3f 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 } +// 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 } diff --git a/agent/consul/intention_endpoint.go b/agent/consul/intention_endpoint.go index b99db7f399..a3ccfea102 100644 --- a/agent/consul/intention_endpoint.go +++ b/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() +} diff --git a/agent/consul/internal_endpoint.go b/agent/consul/internal_endpoint.go index 2549e812fb..2481148aed 100644 --- a/agent/consul/internal_endpoint.go +++ b/agent/consul/internal_endpoint.go @@ -126,7 +126,8 @@ 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) + 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 } @@ -257,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 72393de701..d485d8afc2 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, @@ -1079,12 +1080,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 +1107,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 +1124,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 +1144,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=%q", key.String(), accessorID) metrics.IncrCounter([]string{"acl", "blocked", "check", "deregistration"}, 1) return nil @@ -1159,6 +1165,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 +1182,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 +1197,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 +1232,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 +1246,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 +1256,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 +1283,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=%q", key, accessorID) metrics.IncrCounter([]string{"acl", "blocked", "check", "registration"}, 1) return nil @@ -1285,6 +1295,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 +1303,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 +1317,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=%q accessorID=%q", l.config.NodeID, accessorID) metrics.IncrCounter([]string{"acl", "blocked", "node", "registration"}, 1) return nil @@ -1331,3 +1343,18 @@ func (l *State) notifyIfAliased(serviceID structs.ServiceID) { } } } + +// 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 ident == nil { + return "" + } + return ident.ID() +}