Add more logs to l4netlb

pkg/backends/backends.go

@@ -16,6 +16,7 @@ package backends
 import (
 	"fmt"
 	"net/http"
+	"time"
 
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/meta"
 	"google.golang.org/api/compute/v1"
@@ -284,6 +285,10 @@ func (b *Backends) DeleteSignedUrlKey(be *composite.BackendService, keyName stri
 
 // EnsureL4BackendService creates or updates the backend service with the given name.
 func (b *Backends) EnsureL4BackendService(name, hcLink, protocol, sessionAffinity, scheme string, nm types.NamespacedName) (*composite.BackendService, error) {
+	start := time.Now()
+	klog.V(2).Infof("EnsureL4BackendService(%v, %v, %v): started", name, scheme, protocol)
+	defer klog.V(2).Infof("EnsureL4BackendService(%v, %v, %v): finished, time taken: %v", name, scheme, protocol, time.Since(start))
+
 	klog.V(2).Infof("EnsureL4BackendService(%v, %v, %v): checking existing backend service", name, scheme, protocol)
 	key, err := composite.CreateKey(b.cloud, name, meta.Regional)
 	if err != nil {

pkg/instances/instances.go

@@ -98,6 +98,7 @@ func (i *Instances) EnsureInstanceGroupsAndPorts(name string, ports []int64) (ig
 }
 
 func (i *Instances) ensureInstanceGroupAndPorts(name, zone string, ports []int64) (*compute.InstanceGroup, error) {
+	klog.V(3).Infof("Ensuring instance group %s in zone %s. Ports: %v", name, zone, ports)
 	ig, err := i.Get(name, zone)
 	if err != nil && !utils.IsHTTPErrorCode(err, http.StatusNotFound) {
 		klog.Errorf("Failed to get instance group %v/%v, err: %v", zone, name, err)

pkg/l4lb/l4lbcommon.go

@@ -65,8 +65,10 @@ func mergeAnnotations(existing, lbAnnotations map[string]string, keysToRemove []
 
 // updateL4ResourcesAnnotations this function checks if new annotations should be added to service and patch service metadata if needed.
 func updateL4ResourcesAnnotations(ctx *context.ControllerContext, svc *v1.Service, newL4LBAnnotations map[string]string) error {
+	klog.V(3).Infof("Updating annotations of service %s/%s", svc.Namespace, svc.Name)
 	newObjectMeta := computeNewAnnotationsIfNeeded(svc, newL4LBAnnotations, loadbalancers.L4LBResourceAnnotationKeys)
 	if newObjectMeta == nil {
+		klog.V(3).Infof("Service annotations not changed, skipping patch for service %s/%s", svc.Namespace, svc.Name)
 		return nil
 	}
 	klog.V(3).Infof("Patching annotations of service %v/%v", svc.Namespace, svc.Name)
@@ -106,7 +108,9 @@ func deleteAnnotation(ctx *context.ControllerContext, svc *v1.Service, annotatio
 
 // updateServiceStatus this faction checks if LoadBalancer status changed and patch service if needed.
 func updateServiceStatus(ctx *context.ControllerContext, svc *v1.Service, newStatus *v1.LoadBalancerStatus) error {
+	klog.V(2).Infof("Updating service status, service: %s/%s, new status: %+v", svc.Namespace, svc.Name, newStatus)
 	if helpers.LoadBalancerStatusEqual(&svc.Status.LoadBalancer, newStatus) {
+		klog.V(2).Infof("New and old statuses are equal, skipping patch. Service: %s/%s", svc.Namespace, svc.Name)
 		return nil
 	}
 	return patch.PatchServiceLoadBalancerStatus(ctx.KubeClient.CoreV1(), svc, *newStatus)

pkg/l4lb/l4netlbcontroller.go

@@ -19,6 +19,7 @@ package l4lb
 import (
 	"fmt"
 	"reflect"
+	"time"
 
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud"
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/meta"
@@ -106,6 +107,7 @@ func NewL4NetLBController(
 			svcKey := utils.ServiceKeyFunc(curSvc.Namespace, curSvc.Name)
 			if l4netLBc.shouldProcessService(curSvc, oldSvc) {
 				klog.V(3).Infof("L4 External LoadBalancer Service %s updated, enqueuing", svcKey)
+				l4netLBc.ctx.Recorder(curSvc.Namespace).Eventf(curSvc, v1.EventTypeNormal, "UPDATE", svcKey)
 				l4netLBc.svcQueue.Enqueue(curSvc)
 				l4netLBc.enqueueTracker.Track()
 				return
@@ -213,7 +215,7 @@ func (lc *L4NetLBController) needsUpdate(newSvc, oldSvc *v1.Service) bool {
 	return false
 }
 
-// shouldProcessUpdate checks if given service should be process by controller
+// shouldProcessService checks if given service should be process by controller
 func (lc *L4NetLBController) shouldProcessService(newSvc, oldSvc *v1.Service) bool {
 	if !lc.isRBSBasedService(newSvc) {
 		return false
@@ -260,7 +262,7 @@ func (lc *L4NetLBController) preventLegacyServiceHandling(service *v1.Service, k
 		if utils.HasL4NetLBFinalizerV2(service) {
 			// If we found that RBS finalizer was attached to service, it means that RBS controller
 			// had a race condition on Service creation with Legacy Controller.
-			// It should only happen during service creation and we should clean up RBS resources
+			// It should only happen during service creation, and we should clean up RBS resources
 			return true, lc.preventTargetPoolRaceWithRBSOnCreation(service, key)
 		} else {
 			// Target Pool to RBS migration is NOT yet supported and causes service to break (for now).
@@ -369,7 +371,7 @@ func (lc *L4NetLBController) sync(key string) error {
 	lc.syncTracker.Track()
 	svc, exists, err := lc.ctx.Services().GetByKey(key)
 	if err != nil {
-		return fmt.Errorf("Failed to lookup L4 External LoadBalancer service for key %s : %w", key, err)
+		return fmt.Errorf("failed to lookup L4 External LoadBalancer service for key %s : %w", key, err)
 	}
 	if !exists || svc == nil {
 		klog.V(3).Infof("Ignoring sync of non-existent service %s", key)
@@ -476,6 +478,10 @@ func (lc *L4NetLBController) syncInternal(service *v1.Service) *loadbalancers.L4
 }
 
 func (lc *L4NetLBController) ensureBackendLinking(service *v1.Service) error {
+	start := time.Now()
+	klog.V(2).Infof("Linking backend service with instance groups for service %s/%s", service.Namespace, service.Name)
+	defer klog.V(2).Infof("Finished linking backend service with instance groups for service %s/%s, time taken: %v", service.Namespace, service.Name, time.Since(start))
+
 	zones, err := lc.translator.ListZones(utils.CandidateNodesPredicate)
 	if err != nil {
 		return err
@@ -496,6 +502,10 @@ func (lc *L4NetLBController) ensureBackendLinking(service *v1.Service) error {
 func (lc *L4NetLBController) ensureInstanceGroups(service *v1.Service, nodeNames []string) error {
 	// TODO(kl52752) Move instance creation and deletion logic to NodeController
 	// to avoid race condition between controllers
+	start := time.Now()
+	klog.V(2).Infof("Ensuring instance groups for L4 NetLB Service %s/%s, len(nodeNames): %v", service.Namespace, service.Name, len(nodeNames))
+	defer klog.V(2).Infof("Finished ensuring instance groups for L4 NetLB Service %s/%s, time taken: %v", service.Namespace, service.Name, time.Since(start))
+
 	nodePorts := utils.GetNodePorts(service.Spec.Ports)
 	_, err := lc.instancePool.EnsureInstanceGroupsAndPorts(lc.ctx.ClusterNamer.InstanceGroup(), nodePorts)
 	if err != nil {

pkg/loadbalancers/forwarding_rules.go

@@ -269,6 +269,11 @@ func (l4 *L4) ensureForwardingRule(bsLink string, options gce.ILBOptions, existi
 // if it does not exist. It updates the existing forwarding rule if needed.
 func (l4netlb *L4NetLB) ensureExternalForwardingRule(bsLink string) (*composite.ForwardingRule, IPAddressType, error) {
 	frName := l4netlb.GetFRName()
+
+	start := time.Now()
+	klog.V(2).Infof("Ensuring external forwarding rule %s, backend service link: %s", frName, bsLink)
+	defer klog.V(2).Infof("Finished ensuring external forwarding rule %s, time taken: %v", frName, time.Since(start))
+
 	// version used for creating the existing forwarding rule.
 	version := meta.VersionGA
 	existingFwdRule, err := l4netlb.forwardingRules.Get(frName)

pkg/loadbalancers/l4netlb.go

@@ -120,6 +120,7 @@ func (l4netlb *L4NetLB) EnsureFrontend(nodeNames []string, svc *corev1.Service)
 	if len(svc.Status.LoadBalancer.Ingress) > 0 {
 		result.SyncType = SyncTypeUpdate
 	}
+	klog.V(3).Infof("EnsureFrontend started for service %s/%s, len(nodeNames) = %d, SyncType: %s", svc.Namespace, svc.Name, len(nodeNames), result.SyncType)
 
 	l4netlb.Service = svc
 
@@ -164,7 +165,7 @@ func (l4netlb *L4NetLB) EnsureFrontend(nodeNames []string, svc *corev1.Service)
 
 	firewallName := l4netlb.namer.L4Firewall(l4netlb.Service.Namespace, l4netlb.Service.Name)
 	portRanges := utils.GetServicePortRanges(servicePorts)
-	res := l4netlb.createFirewalls(firewallName, nodeNames, fr.IPAddress, portRanges, string(protocol))
+	res := l4netlb.ensureNodesFirewall(firewallName, nodeNames, fr.IPAddress, portRanges, string(protocol))
 	if res.Error != nil {
 		return res
 	}
@@ -267,7 +268,11 @@ func (l4netlb *L4NetLB) GetFRName() string {
 	return utils.LegacyForwardingRuleName(l4netlb.Service)
 }
 
-func (l4netlb *L4NetLB) createFirewalls(name string, nodeNames []string, ipAddress string, portRanges []string, protocol string) *L4NetLBSyncResult {
+func (l4netlb *L4NetLB) ensureNodesFirewall(name string, nodeNames []string, ipAddress string, portRanges []string, protocol string) *L4NetLBSyncResult {
+	start := time.Now()
+	klog.V(2).Infof("Ensuring l4 NetLB nodes firewall %s, ipAddress: %s, protocol: %s, len(nodeNames): %v, portRanges: %v", name, ipAddress, protocol, len(nodeNames), portRanges)
+	defer klog.V(2).Infof("Finished ensuring l4 NetLB nodes firewall %s, time taken: %v", name, time.Since(start))
+
 	result := &L4NetLBSyncResult{}
 	sourceRanges, err := helpers.GetLoadBalancerSourceRanges(l4netlb.Service)
 	if err != nil {