From 293531f787843b4a89a2b01fcb66dc4a90d06730 Mon Sep 17 00:00:00 2001 From: Shulin Jia <83986148+shulin-sq@users.noreply.github.com> Date: Tue, 18 Jun 2024 13:04:44 -0700 Subject: [PATCH] Add Trace IDs and metadata to log lines (#648) --- cmd/aws-application-networking-k8s/main.go | 5 +- go.mod | 2 +- pkg/aws/cloud.go | 4 +- pkg/controllers/accesslogpolicy_controller.go | 22 ++-- pkg/controllers/eventhandlers/gateway.go | 14 +-- pkg/controllers/eventhandlers/gatewayclass.go | 4 +- pkg/controllers/eventhandlers/mapper.go | 14 +-- pkg/controllers/eventhandlers/service.go | 4 +- .../eventhandlers/serviceimport.go | 2 +- pkg/controllers/gateway_controller.go | 23 ++-- pkg/controllers/gatewayclass_controller.go | 11 +- pkg/controllers/iamauthpolicy_controller.go | 9 +- pkg/controllers/route_controller.go | 44 +++---- pkg/controllers/route_controller_test.go | 32 ++--- pkg/controllers/service_controller.go | 10 +- pkg/controllers/serviceexport_controller.go | 22 ++-- pkg/controllers/serviceimport_controller.go | 11 +- .../targetgrouppolicy_controller.go | 9 +- .../vpcassociationpolicy_controller.go | 11 +- pkg/deploy/externaldns/dnsendpoint_manager.go | 12 +- .../access_log_subscription_synthesizer.go | 8 +- pkg/deploy/lattice/listener_manager.go | 25 ++-- pkg/deploy/lattice/listener_manager_test.go | 4 +- pkg/deploy/lattice/listener_synthesizer.go | 6 +- pkg/deploy/lattice/rule_manager.go | 16 +-- pkg/deploy/lattice/rule_synthesizer.go | 2 +- pkg/deploy/lattice/service_manager.go | 12 +- pkg/deploy/lattice/service_network_manager.go | 18 +-- pkg/deploy/lattice/service_synthesizer.go | 2 +- pkg/deploy/lattice/target_group_manager.go | 28 ++--- .../lattice/target_group_synthesizer.go | 44 +++---- pkg/deploy/lattice/targets_manager.go | 6 +- pkg/deploy/lattice/targets_synthesizer.go | 4 +- pkg/deploy/stack_deployer.go | 8 +- .../model_build_access_log_subscription.go | 2 +- pkg/gateway/model_build_lattice_service.go | 14 +-- pkg/gateway/model_build_listener.go | 14 +-- pkg/gateway/model_build_rule.go | 39 ++++--- pkg/gateway/model_build_targetgroup.go | 10 +- pkg/gateway/model_build_targets.go | 8 +- pkg/k8s/policyhelper/policy.go | 4 +- pkg/utils/gwlog/actions.go | 4 + pkg/utils/gwlog/gwlog.go | 110 +++++++++++++++++- pkg/utils/gwlog/metadata.go | 83 +++++++++++++ pkg/utils/gwlog/metadata_test.go | 32 +++++ pkg/webhook/core/mutating_handler.go | 4 +- pkg/webhook/pod_readiness_gate_injector.go | 28 ++--- test/pkg/test/framework.go | 38 +++--- test/suites/integration/byoc_test.go | 26 ++--- .../integration/httproute_update_test.go | 2 +- test/suites/integration/iamauthpolicy_test.go | 12 +- test/suites/integration/suite_test.go | 2 +- test/suites/webhook/suite_test.go | 2 +- 53 files changed, 576 insertions(+), 306 deletions(-) create mode 100644 pkg/utils/gwlog/actions.go create mode 100644 pkg/utils/gwlog/metadata.go create mode 100644 pkg/utils/gwlog/metadata_test.go diff --git a/cmd/aws-application-networking-k8s/main.go b/cmd/aws-application-networking-k8s/main.go index 8ac03446..50504813 100644 --- a/cmd/aws-application-networking-k8s/main.go +++ b/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) diff --git a/go.mod b/go.mod index 5d945618..85456b78 100644 --- a/go.mod +++ b/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 diff --git a/pkg/aws/cloud.go b/pkg/aws/cloud.go index 3dc49e08..b2837453 100644 --- a/pkg/aws/cloud.go +++ b/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, diff --git a/pkg/controllers/accesslogpolicy_controller.go b/pkg/controllers/accesslogpolicy_controller.go index 6643cf93..0888a002 100644 --- a/pkg/controllers/accesslogpolicy_controller.go +++ b/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, diff --git a/pkg/controllers/eventhandlers/gateway.go b/pkg/controllers/eventhandlers/gateway.go index 72d69828..07622b1b 100644 --- a/pkg/controllers/eventhandlers/gateway.go +++ b/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(), diff --git a/pkg/controllers/eventhandlers/gatewayclass.go b/pkg/controllers/eventhandlers/gatewayclass.go index 711ce2d2..32501f24 100644 --- a/pkg/controllers/eventhandlers/gatewayclass.go +++ b/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, diff --git a/pkg/controllers/eventhandlers/mapper.go b/pkg/controllers/eventhandlers/mapper.go index 716c3268..37c4c5ea 100644 --- a/pkg/controllers/eventhandlers/mapper.go +++ b/pkg/controllers/eventhandlers/mapper.go @@ -98,13 +98,13 @@ 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()) @@ -112,7 +112,7 @@ func policyToTargetRefObj[T client.Object](r *resourceMapper, ctx context.Contex } 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, @@ -120,7 +120,7 @@ func policyToTargetRefObj[T client.Object](r *resourceMapper, ctx context.Contex 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 diff --git a/pkg/controllers/eventhandlers/service.go b/pkg/controllers/eventhandlers/service.go index 76d3726f..2b6b9a66 100644 --- a/pkg/controllers/eventhandlers/service.go +++ b/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 diff --git a/pkg/controllers/eventhandlers/serviceimport.go b/pkg/controllers/eventhandlers/serviceimport.go index d13ae46b..148cf17f 100644 --- a/pkg/controllers/eventhandlers/serviceimport.go +++ b/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 diff --git a/pkg/controllers/gateway_controller.go b/pkg/controllers/gateway_controller.go index 4518a2b0..6b406315 100644 --- a/pkg/controllers/gateway_controller.go +++ b/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 } diff --git a/pkg/controllers/gatewayclass_controller.go b/pkg/controllers/gatewayclass_controller.go index 9a6ea3cb..d388d814 100644 --- a/pkg/controllers/gatewayclass_controller.go +++ b/pkg/controllers/gatewayclass_controller.go @@ -56,11 +56,14 @@ func RegisterGatewayClassController(log gwlog.Logger, mgr ctrl.Manager) error { //+kubebuilder:rbac:groups=gateway.networking.k8s.io,resources=gatewayclasses/finalizers,verbs=update func (r *gatewayClassReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.log.Infow("reconcile", "name", req.Name) + ctx = gwlog.StartReconcileTrace(ctx, r.log, "gatewayclass", req.Name, req.Namespace) + defer func() { + gwlog.EndReconcileTrace(ctx, r.log) + }() gwClass := &gwv1beta1.GatewayClass{} if err := r.client.Get(ctx, req.NamespacedName, gwClass); err != nil { - r.log.Debugw("gateway not found", "name", req.Name) + r.log.Debugw(ctx, "gateway not found", "name", req.Name) return ctrl.Result{}, nil } @@ -69,7 +72,7 @@ func (r *gatewayClassReconciler) Reconcile(ctx context.Context, req ctrl.Request } if !gwClass.DeletionTimestamp.IsZero() { r.latticeControllerEnabled = false - r.log.Infow("deleted", "name", gwClass.Name) + r.log.Infow(ctx, "deleted", "name", gwClass.Name) return ctrl.Result{}, nil } r.latticeControllerEnabled = true @@ -86,6 +89,6 @@ func (r *gatewayClassReconciler) Reconcile(ctx context.Context, req ctrl.Request return ctrl.Result{}, errors.Wrapf(err, "failed to update gatewayclass status") } - r.log.Infow("reconciled", "name", gwClass.Name, "status", gwClass.Status) + r.log.Infow(ctx, "reconciled", "name", gwClass.Name, "status", gwClass.Status) return ctrl.Result{}, nil } diff --git a/pkg/controllers/iamauthpolicy_controller.go b/pkg/controllers/iamauthpolicy_controller.go index e34f4984..9d485ce0 100644 --- a/pkg/controllers/iamauthpolicy_controller.go +++ b/pkg/controllers/iamauthpolicy_controller.go @@ -78,13 +78,18 @@ func RegisterIAMAuthPolicyController(log gwlog.Logger, mgr ctrl.Manager, cloud p // // Policy Attachment Spec is defined in [GEP-713]: https://gateway-api.sigs.k8s.io/geps/gep-713/. func (c *IAMAuthPolicyController) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx = gwlog.StartReconcileTrace(ctx, c.log, "iamauthpolicy", req.Name, req.Namespace) + defer func() { + gwlog.EndReconcileTrace(ctx, c.log) + }() + k8sPolicy := &anv1alpha1.IAMAuthPolicy{} err := c.client.Get(ctx, req.NamespacedName, k8sPolicy) if err != nil { return ctrl.Result{}, client.IgnoreNotFound(err) } - c.log.Infow("reconcile IAM policy", "req", req, "targetRef", k8sPolicy.Spec.TargetRef) + c.log.Infow(ctx, "reconcile IAM policy", "req", req, "targetRef", k8sPolicy.Spec.TargetRef) isDelete := !k8sPolicy.DeletionTimestamp.IsZero() var res ctrl.Result @@ -102,7 +107,7 @@ func (c *IAMAuthPolicyController) Reconcile(ctx context.Context, req ctrl.Reques return reconcile.Result{}, err } - c.log.Infow("reconciled IAM policy", + c.log.Infow(ctx, "reconciled IAM policy", "req", req, "targetRef", k8sPolicy.Spec.TargetRef, "isDeleted", isDelete, diff --git a/pkg/controllers/route_controller.go b/pkg/controllers/route_controller.go index ebdbe902..f252fd15 100644 --- a/pkg/controllers/route_controller.go +++ b/pkg/controllers/route_controller.go @@ -127,7 +127,7 @@ func RegisterAllRouteControllers( if err != nil { return err } - log.Infof("TargetGroupPolicy CRD is not installed, skipping watch") + log.Infof(context.TODO(), "TargetGroupPolicy CRD is not installed, skipping watch") } if ok, err := k8s.IsGVKSupported(mgr, "externaldns.k8s.io/v1alpha1", "DNSEndpoint"); ok { @@ -136,7 +136,7 @@ func RegisterAllRouteControllers( if err != nil { return err } - log.Infof("DNSEndpoint CRD is not installed, skipping watch") + log.Infof(context.TODO(), "DNSEndpoint CRD is not installed, skipping watch") } err := builder.Complete(&reconciler) @@ -149,10 +149,14 @@ func RegisterAllRouteControllers( } func (r *routeReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.log.Infow("reconcile", "name", req.Name) + ctx = gwlog.StartReconcileTrace(ctx, r.log, "route", 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()) } return lattice_runtime.HandleReconcileError(recErr) } @@ -179,7 +183,7 @@ func (r *routeReconciler) reconcile(ctx context.Context, req ctrl.Request) error } func (r *routeReconciler) reconcileDelete(ctx context.Context, req ctrl.Request, route core.Route) error { - r.log.Infow("reconcile, deleting", "name", req.Name) + r.log.Infow(ctx, "reconcile, deleting", "name", req.Name) r.eventRecorder.Event(route.K8sObject(), corev1.EventTypeNormal, k8s.RouteEventReasonReconcile, "Deleting Reconcile") @@ -191,7 +195,7 @@ func (r *routeReconciler) reconcileDelete(ctx context.Context, req ctrl.Request, return err } - r.log.Infow("reconciled", "name", req.Name) + r.log.Infow(ctx, "reconciled", "name", req.Name) return r.finalizerManager.RemoveFinalizers(ctx, route.K8sObject(), routeTypeToFinalizer[r.routeType]) } @@ -230,7 +234,7 @@ func updateRouteListenerStatus(ctx context.Context, k8sClient client.Client, rou func (r *routeReconciler) isRouteRelevant(ctx context.Context, route core.Route) bool { if len(route.Spec().ParentRefs()) == 0 { - r.log.Infof("Ignore Route which has no ParentRefs gateway %s ", route.Name()) + r.log.Infof(ctx, "Ignore Route which has no ParentRefs gateway %s ", route.Name()) return false } @@ -246,7 +250,7 @@ func (r *routeReconciler) isRouteRelevant(ctx context.Context, route core.Route) } if err := r.client.Get(ctx, gwName, gw); err != nil { - r.log.Infof("Could not find gateway %s with err %s. Ignoring route %+v whose ParentRef gateway object"+ + r.log.Infof(ctx, "Could not find gateway %s with err %s. Ignoring route %+v whose ParentRef gateway object"+ " is not defined.", gwName.String(), err, route.Spec()) return false } @@ -259,16 +263,16 @@ func (r *routeReconciler) isRouteRelevant(ctx context.Context, route core.Route) } if err := r.client.Get(ctx, gwClassName, gwClass); err != nil { - r.log.Infof("Ignore Route not controlled by any GatewayClass %s, %s", route.Name(), route.Namespace()) + r.log.Infof(ctx, "Ignore Route not controlled by any GatewayClass %s, %s", route.Name(), route.Namespace()) return false } if gwClass.Spec.ControllerName == config.LatticeGatewayControllerName { - r.log.Infof("Found aws-vpc-lattice for Route for %s, %s", route.Name(), route.Namespace()) + r.log.Infof(ctx, "Found aws-vpc-lattice for Route for %s, %s", route.Name(), route.Namespace()) return true } - r.log.Infof("Ignore non aws-vpc-lattice Route %s, %s", route.Name(), route.Namespace()) + r.log.Infof(ctx, "Ignore non aws-vpc-lattice Route %s, %s", route.Name(), route.Namespace()) return false } @@ -281,7 +285,7 @@ func (r *routeReconciler) buildAndDeployModel( if err != nil { r.eventRecorder.Event(route.K8sObject(), corev1.EventTypeWarning, k8s.RouteEventReasonFailedBuildModel, fmt.Sprintf("Failed build model due to %s", err)) - r.log.Infof("buildAndDeployModel, Failed build model for %s due to %s", route.Name(), err) + r.log.Infof(ctx, "buildAndDeployModel, Failed build model for %s due to %s", route.Name(), err) // Build failed // TODO continue deploy to trigger reconcile of stale Route and policy @@ -290,10 +294,10 @@ func (r *routeReconciler) buildAndDeployModel( json, err := r.stackMarshaller.Marshal(stack) if err != nil { - r.log.Errorf("error on r.stackMarshaller.Marshal error %s", err) + r.log.Errorf(ctx, "error on r.stackMarshaller.Marshal error %s", err) } - r.log.Debugf("stack: %s", json) + r.log.Debugf(ctx, "stack: %s", json) if err := r.stackDeployer.Deploy(ctx, stack); err != nil { if errors.As(err, &lattice.RetryErr) { @@ -310,7 +314,7 @@ func (r *routeReconciler) buildAndDeployModel( } func (r *routeReconciler) reconcileUpsert(ctx context.Context, req ctrl.Request, route core.Route) error { - r.log.Infow("reconcile, adding or updating", "name", req.Name) + r.log.Infow(ctx, "reconcile, adding or updating", "name", req.Name) r.eventRecorder.Event(route.K8sObject(), corev1.EventTypeNormal, k8s.RouteEventReasonReconcile, "Adding/Updating Reconcile") @@ -323,7 +327,7 @@ func (r *routeReconciler) reconcileUpsert(ctx context.Context, req ctrl.Request, // we delete Service and we suppose to delete TargetGroup, this validation will // throw error if Service is not found. For now just update route status and log // error. - r.log.Infof("route: %s: %s", route.Name(), err) + r.log.Infof(ctx, "route: %s: %s", route.Name(), err) } backendRefIPFamiliesErr := r.validateBackendRefsIpFamilies(ctx, route) @@ -377,7 +381,7 @@ func (r *routeReconciler) reconcileUpsert(ctx context.Context, req ctrl.Request, } if svc == nil || svc.DnsEntry == nil || svc.DnsEntry.DomainName == nil { - r.log.Infof("Either service, dns entry, or domain name is not available. Will Retry") + r.log.Infof(ctx, "Either service, dns entry, or domain name is not available. Will Retry") return errors.New(lattice.LATTICE_RETRY) } @@ -385,12 +389,12 @@ func (r *routeReconciler) reconcileUpsert(ctx context.Context, req ctrl.Request, return err } - r.log.Infow("reconciled", "name", req.Name) + r.log.Infow(ctx, "reconciled", "name", req.Name) return nil } func (r *routeReconciler) updateRouteAnnotation(ctx context.Context, dns string, route core.Route) error { - r.log.Debugf("Updating route %s-%s with DNS %s", route.Name(), route.Namespace(), dns) + r.log.Debugf(ctx, "Updating route %s-%s with DNS %s", route.Name(), route.Namespace(), dns) routeOld := route.DeepCopy() if len(route.K8sObject().GetAnnotations()) == 0 { @@ -402,7 +406,7 @@ func (r *routeReconciler) updateRouteAnnotation(ctx context.Context, dns string, return fmt.Errorf("failed to update route status due to err %w", err) } - r.log.Debugf("Successfully updated route %s-%s with DNS %s", route.Name(), route.Namespace(), dns) + r.log.Debugf(ctx, "Successfully updated route %s-%s with DNS %s", route.Name(), route.Namespace(), dns) return nil } diff --git a/pkg/controllers/route_controller_test.go b/pkg/controllers/route_controller_test.go index 38920d64..a6c1ffc5 100644 --- a/pkg/controllers/route_controller_test.go +++ b/pkg/controllers/route_controller_test.go @@ -172,9 +172,9 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { mockCloud.EXPECT().DefaultTagsMergedWith(gomock.Any()).Return(mocks.Tags{}).AnyTimes() // we expect a fair number of lattice calls - mockLattice.EXPECT().ListTargetsAsList(ctx, gomock.Any()).Return( + mockLattice.EXPECT().ListTargetsAsList(gomock.Any(), gomock.Any()).Return( []*vpclattice.TargetSummary{}, nil) - mockLattice.EXPECT().ListTargetsAsList(ctx, gomock.Any()).Return( + mockLattice.EXPECT().ListTargetsAsList(gomock.Any(), gomock.Any()).Return( []*vpclattice.TargetSummary{ { Id: aws.String("192.0.2.22"), @@ -185,7 +185,7 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { Port: aws.Int64(8090), }, }, nil) - mockLattice.EXPECT().RegisterTargetsWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().RegisterTargetsWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.RegisterTargetsOutput{ Successful: []*vpclattice.Target{ { @@ -198,7 +198,7 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { }, }, }, nil) - mockLattice.EXPECT().FindServiceNetwork(ctx, gomock.Any()).Return( + mockLattice.EXPECT().FindServiceNetwork(gomock.Any(), gomock.Any()).Return( &mocks.ServiceNetworkInfo{ SvcNetwork: vpclattice.ServiceNetworkSummary{ Arn: aws.String("sn-arn"), @@ -206,22 +206,22 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { Name: aws.String("sn-name"), }, }, nil) - mockLattice.EXPECT().FindService(ctx, gomock.Any()).Return( + mockLattice.EXPECT().FindService(gomock.Any(), gomock.Any()).Return( nil, mocks.NewNotFoundError("Service", "svc-name")) // will trigger create - mockLattice.EXPECT().CreateServiceWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().CreateServiceWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.CreateServiceOutput{ Arn: aws.String("svc-arn"), Id: aws.String("svc-id"), Name: aws.String("svc-name"), Status: aws.String(vpclattice.ServiceStatusActive), }, nil) - mockLattice.EXPECT().CreateServiceNetworkServiceAssociationWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().CreateServiceNetworkServiceAssociationWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.CreateServiceNetworkServiceAssociationOutput{ Arn: aws.String("sns-assoc-arn"), Id: aws.String("sns-assoc-id"), Status: aws.String(vpclattice.ServiceNetworkServiceAssociationStatusActive), }, nil) - mockLattice.EXPECT().FindService(ctx, gomock.Any()).Return( + mockLattice.EXPECT().FindService(gomock.Any(), gomock.Any()).Return( &vpclattice.ServiceSummary{ Arn: aws.String("svc-arn"), Id: aws.String("svc-id"), @@ -233,10 +233,10 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { }, }, nil) // will trigger DNS Update - mockTagging.EXPECT().FindResourcesByTags(ctx, gomock.Any(), gomock.Any()).Return(nil, nil) - mockLattice.EXPECT().ListTargetGroupsAsList(ctx, gomock.Any()).Return( + mockTagging.EXPECT().FindResourcesByTags(gomock.Any(), gomock.Any(), gomock.Any()).Return(nil, nil) + mockLattice.EXPECT().ListTargetGroupsAsList(gomock.Any(), gomock.Any()).Return( []*vpclattice.TargetGroupSummary{}, nil).AnyTimes() // this will cause us to skip "unused delete" step - mockLattice.EXPECT().CreateTargetGroupWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().CreateTargetGroupWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.CreateTargetGroupOutput{ Arn: aws.String("tg-arn"), Id: aws.String("tg-id"), @@ -244,12 +244,12 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { Status: aws.String(vpclattice.TargetGroupStatusActive), }, nil) - mockLattice.EXPECT().ListListenersWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().ListListenersWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.ListListenersOutput{ Items: []*vpclattice.ListenerSummary{}, NextToken: nil, }, nil).AnyTimes() - mockLattice.EXPECT().CreateListenerWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().CreateListenerWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.CreateListenerOutput{ Arn: aws.String("listener-arn"), Id: aws.String("listener-id"), @@ -258,9 +258,9 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { ServiceId: aws.String("svc-id"), }, nil) - mockLattice.EXPECT().GetRulesAsList(ctx, gomock.Any()).Return( + mockLattice.EXPECT().GetRulesAsList(gomock.Any(), gomock.Any()).Return( []*vpclattice.GetRuleOutput{}, nil) - mockLattice.EXPECT().CreateRuleWithContext(ctx, gomock.Any()).Return( + mockLattice.EXPECT().CreateRuleWithContext(gomock.Any(), gomock.Any()).Return( &vpclattice.CreateRuleOutput{ Arn: aws.String("rule-arn"), Id: aws.String("rule-id"), @@ -268,7 +268,7 @@ func TestRouteReconciler_ReconcileCreates(t *testing.T) { Priority: aws.Int64(1), }, nil) // List is called after create, so we'll return what we have - mockLattice.EXPECT().ListRulesAsList(ctx, gomock.Any()).Return( + mockLattice.EXPECT().ListRulesAsList(gomock.Any(), gomock.Any()).Return( []*vpclattice.RuleSummary{ { Arn: aws.String("rule-arn"), diff --git a/pkg/controllers/service_controller.go b/pkg/controllers/service_controller.go index 2ace7266..b1fc338e 100644 --- a/pkg/controllers/service_controller.go +++ b/pkg/controllers/service_controller.go @@ -73,10 +73,14 @@ func RegisterServiceController( //+kubebuilder:rbac:groups=core,resources=configmaps, verbs=create;delete;patch;update;get;list;watch func (r *serviceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.log.Infow("reconcile", "name", req.Name) + ctx = gwlog.StartReconcileTrace(ctx, r.log, "service", 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()) } return lattice_runtime.HandleReconcileError(recErr) } @@ -94,6 +98,6 @@ func (r *serviceReconciler) reconcile(ctx context.Context, req ctrl.Request) err r.finalizerManager.RemoveFinalizers(ctx, svc, serviceFinalizer) } - r.log.Infow("reconciled", "name", req.Name) + r.log.Infow(ctx, "reconciled", "name", req.Name) return nil } diff --git a/pkg/controllers/serviceexport_controller.go b/pkg/controllers/serviceexport_controller.go index 6244277c..e58db107 100644 --- a/pkg/controllers/serviceexport_controller.go +++ b/pkg/controllers/serviceexport_controller.go @@ -91,7 +91,7 @@ func RegisterServiceExportController( if err != nil { return err } - log.Infof("TargetGroupPolicy CRD is not installed, skipping watch") + log.Infof(context.TODO(), "TargetGroupPolicy CRD is not installed, skipping watch") } return builder.Complete(r) @@ -102,10 +102,14 @@ func RegisterServiceExportController( //+kubebuilder:rbac:groups=application-networking.k8s.aws,resources=serviceexports/finalizers,verbs=update func (r *serviceExportReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.log.Infow("reconcile", "name", req.Name) + ctx = gwlog.StartReconcileTrace(ctx, r.log, "serviceexport", 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()) } return lattice_runtime.HandleReconcileError(recErr) } @@ -120,7 +124,7 @@ func (r *serviceExportReconciler) reconcile(ctx context.Context, req ctrl.Reques if srvExport.ObjectMeta.Annotations["application-networking.k8s.aws/federation"] != "amazon-vpc-lattice" { return nil } - r.log.Debugf("Found matching service export %s-%s", srvExport.Name, srvExport.Namespace) + r.log.Debugf(ctx, "Found matching service export %s-%s", srvExport.Name, srvExport.Namespace) if !srvExport.DeletionTimestamp.IsZero() { if err := r.buildAndDeployModel(ctx, srvExport); err != nil { @@ -128,7 +132,7 @@ func (r *serviceExportReconciler) reconcile(ctx context.Context, req ctrl.Reques } err := r.finalizerManager.RemoveFinalizers(ctx, srvExport, serviceExportFinalizer) if err != nil { - r.log.Errorf("Failed to remove finalizers for service export %s-%s due to %s", + r.log.Errorf(ctx, "Failed to remove finalizers for service export %s-%s due to %s", srvExport.Name, srvExport.Namespace, err) } return nil @@ -150,7 +154,7 @@ func (r *serviceExportReconciler) buildAndDeployModel( stack, err := r.modelBuilder.Build(ctx, srvExport) if err != nil { - r.log.Debugf("Failed to buildAndDeployModel for service export %s-%s due to %s", + r.log.Debugf(ctx, "Failed to buildAndDeployModel for service export %s-%s due to %s", srvExport.Name, srvExport.Namespace, err) r.eventRecorder.Event(srvExport, corev1.EventTypeWarning, @@ -162,9 +166,9 @@ func (r *serviceExportReconciler) buildAndDeployModel( json, err := r.stackMarshaller.Marshal(stack) if err != nil { - r.log.Errorf("Error on marshalling model for service export %s-%s", srvExport.Name, srvExport.Namespace) + r.log.Errorf(ctx, "Error on marshalling model for service export %s-%s", srvExport.Name, srvExport.Namespace) } - r.log.Debugf("stack: %s", json) + r.log.Debugf(ctx, "stack: %s", json) if err := r.stackDeployer.Deploy(ctx, stack); err != nil { r.eventRecorder.Event(srvExport, corev1.EventTypeWarning, @@ -172,6 +176,6 @@ func (r *serviceExportReconciler) buildAndDeployModel( return err } - r.log.Debugf("Successfully deployed model for service export %s-%s", srvExport.Name, srvExport.Namespace) + r.log.Debugf(ctx, "Successfully deployed model for service export %s-%s", srvExport.Name, srvExport.Namespace) return err } diff --git a/pkg/controllers/serviceimport_controller.go b/pkg/controllers/serviceimport_controller.go index f8b3c9ec..45500ba5 100644 --- a/pkg/controllers/serviceimport_controller.go +++ b/pkg/controllers/serviceimport_controller.go @@ -71,17 +71,20 @@ func RegisterServiceImportController( //+kubebuilder:rbac:groups=application-networking.k8s.aws,resources=serviceimports/finalizers,verbs=update func (r *serviceImportReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - r.log.Infow("reconcile", "name", req.Name) + ctx = gwlog.StartReconcileTrace(ctx, r.log, "serviceimport", req.Name, req.Namespace) + defer func() { + gwlog.EndReconcileTrace(ctx, r.log) + }() serviceImport := &anv1alpha1.ServiceImport{} if err := r.client.Get(ctx, req.NamespacedName, serviceImport); err != nil { - r.log.Info("Item Not Found") + r.log.Info(ctx, "Item Not Found") return ctrl.Result{}, nil } if !serviceImport.DeletionTimestamp.IsZero() { - r.log.Info("Deleting") + r.log.Info(ctx, "Deleting") r.finalizerManager.RemoveFinalizers(ctx, serviceImport, serviceImportFinalizer) return ctrl.Result{}, nil } else { @@ -89,7 +92,7 @@ func (r *serviceImportReconciler) Reconcile(ctx context.Context, req ctrl.Reques r.eventRecorder.Event(serviceImport, corev1.EventTypeWarning, k8s.ServiceImportEventReasonFailedAddFinalizer, fmt.Sprintf("Failed add finalizer due to %v", err)) return ctrl.Result{}, nil } - r.log.Info("Adding/Updating") + r.log.Info(ctx, "Adding/Updating") return ctrl.Result{}, nil } diff --git a/pkg/controllers/targetgrouppolicy_controller.go b/pkg/controllers/targetgrouppolicy_controller.go index fa1e5449..cd6f202b 100644 --- a/pkg/controllers/targetgrouppolicy_controller.go +++ b/pkg/controllers/targetgrouppolicy_controller.go @@ -41,19 +41,24 @@ func RegisterTargetGroupPolicyController(log gwlog.Logger, mgr ctrl.Manager) err } func (c *TargetGroupPolicyController) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx = gwlog.StartReconcileTrace(ctx, c.log, "targetgrouppolicy", req.Name, req.Namespace) + defer func() { + gwlog.EndReconcileTrace(ctx, c.log) + }() + tgPolicy := &TGP{} err := c.client.Get(ctx, req.NamespacedName, tgPolicy) if err != nil { return ctrl.Result{}, client.IgnoreNotFound(err) } - c.log.Infow("reconcile target group policy", "req", req, "targetRef", tgPolicy.Spec.TargetRef) + c.log.Infow(ctx, "reconcile target group policy", "req", req, "targetRef", tgPolicy.Spec.TargetRef) _, err = c.ph.ValidateAndUpdateCondition(ctx, tgPolicy) if err != nil { return ctrl.Result{}, err } - c.log.Infow("reconciled target group policy", + c.log.Infow(ctx, "reconciled target group policy", "req", req, "targetRef", tgPolicy.Spec.TargetRef, ) diff --git a/pkg/controllers/vpcassociationpolicy_controller.go b/pkg/controllers/vpcassociationpolicy_controller.go index 9a61f9c3..0b778621 100644 --- a/pkg/controllers/vpcassociationpolicy_controller.go +++ b/pkg/controllers/vpcassociationpolicy_controller.go @@ -55,12 +55,17 @@ func RegisterVpcAssociationPolicyController(log gwlog.Logger, cloud pkg_aws.Clou } func (c *vpcAssociationPolicyReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + ctx = gwlog.StartReconcileTrace(ctx, c.log, "vpcassociationpolicy", req.Name, req.Namespace) + defer func() { + gwlog.EndReconcileTrace(ctx, c.log) + }() + k8sPolicy := &anv1alpha1.VpcAssociationPolicy{} err := c.client.Get(ctx, req.NamespacedName, k8sPolicy) if err != nil { return ctrl.Result{}, client.IgnoreNotFound(err) } - c.log.Infow("reconcile", "req", req, "targetRef", k8sPolicy.Spec.TargetRef) + c.log.Infow(ctx, "reconcile", "req", req, "targetRef", k8sPolicy.Spec.TargetRef) isDelete := !k8sPolicy.DeletionTimestamp.IsZero() isAssociation := k8sPolicy.Spec.AssociateWithVpc == nil || *k8sPolicy.Spec.AssociateWithVpc @@ -71,11 +76,11 @@ func (c *vpcAssociationPolicyReconciler) Reconcile(ctx context.Context, req ctrl err = c.upsert(ctx, k8sPolicy) } if err != nil { - c.log.Infof("reconcile error, retry in 30 sec: %s", err) + c.log.Infof(ctx, "reconcile error, retry in 30 sec: %s", err) return ctrl.Result{RequeueAfter: time.Second * 30}, nil } - c.log.Infow("reconciled vpc association policy", + c.log.Infow(ctx, "reconciled vpc association policy", "req", req, "targetRef", k8sPolicy.Spec.TargetRef, "isDeleted", isDelete, diff --git a/pkg/deploy/externaldns/dnsendpoint_manager.go b/pkg/deploy/externaldns/dnsendpoint_manager.go index 51f595dc..fc64761a 100644 --- a/pkg/deploy/externaldns/dnsendpoint_manager.go +++ b/pkg/deploy/externaldns/dnsendpoint_manager.go @@ -41,11 +41,11 @@ func (s *defaultDnsEndpointManager) Create(ctx context.Context, service *lattice Name: service.Spec.RouteName + "-dns", } if service.Spec.CustomerDomainName == "" { - s.log.Debugf("Skipping creation of %s: detected no custom domain", namespacedName) + s.log.Debugf(ctx, "Skipping creation of %s: detected no custom domain", namespacedName) return nil } if service.Status == nil || service.Status.Dns == "" { - s.log.Debugf("Skipping creation of %s: DNS target not ready in svc status", namespacedName) + s.log.Debugf(ctx, "Skipping creation of %s: DNS target not ready in svc status", namespacedName) return nil } @@ -65,14 +65,14 @@ func (s *defaultDnsEndpointManager) Create(ctx context.Context, service *lattice route, err = core.GetHTTPRoute(ctx, s.k8sClient, routeNamespacedName) } if err != nil { - s.log.Debugf("Skipping creation of %s: Could not find corresponding route", namespacedName.String()) + s.log.Debugf(ctx, "Skipping creation of %s: Could not find corresponding route", namespacedName.String()) return nil } ep := &endpoint.DNSEndpoint{} if err := s.k8sClient.Get(ctx, namespacedName, ep); err != nil { if apierrors.IsNotFound(err) { - s.log.Debugf("Attempting creation of DNSEndpoint for %s - %s -> %s", + s.log.Debugf(ctx, "Attempting creation of DNSEndpoint for %s - %s -> %s", namespacedName.String(), service.Spec.CustomerDomainName, service.Status.Dns) ep = &endpoint.DNSEndpoint{ ObjectMeta: metav1.ObjectMeta{ @@ -97,13 +97,13 @@ func (s *defaultDnsEndpointManager) Create(ctx context.Context, service *lattice return err } } else if meta.IsNoMatchError(err) { - s.log.Debugf("DNSEndpoint CRD not supported, skipping") + s.log.Debugf(ctx, "DNSEndpoint CRD not supported, skipping") return nil } else { return err } } else { - s.log.Debugf("Attempting update of DNSEndpoint for %s - %s -> %s", + s.log.Debugf(ctx, "Attempting update of DNSEndpoint for %s - %s -> %s", namespacedName.String(), service.Spec.CustomerDomainName, service.Status.Dns) old := ep.DeepCopy() ep.Spec.Endpoints = []*endpoint.Endpoint{ diff --git a/pkg/deploy/lattice/access_log_subscription_synthesizer.go b/pkg/deploy/lattice/access_log_subscription_synthesizer.go index 97e036d5..af0347a0 100644 --- a/pkg/deploy/lattice/access_log_subscription_synthesizer.go +++ b/pkg/deploy/lattice/access_log_subscription_synthesizer.go @@ -41,23 +41,23 @@ func (s *accessLogSubscriptionSynthesizer) Synthesize(ctx context.Context) error for _, als := range accessLogSubscriptions { switch als.Spec.EventType { case core.CreateEvent: - s.log.Debugf("Started creating Access Log Subscription %s", als.ID()) + s.log.Debugf(ctx, "Started creating Access Log Subscription %s", als.ID()) alsStatus, err := s.accessLogSubscriptionManager.Create(ctx, als) if err != nil { return err } als.Status = alsStatus case core.UpdateEvent: - s.log.Debugf("Started updating Access Log Subscription %s", als.ID()) + s.log.Debugf(ctx, "Started updating Access Log Subscription %s", als.ID()) alsStatus, err := s.accessLogSubscriptionManager.Update(ctx, als) if err != nil { return err } als.Status = alsStatus case core.DeleteEvent: - s.log.Debugf("Started deleting Access Log Subscription %s", als.ID()) + s.log.Debugf(ctx, "Started deleting Access Log Subscription %s", als.ID()) if als.Status == nil { - s.log.Debugf("Ignoring deletion of Access Log Subscription because als %s has no ARN", als.ID()) + s.log.Debugf(ctx, "Ignoring deletion of Access Log Subscription because als %s has no ARN", als.ID()) return nil } err := s.accessLogSubscriptionManager.Delete(ctx, als.Status.Arn) diff --git a/pkg/deploy/lattice/listener_manager.go b/pkg/deploy/lattice/listener_manager.go index e81646b8..ed3aba4f 100644 --- a/pkg/deploy/lattice/listener_manager.go +++ b/pkg/deploy/lattice/listener_manager.go @@ -52,14 +52,15 @@ func (d *defaultListenerManager) Upsert( return model.ListenerStatus{}, errors.New("model service is missing id") } - d.log.Infof("Upsert listener %s-%s", modelListener.Spec.K8SRouteName, modelListener.Spec.K8SRouteNamespace) + d.log.Infof(ctx, "Upsert listener %s-%s", modelListener.Spec.K8SRouteName, modelListener.Spec.K8SRouteNamespace) latticeSvcId := modelSvc.Status.Id latticeListenerSummary, err := d.findListenerByPort(ctx, latticeSvcId, modelListener.Spec.Port) + if err != nil { return model.ListenerStatus{}, err } - defaultAction, err := d.getLatticeListenerDefaultAction(modelListener) + defaultAction, err := d.getLatticeListenerDefaultAction(ctx, modelListener) if err != nil { return model.ListenerStatus{}, err } @@ -110,7 +111,7 @@ func (d *defaultListenerManager) create(ctx context.Context, latticeSvcId string return model.ListenerStatus{}, fmt.Errorf("Failed CreateListener %s due to %s", aws.StringValue(listenerInput.Name), err) } - d.log.Infof("Success CreateListener %s, %s", aws.StringValue(resp.Name), aws.StringValue(resp.Id)) + d.log.Infof(ctx, "Success CreateListener %s, %s", aws.StringValue(resp.Name), aws.StringValue(resp.Id)) return model.ListenerStatus{ Name: aws.StringValue(resp.Name), @@ -122,7 +123,7 @@ func (d *defaultListenerManager) create(ctx context.Context, latticeSvcId string func (d *defaultListenerManager) update(ctx context.Context, latticeSvcId string, listener *vpclattice.ListenerSummary, defaultAction *vpclattice.RuleAction) error { - d.log.Debugf("Updating listener %s default action", aws.StringValue(listener.Id)) + d.log.Debugf(ctx, "Updating listener %s default action", aws.StringValue(listener.Id)) _, err := d.cloud.Lattice().UpdateListenerWithContext(ctx, &vpclattice.UpdateListenerInput{ DefaultAction: defaultAction, ListenerIdentifier: listener.Id, @@ -131,11 +132,11 @@ func (d *defaultListenerManager) update(ctx context.Context, latticeSvcId string if err != nil { return fmt.Errorf("failed to update lattice listener %s due to %s", aws.StringValue(listener.Id), err) } - d.log.Infof("Success update listener %s default action", aws.StringValue(listener.Id)) + d.log.Infof(ctx, "Success update listener %s default action", aws.StringValue(listener.Id)) return nil } -func (d *defaultListenerManager) getLatticeListenerDefaultAction(stackListener *model.Listener) (*vpclattice.RuleAction, error) { +func (d *defaultListenerManager) getLatticeListenerDefaultAction(ctx context.Context, stackListener *model.Listener) (*vpclattice.RuleAction, error) { if stackListener.Spec.DefaultAction.FixedResponseStatusCode != nil { return &vpclattice.RuleAction{ FixedResponse: &vpclattice.FixedResponseAction{ @@ -172,7 +173,7 @@ func (d *defaultListenerManager) getLatticeListenerDefaultAction(stackListener * latticeTGs = append(latticeTGs, &latticeTG) } - d.log.Debugf("DefaultAction Forward target groups: %v", latticeTGs) + d.log.Debugf(ctx, "DefaultAction Forward target groups: %v", latticeTGs) return &vpclattice.RuleAction{ Forward: &vpclattice.ForwardAction{ TargetGroups: latticeTGs, @@ -197,7 +198,7 @@ func k8sLatticeListenerName(modelListener *model.Listener) string { func (d *defaultListenerManager) List(ctx context.Context, serviceID string) ([]*vpclattice.ListenerSummary, error) { var sdkListeners []*vpclattice.ListenerSummary - d.log.Debugf("Listing listeners for service %s", serviceID) + d.log.Debugf(ctx, "Listing listeners for service %s", serviceID) listenerListInput := vpclattice.ListListenersInput{ ServiceIdentifier: aws.String(serviceID), } @@ -254,7 +255,7 @@ func (d *defaultListenerManager) findListenerByPort( for _, r := range resp.Items { if aws.Int64Value(r.Port) == port { - d.log.Debugf("Port %d already in use by listener %s for service %s", port, *r.Arn, latticeSvcId) + d.log.Debugf(ctx, "Port %d already in use by listener %s for service %s", port, *r.Arn, latticeSvcId) return r, nil } } @@ -267,7 +268,7 @@ func (d *defaultListenerManager) Delete(ctx context.Context, modelListener *mode return errors.New("model listener and model listener status cannot be nil") } - d.log.Debugf("Deleting listener %s in service %s", modelListener.Status.Id, modelListener.Status.ServiceId) + d.log.Debugf(ctx, "Deleting listener %s in service %s", modelListener.Status.Id, modelListener.Status.ServiceId) listenerDeleteInput := vpclattice.DeleteListenerInput{ ServiceIdentifier: aws.String(modelListener.Status.ServiceId), ListenerIdentifier: aws.String(modelListener.Status.Id), @@ -276,12 +277,12 @@ func (d *defaultListenerManager) Delete(ctx context.Context, modelListener *mode _, err := d.cloud.Lattice().DeleteListenerWithContext(ctx, &listenerDeleteInput) if err != nil { if services.IsLatticeAPINotFoundErr(err) { - d.log.Debugf("Listener already deleted") + d.log.Debugf(ctx, "Listener already deleted") return nil } return fmt.Errorf("Failed DeleteListener %s, %s due to %s", modelListener.Status.Id, modelListener.Status.ServiceId, err) } - d.log.Infof("Success DeleteListener %s, %s", modelListener.Status.Id, modelListener.Status.ServiceId) + d.log.Infof(ctx, "Success DeleteListener %s, %s", modelListener.Status.Id, modelListener.Status.ServiceId) return nil } diff --git a/pkg/deploy/lattice/listener_manager_test.go b/pkg/deploy/lattice/listener_manager_test.go index f16a1348..99b4e6d1 100644 --- a/pkg/deploy/lattice/listener_manager_test.go +++ b/pkg/deploy/lattice/listener_manager_test.go @@ -510,7 +510,7 @@ func Test_defaultListenerManager_getLatticeListenerDefaultAction_HTTP_HTTPS_List log: gwlog.FallbackLogger, cloud: cloud, } - got, err := d.getLatticeListenerDefaultAction(modelListener) + got, err := d.getLatticeListenerDefaultAction(context.TODO(), modelListener) if tt.wantErr { assert.Error(t, err) } else { @@ -643,7 +643,7 @@ func Test_ListenerManager_getLatticeListenerDefaultAction_TLS_PASSTHROUGH_Listen log: gwlog.FallbackLogger, cloud: cloud, } - gotDefaultAction, err := d.getLatticeListenerDefaultAction(modelListener) + gotDefaultAction, err := d.getLatticeListenerDefaultAction(context.TODO(), modelListener) if tt.wantErr { assert.Error(t, err) } else { diff --git a/pkg/deploy/lattice/listener_synthesizer.go b/pkg/deploy/lattice/listener_synthesizer.go index 621172fc..a127f24e 100644 --- a/pkg/deploy/lattice/listener_synthesizer.go +++ b/pkg/deploy/lattice/listener_synthesizer.go @@ -82,7 +82,7 @@ func (l *listenerSynthesizer) Synthesize(ctx context.Context) error { if l.shouldDelete(latticeListenerAsModel, stackListeners) { err = l.listenerMgr.Delete(ctx, latticeListenerAsModel) if err != nil { - l.log.Infof("Failed ListenerManager.Delete %s due to %s", latticeListenerAsModel.Status.Id, err) + l.log.Infof(ctx, "Failed ListenerManager.Delete %s due to %s", latticeListenerAsModel.Status.Id, err) } } } @@ -114,13 +114,13 @@ func (l *listenerSynthesizer) getLatticeListenersAsModels(ctx context.Context) ( // get the listeners for each service for _, modelSvc := range modelSvcs { if modelSvc.IsDeleted { - l.log.Debugf("Ignoring deleted service %s", modelSvc.LatticeServiceName()) + l.log.Debugf(ctx, "Ignoring deleted service %s", modelSvc.LatticeServiceName()) continue } listenerSummaries, err := l.listenerMgr.List(ctx, modelSvc.Status.Id) if err != nil { - l.log.Infof("Ignoring error when listing listeners %s", err) + l.log.Infof(ctx, "Ignoring error when listing listeners %s", err) continue } for _, latticeListener := range listenerSummaries { diff --git a/pkg/deploy/lattice/rule_manager.go b/pkg/deploy/lattice/rule_manager.go index 39adf5cd..4232b82e 100644 --- a/pkg/deploy/lattice/rule_manager.go +++ b/pkg/deploy/lattice/rule_manager.go @@ -85,7 +85,7 @@ func (r *defaultRuleManager) UpdatePriorities(ctx context.Context, svcId string, return fmt.Errorf("failed BatchUpdateRule %s, %s, due to %s", svcId, listenerId, err) } - r.log.Infof("Success BatchUpdateRule %s, %s", svcId, listenerId) + r.log.Infof(ctx, "Success BatchUpdateRule %s, %s", svcId, listenerId) return nil } @@ -131,7 +131,7 @@ func (r *defaultRuleManager) buildLatticeRule(modelRule *model.Rule) (*vpclattic }, } } else { - r.log.Debugf("There are no valid target groups, defaulting to 404 Fixed response") + r.log.Debugf(context.TODO(), "There are no valid target groups, defaulting to 404 Fixed response") gro.Action = &vpclattice.RuleAction{ FixedResponse: &vpclattice.FixedResponseAction{ StatusCode: aws.Int64(model.DefaultActionFixedResponseStatusCode), @@ -169,7 +169,7 @@ func (r *defaultRuleManager) Upsert( return model.RuleStatus{}, err } - r.log.Debugf("Upsert rule %s for service %s-%s and listener port %d and protocol %s", + r.log.Debugf(ctx, "Upsert rule %s for service %s-%s and listener port %d and protocol %s", aws.StringValue(latticeRuleFromModel.Name), latticeServiceId, latticeListenerId, modelListener.Spec.Port, modelListener.Spec.Protocol) @@ -217,7 +217,7 @@ func (r *defaultRuleManager) updateIfNeeded( // we already validated Match, if Action is also the same then no updates required updateNeeded := !reflect.DeepEqual(ruleToUpdate.Action, matchingRule.Action) if !updateNeeded { - r.log.Debugf("rule unchanged, no updates required") + r.log.Debugf(ctx, "rule unchanged, no updates required") return updatedRuleStatus, nil } @@ -240,7 +240,7 @@ func (r *defaultRuleManager) updateIfNeeded( ruleToUpdate.Priority, latticeListenerId, latticeSvcId, err) } - r.log.Infof("Success UpdateRule %d for %s, %s", ruleToUpdate.Priority, latticeListenerId, latticeSvcId) + r.log.Infof(ctx, "Success UpdateRule %d for %s, %s", ruleToUpdate.Priority, latticeListenerId, latticeSvcId) return updatedRuleStatus, nil } @@ -276,7 +276,7 @@ func (r *defaultRuleManager) create( return model.RuleStatus{}, fmt.Errorf("failed CreateRule %s, %s due to %s", latticeListenerId, latticeSvcId, err) } - r.log.Infof("Success CreateRule %s, %s", aws.StringValue(res.Name), aws.StringValue(res.Id)) + r.log.Infof(ctx, "Success CreateRule %s, %s", aws.StringValue(res.Name), aws.StringValue(res.Id)) return model.RuleStatus{ Name: aws.StringValue(res.Name), @@ -364,7 +364,7 @@ func (r *defaultRuleManager) nextAvailablePriority(latticeRules []*vpclattice.Ge } func (r *defaultRuleManager) Delete(ctx context.Context, ruleId string, serviceId string, listenerId string) error { - r.log.Debugf("Deleting rule %s for listener %s and service %s", ruleId, listenerId, serviceId) + r.log.Debugf(ctx, "Deleting rule %s for listener %s and service %s", ruleId, listenerId, serviceId) deleteInput := vpclattice.DeleteRuleInput{ ServiceIdentifier: aws.String(serviceId), @@ -377,6 +377,6 @@ func (r *defaultRuleManager) Delete(ctx context.Context, ruleId string, serviceI return fmt.Errorf("failed DeleteRule %s/%s/%s due to %s", serviceId, listenerId, ruleId, err) } - r.log.Infof("Success DeleteRule %s/%s/%s", serviceId, listenerId, ruleId) + r.log.Infof(ctx, "Success DeleteRule %s/%s/%s", serviceId, listenerId, ruleId) return nil } diff --git a/pkg/deploy/lattice/rule_synthesizer.go b/pkg/deploy/lattice/rule_synthesizer.go index 5ab373f3..28398343 100644 --- a/pkg/deploy/lattice/rule_synthesizer.go +++ b/pkg/deploy/lattice/rule_synthesizer.go @@ -144,7 +144,7 @@ func (r *ruleSynthesizer) adjustPriorities(ctx context.Context, snlStackRules ma for _, rule := range activeRules { if rule.Spec.Priority != rule.Status.Priority { // *any* mismatch in priority prompts a batch update of ALL priorities - r.log.Debugf("Found rule priority mismatch, update required") + r.log.Debugf(ctx, "Found rule priority mismatch, update required") var rulesToUpdate []*model.Rule for _, snlRule := range activeRules { diff --git a/pkg/deploy/lattice/service_manager.go b/pkg/deploy/lattice/service_manager.go index 52fc409d..49521df9 100644 --- a/pkg/deploy/lattice/service_manager.go +++ b/pkg/deploy/lattice/service_manager.go @@ -55,7 +55,7 @@ func (m *defaultServiceManager) createServiceAndAssociate(ctx context.Context, s return ServiceInfo{}, fmt.Errorf("failed CreateService %s due to %s", aws.StringValue(createSvcReq.Name), err) } - m.log.Infof("Success CreateService %s %s", + m.log.Infof(ctx, "Success CreateService %s %s", aws.StringValue(createSvcResp.Name), aws.StringValue(createSvcResp.Id)) for _, snName := range svc.Spec.ServiceNetworkNames { @@ -84,7 +84,7 @@ func (m *defaultServiceManager) createAssociation(ctx context.Context, svcId *st return fmt.Errorf("failed CreateServiceNetworkServiceAssociation %s %s due to %s", aws.StringValue(assocReq.ServiceNetworkIdentifier), aws.StringValue(assocReq.ServiceIdentifier), err) } - m.log.Infof("Success CreateServiceNetworkServiceAssociation %s %s", + m.log.Infof(ctx, "Success CreateServiceNetworkServiceAssociation %s %s", aws.StringValue(assocReq.ServiceNetworkIdentifier), aws.StringValue(assocReq.ServiceIdentifier)) err = handleCreateAssociationResp(assocResp) @@ -229,7 +229,7 @@ func (m *defaultServiceManager) updateAssociations(ctx context.Context, svc *Ser // In a scenario that the service association is created by a foreign account, // the owner account's controller cannot read the tags of this ServiceNetworkServiceAssociation, // and AccessDeniedException is expected. - m.log.Warnf("skipping update associations service: %s, association: %s, error: %s", svc.LatticeServiceName(), *assoc.Arn, err) + m.log.Warnf(ctx, "skipping update associations service: %s, association: %s, error: %s", svc.LatticeServiceName(), *assoc.Arn, err) continue } @@ -337,7 +337,7 @@ func (m *defaultServiceManager) deleteAssociation(ctx context.Context, assocArn aws.StringValue(assocArn), err) } - m.log.Infof("Success DeleteServiceNetworkServiceAssociation %s", aws.StringValue(assocArn)) + m.log.Infof(ctx, "Success DeleteServiceNetworkServiceAssociation %s", aws.StringValue(assocArn)) return nil } @@ -350,7 +350,7 @@ func (m *defaultServiceManager) deleteService(ctx context.Context, svc *SvcSumma return fmt.Errorf("failed DeleteService %s due to %s", aws.StringValue(svc.Id), err) } - m.log.Infof("Success DeleteService %s", svc.Id) + m.log.Infof(ctx, "Success DeleteService %s", *svc.Id) return nil } @@ -389,7 +389,7 @@ func (m *defaultServiceManager) Delete(ctx context.Context, svc *Service) error err = m.checkAndUpdateTags(ctx, svc, svcSum) if err != nil { - m.log.Infof("Service %s is either invalid or not owned. Skipping VPC Lattice resource deletion.", svc.LatticeServiceName()) + m.log.Infof(ctx, "Service %s is either invalid or not owned. Skipping VPC Lattice resource deletion.", svc.LatticeServiceName()) return nil } diff --git a/pkg/deploy/lattice/service_network_manager.go b/pkg/deploy/lattice/service_network_manager.go index 31976c33..b4a76d66 100644 --- a/pkg/deploy/lattice/service_network_manager.go +++ b/pkg/deploy/lattice/service_network_manager.go @@ -97,7 +97,7 @@ func (m *defaultServiceNetworkManager) DeleteVpcAssociation(ctx context.Context, } if snva != nil { // association is active - m.log.Debugf("Disassociating ServiceNetwork %s from VPC", snName) + m.log.Debugf(ctx, "Disassociating ServiceNetwork %s from VPC", snName) owned, err := m.cloud.IsArnManaged(ctx, *snva.Arn) if err != nil { @@ -109,12 +109,12 @@ func (m *defaultServiceNetworkManager) DeleteVpcAssociation(ctx context.Context, // In a scenario that the vpc association is created by a foreign account, // the owner account's controller cannot read the tags of this ServiceNetworkVpcAssociation, // and AccessDeniedException is expected. - m.log.Warnf("skipping delete vpc association, association: %s, error: %s", *snva.Arn, err) + m.log.Warnf(ctx, "skipping delete vpc association, association: %s, error: %s", *snva.Arn, err) return nil } if !owned { - m.log.Infof("Association %s for %s not owned by controller, skipping deletion", *snva.Arn, snName) + m.log.Infof(ctx, "Association %s for %s not owned by controller, skipping deletion", *snva.Arn, snName) return nil } @@ -123,7 +123,7 @@ func (m *defaultServiceNetworkManager) DeleteVpcAssociation(ctx context.Context, } resp, err := m.cloud.Lattice().DeleteServiceNetworkVpcAssociationWithContext(ctx, &deleteServiceNetworkVpcAssociationInput) if err != nil { - m.log.Infof("Failed to delete association %s for %s, with response %s and err %s", *snva.Arn, snName, resp, err.Error()) + m.log.Infof(ctx, "Failed to delete association %s for %s, with response %s and err %s", *snva.Arn, snName, resp, err.Error()) } return errors.New(LATTICE_RETRY) } @@ -150,7 +150,7 @@ func (m *defaultServiceNetworkManager) getActiveVpcAssociation(ctx context.Conte if aws.StringValue(snva.Status) == vpclattice.ServiceNetworkVpcAssociationStatusActive { return snva, nil } - m.log.Debugf("snva %s status: %s", + m.log.Debugf(ctx, "snva %s status: %s", aws.StringValue(snva.Arn), aws.StringValue(snva.Status)) switch aws.StringValue(snva.Status) { case vpclattice.ServiceNetworkVpcAssociationStatusActive, @@ -180,7 +180,7 @@ func (m *defaultServiceNetworkManager) CreateOrUpdate(ctx context.Context, servi var serviceNetworkArn string vpcLatticeSess := m.cloud.Lattice() if foundSnSummary == nil { - m.log.Debugf("Creating ServiceNetwork %s and tagging it with vpcId %s", + m.log.Debugf(ctx, "Creating ServiceNetwork %s and tagging it with vpcId %s", serviceNetwork.Spec.Name, config.VpcID) serviceNetworkInput := vpclattice.CreateServiceNetworkInput{ @@ -195,7 +195,7 @@ func (m *defaultServiceNetworkManager) CreateOrUpdate(ctx context.Context, servi serviceNetworkId = aws.StringValue(resp.Id) serviceNetworkArn = aws.StringValue(resp.Arn) } else { - m.log.Debugf("ServiceNetwork %s exists, checking its VPC association", serviceNetwork.Spec.Name) + m.log.Debugf(ctx, "ServiceNetwork %s exists, checking its VPC association", serviceNetwork.Spec.Name) serviceNetworkId = aws.StringValue(foundSnSummary.SvcNetwork.Id) serviceNetworkArn = aws.StringValue(foundSnSummary.SvcNetwork.Arn) @@ -204,13 +204,13 @@ func (m *defaultServiceNetworkManager) CreateOrUpdate(ctx context.Context, servi return model.ServiceNetworkStatus{}, err } if snva != nil { - m.log.Debugf("ServiceNetwork %s already has VPC association %s", + m.log.Debugf(ctx, "ServiceNetwork %s already has VPC association %s", serviceNetwork.Spec.Name, aws.StringValue(snva.Arn)) return model.ServiceNetworkStatus{ServiceNetworkARN: serviceNetworkArn, ServiceNetworkID: serviceNetworkId}, nil } } - m.log.Debugf("Creating association between ServiceNetwork %s and VPC %s", serviceNetworkId, config.VpcID) + m.log.Debugf(ctx, "Creating association between ServiceNetwork %s and VPC %s", serviceNetworkId, config.VpcID) createServiceNetworkVpcAssociationInput := vpclattice.CreateServiceNetworkVpcAssociationInput{ ServiceNetworkIdentifier: &serviceNetworkId, VpcIdentifier: &config.VpcID, diff --git a/pkg/deploy/lattice/service_synthesizer.go b/pkg/deploy/lattice/service_synthesizer.go index 1adefc8b..55944ed8 100644 --- a/pkg/deploy/lattice/service_synthesizer.go +++ b/pkg/deploy/lattice/service_synthesizer.go @@ -41,7 +41,7 @@ func (s *serviceSynthesizer) Synthesize(ctx context.Context) error { var svcErr error for _, resService := range resServices { svcName := utils.LatticeServiceName(resService.Spec.RouteName, resService.Spec.RouteNamespace) - s.log.Debugf("Synthesizing service: %s", svcName) + s.log.Debugf(ctx, "Synthesizing service: %s", svcName) if resService.IsDeleted { err := s.serviceManager.Delete(ctx, resService) if err != nil { diff --git a/pkg/deploy/lattice/target_group_manager.go b/pkg/deploy/lattice/target_group_manager.go index 7647a3fe..268087aa 100644 --- a/pkg/deploy/lattice/target_group_manager.go +++ b/pkg/deploy/lattice/target_group_manager.go @@ -105,13 +105,13 @@ func (s *defaultTargetGroupManager) create(ctx context.Context, modelTg *model.T return model.TargetGroupStatus{}, fmt.Errorf("Failed CreateTargetGroup %s due to %s", latticeTgName, err) } - s.log.Infof("Success CreateTargetGroup %s", latticeTgName) + s.log.Infof(ctx, "Success CreateTargetGroup %s", latticeTgName) latticeTgStatus := aws.StringValue(resp.Status) if latticeTgStatus != vpclattice.TargetGroupStatusActive && latticeTgStatus != vpclattice.TargetGroupStatusCreateInProgress { - s.log.Infof("Target group is not in the desired state. State is %s, will retry", latticeTgStatus) + s.log.Infof(ctx, "Target group is not in the desired state. State is %s, will retry", latticeTgStatus) return model.TargetGroupStatus{}, errors.New(LATTICE_RETRY) } @@ -127,7 +127,7 @@ func (s *defaultTargetGroupManager) update(ctx context.Context, targetGroup *mod healthCheckConfig := targetGroup.Spec.HealthCheckConfig if healthCheckConfig == nil { - s.log.Debugf("HealthCheck is empty. Resetting to default settings") + s.log.Debugf(ctx, "HealthCheck is empty. Resetting to default settings") healthCheckConfig = &vpclattice.HealthCheckConfig{} } s.fillDefaultHealthCheckConfig(healthCheckConfig, targetGroup.Spec.Protocol, targetGroup.Spec.ProtocolVersion) @@ -161,7 +161,7 @@ func (s *defaultTargetGroupManager) Delete(ctx context.Context, modelTg *model.T if latticeTgSummary == nil { // nothing to delete - s.log.Infof("Target group with name prefix %s does not exist, nothing to delete", model.TgNamePrefix(modelTg.Spec)) + s.log.Infof(ctx, "Target group with name prefix %s does not exist, nothing to delete", model.TgNamePrefix(modelTg.Spec)) return nil } @@ -171,7 +171,7 @@ func (s *defaultTargetGroupManager) Delete(ctx context.Context, modelTg *model.T Id: aws.StringValue(latticeTgSummary.Id), } } - s.log.Debugf("Deleting target group %s", modelTg.Status.Id) + s.log.Debugf(ctx, "Deleting target group %s", modelTg.Status.Id) lattice := s.cloud.Lattice() @@ -183,7 +183,7 @@ func (s *defaultTargetGroupManager) Delete(ctx context.Context, modelTg *model.T listResp, err := lattice.ListTargetsAsList(ctx, &listTargetsInput) if err != nil { if services.IsLatticeAPINotFoundErr(err) { - s.log.Debugf("Target group %s was already deleted", modelTg.Status.Id) + s.log.Debugf(ctx, "Target group %s was already deleted", modelTg.Status.Id) return nil } return fmt.Errorf("failed ListTargets %s due to %s", modelTg.Status.Id, err) @@ -223,7 +223,7 @@ func (s *defaultTargetGroupManager) Delete(ctx context.Context, modelTg *model.T deregisterTargetsError = errors.Join(deregisterTargetsError, fmt.Errorf("failed to deregister targets from VPC Lattice Target Group %s for chunk %d/%d, unsuccessful targets %v", modelTg.Status.Id, i+1, len(chunks), deregisterResponse.Unsuccessful)) } - s.log.Debugf("Successfully deregistered targets from VPC Lattice Target Group %s for chunk %d/%d", modelTg.Status.Id, i+1, len(chunks)) + s.log.Debugf(ctx, "Successfully deregistered targets from VPC Lattice Target Group %s for chunk %d/%d", modelTg.Status.Id, i+1, len(chunks)) } if deregisterTargetsError != nil { return deregisterTargetsError @@ -236,14 +236,14 @@ func (s *defaultTargetGroupManager) Delete(ctx context.Context, modelTg *model.T _, err = lattice.DeleteTargetGroupWithContext(ctx, &deleteTGInput) if err != nil { if services.IsLatticeAPINotFoundErr(err) { - s.log.Infof("Target group %s was already deleted", modelTg.Status.Id) + s.log.Infof(ctx, "Target group %s was already deleted", modelTg.Status.Id) return nil } else { return fmt.Errorf("failed DeleteTargetGroup %s due to %s", modelTg.Status.Id, err) } } - s.log.Infof("Success DeleteTargetGroup %s", modelTg.Status.Id) + s.log.Infof(ctx, "Success DeleteTargetGroup %s", modelTg.Status.Id) return nil } @@ -458,7 +458,7 @@ func (s *defaultTargetGroupManager) findSvcExportTG(ctx context.Context, svcImpo // ResolveRuleTgIds populates all target group ids in the rule's actions func (s *defaultTargetGroupManager) ResolveRuleTgIds(ctx context.Context, ruleAction *model.RuleAction, stack core.Stack) error { if len(ruleAction.TargetGroups) == 0 { - s.log.Debugf("no target groups to resolve for rule") + s.log.Debugf(ctx, "no target groups to resolve for rule") return nil } for i, ruleActionTg := range ruleAction.TargetGroups { @@ -466,16 +466,16 @@ func (s *defaultTargetGroupManager) ResolveRuleTgIds(ctx context.Context, ruleAc return errors.New("rule TG is missing a required target group identifier") } if ruleActionTg.LatticeTgId != "" { - s.log.Debugf("Rule TG %d already resolved %s", i, ruleActionTg.LatticeTgId) + s.log.Debugf(ctx, "Rule TG %d already resolved %s", i, ruleActionTg.LatticeTgId) continue } if ruleActionTg.StackTargetGroupId != "" { if ruleActionTg.StackTargetGroupId == model.InvalidBackendRefTgId { - s.log.Debugf("Rule TG has an invalid backendref, setting TG id to invalid") + s.log.Debugf(ctx, "Rule TG has an invalid backendref, setting TG id to invalid") ruleActionTg.LatticeTgId = model.InvalidBackendRefTgId continue } - s.log.Debugf("Fetching TG %d from the stack (ID %s)", i, ruleActionTg.StackTargetGroupId) + s.log.Debugf(ctx, "Fetching TG %d from the stack (ID %s)", i, ruleActionTg.StackTargetGroupId) stackTg := &model.TargetGroup{} err := stack.GetResource(ruleActionTg.StackTargetGroupId, stackTg) if err != nil { @@ -487,7 +487,7 @@ func (s *defaultTargetGroupManager) ResolveRuleTgIds(ctx context.Context, ruleAc ruleActionTg.LatticeTgId = stackTg.Status.Id } if ruleActionTg.SvcImportTG != nil { - s.log.Debugf("Getting target group for service import %s %s (%s, %s)", + s.log.Debugf(ctx, "Getting target group for service import %s %s (%s, %s)", ruleActionTg.SvcImportTG.K8SServiceName, ruleActionTg.SvcImportTG.K8SServiceNamespace, ruleActionTg.SvcImportTG.K8SClusterName, ruleActionTg.SvcImportTG.VpcId) tgId, err := s.findSvcExportTG(ctx, *ruleActionTg.SvcImportTG) diff --git a/pkg/deploy/lattice/target_group_synthesizer.go b/pkg/deploy/lattice/target_group_synthesizer.go index 1a75e45b..2fbe782a 100644 --- a/pkg/deploy/lattice/target_group_synthesizer.go +++ b/pkg/deploy/lattice/target_group_synthesizer.go @@ -78,7 +78,7 @@ func (t *TargetGroupSynthesizer) SynthesizeCreate(ctx context.Context) error { if err == nil { resTargetGroup.Status = &tgStatus } else { - t.log.Debugf("Failed TargetGroupManager.Upsert %s due to %s", prefix, err) + t.log.Debugf(ctx, "Failed TargetGroupManager.Upsert %s due to %s", prefix, err) returnErr = true } } @@ -181,7 +181,7 @@ func (t *TargetGroupSynthesizer) calculateTargetGroupsToDelete(ctx context.Conte // most importantly, is the tg in use? if len(latticeTg.tgSummary.ServiceArns) > 0 { - t.log.Debugf("TargetGroup %s (%s) is referenced by lattice service", + t.log.Debugf(ctx, "TargetGroup %s (%s) is referenced by lattice service", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) continue } @@ -207,7 +207,7 @@ func (t *TargetGroupSynthesizer) shouldDeleteSvcExportTg( Name: tagFields.K8SServiceName, } - t.log.Debugf("TargetGroup %s (%s) is referenced by ServiceExport", + t.log.Debugf(ctx, "TargetGroup %s (%s) is referenced by ServiceExport", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) svcExport := &anv1alpha1.ServiceExport{} @@ -215,19 +215,19 @@ func (t *TargetGroupSynthesizer) shouldDeleteSvcExportTg( if err != nil { if apierrors.IsNotFound(err) { // if the service export does not exist, we can safely delete - t.log.Infof("Will delete TargetGroup %s (%s) - ServiceExport is not found", + t.log.Infof(ctx, "Will delete TargetGroup %s (%s) - ServiceExport is not found", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true } else { // skip if we have an unknown error - t.log.Infof("Received unexpected API error getting service export %s", err) + t.log.Infof(ctx, "Received unexpected API error getting service export %s", err) return false } } if !svcExport.DeletionTimestamp.IsZero() { // backing object is deleted, we can delete too - t.log.Infof("Will delete TargetGroup %s (%s) - ServiceExport has been deleted", + t.log.Infof(ctx, "Will delete TargetGroup %s (%s) - ServiceExport has been deleted", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true } @@ -237,7 +237,7 @@ func (t *TargetGroupSynthesizer) shouldDeleteSvcExportTg( // reconstruct the target group spec from the service export itself, then compare fields modelTg, err := t.svcExportTgBuilder.BuildTargetGroup(ctx, svcExport) if err != nil { - t.log.Infof("Received error building svc export target group model %s", err) + t.log.Infof(ctx, "Received error building svc export target group model %s", err) return false } @@ -249,12 +249,12 @@ func (t *TargetGroupSynthesizer) shouldDeleteSvcExportTg( modelTg.Spec.IpAddressType != aws.StringValue(latticeTg.tgSummary.IpAddressType) { // one or more immutable fields differ from the source, so the TG is out of date - t.log.Infof("Will delete TargetGroup %s (%s) - fields differ from source service/service export", + t.log.Infof(ctx, "Will delete TargetGroup %s (%s) - fields differ from source service/service export", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true } - t.log.Debugf("ServiceExport TargetGroup %s (%s) is up to date", + t.log.Debugf(ctx, "ServiceExport TargetGroup %s (%s) is up to date", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false @@ -281,18 +281,18 @@ func (t *TargetGroupSynthesizer) shouldDeleteRouteTg( if err != nil { if apierrors.IsNotFound(err) { // if the route does not exist, we can safely delete - t.log.Debugf("Will delete TargetGroup %s (%s) - Route is not found", + t.log.Debugf(ctx, "Will delete TargetGroup %s (%s) - Route is not found", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true } else { // skip if we have an unknown error - t.log.Infof("Received unexpected API error getting route %s", err) + t.log.Infof(ctx, "Received unexpected API error getting route %s", err) return false } } if !route.DeletionTimestamp().IsZero() { - t.log.Debugf("Will delete TargetGroup %s (%s) - Route is deleted", + t.log.Debugf(ctx, "Will delete TargetGroup %s (%s) - Route is deleted", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true } @@ -300,14 +300,14 @@ func (t *TargetGroupSynthesizer) shouldDeleteRouteTg( // basically rebuild everything for the route and see if one of the TGs matches routeStack, err := t.svcBuilder.Build(ctx, route) if err != nil { - t.log.Infof("Received error building route model %s", err) + t.log.Infof(ctx, "Received error building route model %s", err) return false } var resTargetGroups []*model.TargetGroup err = routeStack.ListResources(&resTargetGroups) if err != nil { - t.log.Infof("Error listing stack target groups %s", err) + t.log.Infof(ctx, "Error listing stack target groups %s", err) return false } @@ -315,12 +315,12 @@ func (t *TargetGroupSynthesizer) shouldDeleteRouteTg( for _, modelTg := range resTargetGroups { match, err := t.targetGroupManager.IsTargetGroupMatch(ctx, modelTg, latticeTg.tgSummary, &tagFields) if err != nil { - t.log.Infof("Received error during tg comparison %s", err) + t.log.Infof(ctx, "Received error during tg comparison %s", err) continue } if match { - t.log.Debugf("Route TargetGroup %s (%s) is up to date", + t.log.Debugf(ctx, "Route TargetGroup %s (%s) is up to date", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) matchFound = true @@ -329,7 +329,7 @@ func (t *TargetGroupSynthesizer) shouldDeleteRouteTg( } if !matchFound { - t.log.Debugf("Will delete TargetGroup %s (%s) - TG is not up to date", + t.log.Debugf(ctx, "Will delete TargetGroup %s (%s) - TG is not up to date", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return true // safe to delete @@ -340,7 +340,7 @@ func (t *TargetGroupSynthesizer) shouldDeleteRouteTg( func (t *TargetGroupSynthesizer) hasTags(latticeTg tgListOutput) bool { if latticeTg.tags == nil { - t.log.Debugf("Ignoring target group %s (%s) because tag fetch was not successful", + t.log.Debugf(context.TODO(), "Ignoring target group %s (%s) because tag fetch was not successful", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false } @@ -349,7 +349,7 @@ func (t *TargetGroupSynthesizer) hasTags(latticeTg tgListOutput) bool { func (t *TargetGroupSynthesizer) vpcMatchesConfig(latticeTg tgListOutput) bool { if aws.StringValue(latticeTg.tgSummary.VpcIdentifier) != config.VpcID { - t.log.Debugf("Ignoring target group %s (%s) because it is not configured for this VPC", + t.log.Debugf(context.TODO(), "Ignoring target group %s (%s) because it is not configured for this VPC", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false } @@ -358,7 +358,7 @@ func (t *TargetGroupSynthesizer) vpcMatchesConfig(latticeTg tgListOutput) bool { func (t *TargetGroupSynthesizer) hasExpectedTags(latticeTg tgListOutput, tagFields model.TargetGroupTagFields) bool { if tagFields.K8SClusterName != config.ClusterName { - t.log.Debugf("Ignoring target group %s (%s) because it is not configured for this Cluster", + t.log.Debugf(context.TODO(), "Ignoring target group %s (%s) because it is not configured for this Cluster", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false } @@ -366,14 +366,14 @@ func (t *TargetGroupSynthesizer) hasExpectedTags(latticeTg tgListOutput, tagFiel if tagFields.K8SSourceType == model.SourceTypeInvalid || tagFields.K8SServiceName == "" || tagFields.K8SServiceNamespace == "" { - t.log.Infof("Ignoring target group %s (%s) as one or more required tags are missing", + t.log.Infof(context.TODO(), "Ignoring target group %s (%s) as one or more required tags are missing", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false } // route-based TGs should have the additional route keys if tagFields.IsSourceTypeRoute() && (tagFields.K8SRouteName == "" || tagFields.K8SRouteNamespace == "") { - t.log.Infof("Ignoring route-based target group %s (%s) as one or more required tags are missing", + t.log.Infof(context.TODO(), "Ignoring route-based target group %s (%s) as one or more required tags are missing", *latticeTg.tgSummary.Arn, *latticeTg.tgSummary.Name) return false } diff --git a/pkg/deploy/lattice/targets_manager.go b/pkg/deploy/lattice/targets_manager.go index 42cb16ca..4fced646 100644 --- a/pkg/deploy/lattice/targets_manager.go +++ b/pkg/deploy/lattice/targets_manager.go @@ -59,7 +59,7 @@ func (s *defaultTargetsManager) Update(ctx context.Context, modelTargets *model. modelTg.ID(), modelTargets.Spec.StackTargetGroupId) } - s.log.Debugf("Creating targets for target group %s", modelTg.Status.Id) + s.log.Debugf(ctx, "Creating targets for target group %s", modelTg.Status.Id) latticeTargets, err := s.List(ctx, modelTg) if err != nil { @@ -125,7 +125,7 @@ func (s *defaultTargetsManager) registerTargets( registerTargetsError = errors.Join(registerTargetsError, fmt.Errorf("Failed to register targets from VPC Lattice Target Group %s for chunk %d/%d, unsuccessful targets %v", modelTg.Status.Id, i+1, len(chunks), resp.Unsuccessful)) } - s.log.Debugf("Successfully registered %d targets from VPC Lattice Target Group %s for chunk %d/%d", + s.log.Debugf(ctx, "Successfully registered %d targets from VPC Lattice Target Group %s for chunk %d/%d", len(resp.Successful), modelTg.Status.Id, i+1, len(chunks)) } return registerTargetsError @@ -158,7 +158,7 @@ func (s *defaultTargetsManager) deregisterTargets( deregisterTargetsError = errors.Join(deregisterTargetsError, fmt.Errorf("Failed to deregister targets from VPC Lattice Target Group %s for chunk %d/%d, unsuccessful targets %v", modelTg.Status.Id, i+1, len(chunks), resp.Unsuccessful)) } - s.log.Debugf("Successfully deregistered %d targets from VPC Lattice Target Group %s for chunk %d/%d", resp.Successful, modelTg.Status.Id, i+1, len(chunks)) + s.log.Debugf(ctx, "Successfully deregistered %d targets from VPC Lattice Target Group %s for chunk %d/%d", len(resp.Successful), modelTg.Status.Id, i+1, len(chunks)) } return deregisterTargetsError } diff --git a/pkg/deploy/lattice/targets_synthesizer.go b/pkg/deploy/lattice/targets_synthesizer.go index ede71ec9..05502821 100644 --- a/pkg/deploy/lattice/targets_synthesizer.go +++ b/pkg/deploy/lattice/targets_synthesizer.go @@ -52,7 +52,7 @@ func (t *targetsSynthesizer) Synthesize(ctx context.Context) error { var resTargets []*model.Targets err := t.stack.ListResources(&resTargets) if err != nil { - t.log.Errorf("Failed to list targets due to %s", err) + t.log.Errorf(ctx, "Failed to list targets due to %s", err) } for _, targets := range resTargets { @@ -78,7 +78,7 @@ func (t *targetsSynthesizer) PostSynthesize(ctx context.Context) error { var resTargets []*model.Targets err := t.stack.ListResources(&resTargets) if err != nil { - t.log.Errorf("Failed to list targets due to %s", err) + t.log.Errorf(ctx, "Failed to list targets due to %s", err) } requeueNeeded := false diff --git a/pkg/deploy/stack_deployer.go b/pkg/deploy/stack_deployer.go index 35075b68..66534fed 100644 --- a/pkg/deploy/stack_deployer.go +++ b/pkg/deploy/stack_deployer.go @@ -153,7 +153,7 @@ func (gc *TgGc) start() { for { select { case <-gc.ctx.Done(): - gc.log.Info("stop GC, ctx is done") + gc.log.Info(context.TODO(), "stop GC, ctx is done") gc.isDone.Store(true) return case <-ticker.C: @@ -166,16 +166,16 @@ func (gc *TgGc) start() { func (gc *TgGc) cycle() { defer func() { if r := recover(); r != nil { - gc.log.Errorf("gc cycle panic: %s", r) + gc.log.Errorf(context.TODO(), "gc cycle panic: %s", r) } gc.lock.Unlock() }() gc.lock.Lock() res, err := gc.cycleFn(gc.ctx) if err != nil { - gc.log.Debugf("gc cycle error: %s", err) + gc.log.Debugf(context.TODO(), "gc cycle error: %s", err) } - gc.log.Debugw("gc stats", + gc.log.Debugw(context.TODO(), "gc stats", "delete_attempts", res.att, "delete_success", res.succ, "duration", res.duration, diff --git a/pkg/gateway/model_build_access_log_subscription.go b/pkg/gateway/model_build_access_log_subscription.go index 71448a44..b2c6badb 100644 --- a/pkg/gateway/model_build_access_log_subscription.go +++ b/pkg/gateway/model_build_access_log_subscription.go @@ -91,7 +91,7 @@ func (t *accessLogSubscriptionModelBuildTask) run(ctx context.Context) error { Arn: value, } } else { - t.log.Debugf("access log policy is missing %s annotation during %s event", + t.log.Debugf(ctx, "access log policy is missing %s annotation during %s event", anv1alpha1.AccessLogSubscriptionAnnotationKey, eventType) } } diff --git a/pkg/gateway/model_build_lattice_service.go b/pkg/gateway/model_build_lattice_service.go index ca71abab..dd54994b 100644 --- a/pkg/gateway/model_build_lattice_service.go +++ b/pkg/gateway/model_build_lattice_service.go @@ -84,10 +84,10 @@ func (t *latticeServiceModelBuildTask) buildModel(ctx context.Context) error { if err != nil { return err } - t.log.Debugf("Building rules for %d listeners", len(modelListeners)) + t.log.Debugf(ctx, "Building rules for %d listeners", len(modelListeners)) for _, modelListener := range modelListeners { if modelListener.Spec.Protocol == vpclattice.ListenerProtocolTlsPassthrough { - t.log.Debugf("Skip building rules for TLS_PASSTHROUGH listener %s, since lattice TLS_PASSTHROUGH listener can only have listener defaultAction and without any other rule", modelListener.ID()) + t.log.Debugf(ctx, "Skip building rules for TLS_PASSTHROUGH listener %s, since lattice TLS_PASSTHROUGH listener can only have listener defaultAction and without any other rule", modelListener.ID()) continue } @@ -134,10 +134,10 @@ func (t *latticeServiceModelBuildTask) buildLatticeService(ctx context.Context) // The 1st hostname will be used as lattice customer-domain-name spec.CustomerDomainName = string(t.route.Spec().Hostnames()[0]) - t.log.Infof("Setting customer-domain-name: %s for route %s-%s", + t.log.Infof(ctx, "Setting customer-domain-name: %s for route %s-%s", spec.CustomerDomainName, t.route.Name(), t.route.Namespace()) } else { - t.log.Infof("No custom-domain-name for route %s-%s", + t.log.Infof(ctx, "No custom-domain-name for route %s-%s", t.route.Name(), t.route.Namespace()) spec.CustomerDomainName = "" } @@ -153,7 +153,7 @@ func (t *latticeServiceModelBuildTask) buildLatticeService(ctx context.Context) return nil, err } - t.log.Debugf("Added service %s to the stack (ID %s)", svc.Spec.LatticeServiceName(), svc.ID()) + t.log.Debugf(ctx, "Added service %s to the stack (ID %s)", svc.Spec.LatticeServiceName(), svc.ID()) svc.IsDeleted = !t.route.DeletionTimestamp().IsZero() return svc, nil } @@ -172,7 +172,7 @@ func (t *latticeServiceModelBuildTask) getACMCertArn(ctx context.Context) (strin if parentRef.Name != t.route.Spec().ParentRefs()[0].Name { // when a service is associate to multiple service network(s), all listener config MUST be same // so here we are only using the 1st gateway - t.log.Debugf("Ignore ParentRef of different gateway %s-%s", parentRef.Name, parentRef.Namespace) + t.log.Debugf(ctx, "Ignore ParentRef of different gateway %s-%s", parentRef.Name, *parentRef.Namespace) continue } @@ -185,7 +185,7 @@ func (t *latticeServiceModelBuildTask) getACMCertArn(ctx context.Context) (strin if section.TLS.Mode != nil && *section.TLS.Mode == gwv1.TLSModeTerminate { curCertARN, ok := section.TLS.Options[awsCustomCertARN] if ok { - t.log.Debugf("Found certification %s under section %s", curCertARN, section.Name) + t.log.Debugf(ctx, "Found certification %s under section %s", curCertARN, section.Name) return string(curCertARN), nil } } diff --git a/pkg/gateway/model_build_listener.go b/pkg/gateway/model_build_listener.go index 8ccd38e0..ebd3471a 100644 --- a/pkg/gateway/model_build_listener.go +++ b/pkg/gateway/model_build_listener.go @@ -23,10 +23,10 @@ func (t *latticeServiceModelBuildTask) extractListenerInfo( parentRef gwv1beta1.ParentReference, ) (int64, string, error) { if parentRef.SectionName != nil { - t.log.Debugf("Listener parentRef SectionName is %s", *parentRef.SectionName) + t.log.Debugf(ctx, "Listener parentRef SectionName is %s", *parentRef.SectionName) } - t.log.Debugf("Building Listener for Route %s-%s", t.route.Name(), t.route.Namespace()) + t.log.Debugf(ctx, "Building Listener for Route %s-%s", t.route.Name(), t.route.Namespace()) gw, err := t.getGateway(ctx) if err != nil { return 0, "", err @@ -46,7 +46,7 @@ func (t *latticeServiceModelBuildTask) extractListenerInfo( listenerPort := int(section.Port) protocol := section.Protocol if isTLSPassthroughGatewayListener(§ion) { - t.log.Debugf("Found TLS passthrough section %v", section.TLS) + t.log.Debugf(ctx, "Found TLS passthrough section %v", section.TLS) protocol = vpclattice.ListenerProtocolTlsPassthrough } return int64(listenerPort), string(protocol), nil @@ -79,10 +79,10 @@ func (t *latticeServiceModelBuildTask) getGateway(ctx context.Context) (*gwv1bet func (t *latticeServiceModelBuildTask) buildListeners(ctx context.Context, stackSvcId string) error { if len(t.route.Spec().ParentRefs()) == 0 { - t.log.Debugf("No ParentRefs on route %s-%s, nothing to do", t.route.Name(), t.route.Namespace()) + t.log.Debugf(ctx, "No ParentRefs on route %s-%s, nothing to do", t.route.Name(), t.route.Namespace()) } if !t.route.DeletionTimestamp().IsZero() { - t.log.Debugf("Route %s-%s is deleted, skipping listener build", t.route.Name(), t.route.Namespace()) + t.log.Debugf(ctx, "Route %s-%s is deleted, skipping listener build", t.route.Name(), t.route.Namespace()) return nil } @@ -90,7 +90,7 @@ func (t *latticeServiceModelBuildTask) buildListeners(ctx context.Context, stack if parentRef.Name != t.route.Spec().ParentRefs()[0].Name { // when a service is associate to multiple service network(s), all listener config MUST be same // so here we are only using the 1st gateway - t.log.Debugf("Ignore parentref of different gateway %s-%s", parentRef.Name, parentRef.Namespace) + t.log.Debugf(ctx, "Ignore parentref of different gateway %s-%s", parentRef.Name, *parentRef.Namespace) continue } @@ -117,7 +117,7 @@ func (t *latticeServiceModelBuildTask) buildListeners(ctx context.Context, stack return err } - t.log.Debugf("Added listener %s-%s to the stack (ID %s)", + t.log.Debugf(ctx, "Added listener %s-%s to the stack (ID %s)", modelListener.Spec.K8SRouteName, modelListener.Spec.K8SRouteNamespace, modelListener.ID()) } diff --git a/pkg/gateway/model_build_rule.go b/pkg/gateway/model_build_rule.go index aef69617..3418b2b3 100644 --- a/pkg/gateway/model_build_rule.go +++ b/pkg/gateway/model_build_rule.go @@ -32,7 +32,8 @@ const ( func (t *latticeServiceModelBuildTask) buildRules(ctx context.Context, stackListenerId string) error { // note we only build rules for non-deleted routes - t.log.Debugf("Processing %d rules", len(t.route.Spec().Rules())) + t.log.Debugf(ctx, "Processing %d rules", len(t.route.Spec().Rules())) + for i, rule := range t.route.Spec().Rules() { ruleSpec := model.RuleSpec{ StackListenerId: stackListenerId, @@ -43,7 +44,7 @@ func (t *latticeServiceModelBuildTask) buildRules(ctx context.Context, stackList // only support 1 match today return errors.New(LATTICE_NO_SUPPORT_FOR_MULTIPLE_MATCHES) } else if len(rule.Matches()) > 0 { - t.log.Debugf("Processing rule match") + t.log.Debugf(ctx, "Processing rule match") match := rule.Matches()[0] switch m := match.(type) { @@ -89,9 +90,9 @@ func (t *latticeServiceModelBuildTask) buildRules(ctx context.Context, stackList if err != nil { return err } - t.log.Debugf("Added rule %d to the stack (ID %s)", stackRule.Spec.Priority, stackRule.ID()) + t.log.Debugf(ctx, "Added rule %d to the stack (ID %s)", stackRule.Spec.Priority, stackRule.ID()) } else { - t.log.Debugf("Skipping adding rule %d to the stack since the route is deleted", ruleSpec.Priority) + t.log.Debugf(ctx, "Skipping adding rule %d to the stack since the route is deleted", ruleSpec.Priority) } } @@ -107,21 +108,21 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecForHttpRoute(m *core.HTTPRo } if hasPath { - t.log.Debugf("Examining pathmatch type %s value %s for for httproute %s-%s ", + t.log.Debugf(context.TODO(), "Examining pathmatch type %s value %s for for httproute %s-%s ", *m.Path().Type, *m.Path().Value, t.route.Name(), t.route.Namespace()) switch *m.Path().Type { case gwv1.PathMatchExact: - t.log.Debugf("Using PathMatchExact for httproute %s-%s ", + t.log.Debugf(context.TODO(), "Using PathMatchExact for httproute %s-%s ", t.route.Name(), t.route.Namespace()) ruleSpec.PathMatchExact = true case gwv1.PathMatchPathPrefix: - t.log.Debugf("Using PathMatchPathPrefix for httproute %s-%s ", + t.log.Debugf(context.TODO(), "Using PathMatchPathPrefix for httproute %s-%s ", t.route.Name(), t.route.Namespace()) ruleSpec.PathMatchPrefix = true default: - t.log.Debugf("Unsupported path match type %s for httproute %s-%s", + t.log.Debugf(context.TODO(), "Unsupported path match type %s for httproute %s-%s", *m.Path().Type, t.route.Name(), t.route.Namespace()) return errors.New(LATTICE_UNSUPPORTED_PATH_MATCH_TYPE) } @@ -130,7 +131,7 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecForHttpRoute(m *core.HTTPRo // method based match if m.Method() != nil { - t.log.Infof("Examining http method %s for httproute %s-%s", + t.log.Infof(context.TODO(), "Examining http method %s for httproute %s-%s", *m.Method(), t.route.Name(), t.route.Namespace()) ruleSpec.Method = string(*m.Method()) @@ -138,7 +139,7 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecForHttpRoute(m *core.HTTPRo // controller does not support query matcher type today if m.QueryParams() != nil { - t.log.Infof("Unsupported match type for httproute %s, namespace %s", + t.log.Infof(context.TODO(), "Unsupported match type for httproute %s, namespace %s", t.route.Name(), t.route.Namespace()) return errors.New(LATTICE_UNSUPPORTED_MATCH_TYPE) } @@ -146,7 +147,7 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecForHttpRoute(m *core.HTTPRo } func (t *latticeServiceModelBuildTask) updateRuleSpecForGrpcRoute(m *core.GRPCRouteMatch, ruleSpec *model.RuleSpec) error { - t.log.Debugf("Building rule with GRPCRouteMatch, %+v", *m) + t.log.Debugf(context.TODO(), "Building rule with GRPCRouteMatch, %+v", *m) ruleSpec.Method = string(gwv1.HTTPMethodPost) // GRPC is always POST method := m.Method() // VPC Lattice doesn't support suffix/regex matching, so we can't support method match without service @@ -156,15 +157,15 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecForGrpcRoute(m *core.GRPCRo switch *method.Type { case gwv1alpha2.GRPCMethodMatchExact: if method.Service == nil { - t.log.Debugf("Match all paths due to nil service and nil method") + t.log.Debugf(context.TODO(), "Match all paths due to nil service and nil method") ruleSpec.PathMatchPrefix = true ruleSpec.PathMatchValue = "/" } else if method.Method == nil { - t.log.Debugf("Match by specific gRPC service %s, regardless of method", *method.Service) + t.log.Debugf(context.TODO(), "Match by specific gRPC service %s, regardless of method", *method.Service) ruleSpec.PathMatchPrefix = true ruleSpec.PathMatchValue = fmt.Sprintf("/%s/", *method.Service) } else { - t.log.Debugf("Match by specific gRPC service %s and method %s", *method.Service, *method.Method) + t.log.Debugf(context.TODO(), "Match by specific gRPC service %s and method %s", *method.Service, *method.Method) ruleSpec.PathMatchExact = true ruleSpec.PathMatchValue = fmt.Sprintf("/%s/%s", *method.Service, *method.Method) } @@ -183,12 +184,12 @@ func (t *latticeServiceModelBuildTask) updateRuleSpecWithHeaderMatches(match cor return errors.New(LATTICE_EXCEED_MAX_HEADER_MATCHES) } - t.log.Debugf("Examining match headers for route %s-%s", t.route.Name(), t.route.Namespace()) + t.log.Debugf(context.TODO(), "Examining match headers for route %s-%s", t.route.Name(), t.route.Namespace()) for _, header := range match.Headers() { - t.log.Debugf("Examining match.Header: header.Type %s", *header.Type()) + t.log.Debugf(context.TODO(), "Examining match.Header: header.Type %s", *header.Type()) if header.Type() != nil && *header.Type() != gwv1.HeaderMatchExact { - t.log.Debugf("Unsupported header matchtype %s for httproute %s-%s", + t.log.Debugf(context.TODO(), "Unsupported header matchtype %s for httproute %s-%s", *header.Type(), t.route.Name(), t.route.Namespace()) return errors.New(LATTICE_UNSUPPORTED_HEADER_MATCH_TYPE) } @@ -224,7 +225,7 @@ func (t *latticeServiceModelBuildTask) getTargetGroupsForRuleAction(ctx context. namespace = string(*backendRef.Namespace()) } - t.log.Debugf("Processing %s backendRef %s-%s", string(*backendRef.Kind()), backendRef.Name(), namespace) + t.log.Debugf(ctx, "Processing %s backendRef %s-%s", string(*backendRef.Kind()), backendRef.Name(), namespace) if string(*backendRef.Kind()) == "ServiceImport" { // there needs to be a pre-existing target group, we fetch all the fields @@ -266,7 +267,7 @@ func (t *latticeServiceModelBuildTask) getTargetGroupsForRuleAction(ctx context. return nil, err } - t.log.Infof("Invalid backendRef found on route %s", t.route.Name()) + t.log.Infof(ctx, "Invalid backendRef found on route %s", t.route.Name()) ruleTG.StackTargetGroupId = model.InvalidBackendRefTgId } else { ruleTG.StackTargetGroupId = tg.ID() diff --git a/pkg/gateway/model_build_targetgroup.go b/pkg/gateway/model_build_targetgroup.go index de632c2e..6c96d3e0 100644 --- a/pkg/gateway/model_build_targetgroup.go +++ b/pkg/gateway/model_build_targetgroup.go @@ -111,7 +111,7 @@ func (t *svcExportTargetGroupModelBuildTask) run(ctx context.Context) error { if !tg.IsDeleted { err = t.buildTargets(ctx, tg.ID()) if err != nil { - t.log.Debugf("Failed to build targets for service export %s-%s due to %s", + t.log.Debugf(ctx, "Failed to build targets for service export %s-%s due to %s", t.serviceExport.Name, t.serviceExport.Namespace, err) return err } @@ -220,7 +220,7 @@ func (b *BackendRefTargetGroupBuilder) Build( ) (core.Stack, *model.TargetGroup, error) { if stack == nil { stack = core.NewDefaultStack(core.StackID(k8s.NamespacedName(route.K8sObject()))) - b.log.Debugf("Creating new stack for build task") + b.log.Debugf(ctx, "Creating new stack for build task") } task := backendRefTargetGroupModelBuildTask{ @@ -253,7 +253,7 @@ func (t *backendRefTargetGroupModelBuildTask) buildTargetGroup(ctx context.Conte if err != nil { return nil, err } - t.log.Debugf("Added target group for backendRef %s to the stack %s", t.backendRef.Name(), stackTG.ID()) + t.log.Debugf(ctx, "Added target group for backendRef %s to the stack %s", t.backendRef.Name(), stackTG.ID()) stackTG.IsDeleted = !t.route.DeletionTimestamp().IsZero() // should always be false if !stackTG.IsDeleted { @@ -265,7 +265,7 @@ func (t *backendRefTargetGroupModelBuildTask) buildTargetGroup(ctx context.Conte func (t *backendRefTargetGroupModelBuildTask) buildTargets(ctx context.Context, stackTgId string) error { if string(*t.backendRef.Kind()) == "ServiceImport" { - t.log.Debugf("Service import does not manage targets, returning") + t.log.Debugf(ctx, "Service import does not manage targets, returning") return nil } backendRefNsName := getBackendRefNsName(t.route, t.backendRef) @@ -287,7 +287,7 @@ func (t *backendRefTargetGroupModelBuildTask) buildTargets(ctx context.Context, func (t *backendRefTargetGroupModelBuildTask) buildTargetGroupSpec(ctx context.Context) (model.TargetGroupSpec, error) { // note we only build target groups for backendRefs on non-deleted routes backendKind := string(*t.backendRef.Kind()) - t.log.Debugf("buildTargetGroupSpec, kind %s", backendKind) + t.log.Debugf(ctx, "buildTargetGroupSpec, kind %s", backendKind) vpc := config.VpcID eksCluster := config.ClusterName diff --git a/pkg/gateway/model_build_targets.go b/pkg/gateway/model_build_targets.go index 187bbc85..a7f8292d 100644 --- a/pkg/gateway/model_build_targets.go +++ b/pkg/gateway/model_build_targets.go @@ -73,7 +73,7 @@ func (b *LatticeTargetsModelBuilder) build(ctx context.Context, } if isServiceExport { - b.log.Debugf("Processing targets for service export %s-%s", serviceExport.Name, serviceExport.Namespace) + b.log.Debugf(ctx, "Processing targets for service export %s-%s", serviceExport.Name, serviceExport.Namespace) serviceName := types.NamespacedName{ Namespace: serviceExport.Namespace, @@ -86,7 +86,7 @@ func (b *LatticeTargetsModelBuilder) build(ctx context.Context, } service = tmpSvc } else { - b.log.Debugf("Processing targets for service %s-%s", service.Name, service.Namespace) + b.log.Debugf(ctx, "Processing targets for service %s-%s", service.Name, service.Namespace) } if stack == nil { @@ -94,7 +94,7 @@ func (b *LatticeTargetsModelBuilder) build(ctx context.Context, } if !service.DeletionTimestamp.IsZero() { - b.log.Debugf("service %s/%s is deleted, skipping target build", service.Name, service.Namespace) + b.log.Debugf(ctx, "service %s/%s is deleted, skipping target build", service.Name, service.Namespace) return stack, nil } @@ -218,7 +218,7 @@ func (t *latticeTargetsModelBuildTask) getDefinedPorts() map[int32]struct{} { if portAnnotation != "" { definedPort, err := strconv.ParseInt(portAnnotation, 10, 32) if err != nil { - t.log.Infof("failed to read Annotations/Port: %s due to %s", + t.log.Infof(context.TODO(), "failed to read Annotations/Port: %s due to %s", t.serviceExport.ObjectMeta.Annotations[portAnnotationsKey], err) } else { definedPorts[int32(definedPort)] = struct{}{} diff --git a/pkg/k8s/policyhelper/policy.go b/pkg/k8s/policyhelper/policy.go index b7b2b536..5f5c74c4 100644 --- a/pkg/k8s/policyhelper/policy.go +++ b/pkg/k8s/policyhelper/policy.go @@ -249,7 +249,7 @@ func (h *PolicyHandler[P]) ObjResolvedPolicy(ctx context.Context, obj k8sclient. // Add Watchers for configured Kinds to controller builder func (h *PolicyHandler[P]) AddWatchers(b *builder.Builder, objs ...k8sclient.Object) { - h.log.Debugf("add watchers for types: %v", NewGroupKindSet(objs...).Items()) + h.log.Debugf(context.TODO(), "add watchers for types: %v", NewGroupKindSet(objs...).Items()) for _, watchObj := range objs { b.Watches(watchObj, handler.EnqueueRequestsFromMapFunc(h.watchMapFn)) } @@ -259,7 +259,7 @@ func (h *PolicyHandler[P]) watchMapFn(ctx context.Context, obj k8sclient.Object) out := []reconcile.Request{} policies, err := h.client.List(ctx, obj.GetNamespace()) if err != nil { - h.log.Errorf("watch mapfn error: for obj=%s/%s: %w", + h.log.Errorf(ctx, "watch mapfn error: for obj=%s/%s: %s", obj.GetName(), obj.GetNamespace(), err) return nil } diff --git a/pkg/utils/gwlog/actions.go b/pkg/utils/gwlog/actions.go new file mode 100644 index 00000000..7de0edf7 --- /dev/null +++ b/pkg/utils/gwlog/actions.go @@ -0,0 +1,4 @@ +package gwlog + +const ReconcileStart = "RECONCILE_START_MARKER" +const ReconcileEnd = "RECONCILE_END_MARKER" diff --git a/pkg/utils/gwlog/gwlog.go b/pkg/utils/gwlog/gwlog.go index 1f129b51..2e56b966 100644 --- a/pkg/utils/gwlog/gwlog.go +++ b/pkg/utils/gwlog/gwlog.go @@ -1,6 +1,8 @@ package gwlog import ( + "context" + "fmt" "log" "os" @@ -8,7 +10,111 @@ import ( "go.uber.org/zap/zapcore" ) -type Logger = *zap.SugaredLogger +type TracedLogger struct { + InnerLogger *zap.SugaredLogger +} + +func (t *TracedLogger) Infoln(args ...interface{}) { + t.InnerLogger.Infoln(args...) +} + +func (t *TracedLogger) Infow(ctx context.Context, msg string, keysAndValues ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + keysAndValues = append(keysAndValues, traceID, tr) + } + t.InnerLogger.Infow(msg, keysAndValues...) +} + +func (t *TracedLogger) Infof(ctx context.Context, template string, args ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Infow(fmt.Sprintf(template, args...), traceID, tr) + return + } + t.InnerLogger.Infof(template, args...) +} + +func (t *TracedLogger) Info(ctx context.Context, msg string) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Infow(msg, traceID, tr) + return + } + t.InnerLogger.Info(msg) +} + +func (t *TracedLogger) Errorw(ctx context.Context, msg string, keysAndValues ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + keysAndValues = append(keysAndValues, traceID, tr) + } + t.InnerLogger.Errorw(msg, keysAndValues) +} + +func (t *TracedLogger) Errorf(ctx context.Context, template string, args ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Errorw(fmt.Sprintf(template, args...), traceID, tr) + return + } + t.InnerLogger.Errorf(template, args...) +} + +func (t *TracedLogger) Error(ctx context.Context, msg string) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Errorw(msg, traceID, tr) + return + } + t.InnerLogger.Error(msg) +} + +func (t *TracedLogger) Debugw(ctx context.Context, msg string, keysAndValues ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + keysAndValues = append(keysAndValues, traceID, tr) + } + t.InnerLogger.Debugw(msg, keysAndValues...) +} + +func (t *TracedLogger) Debugf(ctx context.Context, template string, args ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Debugw(fmt.Sprintf(template, args...), traceID, tr) + return + } + t.InnerLogger.Debugf(template, args...) +} + +func (t *TracedLogger) Debug(ctx context.Context, msg string) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Debugw(msg, traceID, tr) + return + } + t.InnerLogger.Debug(msg) +} + +func (t *TracedLogger) Warnw(ctx context.Context, msg string, keysAndValues ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + keysAndValues = append(keysAndValues, traceID, tr) + } + t.InnerLogger.Warnw(msg, keysAndValues...) +} + +func (t *TracedLogger) Warnf(ctx context.Context, template string, args ...interface{}) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Warnw(fmt.Sprintf(template, args...), traceID, tr) + return + } + t.InnerLogger.Warnf(template, args...) +} + +func (t *TracedLogger) Warn(ctx context.Context, msg string) { + if tr := GetTraceID(ctx); tr != "" { + t.InnerLogger.Warnw(msg, traceID, tr) + return + } + t.InnerLogger.Warn(msg) +} + +func (t *TracedLogger) Named(name string) *TracedLogger { + return &TracedLogger{InnerLogger: t.InnerLogger.Named(name)} +} + +type Logger = *TracedLogger func NewLogger(level zapcore.Level) Logger { var zc zap.Config @@ -28,7 +134,7 @@ func NewLogger(level zapcore.Level) Logger { if err != nil { log.Fatal("cannot initialize zapr logger", err) } - return z.Sugar() + return &TracedLogger{InnerLogger: z.Sugar().WithOptions(zap.AddCallerSkip(1))} } var FallbackLogger = NewLogger(zap.DebugLevel) diff --git a/pkg/utils/gwlog/metadata.go b/pkg/utils/gwlog/metadata.go new file mode 100644 index 00000000..c35be8e7 --- /dev/null +++ b/pkg/utils/gwlog/metadata.go @@ -0,0 +1,83 @@ +package gwlog + +import ( + "context" + + "github.com/google/uuid" +) + +type key string + +const metadataKey key = "metadata_key" +const traceID string = "trace_id" + +type metadata struct { + m map[string]string +} + +func (mv *metadata) set(key, val string) { + mv.m[key] = val +} + +func newMetadata() *metadata { + return &metadata{ + m: make(map[string]string), + } +} + +func NewTrace(ctx context.Context) context.Context { + currID := uuid.New() + + newCtx := context.WithValue(ctx, metadataKey, newMetadata()) + AddMetadata(newCtx, traceID, currID.String()) + + return newCtx +} + +func AddMetadata(ctx context.Context, key, value string) { + if ctx.Value(metadataKey) != nil { + ctx.Value(metadataKey).(*metadata).set(key, value) + } +} + +func getMetadata(ctx context.Context) []interface{} { + var fields []interface{} + + if ctx.Value(metadataKey) != nil { + for k, v := range ctx.Value(metadataKey).(*metadata).m { + if k == traceID { + // skip since there's a separate method to grab the trace id + continue + } + fields = append(fields, k) + fields = append(fields, v) + } + } + return fields +} + +func GetTraceID(ctx context.Context) string { + if ctx.Value(metadataKey) != nil { + m := ctx.Value(metadataKey).(*metadata).m + if m == nil { + return "" + } + return ctx.Value(metadataKey).(*metadata).m[traceID] + } + return "" +} + +func StartReconcileTrace(ctx context.Context, log Logger, k8sresourcetype, name, namespace string) context.Context { + ctx = NewTrace(ctx) + AddMetadata(ctx, "type", k8sresourcetype) + AddMetadata(ctx, "name", name) + AddMetadata(ctx, "namespace", namespace) + + log.Infow(ctx, ReconcileStart, getMetadata(ctx)...) + + return ctx +} + +func EndReconcileTrace(ctx context.Context, log Logger) { + log.Infow(ctx, ReconcileEnd, getMetadata(ctx)...) +} diff --git a/pkg/utils/gwlog/metadata_test.go b/pkg/utils/gwlog/metadata_test.go new file mode 100644 index 00000000..91be7d3b --- /dev/null +++ b/pkg/utils/gwlog/metadata_test.go @@ -0,0 +1,32 @@ +package gwlog + +import ( + "context" + "fmt" + "testing" +) + +func TestGetTrace(t *testing.T) { + if GetTraceID(context.TODO()) != "" { + t.Errorf("expected context with no trace_id to return empty string") + } + + if GetTraceID(NewTrace(context.TODO())) == "" { + t.Errorf("expected context with trace_id to return non-empty string") + } +} + +func TestMetadata(t *testing.T) { + ctx := NewTrace(context.TODO()) + AddMetadata(ctx, "foo", "bar") + + md := getMetadata(ctx) + mdMap := map[string]bool{} + for _, m := range md { + mdMap[fmt.Sprint(m)] = true + } + + if !mdMap["foo"] || !mdMap["bar"] { + t.Errorf("expected context to have metadata with key foo and val bar, got %s", md) + } +} diff --git a/pkg/webhook/core/mutating_handler.go b/pkg/webhook/core/mutating_handler.go index c03cdc2a..778ad1cd 100644 --- a/pkg/webhook/core/mutating_handler.go +++ b/pkg/webhook/core/mutating_handler.go @@ -21,7 +21,7 @@ func (h *mutatingHandler) SetDecoder(d *admission.Decoder) { // Handle handles admission requests. func (h *mutatingHandler) Handle(ctx context.Context, req admission.Request) admission.Response { - h.log.Debugw("mutating webhook request", "operation", req.Operation, "name", req.Name, "namespace", req.Namespace) + h.log.Debugw(ctx, "mutating webhook request", "operation", req.Operation, "name", req.Name, "namespace", req.Namespace) var resp admission.Response switch req.Operation { case admissionv1.Create: @@ -31,7 +31,7 @@ func (h *mutatingHandler) Handle(ctx context.Context, req admission.Request) adm default: resp = admission.Allowed("") } - h.log.Debugw("mutating webhook response", "patches", resp.Patches) + h.log.Debugw(ctx, "mutating webhook response", "patches", resp.Patches) return resp } diff --git a/pkg/webhook/pod_readiness_gate_injector.go b/pkg/webhook/pod_readiness_gate_injector.go index 424109b7..98f5d2a9 100644 --- a/pkg/webhook/pod_readiness_gate_injector.go +++ b/pkg/webhook/pod_readiness_gate_injector.go @@ -34,7 +34,7 @@ type PodReadinessGateInjector struct { func (m *PodReadinessGateInjector) MutateCreate(ctx context.Context, pod *corev1.Pod) error { pct := corev1.PodConditionType(PodReadinessGateConditionType) - m.log.Debugf("Webhook invoked for pod %s/%s", pod.Namespace, getPodName(pod)) + m.log.Debugf(ctx, "Webhook invoked for pod %s/%s", pod.Namespace, getPodName(pod)) found := false for _, rg := range pod.Spec.ReadinessGates { @@ -68,7 +68,7 @@ func (m *PodReadinessGateInjector) requiresReadinessGate(ctx context.Context, po svcMatches := m.servicesForPod(pod, svcList) if len(svcMatches) == 0 { - m.log.Debugf("No services found for pod %s/%s", pod.Namespace, getPodName(pod)) + m.log.Debugf(ctx, "No services found for pod %s/%s", pod.Namespace, getPodName(pod)) return false, nil } @@ -77,7 +77,7 @@ func (m *PodReadinessGateInjector) requiresReadinessGate(ctx context.Context, po for _, route := range routes { if svc := m.isPodUsedByRoute(route, svcMatches); svc != nil { if m.routeHasLatticeGateway(ctx, route) { - m.log.Debugf("Pod %s/%s is used by service %s/%s and route %s/%s", pod.Namespace, getPodName(pod), + m.log.Debugf(ctx, "Pod %s/%s is used by service %s/%s and route %s/%s", pod.Namespace, getPodName(pod), svc.Namespace, svc.Name, route.Namespace(), route.Name()) return true, nil } @@ -91,12 +91,12 @@ func (m *PodReadinessGateInjector) requiresReadinessGate(ctx context.Context, po continue } - m.log.Debugf("Pod %s/%s is used by service %s/%s and service export %s/%s", pod.Namespace, getPodName(pod), + m.log.Debugf(ctx, "Pod %s/%s is used by service %s/%s and service export %s/%s", pod.Namespace, getPodName(pod), svc.Namespace, svc.Name, svcExport.Namespace, svcExport.Name) return true, nil } - m.log.Debugf("Pod %s/%s does not require a readiness gate", pod.Namespace, getPodName(pod)) + m.log.Debugf(ctx, "Pod %s/%s does not require a readiness gate", pod.Namespace, getPodName(pod)) return false, nil } @@ -106,7 +106,7 @@ func (m *PodReadinessGateInjector) listAllRoutes(ctx context.Context) []core.Rou httpRouteList := &gwv1beta1.HTTPRouteList{} err := m.k8sClient.List(ctx, httpRouteList) if err != nil { - m.log.Errorf("Error fetching beta1 HTTPRoutes: %s", err) + m.log.Errorf(ctx, "Error fetching beta1 HTTPRoutes: %s", err) } for _, k8sRoute := range httpRouteList.Items { routes = append(routes, core.NewHTTPRoute(k8sRoute)) @@ -115,7 +115,7 @@ func (m *PodReadinessGateInjector) listAllRoutes(ctx context.Context) []core.Rou grpcRouteList := &gwv1alpha2.GRPCRouteList{} err = m.k8sClient.List(ctx, grpcRouteList) if err != nil { - m.log.Errorf("Error fetching GRPCRoutes: %s", err) + m.log.Errorf(ctx, "Error fetching GRPCRoutes: %s", err) } for _, k8sRoute := range grpcRouteList.Items { routes = append(routes, core.NewGRPCRoute(k8sRoute)) @@ -140,7 +140,7 @@ func (m *PodReadinessGateInjector) servicesForPod(pod *corev1.Pod, svcList *core for _, svc := range svcList.Items { svcSelector := labels.SelectorFromSet(svc.Spec.Selector) if svcSelector.Matches(podLabels) { - m.log.Debugf("Found service %s/%s that matches pod %s/%s", + m.log.Debugf(context.TODO(), "Found service %s/%s that matches pod %s/%s", svc.Namespace, svc.Name, pod.Namespace, getPodName(pod)) svcMatches[svc.Name] = &svc @@ -164,7 +164,7 @@ func (m *PodReadinessGateInjector) isPodUsedByRoute(route core.Route, svcMap map isNamespaceEqual := svc != nil && namespace == svc.GetNamespace() if isGroupEqual && isKindEqual && isNameEqual && isNamespaceEqual { - m.log.Debugf("Found route %s/%s that matches service %s/%s", + m.log.Debugf(context.TODO(), "Found route %s/%s that matches service %s/%s", route.Namespace(), route.Name(), svc.Namespace, svc.Name) return svc @@ -176,7 +176,7 @@ func (m *PodReadinessGateInjector) isPodUsedByRoute(route core.Route, svcMap map func (m *PodReadinessGateInjector) routeHasLatticeGateway(ctx context.Context, route core.Route) bool { if len(route.Spec().ParentRefs()) == 0 { - m.log.Debugf("Route %s/%s has no parentRefs", route.Namespace(), route.Name()) + m.log.Debugf(ctx, "Route %s/%s has no parentRefs", route.Namespace(), route.Name()) return false } @@ -191,7 +191,7 @@ func (m *PodReadinessGateInjector) routeHasLatticeGateway(ctx context.Context, r } if err := m.k8sClient.Get(ctx, gwName, gw); err != nil { - m.log.Debugf("Unable to retrieve gateway %s/%s for route %s/%s, %s", + m.log.Debugf(ctx, "Unable to retrieve gateway %s/%s for route %s/%s, %s", gwName.Namespace, gwName.Name, route.Namespace(), route.Name(), err) return false } @@ -204,16 +204,16 @@ func (m *PodReadinessGateInjector) routeHasLatticeGateway(ctx context.Context, r } if err := m.k8sClient.Get(ctx, gwClassName, gwClass); err != nil { - m.log.Debugf("Unable to retrieve gateway class %s/%s for gateway %s/%s, %s", + m.log.Debugf(ctx, "Unable to retrieve gateway class %s/%s for gateway %s/%s, %s", gwClassName.Namespace, gwClass.Name, gwName.Namespace, gwName.Name, err) return false } if gwClass.Spec.ControllerName == config.LatticeGatewayControllerName { - m.log.Debugf("Gateway %s/%s is a lattice gateway", gwName.Namespace, gwName.Name) + m.log.Debugf(ctx, "Gateway %s/%s is a lattice gateway", gwName.Namespace, gwName.Name) return true } - m.log.Debugf("Gateway %s/%s is not a lattice gateway", gwName.Namespace, gwName.Name) + m.log.Debugf(ctx, "Gateway %s/%s is not a lattice gateway", gwName.Namespace, gwName.Name) return false } diff --git a/test/pkg/test/framework.go b/test/pkg/test/framework.go index fbe24b70..9b6721ea 100644 --- a/test/pkg/test/framework.go +++ b/test/pkg/test/framework.go @@ -149,7 +149,7 @@ func NewFramework(ctx context.Context, log gwlog.Logger, testNamespace string) * } func (env *Framework) ExpectToBeClean(ctx context.Context) { - env.Log.Info("Expecting the test environment to be clean") + env.Log.Info(ctx, "Expecting the test environment to be clean") // Kubernetes API Objects parallel.ForEach(TestObjects, func(testObject TestObject, _ int) { defer GinkgoRecover() @@ -159,14 +159,14 @@ func (env *Framework) ExpectToBeClean(ctx context.Context) { tags[model.K8SServiceNamespaceKey] = aws.String(K8sNamespace) Eventually(func(g Gomega) { arns, err := env.TaggingClient.FindResourcesByTags(ctx, services.ResourceTypeService, tags) - env.Log.Infow("Expecting no services created by the controller", "found", arns, "err", err) + env.Log.Infow(ctx, "Expecting no services created by the controller", "found", arns, "err", err) g.Expect(err).To(BeNil()) g.Expect(arns).To(BeEmpty()) }).Should(Succeed()) Eventually(func(g Gomega) { arns, err := env.TaggingClient.FindResourcesByTags(ctx, services.ResourceTypeTargetGroup, tags) - env.Log.Infow("Expecting no target groups created by the controller", "found", arns, "err", err) + env.Log.Infow(ctx, "Expecting no target groups created by the controller", "found", arns, "err", err) g.Expect(err).To(BeNil()) g.Expect(arns).To(BeEmpty()) }).Should(Succeed()) @@ -183,14 +183,14 @@ func objectsInfo(objs []client.Object) string { } func (env *Framework) ExpectCreated(ctx context.Context, objects ...client.Object) { - env.Log.Infof("Creating objects: %s", objectsInfo(objects)) + env.Log.Infof(ctx, "Creating objects: %s", objectsInfo(objects)) parallel.ForEach(objects, func(obj client.Object, _ int) { Expect(env.Create(ctx, obj)).WithOffset(1).To(Succeed()) }) } func (env *Framework) ExpectUpdated(ctx context.Context, objects ...client.Object) { - env.Log.Infof("Updating objects: %s", objectsInfo(objects)) + env.Log.Infof(ctx, "Updating objects: %s", objectsInfo(objects)) parallel.ForEach(objects, func(obj client.Object, _ int) { Expect(env.Update(ctx, obj)).WithOffset(1).To(Succeed()) }) @@ -216,7 +216,7 @@ func (env *Framework) ExpectDeleted(ctx context.Context, objects ...client.Objec } if len(routeObjects) > 0 { - env.Log.Infof("Found %d route objects", len(routeObjects)) + env.Log.Infof(ctx, "Found %d route objects", len(routeObjects)) for _, route := range routeObjects { // for routes, we can speed up deletion by first removing their rules @@ -231,28 +231,28 @@ func (env *Framework) ExpectDeleted(ctx context.Context, objects ...client.Objec http := &gwv1.HTTPRoute{} err := env.Get(ctx, nsName, http) if err != nil { - env.Log.Infof("Error getting http route %s", err) + env.Log.Infof(ctx, "Error getting http route %s", err) continue } - env.Log.Infof("Clearing http route rules for %s", http.Name) + env.Log.Infof(ctx, "Clearing http route rules for %s", http.Name) http.Spec.Rules = make([]gwv1.HTTPRouteRule, 0) err = env.Update(ctx, http) if err != nil { - env.Log.Infof("Error clearing http route rules %s", err) + env.Log.Infof(ctx, "Error clearing http route rules %s", err) } } else if grpcRouteType == t { grpc := &gwv1alpha2.GRPCRoute{} err := env.Get(ctx, nsName, grpc) if err != nil { - env.Log.Infof("Error getting grpc route %s", err) + env.Log.Infof(ctx, "Error getting grpc route %s", err) continue } - env.Log.Infof("Clearing grpc route rules for %s", grpc.Name) + env.Log.Infof(ctx, "Clearing grpc route rules for %s", grpc.Name) grpc.Spec.Rules = make([]gwv1alpha2.GRPCRouteRule, 0) err = env.Update(ctx, grpc) if err != nil { - env.Log.Infof("Error clearing grpc route rules %s", err) + env.Log.Infof(ctx, "Error clearing grpc route rules %s", err) } } } @@ -261,13 +261,13 @@ func (env *Framework) ExpectDeleted(ctx context.Context, objects ...client.Objec env.SleepForRouteUpdate() } - env.Log.Infof("Deleting objects: %s", objectsInfo(objects)) + env.Log.Infof(ctx, "Deleting objects: %s", objectsInfo(objects)) parallel.ForEach(objects, func(obj client.Object, _ int) { err := env.Delete(ctx, obj) if err != nil { // not found is probably OK - means it was deleted elsewhere if !errors.IsNotFound(err) { - env.Log.Error(err) + env.Log.Error(ctx, err.Error()) Expect(err).ToNot(HaveOccurred()) } } @@ -279,7 +279,7 @@ func (env *Framework) ExpectDeleteAllToSucceed(ctx context.Context, object clien } func (env *Framework) EventuallyExpectNotFound(ctx context.Context, objects ...client.Object) { - env.Log.Infof("Waiting for NotFound, objects: %s", objectsInfo(objects)) + env.Log.Infof(ctx, "Waiting for NotFound, objects: %s", objectsInfo(objects)) parallel.ForEach(objects, func(obj client.Object, _ int) { if obj != nil { Eventually(func(g Gomega) { @@ -366,7 +366,7 @@ func (env *Framework) GetTargetGroupWithProtocol(ctx context.Context, service *c Eventually(func(g Gomega) { tg, err := env.FindTargetGroupFromSpec(ctx, tgSpec) if err != nil { - gwlog.FallbackLogger.Infof("Error getting target group %s, %s due to %s", + gwlog.FallbackLogger.Infof(ctx, "Error getting target group %s, %s due to %s", tgSpec.K8SServiceName, tgSpec.K8SServiceNamespace, err) } g.Expect(err).To(BeNil()) @@ -376,7 +376,7 @@ func (env *Framework) GetTargetGroupWithProtocol(ctx context.Context, service *c found = tg }).WithOffset(1).Should(Succeed()) - gwlog.FallbackLogger.Infof("Found target group %s, %s", *found.Name, *found.Id) + gwlog.FallbackLogger.Infof(ctx, "Found target group %s, %s", *found.Name, *found.Id) return found } @@ -495,13 +495,13 @@ func (env *Framework) IsVpcAssociatedWithServiceNetwork(ctx context.Context, vpc } func (env *Framework) AreAllLatticeTargetsHealthy(ctx context.Context, tg *vpclattice.TargetGroupSummary) (bool, error) { - env.Log.Infof("Checking whether AreAllLatticeTargetsHealthy for targetGroup: %v", tg) + env.Log.Infof(ctx, "Checking whether AreAllLatticeTargetsHealthy for targetGroup: %v", tg) targets, err := env.LatticeClient.ListTargetsAsList(ctx, &vpclattice.ListTargetsInput{TargetGroupIdentifier: tg.Id}) if err != nil { return false, err } for _, target := range targets { - env.Log.Infof("Checking target: %v", target) + env.Log.Infof(ctx, "Checking target: %v", target) if *target.Status != vpclattice.TargetStatusHealthy { return false, nil } diff --git a/test/suites/integration/byoc_test.go b/test/suites/integration/byoc_test.go index d8ccf7a8..b08af4a7 100644 --- a/test/suites/integration/byoc_test.go +++ b/test/suites/integration/byoc_test.go @@ -39,9 +39,9 @@ var _ = Describe("Bring your own certificate (BYOC)", Ordered, func() { ) var ( - log = testFramework.Log.Named("byoc") - awsCfg = aws.NewConfig().WithRegion(config.Region) - sess, _ = session.NewSession(awsCfg) + log = testFramework.Log.Named("byoc") + awsCfg = aws.NewConfig().WithRegion(config.Region) + sess, _ = session.NewSession(awsCfg) acmClient = acm.New(sess, awsCfg) r53Client = route53.New(sess) @@ -59,11 +59,11 @@ var _ = Describe("Bring your own certificate (BYOC)", Ordered, func() { // create and deploy certificate to acm certArn, err = createCertIfNotExists(acmClient, certDnsName) Expect(err).To(BeNil()) - log.Infof("created certificate: %s", certArn) + log.Infof(ctx, "created certificate: %s", certArn) // add new certificate to gateway spec addGatewayBYOCListener(cname, certArn) - log.Infof("added listener with cert to gateway") + log.Infof(ctx, "added listener with cert to gateway") // create and deploy service for traffic test deployment, service = testFramework.NewHttpApp(test.HTTPAppOptions{ @@ -81,16 +81,16 @@ var _ = Describe("Bring your own certificate (BYOC)", Ordered, func() { // get lattice service dns name for route53 cname svc := testFramework.GetVpcLatticeService(context.TODO(), core.NewHTTPRoute(gwv1beta1.HTTPRoute(*httpRoute))) latticeSvcDns = *svc.DnsEntry.DomainName - log.Infof("depoloyed lattice service, dns name: %s", latticeSvcDns) + log.Infof(ctx, "depoloyed lattice service, dns name: %s", latticeSvcDns) // create route 53 hosted zone and cname hz, err := createHostedZoneIfNotExists(r53Client, hostedZoneName) Expect(err).To(BeNil()) hostedZoneId = *hz.Id - log.Infof("created route53 hosted zone, id: %s", hostedZoneId) + log.Infof(ctx, "created route53 hosted zone, id: %s", hostedZoneId) err = createCnameIfNotExists(r53Client, hostedZoneId, cname, latticeSvcDns) Expect(err).To(BeNil()) - log.Infof("created cname for lattice service, cname: %s, value: %s", cname, latticeSvcDns) + log.Infof(ctx, "created cname for lattice service, cname: %s, value: %s", cname, latticeSvcDns) }) It("same pod https traffic test", func() { @@ -99,7 +99,7 @@ var _ = Describe("Bring your own certificate (BYOC)", Ordered, func() { pod := pods[0] Eventually(func(g Gomega) { cmd := fmt.Sprintf("curl -v -k https://%s/", cname) - log.Infof("calling lattice service, cmd=%s, pod=%s/%s", cmd, pod.Namespace, pod.Name) + log.Infof(ctx, "calling lattice service, cmd=%s, pod=%s/%s", cmd, pod.Namespace, pod.Name) stdout, stderr, err := testFramework.PodExec(pod, cmd) g.Expect(err).To(BeNil()) g.Expect(stdout).To(ContainSubstring("byoc-app handler pod")) @@ -111,20 +111,20 @@ var _ = Describe("Bring your own certificate (BYOC)", Ordered, func() { log := log.Named("after-all") err = deleteHostedZoneRecords(r53Client, hostedZoneId) Expect(err).To(BeNil()) - log.Infof("deleted hosted zone records for, id: %s", hostedZoneId) + log.Infof(ctx, "deleted hosted zone records for, id: %s", hostedZoneId) err = deleteHostedZone(r53Client, hostedZoneId) Expect(err).To(BeNil()) - log.Infof("deleted route53 hosted zone, id: %s", hostedZoneId) + log.Infof(ctx, "deleted route53 hosted zone, id: %s", hostedZoneId) testFramework.ExpectDeletedThenNotFound(context.TODO(), httpRoute, service, deployment) removeGatewayBYOCListener() - log.Infof("removed listener with custom cert from gateway") + log.Infof(ctx, "removed listener with custom cert from gateway") err = deleteCert(acmClient, certArn) Expect(err).To(BeNil()) - log.Infof("removed custom cert from acm, arn: %s", certArn) + log.Infof(ctx, "removed custom cert from acm, arn: %s", certArn) }) }) diff --git a/test/suites/integration/httproute_update_test.go b/test/suites/integration/httproute_update_test.go index b75d0a29..33efb55b 100644 --- a/test/suites/integration/httproute_update_test.go +++ b/test/suites/integration/httproute_update_test.go @@ -79,7 +79,7 @@ var _ = Describe("HTTPRoute Update", func() { g.Expect(*tg2.Status).To(Equal(vpclattice.TargetGroupStatusActive)) }).WithPolling(15 * time.Second).WithTimeout(2 * time.Minute).Should(Succeed()) - gwlog.FallbackLogger.Infof("Found TG1 %s and TG2 %s", aws.StringValue(tg1.Id), aws.StringValue(tg2.Id)) + gwlog.FallbackLogger.Infof(ctx, "Found TG1 %s and TG2 %s", aws.StringValue(tg1.Id), aws.StringValue(tg2.Id)) Expect(aws.StringValue(tg1.Id) != aws.StringValue(tg2.Id)).To(BeTrue()) // deletion of one should not affect the other diff --git a/test/suites/integration/iamauthpolicy_test.go b/test/suites/integration/iamauthpolicy_test.go index d2fa5c09..96941761 100644 --- a/test/suites/integration/iamauthpolicy_test.go +++ b/test/suites/integration/iamauthpolicy_test.go @@ -165,16 +165,16 @@ var _ = Describe("IAM Auth Policy", Ordered, func() { annotationResId: snId, } testK8sPolicy(policy, wantResults) - log.Infof("policy accepted: %+v", wantResults) + log.Infof(ctx, "policy accepted: %+v", wantResults) // applied testLatticeSnPolicy(snId, vpclattice.AuthTypeAwsIam, policy.Spec.Policy) - log.Infof("policy applied for SN=%s", snId) + log.Infof(ctx, "policy applied for SN=%s", snId) // removed testFramework.ExpectDeletedThenNotFound(ctx, policy) testLatticeSnPolicy(snId, vpclattice.AuthTypeNone, NoPolicy) - log.Infof("policy removed from SN=%s", snId) + log.Infof(ctx, "policy removed from SN=%s", snId) }) It("accepted, applied, and removed from HTTPRoute", func() { @@ -189,16 +189,16 @@ var _ = Describe("IAM Auth Policy", Ordered, func() { annotationResId: svcId, } testK8sPolicy(policy, wantResults) - log.Infof("policy accepted: %+v", wantResults) + log.Infof(ctx, "policy accepted: %+v", wantResults) // applied testLatticeSvcPolicy(svcId, vpclattice.AuthTypeAwsIam, policy.Spec.Policy) - log.Infof("policy applied for Svc=%s", svcId) + log.Infof(ctx, "policy applied for Svc=%s", svcId) // removed testFramework.ExpectDeletedThenNotFound(ctx, policy) testLatticeSvcPolicy(svcId, vpclattice.AuthTypeNone, NoPolicy) - log.Infof("policy removed from Svc=%s", svcId) + log.Infof(ctx, "policy removed from Svc=%s", svcId) }) }) diff --git a/test/suites/integration/suite_test.go b/test/suites/integration/suite_test.go index a9f892a3..4a59138f 100644 --- a/test/suites/integration/suite_test.go +++ b/test/suites/integration/suite_test.go @@ -49,7 +49,7 @@ var _ = SynchronizedBeforeSuite(func() { testServiceNetwork = testFramework.GetServiceNetwork(ctx, testGateway) - testFramework.Log.Infof("Expecting VPC %s and service network %s association", vpcId, *testServiceNetwork.Id) + testFramework.Log.Infof(ctx, "Expecting VPC %s and service network %s association", vpcId, *testServiceNetwork.Id) Eventually(func(g Gomega) { associated, _, _ := testFramework.IsVpcAssociatedWithServiceNetwork(ctx, vpcId, testServiceNetwork) g.Expect(associated).To(BeTrue()) diff --git a/test/suites/webhook/suite_test.go b/test/suites/webhook/suite_test.go index 3f9007db..a869ccad 100644 --- a/test/suites/webhook/suite_test.go +++ b/test/suites/webhook/suite_test.go @@ -34,7 +34,7 @@ var _ = SynchronizedBeforeSuite(func() { testServiceNetwork = testFramework.GetServiceNetwork(ctx, testGateway) - testFramework.Log.Infof("Expecting VPC %s and service network %s association", vpcId, *testServiceNetwork.Id) + testFramework.Log.Infof(ctx, "Expecting VPC %s and service network %s association", vpcId, *testServiceNetwork.Id) Eventually(func(g Gomega) { associated, _, _ := testFramework.IsVpcAssociatedWithServiceNetwork(ctx, vpcId, testServiceNetwork) g.Expect(associated).To(BeTrue())