envoy: streamline logging of proxy object (#4170)

Streamlines the logging of the proxy object so that logs are consistent in syntax which makes it easier to correlate log messages. Required to simplify debugging for #4167 Signed-off-by: Shashank Ram <[email protected]>
openservicemesh · Sep 24, 2021 · 644fbef · 644fbef
1 parent 41c04a2
commit 644fbef
Show file tree

Hide file tree

Showing 14 changed files with 91 additions and 87 deletions.
diff --git a/pkg/envoy/ads/cache_stream.go b/pkg/envoy/ads/cache_stream.go
@@ -100,7 +100,7 @@ func (s *Server) RecordFullSnapshot(proxy *envoy.Proxy, snapshotResources map[en
 	)
 
 	if err := snapshot.Consistent(); err != nil {
-		log.Warn().Msgf("Snapshot for for proxy %s not consistent: %v", proxy.GetCertificateCommonName(), err)
+		log.Warn().Err(err).Str("proxy", proxy.String()).Msgf("Snapshot for proxy not consistent")
 	}
 
 	return s.ch.SetSnapshot(proxy.GetCertificateCommonName().String(), snapshot)

diff --git a/pkg/envoy/ads/grpc.go b/pkg/envoy/ads/grpc.go
@@ -21,14 +21,14 @@ func receive(requests chan xds_discovery.DiscoveryRequest, server *xds_discovery
 		request, recvErr := (*server).Recv()
 		if recvErr != nil {
 			if status.Code(recvErr) == codes.Canceled || recvErr == io.EOF {
-				log.Debug().Err(recvErr).Msgf("[grpc] Connection terminated")
+				log.Debug().Err(recvErr).Str("proxy", proxy.String()).Msg("gRPC Connection terminated")
 				return
 			}
 			log.Error().Err(recvErr).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrGRPCConnectionFailed)).
-				Msgf("[grpc] Connection error")
+				Str("proxy", proxy.String()).Msg("gRPC Connection error")
 			return
 		}
-		log.Trace().Msgf("[grpc] Received DiscoveryRequest from Envoy with certificate SerialNumber %s", proxy.GetCertificateSerialNumber())
+		log.Debug().Str("proxy", proxy.String()).Msgf("Received DiscoveryRequest from proxy")
 		requests <- *request
 	}
 }
