Merge pull request #47177 from rrati/aws-additional-logging

Automatic merge from submit-queue (batch tested with PRs 49107, 47177, 49234, 49224, 49227)

Added logging to AWS api calls. #46969

Additionally logging of when AWS API calls start and end to help diagnose problems with kubelet on cloud provider nodes not reporting node status periodically.  There's some inconsistency in logging around this PR we should discuss.

IMO, the API logging should be at a higher level than most other types of logging as you would probably only want it in limited instances.  For most cases that is easy enough to do, but there are some calls which have some logging around them already, namely in the instance groups.  My preference would be to keep the existing logging as it and just add the new API logs around the API call.

pkg/cloudprovider/providers/aws/aws.go

@@ -480,6 +480,20 @@ func (p *awsSDKProvider) addHandlers(regionName string, h *request.Handlers) {
 			Fn:   delayer.AfterRetry,
 		})
 	}
+
+	p.addAPILoggingHandlers(h)
+}
+
+func (p *awsSDKProvider) addAPILoggingHandlers(h *request.Handlers) {
+	h.Send.PushBackNamed(request.NamedHandler{
+		Name: "k8s/api-request",
+		Fn:   awsSendHandlerLogger,
+	})
+
+	h.ValidateResponse.PushFrontNamed(request.NamedHandler{
+		Name: "k8s/api-validate-response",
+		Fn:   awsValidateResponseHandlerLogger,
+	})
 }
 
 // Get a CrossRequestRetryDelay, scoped to the region, not to the request.
@@ -550,6 +564,7 @@ func (p *awsSDKProvider) Autoscaling(regionName string) (ASG, error) {
 
 func (p *awsSDKProvider) Metadata() (EC2Metadata, error) {
 	client := ec2metadata.New(session.New(&aws.Config{}))
+	p.addAPILoggingHandlers(&client.Handlers)
 	return client, nil
 }
 

pkg/cloudprovider/providers/aws/log_handler.go

@@ -23,12 +23,26 @@ import (
 
 // Handler for aws-sdk-go that logs all requests
 func awsHandlerLogger(req *request.Request) {
+	service, name := awsServiceAndName(req)
+	glog.V(4).Infof("AWS request: %s %s", service, name)
+}
+
+func awsSendHandlerLogger(req *request.Request) {
+	service, name := awsServiceAndName(req)
+	glog.V(4).Infof("AWS API Send: %s %s %v %v", service, name, req.Operation, req.Params)
+}
+
+func awsValidateResponseHandlerLogger(req *request.Request) {
+	service, name := awsServiceAndName(req)
+	glog.V(4).Infof("AWS API ValidateResponse: %s %s %v %v %s", service, name, req.Operation, req.Params, req.HTTPResponse.Status)
+}
+
+func awsServiceAndName(req *request.Request) (string, string) {
 	service := req.ClientInfo.ServiceName
 
 	name := "?"
 	if req.Operation != nil {
 		name = req.Operation.Name
 	}
-
-	glog.V(4).Infof("AWS request: %s %s", service, name)
+	return service, name
 }