Merge pull request #45540 from edevil/azure_extra_logging

Automatic merge from submit-queue (batch tested with PRs 49083, 45540, 46862) Add extra logging to azure API get calls **What this PR does / why we need it**: This PR adds extra logging for external calls to the Azure API, specifically get calls. **Which issue this PR fixes** *(optional, in `fixes #<issue number>(, fixes #<issue_number>, ...)` format, will close that issue when PR gets merged)*: fixes # This will help troubleshoot problems arising from the usage of this cloudprovider. For example, it looks like #43516 is caused by a call to the cloudprovider taking too much time.
2025-09-16 06:32:32 +00:00 · 2017-07-19 21:18:25 -07:00
parent 5a3cc4fab6 4071a36c12
commit ea18935670
7 changed files with 79 additions and 0 deletions
--- a/pkg/cloudprovider/providers/azure/azure_backoff.go
+++ b/pkg/cloudprovider/providers/azure/azure_backoff.go
@@ -79,9 +79,11 @@ func (az *Cloud) GetIPForMachineWithRetry(name types.NodeName) (string, error) {
 func (az *Cloud) CreateOrUpdateSGWithRetry(sg network.SecurityGroup) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%s): start", *sg.Name)
 		respChan, errChan := az.SecurityGroupsClient.CreateOrUpdate(az.ResourceGroup, *sg.Name, sg, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%s): end", *sg.Name)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -90,9 +92,11 @@ func (az *Cloud) CreateOrUpdateSGWithRetry(sg network.SecurityGroup) error {
 func (az *Cloud) CreateOrUpdateLBWithRetry(lb network.LoadBalancer) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%s): start", *lb.Name)
 		respChan, errChan := az.LoadBalancerClient.CreateOrUpdate(az.ResourceGroup, *lb.Name, lb, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%s): end", *lb.Name)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -101,9 +105,11 @@ func (az *Cloud) CreateOrUpdateLBWithRetry(lb network.LoadBalancer) error {
 func (az *Cloud) CreateOrUpdatePIPWithRetry(pip network.PublicIPAddress) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("PublicIPAddressesClient.CreateOrUpdate(%s): start", *pip.Name)
 		respChan, errChan := az.PublicIPAddressesClient.CreateOrUpdate(az.ResourceGroup, *pip.Name, pip, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("PublicIPAddressesClient.CreateOrUpdate(%s): end", *pip.Name)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -112,9 +118,11 @@ func (az *Cloud) CreateOrUpdatePIPWithRetry(pip network.PublicIPAddress) error {
 func (az *Cloud) CreateOrUpdateInterfaceWithRetry(nic network.Interface) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("InterfacesClient.CreateOrUpdate(%s): start", *nic.Name)
 		respChan, errChan := az.InterfacesClient.CreateOrUpdate(az.ResourceGroup, *nic.Name, nic, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("InterfacesClient.CreateOrUpdate(%s): end", *nic.Name)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -123,9 +131,11 @@ func (az *Cloud) CreateOrUpdateInterfaceWithRetry(nic network.Interface) error {
 func (az *Cloud) DeletePublicIPWithRetry(pipName string) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("PublicIPAddressesClient.Delete(%s): start", pipName)
 		respChan, errChan := az.PublicIPAddressesClient.Delete(az.ResourceGroup, pipName, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("PublicIPAddressesClient.Delete(%s): end", pipName)
 		return processRetryResponse(resp, err)
 	})
 }
@@ -134,9 +144,11 @@ func (az *Cloud) DeletePublicIPWithRetry(pipName string) error {
 func (az *Cloud) DeleteLBWithRetry(lbName string) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("LoadBalancerClient.Delete(%s): start", lbName)
 		respChan, errChan := az.LoadBalancerClient.Delete(az.ResourceGroup, lbName, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("LoadBalancerClient.Delete(%s): end", lbName)
 		return processRetryResponse(resp, err)
 	})
 }
@@ -145,9 +157,11 @@ func (az *Cloud) DeleteLBWithRetry(lbName string) error {
 func (az *Cloud) CreateOrUpdateRouteTableWithRetry(routeTable network.RouteTable) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("RouteTablesClient.CreateOrUpdate(%s): start", routeTable)
 		respChan, errChan := az.RouteTablesClient.CreateOrUpdate(az.ResourceGroup, az.RouteTableName, routeTable, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("RouteTablesClient.CreateOrUpdate(%s): end", routeTable)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -156,9 +170,11 @@ func (az *Cloud) CreateOrUpdateRouteTableWithRetry(routeTable network.RouteTable
 func (az *Cloud) CreateOrUpdateRouteWithRetry(route network.Route) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("RoutesClient.CreateOrUpdate(%s): start", *route.Name)
 		respChan, errChan := az.RoutesClient.CreateOrUpdate(az.ResourceGroup, az.RouteTableName, *route.Name, route, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("RoutesClient.CreateOrUpdate(%s): end", *route.Name)
 		return processRetryResponse(resp.Response, err)
 	})
 }
@@ -167,9 +183,11 @@ func (az *Cloud) CreateOrUpdateRouteWithRetry(route network.Route) error {
 func (az *Cloud) DeleteRouteWithRetry(routeName string) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("RoutesClient.Delete(%s): start", az.RouteTableName)
 		respChan, errChan := az.RoutesClient.Delete(az.ResourceGroup, az.RouteTableName, routeName, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("RoutesClient.Delete(%s): end", az.RouteTableName)
 		return processRetryResponse(resp, err)
 	})
 }
@@ -178,9 +196,11 @@ func (az *Cloud) DeleteRouteWithRetry(routeName string) error {
 func (az *Cloud) CreateOrUpdateVMWithRetry(vmName string, newVM compute.VirtualMachine) error {
 	return wait.ExponentialBackoff(az.resourceRequestBackoff, func() (bool, error) {
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("VirtualMachinesClient.CreateOrUpdate(%s): start", vmName)
 		respChan, errChan := az.VirtualMachinesClient.CreateOrUpdate(az.ResourceGroup, vmName, newVM, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("VirtualMachinesClient.CreateOrUpdate(%s): end", vmName)
 		return processRetryResponse(resp.Response, err)
 	})
 }
--- a/pkg/cloudprovider/providers/azure/azure_instances.go
+++ b/pkg/cloudprovider/providers/azure/azure_instances.go
@@ -145,7 +145,9 @@ func (az *Cloud) listAllNodesInResourceGroup() ([]compute.VirtualMachine, error)
 	allNodes := []compute.VirtualMachine{}

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("VirtualMachinesClient.List(%s): start", az.ResourceGroup)
 	result, err := az.VirtualMachinesClient.List(az.ResourceGroup)
+	glog.V(10).Infof("VirtualMachinesClient.List(%s): end", az.ResourceGroup)
 	if err != nil {
 		glog.Errorf("error: az.listAllNodesInResourceGroup(), az.VirtualMachinesClient.List(%s), err=%v", az.ResourceGroup, err)
 		return nil, err
@@ -157,7 +159,9 @@ func (az *Cloud) listAllNodesInResourceGroup() ([]compute.VirtualMachine, error)
 		allNodes = append(allNodes, *result.Value...)

 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("VirtualMachinesClient.ListAllNextResults(%v): start", az.ResourceGroup)
 		result, err = az.VirtualMachinesClient.ListAllNextResults(result)
+		glog.V(10).Infof("VirtualMachinesClient.ListAllNextResults(%v): end", az.ResourceGroup)
 		if err != nil {
 			glog.Errorf("error: az.listAllNodesInResourceGroup(), az.VirtualMachinesClient.ListAllNextResults(%v), err=%v", result, err)
 			return nil, err
--- a/pkg/cloudprovider/providers/azure/azure_loadbalancer.go
+++ b/pkg/cloudprovider/providers/azure/azure_loadbalancer.go
@@ -93,7 +93,9 @@ func (az *Cloud) determinePublicIPName(clusterName string, service *v1.Service)
 	}

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("PublicIPAddressesClient.List(%v): start", az.ResourceGroup)
 	list, err := az.PublicIPAddressesClient.List(az.ResourceGroup)
+	glog.V(10).Infof("PublicIPAddressesClient.List(%v): end", az.ResourceGroup)
 	if err != nil {
 		return "", err
 	}
@@ -129,7 +131,9 @@ func (az *Cloud) EnsureLoadBalancer(clusterName string, service *v1.Service, nod
 	glog.V(5).Infof("ensure(%s): START clusterName=%q lbName=%q", serviceName, clusterName, lbName)

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("SecurityGroupsClient.Get(%q): start", az.SecurityGroupName)
 	sg, err := az.SecurityGroupsClient.Get(az.ResourceGroup, az.SecurityGroupName, "")
+	glog.V(10).Infof("SecurityGroupsClient.Get(%q): end", az.SecurityGroupName)
 	if err != nil {
 		return nil, err
 	}
@@ -144,9 +148,11 @@ func (az *Cloud) EnsureLoadBalancer(clusterName string, service *v1.Service, nod
 		sg.SecurityGroupPropertiesFormat.NetworkInterfaces = nil
 		sg.SecurityGroupPropertiesFormat.Subnets = nil
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%q): start", *sg.Name)
 		respChan, errChan := az.SecurityGroupsClient.CreateOrUpdate(az.ResourceGroup, *sg.Name, sg, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%q): end", *sg.Name)
 		if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 			glog.V(2).Infof("ensure(%s) backing off: sg(%s) - updating", serviceName, *sg.Name)
 			retryErr := az.CreateOrUpdateSGWithRetry(sg)
@@ -225,9 +231,11 @@ func (az *Cloud) EnsureLoadBalancer(clusterName string, service *v1.Service, nod
 	if !existsLb || lbNeedsUpdate {
 		glog.V(3).Infof("ensure(%s): lb(%s) - updating", serviceName, lbName)
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%q): start", *lb.Name)
 		respChan, errChan := az.LoadBalancerClient.CreateOrUpdate(az.ResourceGroup, *lb.Name, lb, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%q): end", *lb.Name)
 		if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 			glog.V(2).Infof("ensure(%s) backing off: lb(%s) - updating", serviceName, lbName)
 			retryErr := az.CreateOrUpdateLBWithRetry(lb)
@@ -320,9 +328,11 @@ func (az *Cloud) EnsureLoadBalancerDeleted(clusterName string, service *v1.Servi
 			sg.SecurityGroupPropertiesFormat.NetworkInterfaces = nil
 			sg.SecurityGroupPropertiesFormat.Subnets = nil
 			az.operationPollRateLimiter.Accept()
+			glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%q): start", *reconciledSg.Name)
 			respChan, errChan := az.SecurityGroupsClient.CreateOrUpdate(az.ResourceGroup, *reconciledSg.Name, reconciledSg, nil)
 			resp := <-respChan
 			err := <-errChan
+			glog.V(10).Infof("SecurityGroupsClient.CreateOrUpdate(%q): end", *reconciledSg.Name)
 			if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 				glog.V(2).Infof("delete(%s) backing off: sg(%s) - updating", serviceName, az.SecurityGroupName)
 				retryErr := az.CreateOrUpdateSGWithRetry(reconciledSg)
@@ -376,9 +386,11 @@ func (az *Cloud) cleanupLoadBalancer(clusterName string, service *v1.Service, is
 			if len(*lb.FrontendIPConfigurations) > 0 {
 				glog.V(3).Infof("delete(%s): lb(%s) - updating", serviceName, lbName)
 				az.operationPollRateLimiter.Accept()
+				glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%q): start", *lb.Name)
 				respChan, errChan := az.LoadBalancerClient.CreateOrUpdate(az.ResourceGroup, *lb.Name, lb, nil)
 				resp := <-respChan
 				err := <-errChan
+				glog.V(10).Infof("LoadBalancerClient.CreateOrUpdate(%q): end", *lb.Name)
 				if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 					glog.V(2).Infof("delete(%s) backing off: sg(%s) - updating", serviceName, az.SecurityGroupName)
 					retryErr := az.CreateOrUpdateLBWithRetry(lb)
@@ -394,9 +406,11 @@ func (az *Cloud) cleanupLoadBalancer(clusterName string, service *v1.Service, is
 				glog.V(3).Infof("delete(%s): lb(%s) - deleting; no remaining frontendipconfigs", serviceName, lbName)

 				az.operationPollRateLimiter.Accept()
+				glog.V(10).Infof("LoadBalancerClient.Delete(%q): start", lbName)
 				respChan, errChan := az.LoadBalancerClient.Delete(az.ResourceGroup, lbName, nil)
 				resp := <-respChan
 				err := <-errChan
+				glog.V(10).Infof("LoadBalancerClient.Delete(%q): end", lbName)
 				if az.CloudProviderBackoff && shouldRetryAPIRequest(resp, err) {
 					glog.V(2).Infof("delete(%s) backing off: lb(%s) - deleting; no remaining frontendipconfigs", serviceName, lbName)
 					retryErr := az.DeleteLBWithRetry(lbName)
@@ -451,9 +465,11 @@ func (az *Cloud) ensurePublicIPExists(serviceName, pipName string) (*network.Pub

 	glog.V(3).Infof("ensure(%s): pip(%s) - creating", serviceName, *pip.Name)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("PublicIPAddressesClient.CreateOrUpdate(%q): start", *pip.Name)
 	respChan, errChan := az.PublicIPAddressesClient.CreateOrUpdate(az.ResourceGroup, *pip.Name, pip, nil)
 	resp := <-respChan
 	err = <-errChan
+	glog.V(10).Infof("PublicIPAddressesClient.CreateOrUpdate(%q): end", *pip.Name)
 	if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 		glog.V(2).Infof("ensure(%s) backing off: pip(%s) - creating", serviceName, *pip.Name)
 		retryErr := az.CreateOrUpdatePIPWithRetry(pip)
@@ -467,7 +483,9 @@ func (az *Cloud) ensurePublicIPExists(serviceName, pipName string) (*network.Pub
 	}

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("PublicIPAddressesClient.Get(%q): start", *pip.Name)
 	pip, err = az.PublicIPAddressesClient.Get(az.ResourceGroup, *pip.Name, "")
+	glog.V(10).Infof("PublicIPAddressesClient.Get(%q): end", *pip.Name)
 	if err != nil {
 		return nil, err
 	}
@@ -479,8 +497,10 @@ func (az *Cloud) ensurePublicIPExists(serviceName, pipName string) (*network.Pub
 func (az *Cloud) ensurePublicIPDeleted(serviceName, pipName string) error {
 	glog.V(2).Infof("ensure(%s): pip(%s) - deleting", serviceName, pipName)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("PublicIPAddressesClient.Delete(%q): start", pipName)
 	resp, deleteErrChan := az.PublicIPAddressesClient.Delete(az.ResourceGroup, pipName, nil)
 	deleteErr := <-deleteErrChan
+	glog.V(10).Infof("PublicIPAddressesClient.Delete(%q): end", pipName) // response not read yet...
 	if az.CloudProviderBackoff && shouldRetryAPIRequest(<-resp, deleteErr) {
 		glog.V(2).Infof("ensure(%s) backing off: pip(%s) - deleting", serviceName, pipName)
 		retryErr := az.DeletePublicIPWithRetry(pipName)
@@ -875,7 +895,9 @@ func (az *Cloud) ensureHostInPool(serviceName string, nodeName types.NodeName, b
 	var machine compute.VirtualMachine
 	vmName := mapNodeNameToVMName(nodeName)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("VirtualMachinesClient.Get(%q): start", vmName)
 	machine, err := az.VirtualMachinesClient.Get(az.ResourceGroup, vmName, "")
+	glog.V(10).Infof("VirtualMachinesClient.Get(%q): end", vmName)
 	if err != nil {
 		if az.CloudProviderBackoff {
 			glog.V(2).Infof("ensureHostInPool(%s, %s, %s) backing off", serviceName, nodeName, backendPoolID)
@@ -910,7 +932,9 @@ func (az *Cloud) ensureHostInPool(serviceName string, nodeName types.NodeName, b
 	}

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("InterfacesClient.Get(%q): start", nicName)
 	nic, err := az.InterfacesClient.Get(az.ResourceGroup, nicName, "")
+	glog.V(10).Infof("InterfacesClient.Get(%q): end", nicName)
 	if err != nil {
 		return err
 	}
@@ -942,9 +966,11 @@ func (az *Cloud) ensureHostInPool(serviceName string, nodeName types.NodeName, b

 		glog.V(3).Infof("nicupdate(%s): nic(%s) - updating", serviceName, nicName)
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("InterfacesClient.CreateOrUpdate(%q): start", *nic.Name)
 		respChan, errChan := az.InterfacesClient.CreateOrUpdate(az.ResourceGroup, *nic.Name, nic, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("InterfacesClient.CreateOrUpdate(%q): end", *nic.Name)
 		if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 			glog.V(2).Infof("nicupdate(%s) backing off: nic(%s) - updating, err=%v", serviceName, nicName, err)
 			retryErr := az.CreateOrUpdateInterfaceWithRetry(nic)
--- a/pkg/cloudprovider/providers/azure/azure_routes.go
+++ b/pkg/cloudprovider/providers/azure/azure_routes.go
@@ -78,9 +78,11 @@ func (az *Cloud) CreateRoute(clusterName string, nameHint string, kubeRoute *clo

 		glog.V(3).Infof("create: creating routetable. routeTableName=%q", az.RouteTableName)
 		az.operationPollRateLimiter.Accept()
+		glog.V(10).Infof("RouteTablesClient.CreateOrUpdate(%q): start", az.RouteTableName)
 		respChan, errChan := az.RouteTablesClient.CreateOrUpdate(az.ResourceGroup, az.RouteTableName, routeTable, nil)
 		resp := <-respChan
 		err := <-errChan
+		glog.V(10).Infof("RouteTablesClient.CreateOrUpdate(%q): end", az.RouteTableName)
 		if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 			glog.V(2).Infof("create backing off: creating routetable. routeTableName=%q", az.RouteTableName)
 			retryErr := az.CreateOrUpdateRouteTableWithRetry(routeTable)
@@ -93,7 +95,9 @@ func (az *Cloud) CreateRoute(clusterName string, nameHint string, kubeRoute *clo
 			return err
 		}

+		glog.V(10).Infof("RouteTablesClient.Get(%q): start", az.RouteTableName)
 		routeTable, err = az.RouteTablesClient.Get(az.ResourceGroup, az.RouteTableName, "")
+		glog.V(10).Infof("RouteTablesClient.Get(%q): end", az.RouteTableName)
 		if err != nil {
 			return err
 		}
@@ -116,9 +120,11 @@ func (az *Cloud) CreateRoute(clusterName string, nameHint string, kubeRoute *clo

 	glog.V(3).Infof("create: creating route: instance=%q cidr=%q", kubeRoute.TargetNode, kubeRoute.DestinationCIDR)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("RoutesClient.CreateOrUpdate(%q): start", az.RouteTableName)
 	respChan, errChan := az.RoutesClient.CreateOrUpdate(az.ResourceGroup, az.RouteTableName, *route.Name, route, nil)
 	resp := <-respChan
 	err = <-errChan
+	glog.V(10).Infof("RoutesClient.CreateOrUpdate(%q): end", az.RouteTableName)
 	if az.CloudProviderBackoff && shouldRetryAPIRequest(resp.Response, err) {
 		glog.V(2).Infof("create backing off: creating route: instance=%q cidr=%q", kubeRoute.TargetNode, kubeRoute.DestinationCIDR)
 		retryErr := az.CreateOrUpdateRouteWithRetry(route)
@@ -142,9 +148,11 @@ func (az *Cloud) DeleteRoute(clusterName string, kubeRoute *cloudprovider.Route)

 	routeName := mapNodeNameToRouteName(kubeRoute.TargetNode)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("RoutesClient.Delete(%q): start", az.RouteTableName)
 	respChan, errChan := az.RoutesClient.Delete(az.ResourceGroup, az.RouteTableName, routeName, nil)
 	resp := <-respChan
 	err := <-errChan
+	glog.V(10).Infof("RoutesClient.Delete(%q): end", az.RouteTableName)

 	if az.CloudProviderBackoff && shouldRetryAPIRequest(resp, err) {
 		glog.V(2).Infof("delete backing off: deleting route. clusterName=%q instance=%q cidr=%q", clusterName, kubeRoute.TargetNode, kubeRoute.DestinationCIDR)
--- a/pkg/cloudprovider/providers/azure/azure_storageaccount.go
+++ b/pkg/cloudprovider/providers/azure/azure_storageaccount.go
@@ -19,6 +19,8 @@ package azure
 import (
 	"fmt"
 	"strings"
+
+	"github.com/golang/glog"
 )

 type accountWithLocation struct {
@@ -28,7 +30,9 @@ type accountWithLocation struct {
 // getStorageAccounts gets the storage accounts' name, type, location in a resource group
 func (az *Cloud) getStorageAccounts() ([]accountWithLocation, error) {
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("StorageAccountClient.ListByResourceGroup(%v): start", az.ResourceGroup)
 	result, err := az.StorageAccountClient.ListByResourceGroup(az.ResourceGroup)
+	glog.V(10).Infof("StorageAccountClient.ListByResourceGroup(%v): end", az.ResourceGroup)
 	if err != nil {
 		return nil, err
 	}
@@ -58,7 +62,9 @@ func (az *Cloud) getStorageAccounts() ([]accountWithLocation, error) {
 // getStorageAccesskey gets the storage account access key
 func (az *Cloud) getStorageAccesskey(account string) (string, error) {
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("StorageAccountClient.ListKeys(%q): start", account)
 	result, err := az.StorageAccountClient.ListKeys(az.ResourceGroup, account)
+	glog.V(10).Infof("StorageAccountClient.ListKeys(%q): end", account)
 	if err != nil {
 		return "", err
 	}
--- a/pkg/cloudprovider/providers/azure/azure_util.go
+++ b/pkg/cloudprovider/providers/azure/azure_util.go
@@ -272,7 +272,9 @@ func (az *Cloud) getIPForMachine(nodeName types.NodeName) (string, error) {
 	}

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("InterfacesClient.Get(%q): start", nicName)
 	nic, err := az.InterfacesClient.Get(az.ResourceGroup, nicName, "")
+	glog.V(10).Infof("InterfacesClient.Get(%q): end", nicName)
 	if err != nil {
 		glog.Errorf("error: az.getIPForMachine(%s), az.InterfacesClient.Get(%s, %s, %s), err=%v", nodeName, az.ResourceGroup, nicName, "", err)
 		return "", err
--- a/pkg/cloudprovider/providers/azure/azure_wrap.go
+++ b/pkg/cloudprovider/providers/azure/azure_wrap.go
@@ -22,6 +22,7 @@ import (
 	"github.com/Azure/azure-sdk-for-go/arm/compute"
 	"github.com/Azure/azure-sdk-for-go/arm/network"
 	"github.com/Azure/go-autorest/autorest"
+	"github.com/golang/glog"
 	"k8s.io/apimachinery/pkg/types"
 )

@@ -44,7 +45,9 @@ func (az *Cloud) getVirtualMachine(nodeName types.NodeName) (vm compute.VirtualM

 	vmName := string(nodeName)
 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("VirtualMachinesClient.Get(%s): start", vmName)
 	vm, err = az.VirtualMachinesClient.Get(az.ResourceGroup, vmName, "")
+	glog.V(10).Infof("VirtualMachinesClient.Get(%s): end", vmName)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {
@@ -62,7 +65,9 @@ func (az *Cloud) getRouteTable() (routeTable network.RouteTable, exists bool, er
 	var realErr error

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("RouteTablesClient.Get(%s): start", az.RouteTableName)
 	routeTable, err = az.RouteTablesClient.Get(az.ResourceGroup, az.RouteTableName, "")
+	glog.V(10).Infof("RouteTablesClient.Get(%s): end", az.RouteTableName)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {
@@ -80,7 +85,9 @@ func (az *Cloud) getSecurityGroup() (sg network.SecurityGroup, exists bool, err
 	var realErr error

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("SecurityGroupsClient.Get(%s): start", az.SecurityGroupName)
 	sg, err = az.SecurityGroupsClient.Get(az.ResourceGroup, az.SecurityGroupName, "")
+	glog.V(10).Infof("SecurityGroupsClient.Get(%s): end", az.SecurityGroupName)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {
@@ -98,7 +105,9 @@ func (az *Cloud) getAzureLoadBalancer(name string) (lb network.LoadBalancer, exi
 	var realErr error

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("LoadBalancerClient.Get(%s): start", name)
 	lb, err = az.LoadBalancerClient.Get(az.ResourceGroup, name, "")
+	glog.V(10).Infof("LoadBalancerClient.Get(%s): end", name)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {
@@ -116,7 +125,9 @@ func (az *Cloud) getPublicIPAddress(name string) (pip network.PublicIPAddress, e
 	var realErr error

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("PublicIPAddressesClient.Get(%s): start", name)
 	pip, err = az.PublicIPAddressesClient.Get(az.ResourceGroup, name, "")
+	glog.V(10).Infof("PublicIPAddressesClient.Get(%s): end", name)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {
@@ -134,7 +145,9 @@ func (az *Cloud) getSubnet(virtualNetworkName string, subnetName string) (subnet
 	var realErr error

 	az.operationPollRateLimiter.Accept()
+	glog.V(10).Infof("SubnetsClient.Get(%s): start", subnetName)
 	subnet, err = az.SubnetsClient.Get(az.ResourceGroup, virtualNetworkName, subnetName, "")
+	glog.V(10).Infof("SubnetsClient.Get(%s): end", subnetName)

 	exists, realErr = checkResourceExistsFromError(err)
 	if realErr != nil {