diff --git a/agent/proxycfg/state.go b/agent/proxycfg/state.go index 59968e83e6..fd9bdc802c 100644 --- a/agent/proxycfg/state.go +++ b/agent/proxycfg/state.go @@ -583,6 +583,8 @@ func (s *state) initialConfigSnapshot() ConfigSnapshot { } func (s *state) run() { + logger := s.logger.Named(logging.ProxyConfig) + // Close the channel we return from Watch when we stop so consumers can stop // watching and clean up their goroutines. It's important we do this here and // not in Close since this routine sends on this chan and so might panic if it @@ -603,10 +605,13 @@ func (s *state) run() { case <-s.ctx.Done(): return case u := <-s.ch: + logger.Trace("A blocking query returned; handling snapshot update", + "proxy-id", s.proxyID.String(), + ) + if err := s.handleUpdate(u, &snap); err != nil { - s.logger.Error("watch error", - "id", u.CorrelationID, - "error", err, + logger.Error("Failed to handle update from watch", + "id", u.CorrelationID, "error", err, ) continue } @@ -616,18 +621,24 @@ func (s *state) run() { // etc on future updates. snapCopy, err := snap.Clone() if err != nil { - s.logger.Error("Failed to copy config snapshot for proxy", - "proxy", s.proxyID, - "error", err, + logger.Error("Failed to copy config snapshot for proxy", + "proxy-id", s.proxyID.String(), "error", err, ) continue } select { + // try to send case s.snapCh <- *snapCopy: - // try to send + logger.Trace("Delivered new snapshot to proxy config watchers", + "proxy-id", s.proxyID.String(), + ) + + // avoid blocking if a snapshot is already buffered default: - // avoid blocking if a snapshot is already buffered + logger.Trace("Failed to deliver new snapshot to proxy config watchers", + "proxy-id", s.proxyID.String(), + ) } // Allow the next change to trigger a send @@ -638,18 +649,25 @@ func (s *state) run() { continue case replyCh := <-s.reqCh: + logger.Trace("A proxy config snapshot was requested", + "proxy-id", s.proxyID.String(), + ) + if !snap.Valid() { // Not valid yet just respond with nil and move on to next task. replyCh <- nil + + logger.Trace("The proxy's config snapshot is not valid yet", + "proxy-id", s.proxyID.String(), + ) continue } // Make a deep copy of snap so we don't mutate any of the embedded structs // etc on future updates. snapCopy, err := snap.Clone() if err != nil { - s.logger.Error("Failed to copy config snapshot for proxy", - "proxy", s.proxyID, - "error", err, + logger.Error("Failed to copy config snapshot for proxy", + "proxy-id", s.proxyID.String(), "error", err, ) continue } diff --git a/agent/xds/server.go b/agent/xds/server.go index d8a7ecbe51..b2506a753c 100644 --- a/agent/xds/server.go +++ b/agent/xds/server.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "github.com/hashicorp/consul/logging" "sync/atomic" "time" @@ -164,6 +165,8 @@ const ( ) func (s *Server) process(stream ADSStream, reqCh <-chan *envoy.DiscoveryRequest) error { + logger := s.Logger.Named(logging.XDS) + // xDS requires a unique nonce to correlate response/request pairs var nonce uint64 @@ -324,6 +327,9 @@ func (s *Server) process(stream ADSStream, reqCh <-chan *envoy.DiscoveryRequest) // state machine. defer watchCancel() + logger.Trace("watching proxy, pending initial proxycfg snapshot", + "proxy-id", proxyID.String()) + // Now wait for the config so we can check ACL state = statePendingInitialConfig case statePendingInitialConfig: @@ -335,6 +341,9 @@ func (s *Server) process(stream ADSStream, reqCh <-chan *envoy.DiscoveryRequest) // Got config, try to authenticate next. state = stateRunning + logger.Trace("Got initial config snapshot", + "proxy-id", cfgSnap.ProxyID.String()) + // Lets actually process the config we just got or we'll mis responding fallthrough case stateRunning: @@ -346,6 +355,9 @@ func (s *Server) process(stream ADSStream, reqCh <-chan *envoy.DiscoveryRequest) // timer is first started. extendAuthTimer() + logger.Trace("Invoking all xDS resource handlers and sending new data if there is any", + "proxy-id", cfgSnap.ProxyID.String()) + // See if any handlers need to have the current (possibly new) config // sent. Note the order here is actually significant so we can't just // range the map which has no determined order. It's important because: diff --git a/logging/names.go b/logging/names.go index 5449900615..b9616b167a 100644 --- a/logging/names.go +++ b/logging/names.go @@ -56,5 +56,6 @@ const ( UIMetricsProxy string = "ui_metrics_proxy" WAN string = "wan" Watch string = "watch" + XDS string = "xds" Vault string = "vault" )