Log http request and count number of traces before logging

Change-Id: I421afd7c0ef3ce7b4cd37c34b60462ce18c00fe7

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/create.go

@@ -22,6 +22,8 @@ import (
 	"net/http"
 	"time"
 
+	"k8s.io/klog"
+
 	"k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/apimachinery/pkg/api/meta"
 	metainternalversion "k8s.io/apimachinery/pkg/apis/meta/internalversion"
@@ -45,6 +47,9 @@ func createHandler(r rest.NamedCreater, scope RequestScope, admit admission.Inte
 		// For performance tracking purposes.
 		trace := utiltrace.New("Create " + req.URL.Path)
 		defer trace.LogIfLong(500 * time.Millisecond)
+		defer trace.LogIfStepsLessThan(4, func() {
+			klog.V(4).Infof(">>>> createHandler bad count : %#v", req)
+		})
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
 			scope.err(errors.NewBadRequest("the dryRun alpha feature is disabled"), w, req)
@@ -145,6 +150,7 @@ func createHandler(r rest.NamedCreater, scope RequestScope, admit admission.Inte
 			)
 		})
 		if err != nil {
+			klog.V(4).Infof("Unable to store in database : %#v", err)
 			scope.err(err, w, req)
 			return
 		}

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/delete.go

@@ -21,6 +21,8 @@ import (
 	"net/http"
 	"time"
 
+	"k8s.io/klog"
+
 	"k8s.io/apimachinery/pkg/api/errors"
 	metainternalversion "k8s.io/apimachinery/pkg/apis/meta/internalversion"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -140,6 +142,7 @@ func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope RequestSco
 			return obj, err
 		})
 		if err != nil {
+			klog.V(4).Infof("Unable to delete from database : %#v", err)
 			scope.err(err, w, req)
 			return
 		}
@@ -289,6 +292,7 @@ func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope RequestSco
 			return r.DeleteCollection(ctx, options, &listOptions)
 		})
 		if err != nil {
+			klog.V(4).Infof("Unable to delete collection : %#v", err)
 			scope.err(err, w, req)
 			return
 		}

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go

@@ -67,6 +67,7 @@ func getResourceHandler(scope RequestScope, getter getterFunc) http.HandlerFunc
 
 		result, err := getter(ctx, name, req, trace)
 		if err != nil {
+			klog.V(4).Infof("Unable to get resource : %#v", err)
 			scope.err(err, w, req)
 			return
 		}
