Merge pull request #1845 from panslava/debug-logs

Add more logs to L4 NetLB

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"
@@ -283,7 +284,13 @@ 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, version meta.Version) (*composite.BackendService, error) {
+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 func() {
+		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 {
@@ -300,11 +307,11 @@ func (b *Backends) EnsureL4BackendService(name, hcLink, protocol, sessionAffinit
 	}
 	expectedBS := &composite.BackendService{
 		Name:                name,
-		Protocol:            string(protocol),
+		Protocol:            protocol,
 		Description:         desc,
 		HealthChecks:        []string{hcLink},
 		SessionAffinity:     utils.TranslateAffinityType(sessionAffinity),
-		LoadBalancingScheme: string(scheme),
+		LoadBalancingScheme: scheme,
 	}
 	if protocol == string(api_v1.ProtocolTCP) {
 		expectedBS.ConnectionDraining = &composite.ConnectionDraining{DrainingTimeoutSec: DefaultConnectionDrainingTimeoutSeconds}
@@ -328,6 +335,7 @@ func (b *Backends) EnsureL4BackendService(name, hcLink, protocol, sessionAffinit
 	}
 
 	if backendSvcEqual(expectedBS, bs) {
+		klog.V(2).Infof("EnsureL4BackendService: backend service %s did not change, skipping update", name)
 		return bs, nil
 	}
 	if bs.ConnectionDraining != nil && bs.ConnectionDraining.DrainingTimeoutSec > 0 && protocol == string(api_v1.ProtocolTCP) {

pkg/backends/regional_ig_linker_test.go

@@ -18,7 +18,6 @@ import (
 	"testing"
 
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud"
-	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/meta"
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/mock"
 	apiv1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/types"
@@ -139,7 +138,7 @@ func createBackendService(t *testing.T, sp utils.ServicePort, backendPool *Backe
 	t.Helper()
 	namespacedName := types.NamespacedName{Name: "service.Name", Namespace: "service.Namespace"}
 	protocol := string(apiv1.ProtocolTCP)
-	if _, err := backendPool.EnsureL4BackendService(sp.BackendName(), hcLink, protocol, string(apiv1.ServiceAffinityNone), string(cloud.SchemeExternal), namespacedName, meta.VersionGA); err != nil {
+	if _, err := backendPool.EnsureL4BackendService(sp.BackendName(), hcLink, protocol, string(apiv1.ServiceAffinityNone), string(cloud.SchemeExternal), namespacedName); err != nil {
 		t.Fatalf("Error creating backend service %v", err)
 	}
 }

pkg/healthchecksl4/healthchecksl4.go

@@ -20,6 +20,7 @@ import (
 	"fmt"
 	"strconv"
 	"sync"
+	"time"
 
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud/meta"
 	corev1 "k8s.io/api/core/v1"
@@ -46,8 +47,6 @@ const (
 	gceSharedHcUnhealthyThreshold = int64(3) // 3  * 8 = 24 seconds before the LB will steer traffic away
 	gceLocalHcUnhealthyThreshold  = int64(2) // 2  * 3 = 6 seconds before the LB will steer traffic away
 	L4ILBIPv6HCRange              = "2600:2d00:1:b029::/64"
-	shouldHandleIPV6              = true
-	shouldHandleIPV4              = true
 )
 
 var (
@@ -120,18 +119,19 @@ func (l4hc *l4HealthChecks) EnsureHealthCheckWithDualStackFirewalls(svc *corev1.
 
 	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, sharedHC)
 	hcPath, hcPort := helpers.GetServiceHealthCheckPathPort(svc)
-	klog.V(3).Infof("Ensuring L4 healthcheck: %s for service %s, shared: %v.", hcName, namespacedName.String(), sharedHC)
+	klog.V(3).Infof("Ensuring L4 healthcheck %s with firewalls for service %s, shared: %v.", hcName, namespacedName.String(), sharedHC)
 
 	if sharedHC {
 		hcPath, hcPort = gce.GetNodesHealthCheckPath(), gce.GetNodesHealthCheckPort()
 		// We need to acquire a controller-wide mutex to ensure that in the case of a healthcheck shared between loadbalancers that the sync of the GCE resources is not performed in parallel.
 		l4hc.sharedResourcesLock.Lock()
 		defer l4hc.sharedResourcesLock.Unlock()
 	}
-	klog.V(3).Infof("L4 Healthcheck %s, path: %q, port %d", hcName, hcPath, hcPort)
+	klog.V(3).Infof("L4 Healthcheck %s, expected path: %q, expected port %d", hcName, hcPath, hcPort)
 
 	hcLink, err := l4hc.ensureHealthCheck(hcName, namespacedName, sharedHC, hcPath, hcPort, scope, l4Type)
 	if err != nil {
+		klog.Errorf("Error while ensuring hc %s, error: %v", hcName, err)
 		return &EnsureHealthCheckResult{
 			GceResourceInError: annotations.HealthcheckResource,
 			Err:                err,
@@ -144,35 +144,25 @@ func (l4hc *l4HealthChecks) EnsureHealthCheckWithDualStackFirewalls(svc *corev1.
 	}
 
 	if needsIPv4 {
-		hcFwName := namer.L4HealthCheckFirewall(svc.Namespace, svc.Name, sharedHC)
-		klog.V(3).Infof("Ensuring IPv4 firewall rule %s for health check %s for service %s", hcFwName, hcName, namespacedName.String())
-		err = l4hc.ensureIPv4Firewall(svc, hcFwName, hcPort, sharedHC, nodeNames)
-		if err != nil {
-			return &EnsureHealthCheckResult{
-				GceResourceInError: annotations.FirewallForHealthcheckResource,
-				Err:                err,
-			}
-		}
-		hcResult.HCFirewallRuleName = hcFwName
+		klog.V(3).Infof("Ensuring IPv4 firewall rule for health check %s for service %s", hcName, namespacedName.String())
+		l4hc.ensureIPv4Firewall(svc, namer, hcPort, sharedHC, nodeNames, hcResult)
 	}
 
 	if needsIPv6 {
-		ipv6HCFWName := namer.L4IPv6HealthCheckFirewall(svc.Namespace, svc.Name, sharedHC)
-		klog.V(3).Infof("Ensuring IPv6 firewall rule %s for health check %s for service %s", ipv6HCFWName, hcName, namespacedName.String())
-		err = l4hc.ensureIPv6Firewall(svc, ipv6HCFWName, hcPort, sharedHC, nodeNames)
-		if err != nil {
-			return &EnsureHealthCheckResult{
-				GceResourceInError: annotations.FirewallForHealthcheckIPv6Resource,
-				Err:                err,
-			}
-		}
-		hcResult.HCFirewallRuleIPv6Name = ipv6HCFWName
+		klog.V(3).Infof("Ensuring IPv6 firewall rule for health check %s for service %s", hcName, namespacedName.String())
+		l4hc.ensureIPv6Firewall(svc, namer, hcPort, sharedHC, nodeNames, hcResult)
 	}
 
 	return hcResult
 }
 
 func (l4hc *l4HealthChecks) ensureHealthCheck(hcName string, svcName types.NamespacedName, shared bool, path string, port int32, scope meta.KeyType, l4Type utils.L4LBType) (string, error) {
+	start := time.Now()
+	klog.V(2).Infof("Ensuring healthcheck %s for service %s, shared = %v, path = %s, port = %d, scope = %s, l4Type = %s", hcName, svcName, shared, path, port, scope, l4Type)
+	defer func() {
+		klog.V(2).Infof("Finished ensuring healthcheck %s for service %s, time taken: %v", hcName, svcName, time.Since(start))
+	}()
+
 	hc, err := l4hc.hcProvider.Get(hcName, scope)
 	if err != nil {
 		return "", err
@@ -200,7 +190,7 @@ func (l4hc *l4HealthChecks) ensureHealthCheck(hcName string, svcName types.Names
 	selfLink := hc.SelfLink
 	if !needToUpdateHealthChecks(hc, expectedHC) {
 		// nothing to do
-		klog.V(3).Infof("Healthcheck %v already exists", hcName)
+		klog.V(3).Infof("Healthcheck %s already exists and does not require update", hcName)
 		return selfLink, nil
 	}
 	mergeHealthChecks(hc, expectedHC)
@@ -216,26 +206,56 @@ func (l4hc *l4HealthChecks) ensureHealthCheck(hcName string, svcName types.Names
 //
 // L4 ILB and L4 NetLB Services with ExternalTrafficPolicy=Cluster use the same firewall
 // rule at global scope.
-func (l4hc *l4HealthChecks) ensureIPv4Firewall(svc *corev1.Service, hcFwName string, hcPort int32, sharedHC bool, nodeNames []string) error {
+func (l4hc *l4HealthChecks) ensureIPv4Firewall(svc *corev1.Service, namer namer.L4ResourcesNamer, hcPort int32, isSharedHC bool, nodeNames []string, hcResult *EnsureHealthCheckResult) {
+	hcFwName := namer.L4HealthCheckFirewall(svc.Namespace, svc.Name, isSharedHC)
+
+	start := time.Now()
+	klog.V(2).Infof("Ensuring IPv4 Firewall %s for health check for service %s/%s, health check port %s, shared health check: %t, len(nodeNames): %d", hcFwName, svc.Namespace, svc.Name, hcPort, isSharedHC, len(nodeNames))
+	defer func() {
+		klog.V(2).Infof("Finished ensuring IPv4 firewall %s for service %s/%s, time taken %v", hcFwName, svc.Namespace, svc.Name, time.Since(start))
+	}()
+
 	hcFWRParams := firewalls.FirewallParams{
 		PortRanges:   []string{strconv.Itoa(int(hcPort))},
 		SourceRanges: gce.L4LoadBalancerSrcRanges(),
 		Protocol:     string(corev1.ProtocolTCP),
 		Name:         hcFwName,
 		NodeNames:    nodeNames,
 	}
-	return firewalls.EnsureL4LBFirewallForHc(svc, sharedHC, &hcFWRParams, l4hc.cloud, l4hc.recorder)
+	err := firewalls.EnsureL4LBFirewallForHc(svc, isSharedHC, &hcFWRParams, l4hc.cloud, l4hc.recorder)
+	if err != nil {
+		klog.Errorf("Error ensuring IPv4 Firewall %s for health check for service %s/%s, error %v", hcFwName, svc.Namespace, svc.Name, err)
+		hcResult.GceResourceInError = annotations.FirewallForHealthcheckResource
+		hcResult.Err = err
+		return
+	}
+	hcResult.HCFirewallRuleName = hcFwName
 }
 
-func (l4hc *l4HealthChecks) ensureIPv6Firewall(svc *corev1.Service, ipv6HCFWName string, hcPort int32, isSharedHC bool, nodeNames []string) error {
+func (l4hc *l4HealthChecks) ensureIPv6Firewall(svc *corev1.Service, namer namer.L4ResourcesNamer, hcPort int32, isSharedHC bool, nodeNames []string, hcResult *EnsureHealthCheckResult) {
+	ipv6HCFWName := namer.L4IPv6HealthCheckFirewall(svc.Namespace, svc.Name, isSharedHC)
+
+	start := time.Now()
+	klog.V(2).Infof("Ensuring IPv6 Firewall %s for health check for service %s/%s, health check port %s, shared health check: %t, len(nodeNames): %d", ipv6HCFWName, svc.Namespace, svc.Name, hcPort, isSharedHC, len(nodeNames))
+	defer func() {
+		klog.V(2).Infof("Finished ensuring IPv6 firewall %s for service %s/%s, time taken %v", ipv6HCFWName, svc.Namespace, svc.Name, time.Since(start))
+	}()
+
 	hcFWRParams := firewalls.FirewallParams{
 		PortRanges:   []string{strconv.Itoa(int(hcPort))},
 		SourceRanges: []string{L4ILBIPv6HCRange},
 		Protocol:     string(corev1.ProtocolTCP),
 		Name:         ipv6HCFWName,
 		NodeNames:    nodeNames,
 	}
-	return firewalls.EnsureL4LBFirewallForHc(svc, isSharedHC, &hcFWRParams, l4hc.cloud, l4hc.recorder)
+	err := firewalls.EnsureL4LBFirewallForHc(svc, isSharedHC, &hcFWRParams, l4hc.cloud, l4hc.recorder)
+	if err != nil {
+		klog.Errorf("Error ensuring IPv6 Firewall %s for health check for service %s/%s, error %v", ipv6HCFWName, svc.Namespace, svc.Name, err)
+		hcResult.GceResourceInError = annotations.FirewallForHealthcheckIPv6Resource
+		hcResult.Err = err
+		return
+	}
+	hcResult.HCFirewallRuleIPv6Name = ipv6HCFWName
 }
 
 func (l4hc *l4HealthChecks) DeleteHealthCheckWithFirewall(svc *corev1.Service, namer namer.L4ResourcesNamer, sharedHC bool, scope meta.KeyType, l4Type utils.L4LBType) (string, error) {
@@ -282,7 +302,13 @@ func (l4hc *l4HealthChecks) deleteHealthCheckWithDualStackFirewalls(svc *corev1.
 
 func (l4hc *l4HealthChecks) deleteHealthCheck(svc *corev1.Service, namer namer.L4ResourcesNamer, sharedHC bool, scope meta.KeyType) (bool, error) {
 	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, sharedHC)
+
+	start := time.Now()
 	klog.V(3).Infof("Deleting L4 healthcheck %s for service %s/%s, shared: %v, scope: %v", hcName, svc.Namespace, svc.Name, sharedHC, scope)
+	defer func() {
+		klog.V(3).Infof("Finished deleting L4 healthcheck %s for service %s/%s, time taken: %v", hcName, svc.Namespace, svc.Name, time.Since(start))
+	}()
+
 	err := l4hc.hcProvider.Delete(hcName, scope)
 	if err != nil {
 		// Ignore deletion error due to health check in use by another resource.
@@ -296,20 +322,30 @@ func (l4hc *l4HealthChecks) deleteHealthCheck(svc *corev1.Service, namer namer.L
 	return true, nil
 }
 
-func (l4hc *l4HealthChecks) deleteIPv4HealthCheckFirewall(svc *corev1.Service, namer namer.L4ResourcesNamer, sharedHC bool, l4type utils.L4LBType) (string, error) {
-	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, sharedHC)
-	hcFwName := namer.L4HealthCheckFirewall(svc.Namespace, svc.Name, sharedHC)
+func (l4hc *l4HealthChecks) deleteIPv4HealthCheckFirewall(svc *corev1.Service, namer namer.L4ResourcesNamer, isSharedHC bool, l4type utils.L4LBType) (string, error) {
+	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, isSharedHC)
+	hcFwName := namer.L4HealthCheckFirewall(svc.Namespace, svc.Name, isSharedHC)
 
+	start := time.Now()
 	klog.V(3).Infof("Deleting IPv4 Firewall %s for health check %s", hcFwName, hcName)
-	return l4hc.deleteHealthCheckFirewall(svc, hcName, hcFwName, sharedHC, l4type)
+	defer func() {
+		klog.V(3).Infof("Finished deleting IPv4 Firewall %s for health check %s, time taken: %v", hcFwName, hcName, time.Since(start))
+	}()
+
+	return l4hc.deleteHealthCheckFirewall(svc, hcName, hcFwName, isSharedHC, l4type)
 }
 
-func (l4hc *l4HealthChecks) deleteIPv6HealthCheckFirewall(svc *corev1.Service, namer namer.L4ResourcesNamer, sharedHC bool, l4type utils.L4LBType) (string, error) {
-	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, sharedHC)
-	ipv6hcFwName := namer.L4IPv6HealthCheckFirewall(svc.Namespace, svc.Name, sharedHC)
+func (l4hc *l4HealthChecks) deleteIPv6HealthCheckFirewall(svc *corev1.Service, namer namer.L4ResourcesNamer, isSharedHC bool, l4type utils.L4LBType) (string, error) {
+	hcName := namer.L4HealthCheck(svc.Namespace, svc.Name, isSharedHC)
+	ipv6hcFwName := namer.L4IPv6HealthCheckFirewall(svc.Namespace, svc.Name, isSharedHC)
 
+	start := time.Now()
 	klog.V(3).Infof("Deleting IPv6 Firewall %s for health check %s", ipv6hcFwName, hcName)
-	return l4hc.deleteHealthCheckFirewall(svc, hcName, ipv6hcFwName, sharedHC, l4type)
+	defer func() {
+		klog.V(3).Infof("Finished deleting IPv6 Firewall %s for health check %s, time taken: %v", ipv6hcFwName, hcName, time.Since(start))
+	}()
+
+	return l4hc.deleteHealthCheckFirewall(svc, hcName, ipv6hcFwName, isSharedHC, l4type)
 }
 
 func (l4hc *l4HealthChecks) deleteHealthCheckFirewall(svc *corev1.Service, hcName, hcFwName string, sharedHC bool, l4Type utils.L4LBType) (string, error) {

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,12 @@ 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 func() {
+		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 +504,12 @@ 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 func() {
+		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 {