Add Trace IDs and metadata to log lines (#648)

Author: shulin-sq

cmd/aws-application-networking-k8s/main.go

@@ -108,9 +108,10 @@ func main() {
 
 	logLevel := logLevel()
 	log := gwlog.NewLogger(logLevel)
-	ctrl.SetLogger(zapr.NewLogger(log.Desugar()).WithName("runtime"))
+	ctrl.SetLogger(zapr.NewLogger(log.InnerLogger.Desugar()).WithName("runtime"))
+
+	setupLog := log.InnerLogger.Named("setup")
 
-	setupLog := log.Named("setup")
 	err := config.ConfigInit()
 	if err != nil {
 		setupLog.Fatalf("init config failed: %s", err)

go.mod

@@ -6,6 +6,7 @@ require (
 	github.com/aws/aws-sdk-go v1.53.7
 	github.com/go-logr/zapr v1.2.4
 	github.com/golang/mock v1.6.0
+	github.com/google/uuid v1.3.1
 	github.com/hashicorp/golang-lru/v2 v2.0.7
 	github.com/onsi/ginkgo v1.16.5
 	github.com/onsi/gomega v1.27.10
@@ -42,7 +43,6 @@ require (
 	github.com/google/gnostic-models v0.6.8 // indirect
 	github.com/google/go-cmp v0.6.0 // indirect
 	github.com/google/gofuzz v1.2.0 // indirect
-	github.com/google/uuid v1.3.1 // indirect
 	github.com/imdario/mergo v0.3.16 // indirect
 	github.com/jmespath/go-jmespath v0.4.0 // indirect
 	github.com/josharian/intern v1.0.0 // indirect

pkg/aws/cloud.go

@@ -59,14 +59,14 @@ func NewCloud(log gwlog.Logger, cfg CloudConfig, metricsRegisterer prometheus.Re
 
 	sess.Handlers.Complete.PushFront(func(r *request.Request) {
 		if r.Error != nil {
-			log.Debugw("error",
+			log.Debugw(context.TODO(), "error",
 				"error", r.Error.Error(),
 				"serviceName", r.ClientInfo.ServiceName,
 				"operation", r.Operation.Name,
 				"params", r.Params,
 			)
 		} else {
-			log.Debugw("response",
+			log.Debugw(context.TODO(), "response",
 				"serviceName", r.ClientInfo.ServiceName,
 				"operation", r.Operation.Name,
 				"params", r.Params,

pkg/controllers/accesslogpolicy_controller.go

@@ -104,18 +104,22 @@ func RegisterAccessLogPolicyController(
 }
 
 func (r *accessLogPolicyReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-	r.log.Infow("reconcile", "name", req.Name)
+	ctx = gwlog.StartReconcileTrace(ctx, r.log, "accesslogpolicy", req.Name, req.Namespace)
+	defer func() {
+		gwlog.EndReconcileTrace(ctx, r.log)
+	}()
+
 	recErr := r.reconcile(ctx, req)
 	if recErr != nil {
-		r.log.Infow("reconcile error", "name", req.Name, "message", recErr.Error())
+		r.log.Infow(ctx, "reconcile error", "name", req.Name, "message", recErr.Error())
 	}
 	res, retryErr := lattice_runtime.HandleReconcileError(recErr)
 	if res.RequeueAfter != 0 {
-		r.log.Infow("requeue request", "name", req.Name, "requeueAfter", res.RequeueAfter)
+		r.log.Infow(ctx, "requeue request", "name", req.Name, "requeueAfter", res.RequeueAfter)
 	} else if res.Requeue {
-		r.log.Infow("requeue request", "name", req.Name)
+		r.log.Infow(ctx, "requeue request", "name", req.Name)
 	} else if retryErr == nil {
-		r.log.Infow("reconciled", "name", req.Name)
+		r.log.Infow(ctx, "reconciled", "name", req.Name)
 	}
 	return res, retryErr
 }
@@ -266,12 +270,12 @@ func (r *accessLogPolicyReconciler) buildAndDeployModel(
 	if err != nil {
 		return nil, err
 	}
-	r.log.Debugw("Successfully built model", "stack", jsonStack)
+	r.log.Debugw(ctx, "Successfully built model", "stack", jsonStack)
 
 	if err := r.stackDeployer.Deploy(ctx, stack); err != nil {
 		return nil, err
 	}
-	r.log.Debugf("successfully deployed model for stack %s:%s", stack.StackID().Name, stack.StackID().Namespace)
+	r.log.Debugf(ctx, "successfully deployed model for stack %s:%s", stack.StackID().Name, stack.StackID().Namespace)
 
 	return stack, nil
 }
@@ -342,7 +346,7 @@ func (r *accessLogPolicyReconciler) findImpactedAccessLogPolicies(ctx context.Co
 	alps := &anv1alpha1.AccessLogPolicyList{}
 	err := r.client.List(ctx, alps, listOptions)
 	if err != nil {
-		r.log.Errorf("Failed to list all Access Log Policies, %s", err)
+		r.log.Errorf(ctx, "Failed to list all Access Log Policies, %s", err)
 		return []reconcile.Request{}
 	}
 
@@ -358,7 +362,7 @@ func (r *accessLogPolicyReconciler) findImpactedAccessLogPolicies(ctx context.Co
 			continue
 		}
 
-		r.log.Debugf("Adding Access Log Policy %s/%s to queue due to %s event", alp.Namespace, alp.Name, targetRefKind)
+		r.log.Debugf(ctx, "Adding Access Log Policy %s/%s to queue due to %s event", alp.Namespace, alp.Name, targetRefKind)
 		requests = append(requests, reconcile.Request{
 			NamespacedName: types.NamespacedName{
 				Namespace: alp.Namespace,

pkg/controllers/eventhandlers/gateway.go

@@ -38,7 +38,7 @@ var ZeroTransitionTime = metav1.NewTime(time.Time{})
 func (h *enqueueRequestsForGatewayEvent) Create(ctx context.Context, e event.CreateEvent, queue workqueue.RateLimitingInterface) {
 	gwNew := e.Object.(*gateway_api.Gateway)
 
-	h.log.Infof("Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)
+	h.log.Infof(ctx, "Received Create event for Gateway %s-%s", gwNew.Name, gwNew.Namespace)
 
 	// initialize transition time
 	gwNew.Status.Conditions[0].LastTransitionTime = ZeroTransitionTime
@@ -49,7 +49,7 @@ func (h *enqueueRequestsForGatewayEvent) Update(ctx context.Context, e event.Upd
 	gwOld := e.ObjectOld.(*gateway_api.Gateway)
 	gwNew := e.ObjectNew.(*gateway_api.Gateway)
 
-	h.log.Infof("Received Update event for Gateway %s-%s", gwNew.GetName(), gwNew.GetNamespace())
+	h.log.Infof(ctx, "Received Update event for Gateway %s-%s", gwNew.GetName(), gwNew.GetNamespace())
 
 	if !equality.Semantic.DeepEqual(gwOld.Spec, gwNew.Spec) {
 		// initialize transition time
@@ -69,13 +69,13 @@ func (h *enqueueRequestsForGatewayEvent) Generic(ctx context.Context, e event.Ge
 func (h *enqueueRequestsForGatewayEvent) enqueueImpactedRoutes(ctx context.Context, queue workqueue.RateLimitingInterface) {
 	routes, err := core.ListAllRoutes(ctx, h.client)
 	if err != nil {
-		h.log.Errorf("Failed to list all routes, %s", err)
+		h.log.Errorf(ctx, "Failed to list all routes, %s", err)
 		return
 	}
 
 	for _, route := range routes {
 		if len(route.Spec().ParentRefs()) <= 0 {
-			h.log.Debugf("Ignoring Route with no parentRef %s-%s", route.Name(), route.Namespace())
+			h.log.Debugf(ctx, "Ignoring Route with no parentRef %s-%s", route.Name(), route.Namespace())
 			continue
 		}
 
@@ -92,7 +92,7 @@ func (h *enqueueRequestsForGatewayEvent) enqueueImpactedRoutes(ctx context.Conte
 
 		gw := &gateway_api.Gateway{}
 		if err := h.client.Get(ctx, gwName, gw); err != nil {
-			h.log.Debugf("Ignoring Route with unknown parentRef %s-%s", route.Name(), route.Namespace())
+			h.log.Debugf(ctx, "Ignoring Route with unknown parentRef %s-%s", route.Name(), route.Namespace())
 			continue
 		}
 
@@ -104,12 +104,12 @@ func (h *enqueueRequestsForGatewayEvent) enqueueImpactedRoutes(ctx context.Conte
 		}
 
 		if err := h.client.Get(ctx, gwClassName, gwClass); err != nil {
-			h.log.Debugf("Ignoring Route with unknown Gateway %s-%s", route.Name(), route.Namespace())
+			h.log.Debugf(ctx, "Ignoring Route with unknown Gateway %s-%s", route.Name(), route.Namespace())
 			continue
 		}
 
 		if gwClass.Spec.ControllerName == config.LatticeGatewayControllerName {
-			h.log.Debugf("Adding Route %s-%s to queue due to Gateway event", route.Name(), route.Namespace())
+			h.log.Debugf(ctx, "Adding Route %s-%s to queue due to Gateway event", route.Name(), route.Namespace())
 			queue.Add(reconcile.Request{
 				NamespacedName: types.NamespacedName{
 					Namespace: route.Namespace(),

pkg/controllers/eventhandlers/gatewayclass.go

@@ -49,14 +49,14 @@ func (h *enqueueRequestsForGatewayClassEvent) enqueueImpactedGateway(
 	gwList := &gateway_api.GatewayList{}
 	err := h.client.List(ctx, gwList)
 	if err != nil {
-		h.log.Errorf("Error listing Gateways during GatewayClass event %s", err)
+		h.log.Errorf(ctx, "Error listing Gateways during GatewayClass event %s", err)
 		return
 	}
 
 	for _, gw := range gwList.Items {
 		if string(gw.Spec.GatewayClassName) == gwClass.Name {
 			if gwClass.Spec.ControllerName == config.LatticeGatewayControllerName {
-				h.log.Debugf("Found matching gateway, %s-%s", gw.Name, gw.Namespace)
+				h.log.Debugf(ctx, "Found matching gateway, %s-%s", gw.Name, gw.Namespace)
 				queue.Add(reconcile.Request{
 					NamespacedName: types.NamespacedName{
 						Namespace: gw.Namespace,

pkg/controllers/eventhandlers/mapper.go

@@ -98,29 +98,29 @@ func policyToTargetRefObj[T client.Object](r *resourceMapper, ctx context.Contex
 
 	targetRef := policy.GetTargetRef()
 	if targetRef == nil {
-		r.log.Infow("Policy does not have targetRef, skipping",
+		r.log.Infow(ctx, "Policy does not have targetRef, skipping",
 			"policyName", policyNamespacedName)
 		return null
 	}
 	expectedGroup, expectedKind, err := k8sResourceTypeToGroupAndKind(retObj)
 	if err != nil {
-		r.log.Errorw("Failed to get expected GroupKind for targetRefObj",
+		r.log.Errorw(ctx, "Failed to get expected GroupKind for targetRefObj",
 			"policyName", policyNamespacedName,
 			"targetRef", targetRef,
 			"reason", err.Error())
 		return null
 	}
 
 	if targetRef.Group != expectedGroup || targetRef.Kind != expectedKind {
-		r.log.Infow("Detected targetRef GroupKind and expected retObj GroupKind are different, skipping",
+		r.log.Infow(ctx, "Detected targetRef GroupKind and expected retObj GroupKind are different, skipping",
 			"policyName", policyNamespacedName,
 			"targetRef", targetRef,
 			"expectedGroup", expectedGroup,
 			"expectedKind", expectedKind)
 		return null
 	}
 	if targetRef.Namespace != nil && policyNamespacedName.Namespace != string(*targetRef.Namespace) {
-		r.log.Infow("Detected Policy and TargetRef namespace are different, skipping",
+		r.log.Infow(ctx, "Detected Policy and TargetRef namespace are different, skipping",
 			"policyNamespacedName", policyNamespacedName, "targetRef", targetRef,
 			"targetRef.Namespace", targetRef.Namespace,
 			"policyNamespacedName.Namespace", policyNamespacedName.Namespace)
@@ -133,16 +133,16 @@ func policyToTargetRefObj[T client.Object](r *resourceMapper, ctx context.Contex
 	}
 	if err := r.client.Get(ctx, key, retObj); err != nil {
 		if errors.IsNotFound(err) {
-			r.log.Debugw("Policy is referring to a non-existent targetRefObj, skipping",
+			r.log.Debugw(ctx, "Policy is referring to a non-existent targetRefObj, skipping",
 				"policyName", policyNamespacedName, "targetRef", targetRef)
 		} else {
 			// Still gracefully skipping the event but errors other than NotFound are bad sign.
-			r.log.Errorw("Failed to query targetRef of TargetGroupPolicy",
+			r.log.Errorw(ctx, "Failed to query targetRef of TargetGroupPolicy",
 				"policyName", policyNamespacedName, "targetRef", targetRef, "reason", err.Error())
 		}
 		return null
 	}
-	r.log.Debugw("Policy change on Service detected",
+	r.log.Debugw(ctx, "Policy change on Service detected",
 		"policyName", policyNamespacedName, "targetRef", targetRef)
 
 	return retObj

pkg/controllers/eventhandlers/service.go

@@ -45,7 +45,7 @@ func (h *serviceEventHandler) mapToServiceExport(ctx context.Context, obj client
 		requests = append(requests, reconcile.Request{
 			NamespacedName: k8s.NamespacedName(svcExport),
 		})
-		h.log.Infow("Service impacting resource change triggered ServiceExport update",
+		h.log.Infow(ctx, "Service impacting resource change triggered ServiceExport update",
 			"serviceName", svc.Namespace+"/"+svc.Name)
 	}
 	return requests
@@ -73,7 +73,7 @@ func (h *serviceEventHandler) mapToRoute(ctx context.Context, obj client.Object,
 	for _, route := range routes {
 		routeName := k8s.NamespacedName(route.K8sObject())
 		requests = append(requests, reconcile.Request{NamespacedName: routeName})
-		h.log.Infow("Service impacting resource change triggered Route update",
+		h.log.Infow(ctx, "Service impacting resource change triggered Route update",
 			"serviceName", svc.Namespace+"/"+svc.Name, "routeName", routeName, "routeType", routeType)
 	}
 	return requests

pkg/controllers/eventhandlers/serviceimport.go

@@ -41,7 +41,7 @@ func (h *serviceImportEventHandler) mapToRoute(ctx context.Context, obj client.O
 	for _, route := range routes {
 		routeName := k8s.NamespacedName(route.K8sObject())
 		requests = append(requests, reconcile.Request{NamespacedName: routeName})
-		h.log.Infow("ServiceImport resource change triggered Route update",
+		h.log.Infow(ctx, "ServiceImport resource change triggered Route update",
 			"serviceName", obj.GetNamespace()+"/"+obj.GetName(), "routeName", routeName, "routeType", routeType)
 	}
 	return requests

pkg/controllers/gateway_controller.go

@@ -19,6 +19,7 @@ package controllers
 import (
 	"context"
 	"fmt"
+
 	anv1alpha1 "github.com/aws/aws-application-networking-k8s/pkg/apis/applicationnetworking/v1alpha1"
 	"github.com/aws/aws-application-networking-k8s/pkg/aws/services"
 	"github.com/aws/aws-application-networking-k8s/pkg/controllers/eventhandlers"
@@ -90,7 +91,7 @@ func RegisterGatewayController(
 			},
 		})
 		if err != nil {
-			log.Infof("Could not setup default service network %s, proceeding without it - %s",
+			log.Infof(context.TODO(), "Could not setup default service network %s, proceeding without it - %s",
 				config.DefaultServiceNetwork, err.Error())
 		}
 	}
@@ -109,7 +110,7 @@ func RegisterGatewayController(
 	if ok {
 		builder.Watches(&anv1alpha1.VpcAssociationPolicy{}, vpcAssociationPolicyEventHandler.MapToGateway())
 	} else {
-		log.Infof("VpcAssociationPolicy CRD is not installed, skipping watch")
+		log.Infof(context.TODO(), "VpcAssociationPolicy CRD is not installed, skipping watch")
 	}
 	return builder.Complete(r)
 }
@@ -119,18 +120,22 @@ func RegisterGatewayController(
 //+kubebuilder:rbac:groups=gateway.networking.k8s.io,resources=gateways/finalizers,verbs=update
 
 func (r *gatewayReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-	r.log.Infow("reconcile", "name", req.Name)
+	ctx = gwlog.StartReconcileTrace(ctx, r.log, "gateway", req.Name, req.Namespace)
+	defer func() {
+		gwlog.EndReconcileTrace(ctx, r.log)
+	}()
+
 	recErr := r.reconcile(ctx, req)
 	if recErr != nil {
-		r.log.Infow("reconcile error", "name", req.Name, "message", recErr.Error())
+		r.log.Infow(ctx, "reconcile error", "name", req.Name, "message", recErr.Error())
 	}
 	res, retryErr := lattice_runtime.HandleReconcileError(recErr)
 	if res.RequeueAfter != 0 {
-		r.log.Infow("requeue request", "name", req.Name, "requeueAfter", res.RequeueAfter)
+		r.log.Infow(ctx, "requeue request", "name", req.Name, "requeueAfter", res.RequeueAfter)
 	} else if res.Requeue {
-		r.log.Infow("requeue request", "name", req.Name)
+		r.log.Infow(ctx, "requeue request", "name", req.Name)
 	} else if retryErr == nil {
-		r.log.Infow("reconciled", "name", req.Name)
+		r.log.Infow(ctx, "reconciled", "name", req.Name)
 	}
 	return res, retryErr
 }
@@ -149,12 +154,12 @@ func (r *gatewayReconciler) reconcile(ctx context.Context, req ctrl.Request) err
 	}
 
 	if err := r.client.Get(ctx, gwClassName, gwClass); err != nil {
-		r.log.Infow("GatewayClass is not found", "name", req.Name, "gwclass", gwClassName)
+		r.log.Infow(ctx, "GatewayClass is not found", "name", req.Name, "gwclass", gwClassName)
 		return client.IgnoreNotFound(err)
 	}
 
 	if gwClass.Spec.ControllerName != config.LatticeGatewayControllerName {
-		r.log.Infow("GatewayClass is not recognized", "name", req.Name, "gwClassControllerName", gwClass.Spec.ControllerName)
+		r.log.Infow(ctx, "GatewayClass is not recognized", "name", req.Name, "gwClassControllerName", gwClass.Spec.ControllerName)
 		return nil
 	}