Merge pull request #1850 from panslava/debug-logs

Add more logs to L4 controllers

pkg/l4lb/l4controller.go

@@ -197,10 +197,17 @@ func (l4c *L4Controller) shouldProcessService(service *v1.Service) bool {
 
 // processServiceCreateOrUpdate ensures load balancer resources for the given service, as needed.
 // Returns an error if processing the service update failed.
-func (l4c *L4Controller) processServiceCreateOrUpdate(key string, service *v1.Service) *loadbalancers.L4ILBSyncResult {
+func (l4c *L4Controller) processServiceCreateOrUpdate(service *v1.Service) *loadbalancers.L4ILBSyncResult {
 	if !l4c.shouldProcessService(service) {
 		return nil
 	}
+
+	startTime := time.Now()
+	klog.Infof("Syncing L4 ILB service %s/%s", service.Namespace, service.Name)
+	defer func() {
+		klog.Infof("Finished syncing L4 ILB service %s/%s, time taken: %v", service.Namespace, service.Name, time.Since(startTime))
+	}()
+
 	// Ensure v2 finalizer
 	if err := common.EnsureServiceFinalizer(service, common.ILBFinalizerV2, l4c.ctx.KubeClient); err != nil {
 		return &loadbalancers.L4ILBSyncResult{Error: fmt.Errorf("Failed to attach finalizer to service %s/%s, err %w", service.Namespace, service.Name, err)}
@@ -277,6 +284,12 @@ func (l4c *L4Controller) emitEnsuredDualStackEvent(service *v1.Service) {
 }
 
 func (l4c *L4Controller) processServiceDeletion(key string, svc *v1.Service) *loadbalancers.L4ILBSyncResult {
+	startTime := time.Now()
+	klog.Infof("Deleting L4 ILB service %s/%s", svc.Namespace, svc.Name)
+	defer func() {
+		klog.Infof("Finished deleting L4 ILB service %s/%s, time taken: %v", svc.Namespace, svc.Name, time.Since(startTime))
+	}()
+
 	l4ilbParams := &loadbalancers.L4ILBParams{
 		Service:          svc,
 		Cloud:            l4c.ctx.Cloud,
@@ -367,7 +380,7 @@ func (l4c *L4Controller) sync(key string) error {
 	// longer needing an ILB.
 	if wantsILB, _ := annotations.WantsL4ILB(svc); wantsILB {
 		klog.V(2).Infof("Ensuring ILB resources for service %s managed by L4 controller", key)
-		result = l4c.processServiceCreateOrUpdate(key, svc)
+		result = l4c.processServiceCreateOrUpdate(svc)
 		if result == nil {
 			// result will be nil if the service was ignored(due to presence of service controller finalizer).
 			return nil

pkg/l4lb/l4netlbcontroller.go

@@ -426,6 +426,12 @@ func (lc *L4NetLBController) syncInternal(service *v1.Service) *loadbalancers.L4
 		return nil
 	}
 
+	startTime := time.Now()
+	klog.Infof("Syncing L4 NetLB RBS service %s/%s", service.Namespace, service.Name)
+	defer func() {
+		klog.Infof("Finished syncing L4 NetLB RBS service %s/%s, time taken: %v", service.Namespace, service.Name, time.Since(startTime))
+	}()
+
 	if err := common.EnsureServiceFinalizer(service, common.NetLBFinalizerV2, lc.ctx.KubeClient); err != nil {
 		return &loadbalancers.L4NetLBSyncResult{Error: fmt.Errorf("Failed to attach L4 External LoadBalancer finalizer to service %s/%s, err %w", service.Namespace, service.Name, err)}
 	}
@@ -519,6 +525,12 @@ func (lc *L4NetLBController) ensureInstanceGroups(service *v1.Service, nodeNames
 
 // garbageCollectRBSNetLB cleans-up all gce resources related to service and removes NetLB finalizer
 func (lc *L4NetLBController) garbageCollectRBSNetLB(key string, svc *v1.Service) *loadbalancers.L4NetLBSyncResult {
+	startTime := time.Now()
+	klog.Infof("Deleting L4 NetLB RBS service %s/%s", svc.Namespace, svc.Name)
+	defer func() {
+		klog.Infof("Finished deleting L4 NetLB service %s/%s, time taken: %v", svc.Namespace, svc.Name, time.Since(startTime))
+	}()
+
 	l4NetLBParams := &loadbalancers.L4NetLBParams{
 		Service:  svc,
 		Cloud:    lc.ctx.Cloud,

pkg/loadbalancers/forwarding_rules.go

@@ -194,13 +194,19 @@ func (l7 *L7) getEffectiveIP() (string, bool, error) {
 	return "", true, nil
 }
 
-// ensureForwardingRule creates a forwarding rule with the given name, if it does not exist. It updates the existing
+// ensureIPv4ForwardingRule creates a forwarding rule with the given name, if it does not exist. It updates the existing
 // forwarding rule if needed.
-func (l4 *L4) ensureForwardingRule(bsLink string, options gce.ILBOptions, existingFwdRule *composite.ForwardingRule, subnetworkURL, ipToUse string) (*composite.ForwardingRule, error) {
+func (l4 *L4) ensureIPv4ForwardingRule(bsLink string, options gce.ILBOptions, existingFwdRule *composite.ForwardingRule, subnetworkURL, ipToUse string) (*composite.ForwardingRule, error) {
 	// version used for creating the existing forwarding rule.
 	version := meta.VersionGA
 	frName := l4.GetFRName()
 
+	start := time.Now()
+	klog.V(2).Infof("Ensuring internal forwarding rule %s for L4 ILB Service %s/%s, backend service link: %s", frName, l4.Service.Namespace, l4.Service.Name, bsLink)
+	defer func() {
+		klog.V(2).Infof("Finished ensuring internal forwarding rule %s for L4 ILB Service %s/%s, time taken: %v", frName, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
 	servicePorts := l4.Service.Spec.Ports
 	ports := utils.GetPorts(servicePorts)
 	protocol := utils.GetProtocol(servicePorts)
@@ -238,19 +244,19 @@ func (l4 *L4) ensureForwardingRule(bsLink string, options gce.ILBOptions, existi
 		}
 		if equal {
 			// nothing to do
-			klog.V(2).Infof("ensureForwardingRule: Skipping update of unchanged forwarding rule - %s", fr.Name)
+			klog.V(2).Infof("ensureIPv4ForwardingRule: Skipping update of unchanged forwarding rule - %s", fr.Name)
 			return existingFwdRule, nil
 		}
 		frDiff := cmp.Diff(existingFwdRule, fr)
 		// If the forwarding rule pointed to a backend service which does not match the controller naming scheme,
 		// that resouce could be leaked. It is not being deleted here because that is a user-managed resource.
-		klog.V(2).Infof("ensureForwardingRule: forwarding rule changed - Existing - %+v\n, New - %+v\n, Diff(-existing, +new) - %s\n. Deleting existing forwarding rule.", existingFwdRule, fr, frDiff)
+		klog.V(2).Infof("ensureIPv4ForwardingRule: forwarding rule changed - Existing - %+v\n, New - %+v\n, Diff(-existing, +new) - %s\n. Deleting existing forwarding rule.", existingFwdRule, fr, frDiff)
 		if err = l4.forwardingRules.Delete(existingFwdRule.Name); err != nil {
 			return nil, err
 		}
 		l4.recorder.Eventf(l4.Service, corev1.EventTypeNormal, events.SyncIngress, "ForwardingRule %q deleted", existingFwdRule.Name)
 	}
-	klog.V(2).Infof("ensureForwardingRule: Creating/Recreating forwarding rule - %s", fr.Name)
+	klog.V(2).Infof("ensureIPv4ForwardingRule: Creating/Recreating forwarding rule - %s", fr.Name)
 	if err = l4.forwardingRules.Create(fr); err != nil {
 		return nil, err
 	}
@@ -271,9 +277,9 @@ func (l4netlb *L4NetLB) ensureExternalForwardingRule(bsLink string) (*composite.
 	frName := l4netlb.GetFRName()
 
 	start := time.Now()
-	klog.V(2).Infof("Ensuring external forwarding rule %s, backend service link: %s", frName, bsLink)
+	klog.V(2).Infof("Ensuring external forwarding rule %s for L4 NetLB Service %s/%s, backend service link: %s", l4netlb.Service.Namespace, l4netlb.Service.Name, frName, bsLink)
 	defer func() {
-		klog.V(2).Infof("Finished ensuring external forwarding rule %s, time taken: %v", frName, time.Since(start))
+		klog.V(2).Infof("Finished ensuring external forwarding rule %s for L4 NetLB Service %s/%s, time taken: %v", l4netlb.Service.Namespace, l4netlb.Service.Name, frName, time.Since(start))
 	}()
 
 	// version used for creating the existing forwarding rule.

pkg/loadbalancers/forwarding_rules_ipv6.go

@@ -18,6 +18,7 @@ package loadbalancers
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/GoogleCloudPlatform/k8s-cloud-provider/pkg/cloud"
 	"github.com/google/go-cmp/cmp"
@@ -36,6 +37,12 @@ func (l4 *L4) ensureIPv6ForwardingRule(bsLink string, options gce.ILBOptions) (*
 		return nil, fmt.Errorf("l4.buildExpectedIPv6ForwardingRule(%s, %v) returned error %w, want nil", bsLink, options, err)
 	}
 
+	start := time.Now()
+	klog.V(2).Infof("Ensuring internal ipv6 forwarding rule %s for L4 ILB Service %s/%s, backend service link: %s", expectedIPv6FwdRule.Name, l4.Service.Namespace, l4.Service.Name, bsLink)
+	defer func() {
+		klog.V(2).Infof("Finished ensuring internal ipv6 forwarding rule %s for L4 ILB Service %s/%s, time taken: %v", expectedIPv6FwdRule.Name, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
 	existingIPv6FwdRule, err := l4.forwardingRules.Get(expectedIPv6FwdRule.Name)
 	if err != nil {
 		return nil, fmt.Errorf("l4.forwardingRules.GetForwardingRule(%s) returned error %w, want nil", expectedIPv6FwdRule.Name, err)

pkg/loadbalancers/l4.go

@@ -115,7 +115,7 @@ func (l4 *L4) getILBOptions() gce.ILBOptions {
 
 // EnsureInternalLoadBalancerDeleted performs a cleanup of all GCE resources for the given loadbalancer service.
 func (l4 *L4) EnsureInternalLoadBalancerDeleted(svc *corev1.Service) *L4ILBSyncResult {
-	klog.V(2).Infof("EnsureInternalLoadBalancerDeleted(%s): attempting delete of load balancer resources", l4.NamespacedName.String())
+	klog.V(2).Infof("EnsureInternalLoadBalancerDeleted(%s): deleting L4 ILB LoadBalancer resources", l4.NamespacedName.String())
 	result := &L4ILBSyncResult{SyncType: SyncTypeDelete, StartTime: time.Now()}
 
 	l4.deleteIPv4ResourcesOnDelete(result)
@@ -163,6 +163,7 @@ func (l4 *L4) EnsureInternalLoadBalancerDeleted(svc *corev1.Service) *L4ILBSyncR
 // If annotation was deleted, but resource still exists, it will be left till the Service deletion,
 // where we delete all resources, no matter if they exist in annotations.
 func (l4 *L4) deleteIPv4ResourcesOnSync(result *L4ILBSyncResult) {
+	klog.Infof("Deleting IPv4 resources for L4 ILB Service %s/%s on sync, with checking for existence in annotation", l4.Service.Namespace, l4.Service.Name)
 	l4.deleteIPv4ResourcesAnnotationBased(result, false)
 }
 
@@ -172,6 +173,7 @@ func (l4 *L4) deleteIPv4ResourcesOnSync(result *L4ILBSyncResult) {
 // so they could be leaked, if annotation was deleted.
 // That's why on service deletion we delete all IPv4 resources, ignoring their existence in annotations
 func (l4 *L4) deleteIPv4ResourcesOnDelete(result *L4ILBSyncResult) {
+	klog.Infof("Deleting IPv4 resources for L4 ILB Service %s/%s on delete, without checking for existence in annotation", l4.Service.Namespace, l4.Service.Name)
 	l4.deleteIPv4ResourcesAnnotationBased(result, true)
 }
 
@@ -184,9 +186,8 @@ func (l4 *L4) deleteIPv4ResourcesOnDelete(result *L4ILBSyncResult) {
 // This function does not delete Backend Service and Health Check, because they are shared between IPv4 and IPv6.
 // IPv4 Firewall Rule for Health Check also will not be deleted here, and will be left till the Service Deletion.
 func (l4 *L4) deleteIPv4ResourcesAnnotationBased(result *L4ILBSyncResult, shouldIgnoreAnnotations bool) {
-	frName := l4.GetFRName()
 	if shouldIgnoreAnnotations || l4.hasAnnotation(annotations.TCPForwardingRuleKey) || l4.hasAnnotation(annotations.UDPForwardingRuleKey) {
-		err := l4.forwardingRules.Delete(frName)
+		err := l4.deleteIPv4ForwardingRule()
 		if err != nil {
 			klog.Errorf("Failed to delete forwarding rule for internal loadbalancer service %s, err %v", l4.NamespacedName.String(), err)
 			result.Error = err
@@ -196,7 +197,7 @@ func (l4 *L4) deleteIPv4ResourcesAnnotationBased(result *L4ILBSyncResult, should
 
 	// Deleting non-existent address do not print error audit logs, and we don't store address in annotations
 	// that's why we can delete it without checking annotation
-	err := ensureAddressDeleted(l4.cloud, frName, l4.cloud.Region())
+	err := l4.deleteIPv4Address()
 	if err != nil {
 		klog.Errorf("Failed to delete address for internal loadbalancer service %s, err %v", l4.NamespacedName.String(), err)
 		result.Error = err
@@ -205,16 +206,51 @@ func (l4 *L4) deleteIPv4ResourcesAnnotationBased(result *L4ILBSyncResult, should
 
 	// delete firewall rule allowing load balancer source ranges
 	if shouldIgnoreAnnotations || l4.hasAnnotation(annotations.FirewallRuleKey) {
-		firewallName := l4.namer.L4Firewall(l4.Service.Namespace, l4.Service.Name)
-		err = l4.deleteFirewall(firewallName)
+		err := l4.deleteIPv4NodesFirewall()
 		if err != nil {
-			klog.Errorf("Failed to delete firewall rule %s for internal loadbalancer service %s, err %v", firewallName, l4.NamespacedName.String(), err)
+			klog.Errorf("Failed to delete firewall rule for internal loadbalancer service %s, err %v", l4.NamespacedName.String(), err)
 			result.GCEResourceInError = annotations.FirewallRuleResource
 			result.Error = err
 		}
 	}
 }
 
+func (l4 *L4) deleteIPv4ForwardingRule() error {
+	frName := l4.GetFRName()
+
+	start := time.Now()
+	klog.Infof("Deleting IPv4 forwarding rule %s for L4 ILB Service %s/%s", frName, l4.Service.Namespace, l4.Service.Name)
+	defer func() {
+		klog.Infof("Finished deleting IPv4 forwarding rule %s for L4 ILB Service %s/%s, time taken: %v", frName, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
+	return l4.forwardingRules.Delete(frName)
+}
+
+func (l4 *L4) deleteIPv4Address() error {
+	addressName := l4.GetFRName()
+
+	start := time.Now()
+	klog.Infof("Deleting IPv4 address %s for L4 ILB Service %s/%s", addressName, l4.Service.Namespace, l4.Service.Name)
+	defer func() {
+		klog.Infof("Finished deleting IPv4 address %s for L4 ILB Service %s/%s, time taken: %v", addressName, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
+	return ensureAddressDeleted(l4.cloud, addressName, l4.cloud.Region())
+}
+
+func (l4 *L4) deleteIPv4NodesFirewall() error {
+	firewallName := l4.namer.L4Firewall(l4.Service.Namespace, l4.Service.Name)
+
+	start := time.Now()
+	klog.Infof("Deleting IPv4 nodes firewall %s for L4 ILB Service %s/%s", firewallName, l4.Service.Namespace, l4.Service.Name)
+	defer func() {
+		klog.Infof("Finished deleting IPv4 nodes firewall %s for L4 ILB Service %s/%s, time taken: %v", firewallName, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
+	return l4.deleteFirewall(firewallName)
+}
+
 func (l4 *L4) deleteFirewall(name string) error {
 	err := firewalls.EnsureL4FirewallRuleDeleted(l4.cloud, name)
 	if err != nil {
@@ -352,9 +388,8 @@ func (l4 *L4) EnsureInternalLoadBalancer(nodeNames []string, svc *corev1.Service
 func (l4 *L4) provideHealthChecks(nodeNames []string, result *L4ILBSyncResult) string {
 	if l4.enableDualStack {
 		return l4.provideDualStackHealthChecks(nodeNames, result)
-	} else {
-		return l4.provideIPv4HealthChecks(nodeNames, result)
 	}
+	return l4.provideIPv4HealthChecks(nodeNames, result)
 }
 
 func (l4 *L4) provideDualStackHealthChecks(nodeNames []string, result *L4ILBSyncResult) string {
@@ -406,9 +441,9 @@ func (l4 *L4) ensureDualStackResources(result *L4ILBSyncResult, nodeNames []stri
 // - IPv4 Forwarding Rule
 // - IPv4 Firewall
 func (l4 *L4) ensureIPv4Resources(result *L4ILBSyncResult, nodeNames []string, options gce.ILBOptions, bs *composite.BackendService, existingFR *composite.ForwardingRule, subnetworkURL, ipToUse string) {
-	fr, err := l4.ensureForwardingRule(bs.SelfLink, options, existingFR, subnetworkURL, ipToUse)
+	fr, err := l4.ensureIPv4ForwardingRule(bs.SelfLink, options, existingFR, subnetworkURL, ipToUse)
 	if err != nil {
-		klog.Errorf("EnsureInternalLoadBalancer: Failed to create forwarding rule - %v", err)
+		klog.Errorf("ensureIPv4Resources: Failed to ensure forwarding rule for L4 ILB Service %s/%s, error: %v", l4.Service.Namespace, l4.Service.Name, err)
 		result.GCEResourceInError = annotations.ForwardingRuleResource
 		result.Error = err
 		return
@@ -419,36 +454,52 @@ func (l4 *L4) ensureIPv4Resources(result *L4ILBSyncResult, nodeNames []string, o
 		result.Annotations[annotations.UDPForwardingRuleKey] = fr.Name
 	}
 
-	// ensure firewalls
-	sourceRanges, err := helpers.GetLoadBalancerSourceRanges(l4.Service)
-	if err != nil {
-		result.Error = err
+	l4.ensureIPv4NodesFirewall(nodeNames, fr.IPAddress, result)
+	if result.Error != nil {
+		klog.Errorf("ensureIPv4Resources: Failed to ensure nodes firewall for L4 ILB Service %s/%s, error: %v", l4.Service.Namespace, l4.Service.Name, err)
 		return
 	}
 
+	result.Status = utils.AddIPToLBStatus(result.Status, fr.IPAddress)
+}
+
+func (l4 *L4) ensureIPv4NodesFirewall(nodeNames []string, ipAddress string, result *L4ILBSyncResult) {
+	start := time.Now()
+
 	firewallName := l4.namer.L4Firewall(l4.Service.Namespace, l4.Service.Name)
 	servicePorts := l4.Service.Spec.Ports
 	protocol := utils.GetProtocol(servicePorts)
 	portRanges := utils.GetServicePortRanges(servicePorts)
+
+	klog.V(2).Infof("Ensuring IPv4 nodes firewall %s for L4 ILB Service %s/%s, ipAddress: %s, protocol: %s, len(nodeNames): %v, portRanges: %v", firewallName, l4.Service.Namespace, l4.Service.Name, ipAddress, protocol, len(nodeNames), portRanges)
+	defer func() {
+		klog.V(2).Infof("Finished ensuring IPv4 nodes firewall %s for L4 ILB Service %s/%s, time taken: %v", firewallName, l4.Service.Namespace, l4.Service.Name, time.Since(start))
+	}()
+
+	// ensure firewalls
+	sourceRanges, err := helpers.GetLoadBalancerSourceRanges(l4.Service)
+	if err != nil {
+		result.Error = err
+		return
+	}
 	// Add firewall rule for ILB traffic to nodes
 	nodesFWRParams := firewalls.FirewallParams{
 		PortRanges:        portRanges,
 		SourceRanges:      sourceRanges.StringSlice(),
-		DestinationRanges: []string{fr.IPAddress},
+		DestinationRanges: []string{ipAddress},
 		Protocol:          string(protocol),
 		Name:              firewallName,
 		NodeNames:         nodeNames,
 		L4Type:            utils.ILB,
 	}
 
-	if err := firewalls.EnsureL4LBFirewallForNodes(l4.Service, &nodesFWRParams, l4.cloud, l4.recorder); err != nil {
+	err = firewalls.EnsureL4LBFirewallForNodes(l4.Service, &nodesFWRParams, l4.cloud, l4.recorder)
+	if err != nil {
 		result.GCEResourceInError = annotations.FirewallRuleResource
 		result.Error = err
 		return
 	}
 	result.Annotations[annotations.FirewallRuleKey] = firewallName
-
-	result.Status = utils.AddIPToLBStatus(result.Status, fr.IPAddress)
 }
 
 func (l4 *L4) getServiceSubnetworkURL(options gce.ILBOptions) (string, error) {