diff --git a/pkg/envoy/ads/jobs.go b/pkg/envoy/ads/jobs.go
@@ -30,8 +30,7 @@ func (proxyJob *proxyResponseJob) GetDoneCh() <-chan struct{} {
 func (proxyJob *proxyResponseJob) Run() {
 	err := (*proxyJob.xdsServer).sendResponse(proxyJob.proxy, proxyJob.adsStream, proxyJob.request, proxyJob.xdsServer.cfg, proxyJob.typeURIs...)
 	if err != nil {
-		log.Error().Err(err).Msgf("Failed to create and send %v update to proxy %s",
-			proxyJob.typeURIs, proxyJob.proxy.String())
+		log.Error().Err(err).Str("proxy", proxyJob.proxy.String()).Msgf("Failed to create and send %v update to proxy", proxyJob.typeURIs)
 	}
 	close(proxyJob.done)
 }

diff --git a/pkg/envoy/ads/profile.go b/pkg/envoy/ads/profile.go
@@ -8,7 +8,6 @@ import (
 	xds_discovery "github.com/envoyproxy/go-control-plane/envoy/service/discovery/v3"
 	"github.com/envoyproxy/go-control-plane/pkg/cache/types"
 	"github.com/envoyproxy/go-control-plane/pkg/cache/v3"
-	"github.com/rs/zerolog"
 
 	"github.com/openservicemesh/osm/pkg/certificate"
 	"github.com/openservicemesh/osm/pkg/envoy"
@@ -20,10 +19,10 @@ const (
 	MaxXdsLogsPerProxy = 20
 )
 
-func xdsPathTimeTrack(startedAt time.Time, log *zerolog.Event, typeURI envoy.TypeURI, proxy *envoy.Proxy, success bool) {
+func xdsPathTimeTrack(startedAt time.Time, typeURI envoy.TypeURI, proxy *envoy.Proxy, success bool) {
 	elapsed := time.Since(startedAt)
 
-	log.Msgf("[%s] processing for Proxy with Certificate SerialNumber=%s took %s", typeURI, proxy.GetCertificateSerialNumber(), elapsed)
+	log.Debug().Str("proxy", proxy.String()).Msgf("Time taken proxy to generate response for request with typeURI=%s: %s", typeURI, elapsed)
 
 	metricsstore.DefaultMetricsStore.ProxyConfigUpdateTime.
 		WithLabelValues(typeURI.String(), fmt.Sprintf("%t", success)).
@@ -73,8 +72,8 @@ func validateRequestResponse(proxy *envoy.Proxy, request *xds_discovery.Discover
 	resDifference := resourcesRequested.Difference(resourcesToSend)
 	diffCardinality := resDifference.Cardinality()
 	if diffCardinality != 0 {
-		log.Warn().Msgf("Proxy %s: not all request resources for type %s are being responded to req [%v] resp [%v] diff [%v]",
-			proxy.String(), envoy.TypeURI(request.TypeUrl).Short(),
+		log.Warn().Str("proxy", proxy.String()).Msgf("Not all request resources for type %s are being responded to req [%v] resp [%v] diff [%v]",
+			envoy.TypeURI(request.TypeUrl).Short(),
 			resourcesRequested, resourcesToSend, resDifference)
 	}
 

diff --git a/pkg/envoy/ads/response.go b/pkg/envoy/ads/response.go
@@ -20,7 +20,7 @@ func (s *Server) getTypeResources(proxy *envoy.Proxy, request *xds_discovery.Dis
 	// Tracks the success of this TypeURI response operation; accounts also for receipt on envoy server side
 	startedAt := time.Now()
 	typeURI := envoy.TypeURI(request.TypeUrl)
-	log.Trace().Msgf("Proxy %s: getting resources for type %s", proxy.String(), typeURI.Short())
+	log.Trace().Str("proxy", proxy.String()).Msgf("Getting resources for type %s", typeURI.Short())
 
 	handler, ok := s.xdsHandlers[typeURI]
 	if !ok {
@@ -34,11 +34,11 @@ func (s *Server) getTypeResources(proxy *envoy.Proxy, request *xds_discovery.Dis
 	// Invoke XDS handler
 	resources, err := handler(s.catalog, proxy, request, s.cfg, s.certManager, s.proxyRegistry)
 	if err != nil {
-		xdsPathTimeTrack(startedAt, log.Debug(), typeURI, proxy, false)
+		xdsPathTimeTrack(startedAt, typeURI, proxy, false)
 		return nil, errCreatingResponse
 	}
 
-	xdsPathTimeTrack(startedAt, log.Debug(), typeURI, proxy, true)
+	xdsPathTimeTrack(startedAt, typeURI, proxy, true)
 	return resources, nil
 }
 
@@ -77,8 +77,8 @@ func (s *Server) sendResponse(proxy *envoy.Proxy, server *xds_discovery.Aggregat
 		// Generate the resources for this request
 		resources, err := s.getTypeResources(proxy, finalReq)
 		if err != nil {
-			log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrGeneratingReqResource)).
-				Msgf("Error generating response for typeURI: %s, proxy %s", typeURI.Short(), proxy.String())
+			log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrGeneratingReqResource)).Str("proxy", proxy.String()).
+				Msgf("Error generating response for typeURI: %s", typeURI.Short())
 			thereWereErrors = true
 			continue
 		}
@@ -89,7 +89,7 @@ func (s *Server) sendResponse(proxy *envoy.Proxy, server *xds_discovery.Aggregat
 		} else {
 			// If cache disabled, craft and send a reply to the proxy on the stream
 			if err := s.SendDiscoveryResponse(proxy, finalReq, server, resources); err != nil {
-				log.Error().Err(err).Msgf("Creating %s update for Proxy %s", typeURI.Short(), proxy.GetCertificateCommonName())
+				log.Error().Err(err).Str("proxy", proxy.String()).Msgf("Error sending DiscoveryResponse for typeUrl: %s", typeURI.Short())
 				thereWereErrors = true
 			}
 		}
@@ -98,16 +98,16 @@ func (s *Server) sendResponse(proxy *envoy.Proxy, server *xds_discovery.Aggregat
 	if s.cacheEnabled {
 		// Store the aggregated resources as a full snapshot
 		if err := s.RecordFullSnapshot(proxy, cacheResourceMap); err != nil {
-			log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrRecordingSnapshot)).
-				Msgf("Failed to record snapshot for proxy %s: %v", proxy.GetCertificateCommonName(), err)
+			log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrRecordingSnapshot)).Str("proxy", proxy.String()).
+				Msgf("Error recording snapshot for proxy: %v", err)
 			thereWereErrors = true
 		}
 	}
 
 	isFullUpdate := len(typeURIsToSend) == len(envoy.XDSResponseOrder)
 	if isFullUpdate {
 		success := !thereWereErrors
-		xdsPathTimeTrack(time.Now(), log.Info(), envoy.TypeADS, proxy, success)
+		xdsPathTimeTrack(time.Now(), envoy.TypeADS, proxy, success)
 	}
 
 	return nil
@@ -160,7 +160,7 @@ func (s *Server) SendDiscoveryResponse(proxy *envoy.Proxy, request *xds_discover
 	// Send the response
 	if err := (*server).Send(response); err != nil {
 		log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrSendingDiscoveryResponse)).
-			Msgf("Error sending response for type %s to proxy %s", typeURI.Short(), proxy.String())
+			Str("proxy", proxy.String()).Msgf("Error sending response for typeURI %s to proxy", typeURI.Short())
 		return err
 	}
 

diff --git a/pkg/envoy/ads/secrets.go b/pkg/envoy/ads/secrets.go
@@ -26,7 +26,7 @@ func makeRequestForAllSecrets(proxy *envoy.Proxy, meshCatalog catalog.MeshCatalo
 	proxyIdentity, err := envoy.GetServiceIdentityFromProxyCertificate(proxy.GetCertificateCommonName())
 	if err != nil {
 		log.Error().Err(err).Str(errcode.Kind, errcode.GetErrCodeWithMetric(errcode.ErrGettingServiceIdentity)).
-			Msgf("Error looking up proxy identity for proxy %s", proxy.String())
+			Str("proxy", proxy.String()).Msgf("Error looking up proxy identity")
 		return nil
 	}