@@ -267,6 +268,7 @@ func ListResource(r rest.Lister, rw rest.Watcher, scope RequestScope, forceWatch
 		trace.Step("About to List from storage")
 		result, err := r.List(ctx, &opts)
 		if err != nil {
+			klog.V(4).Infof("Unable to list from storage : %#v", err)
 			scope.err(err, w, req)
 			return
 		}

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/patch.go

@@ -45,6 +45,8 @@ import (
 	"k8s.io/apiserver/pkg/util/dryrun"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	utiltrace "k8s.io/apiserver/pkg/util/trace"
+
+	"k8s.io/klog"
 )
 
 // PatchResource returns a function that will handle a resource patch.
@@ -53,7 +55,9 @@ func PatchResource(r rest.Patcher, scope RequestScope, admit admission.Interface
 		// For performance tracking purposes.
 		trace := utiltrace.New("Patch " + req.URL.Path)
 		defer trace.LogIfLong(500 * time.Millisecond)
-
+		defer trace.LogIfStepsLessThan(3, func() {
+			klog.V(4).Infof(">>>> PatchResource bad count : %#v", req)
+		})
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
 			scope.err(errors.NewBadRequest("the dryRun alpha feature is disabled"), w, req)
 			return
@@ -191,6 +195,7 @@ func PatchResource(r rest.Patcher, scope RequestScope, admit admission.Interface
 
 		result, err := p.patchResource(ctx)
 		if err != nil {
+			klog.V(4).Infof("Unable to store in database : %#v", err)
 			scope.err(err, w, req)
 			return
 		}

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

@@ -35,20 +35,22 @@ import (
 // transformResponseObject takes an object loaded from storage and performs any necessary transformations.
 // Will write the complete response object.
 func transformResponseObject(ctx context.Context, scope RequestScope, req *http.Request, w http.ResponseWriter, statusCode int, mediaType negotiation.MediaTypeOptions, result runtime.Object) {
+	trace := scope.Trace
+
 	// status objects are ignored for transformation
 	if _, ok := result.(*metav1.Status); ok {
+		trace.Step("writing metav1.Status")
 		responsewriters.WriteObject(statusCode, scope.Kind.GroupVersion(), scope.Serializer, result, w, req)
 		return
 	}
 
 	// ensure the self link and empty list array are set
 	if err := setObjectSelfLink(ctx, result, req, scope.Namer); err != nil {
+		trace.Step("setObjectSelfLink failed")
 		scope.err(err, w, req)
 		return
 	}
 
-	trace := scope.Trace
-
 	// If conversion was allowed by the scope, perform it before writing the response
 	switch target := mediaType.Convert; {
 
@@ -57,6 +59,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 		responsewriters.WriteObject(statusCode, scope.Kind.GroupVersion(), scope.Serializer, result, w, req)
 
 	case target.Kind == "PartialObjectMetadata" && target.GroupVersion() == metav1beta1.SchemeGroupVersion:
+		trace.Step("writing PartialObjectMetadata")
 		partial, err := asV1Beta1PartialObjectMetadata(result)
 		if err != nil {
 			scope.err(err, w, req)
@@ -101,6 +104,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 		}
 
 	default:
+		trace.Step("writing default")
 		// this block should only be hit if scope AllowsConversion is incorrect
 		accepted, _ := negotiation.MediaTypesForSerializer(metainternalversion.Codecs)
 		err := negotiation.NewNotAcceptableError(accepted)

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go

@@ -190,6 +190,7 @@ func finishRequest(timeout time.Duration, fn resultFunc) (result runtime.Object,
 				buf := make([]byte, size)
 				buf = buf[:goruntime.Stack(buf, false)]
 				panicReason = strings.TrimSuffix(fmt.Sprintf("%v\n%s", panicReason, string(buf)), "\n")
+				klog.Errorf(">>>> panic : %s", panicReason)
 			}
 			// Propagate to parent goroutine
 			panicCh <- panicReason
@@ -206,15 +207,19 @@ func finishRequest(timeout time.Duration, fn resultFunc) (result runtime.Object,
 	case result = <-ch:
 		if status, ok := result.(*metav1.Status); ok {
 			if status.Status != metav1.StatusSuccess {
+				klog.Errorf(">>>> caught failure : %#v", errors.FromObject(status))
 				return nil, errors.FromObject(status)
 			}
 		}
 		return result, nil
 	case err = <-errCh:
+		klog.Errorf(">>>> caught error : %#v", err)
 		return nil, err
 	case p := <-panicCh:
+		klog.Errorf(">>>> panicking now : %#v", p)
 		panic(p)
 	case <-time.After(timeout):
+		klog.Errorf(">>>> timing out now")
 		return nil, errors.NewTimeoutError(fmt.Sprintf("request did not complete within requested timeout %s", timeout), 0)
 	}
 }

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/update.go

@@ -23,6 +23,8 @@ import (
 	"sync"
 	"time"
 
+	"k8s.io/klog"
+
 	"k8s.io/apimachinery/pkg/api/errors"
 	metainternalversion "k8s.io/apimachinery/pkg/apis/meta/internalversion"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -47,6 +49,9 @@ func UpdateResource(r rest.Updater, scope RequestScope, admit admission.Interfac
 		// For performance tracking purposes.
 		trace := utiltrace.New("Update " + req.URL.Path)
 		defer trace.LogIfLong(500 * time.Millisecond)
+		defer trace.LogIfStepsLessThan(5, func() {
+			klog.V(4).Infof(">>>> UpdateResource bad count : %#v", req)
+		})
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
 			scope.err(errors.NewBadRequest("the dryRun alpha feature is disabled"), w, req)
@@ -175,6 +180,7 @@ func UpdateResource(r rest.Updater, scope RequestScope, admit admission.Interfac
 			return obj, err
 		})
 		if err != nil {
+			klog.V(4).Infof("Unable to store in database : %#v", err)
 			scope.err(err, w, req)
 			return
 		}

staging/src/k8s.io/apiserver/pkg/util/trace/trace.go

@@ -53,6 +53,14 @@ func (t *Trace) Log() {
 	t.logWithStepThreshold(0)
 }
 
+func (t *Trace) LogIfStepsLessThan(count int, f func()) {
+	if len(t.steps) < count {
+		// an explicit logging request should dump all the steps out at the higher level
+		t.logWithStepThreshold(0)
+		f()
+	}
+}
+
 func (t *Trace) logWithStepThreshold(stepThreshold time.Duration) {
 	var buffer bytes.Buffer
 	tracenum := rand.Int31()