add analysis, possible goroutine dump, to the context with timeout in…

… dynamic reconclier

rh-pre-commit.version: 2.2.0
rh-pre-commit.check-secrets: ENABLED

pkg/watcher/reconciler/dynamic/dynamic.go

@@ -18,6 +18,8 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"os"
+	"runtime/pprof"
 	"strings"
 	"time"
 
@@ -94,12 +96,57 @@ func NewDynamicReconciler(rc pb.ResultsClient, lc pb.LogsClient, oc ObjectClient
 // If enabled, the object may be deleted upon successful result upload.
 func (r *Reconciler) Reconcile(ctx context.Context, o results.Object) error {
 	dynamicContext, dynamicCancel := context.WithTimeout(ctx, 5*time.Minute)
-	defer dynamicCancel()
+	// we dont defer the dynamicCancle because golang defers follow a LIFO pattern
+	// and we want to have our context analysis defer function be able to distinguish between
+	// the context channel being closed because of Canceled or DeadlineExceeded
 	logger := logging.FromContext(dynamicContext)
+	defer func() {
+		ctxErr := dynamicContext.Err()
+		if ctxErr == nil {
+			logger.Warnw("Leaving dynamic Reconciler somehow but the context channel is not closed",
+				zap.String("namespace", o.GetNamespace()),
+				zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
+				zap.String("name", o.GetName()))
+			return
+		}
+		if ctxErr == context.Canceled {
+			logger.Infow("Leaving dynamic Reconciler normally with context properly canceled",
+				zap.String("namespace", o.GetNamespace()),
+				zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
+				zap.String("name", o.GetName()))
+			return
+		}
+		if ctxErr == context.DeadlineExceeded {
+			logger.Warnw("Leaving dynamic Reconciler only after context timeout, initiating thread dump",
+				zap.String("namespace", o.GetNamespace()),
+				zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
+				zap.String("name", o.GetName()))
+
+			// manual testing has confirmed you don't have to explicitly enable pprof to get goroutine dumps with
+			// stack traces; this lines up with the stack traces you receive if a panic occurs, as well as the
+			// stack trace you receive if you send a SIGQUIT and/or SIGABRT to a running go program
+			profile := pprof.Lookup("goroutine")
+			if profile == nil {
+				logger.Warnw("Leaving dynamic Reconciler only after context timeout, number of profiles found",
+					zap.String("namespace", o.GetNamespace()),
+					zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
+					zap.String("name", o.GetName()))
+			} else {
+				profile.WriteTo(os.Stdout, 2)
+			}
+			return
+		}
+		logger.Warnw("Leaving dynamic Reconciler with unexpected error",
+			zap.String("error", ctxErr.Error()),
+			zap.String("namespace", o.GetNamespace()),
+			zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
+			zap.String("name", o.GetName()))
+	}()
 
 	if o.GetObjectKind().GroupVersionKind().Empty() {
 		gvk, err := convert.InferGVK(o)
 		if err != nil {
+			dynamicCancel()
 			return err
 		}
 		o.GetObjectKind().SetGroupVersionKind(gvk)
@@ -113,18 +160,20 @@ func (r *Reconciler) Reconcile(ctx context.Context, o results.Object) error {
 
 	if err != nil {
 		logger.Debugw("Error upserting record to API server", zap.Error(err), timeTakenField)
+		dynamicCancel()
 		return fmt.Errorf("error upserting record: %w", err)
 	}
 
 	// Update logs if enabled.
 	if r.resultsClient.LogsClient != nil {
-		if err := r.sendLog(dynamicContext, o); err != nil {
+		if err = r.sendLog(dynamicContext, o); err != nil {
 			logger.Errorw("Error sending log",
 				zap.String("namespace", o.GetNamespace()),
 				zap.String("kind", o.GetObjectKind().GroupVersionKind().Kind),
 				zap.String("name", o.GetName()),
 				zap.Error(err),
 			)
+			dynamicCancel()
 			return err
 		}
 	}
@@ -135,11 +184,17 @@ func (r *Reconciler) Reconcile(ctx context.Context, o results.Object) error {
 
 	recordAnnotation := annotation.Annotation{Name: annotation.Record, Value: rec.GetName()}
 	resultAnnotation := annotation.Annotation{Name: annotation.Result, Value: res.GetName()}
-	if err := r.addResultsAnnotations(logging.WithLogger(dynamicContext, logger), o, recordAnnotation, resultAnnotation); err != nil {
+	if err = r.addResultsAnnotations(logging.WithLogger(dynamicContext, logger), o, recordAnnotation, resultAnnotation); err != nil {
+		dynamicCancel()
 		return err
 	}
 
-	return r.deleteUponCompletion(logging.WithLogger(dynamicContext, logger), o)
+	if err = r.deleteUponCompletion(logging.WithLogger(dynamicContext, logger), o); err != nil {
+		dynamicCancel()
+		return err
+	}
+	dynamicCancel()
+	return nil
 }
 
 // addResultsAnnotations adds Results annotations to the object in question if