Add logging to TimeoutHandler

The reconcile tests were causing panics or tripping race detection
because the timeout handler was using the *testing.T methods after the
test was already marked done.
The solution is to use loggers that are not tied to the testing
framework. The downside is that you may see logs from prior tests
intermixed but that is usually just the one associated with stopping the
timeout.

Author: fraenkel

pkg/reconciler/pipelinerun/cancel_test.go

@@ -22,11 +22,11 @@ import (
 
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline/v1alpha1"
 	"github.com/tektoncd/pipeline/pkg/reconciler/pipelinerun/resources"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/test"
 	tb "github.com/tektoncd/pipeline/test/builder"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"knative.dev/pkg/apis"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 func TestCancelPipelineRun(t *testing.T) {
@@ -74,7 +74,7 @@ func TestCancelPipelineRun(t *testing.T) {
 				PipelineRuns: []*v1alpha1.PipelineRun{tc.pipelineRun},
 				TaskRuns:     tc.taskRuns,
 			}
-			ctx, _ := rtesting.SetupFakeContext(t)
+			ctx, _ := ttesting.SetupFakeContext(t)
 			ctx, cancel := context.WithCancel(ctx)
 			defer cancel()
 			c, _ := test.SeedTestData(t, ctx, d)

pkg/reconciler/pipelinerun/config/store_test.go

@@ -23,13 +23,13 @@ import (
 	"github.com/google/go-cmp/cmp"
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline"
 	"github.com/tektoncd/pipeline/pkg/artifacts"
-	logtesting "knative.dev/pkg/logging/testing"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 
 	test "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 )
 
 func TestStoreLoadWithContext(t *testing.T) {
-	store := NewStore(pipeline.Images{}, logtesting.TestLogger(t))
+	store := NewStore(pipeline.Images{}, ttesting.TestLogger(t))
 	bucketConfig := test.ConfigMapFromTestFile(t, "config-artifact-bucket")
 	store.OnConfigChanged(bucketConfig)
 
@@ -41,7 +41,7 @@ func TestStoreLoadWithContext(t *testing.T) {
 	}
 }
 func TestStoreImmutableConfig(t *testing.T) {
-	store := NewStore(pipeline.Images{}, logtesting.TestLogger(t))
+	store := NewStore(pipeline.Images{}, ttesting.TestLogger(t))
 	store.OnConfigChanged(test.ConfigMapFromTestFile(t, "config-artifact-bucket"))
 
 	config := store.Load()

pkg/reconciler/pipelinerun/pipelinerun_test.go

@@ -29,6 +29,7 @@ import (
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline/v1alpha1"
 	"github.com/tektoncd/pipeline/pkg/reconciler/pipelinerun/resources"
 	taskrunresources "github.com/tektoncd/pipeline/pkg/reconciler/taskrun/resources"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/pkg/system"
 	"github.com/tektoncd/pipeline/test"
 	tb "github.com/tektoncd/pipeline/test/builder"
@@ -39,7 +40,6 @@ import (
 	"knative.dev/pkg/apis"
 	duckv1beta1 "knative.dev/pkg/apis/duck/v1beta1"
 	"knative.dev/pkg/configmap"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 var (
@@ -65,7 +65,7 @@ func getRunName(pr *v1alpha1.PipelineRun) string {
 // getPipelineRunController returns an instance of the PipelineRun controller/reconciler that has been seeded with
 // d, where d represents the state of the system (existing resources) needed for the test.
 func getPipelineRunController(t *testing.T, d test.Data) (test.TestAssets, func()) {
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	c, _ := test.SeedTestData(t, ctx, d)
 	configMapWatcher := configmap.NewInformedWatcher(c.Kube, system.GetNamespace())
 	ctx, cancel := context.WithCancel(ctx)

pkg/reconciler/reconciler_test.go

@@ -25,14 +25,14 @@ import (
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline"
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline/v1alpha1"
 	"github.com/tektoncd/pipeline/pkg/reconciler/pipelinerun/resources"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/test"
 	tb "github.com/tektoncd/pipeline/test/builder"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zaptest/observer"
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/client-go/tools/record"
 	"knative.dev/pkg/apis"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 // Test case for providing recorder in the option
@@ -56,7 +56,7 @@ func TestRecorderOptions(t *testing.T) {
 		Pipelines:    ps,
 		Tasks:        ts,
 	}
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
 	c, _ := test.SeedTestData(t, ctx, d)

pkg/reconciler/taskrun/cancel_test.go

@@ -22,14 +22,14 @@ import (
 
 	"github.com/google/go-cmp/cmp"
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline/v1alpha1"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/test"
 	tb "github.com/tektoncd/pipeline/test/builder"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zaptest/observer"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"knative.dev/pkg/apis"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 func TestCancelTaskRun(t *testing.T) {
@@ -83,7 +83,7 @@ func TestCancelTaskRun(t *testing.T) {
 				d.Pods = []*corev1.Pod{tc.pod}
 			}
 
-			ctx, _ := rtesting.SetupFakeContext(t)
+			ctx, _ := ttesting.SetupFakeContext(t)
 			ctx, cancel := context.WithCancel(ctx)
 			defer cancel()
 			c, _ := test.SeedTestData(t, ctx, d)

pkg/reconciler/taskrun/taskrun_test.go

@@ -32,6 +32,7 @@ import (
 	"github.com/tektoncd/pipeline/pkg/reconciler/taskrun/entrypoint"
 	"github.com/tektoncd/pipeline/pkg/reconciler/taskrun/resources"
 	"github.com/tektoncd/pipeline/pkg/reconciler/taskrun/resources/cloudevent"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/pkg/status"
 	"github.com/tektoncd/pipeline/pkg/system"
 	"github.com/tektoncd/pipeline/test"
@@ -51,7 +52,6 @@ import (
 	"k8s.io/client-go/tools/cache"
 	"knative.dev/pkg/apis"
 	"knative.dev/pkg/configmap"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 const (
@@ -267,7 +267,7 @@ func getRunName(tr *v1alpha1.TaskRun) string {
 // getTaskRunController returns an instance of the TaskRun controller/reconciler that has been seeded with
 // d, where d represents the state of the system (existing resources) needed for the test.
 func getTaskRunController(t *testing.T, d test.Data) (test.TestAssets, func()) {
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	ctx, cancel := context.WithCancel(ctx)
 	cloudEventClientBehaviour := cloudevent.FakeClientBehaviour{
 		SendSuccessfully: true,

pkg/reconciler/testing/logger.go

@@ -0,0 +1,28 @@
+package testing
+
+import (
+	"context"
+	"testing"
+
+	"go.uber.org/zap"
+	"knative.dev/pkg/controller"
+	"knative.dev/pkg/logging"
+	rtesting "knative.dev/pkg/reconciler/testing"
+)
+
+func SetupFakeContext(t *testing.T) (context.Context, []controller.Informer) {
+	ctx, informer := rtesting.SetupFakeContext(t)
+	return WithLogger(ctx, t), informer
+}
+
+func WithLogger(ctx context.Context, t *testing.T) context.Context {
+	return logging.WithLogger(ctx, TestLogger(t))
+}
+
+func TestLogger(t *testing.T) *zap.SugaredLogger {
+	logger, err := zap.NewDevelopment(zap.AddCaller())
+	if err != nil {
+		t.Fatalf("failed to create logger: %s", err)
+	}
+	return logger.Sugar().Named(t.Name())
+}

pkg/reconciler/timeout_handler.go

@@ -170,6 +170,7 @@ func backoffDuration(count uint, jf jitterFunc) time.Duration {
 func (t *TimeoutSet) checkPipelineRunTimeouts(namespace string, pipelineclientset clientset.Interface) {
 	pipelineRuns, err := pipelineclientset.TektonV1alpha1().PipelineRuns(namespace).List(metav1.ListOptions{})
 	if err != nil {
+		t.logger.Errorf("Can't get pipelinerun list in namespace %s: %s", namespace, err)
 		return
 	}
 	for _, pipelineRun := range pipelineRuns.Items {
@@ -188,6 +189,7 @@ func (t *TimeoutSet) checkPipelineRunTimeouts(namespace string, pipelineclientse
 func (t *TimeoutSet) CheckTimeouts(kubeclientset kubernetes.Interface, pipelineclientset clientset.Interface) {
 	namespaces, err := kubeclientset.CoreV1().Namespaces().List(metav1.ListOptions{})
 	if err != nil {
+		t.logger.Errorf("Can't get namespaces list: %s", err)
 		return
 	}
 	for _, namespace := range namespaces.Items {
@@ -201,6 +203,7 @@ func (t *TimeoutSet) CheckTimeouts(kubeclientset kubernetes.Interface, pipelinec
 func (t *TimeoutSet) checkTaskRunTimeouts(namespace string, pipelineclientset clientset.Interface) {
 	taskruns, err := pipelineclientset.TektonV1alpha1().TaskRuns(namespace).List(metav1.ListOptions{})
 	if err != nil {
+		t.logger.Errorf("Can't get taskrun list in namespace %s: %s", namespace, err)
 		return
 	}
 	for _, taskrun := range taskruns.Items {
@@ -242,12 +245,14 @@ func (t *TimeoutSet) WaitPipelineRun(pr *v1alpha1.PipelineRun, startTime *metav1
 
 func (t *TimeoutSet) waitRun(runObj StatusKey, timeout time.Duration, startTime *metav1.Time, callback func(interface{})) {
 	if startTime == nil {
+		t.logger.Errorf("startTime must be specified in order for a timeout to be calculated accurately for %s", runObj.GetRunKey())
 		return
 	}
 	if callback == nil {
 		callback = defaultFunc
 	}
 	runtime := time.Since(startTime.Time)
+	t.logger.Infof("About to start timeout timer for %s. started at %s, timeout is %s, running for %s", runObj.GetRunKey(), startTime.Time, timeout, runtime)
 	defer t.Release(runObj)
 	t.setTimer(runObj, timeout-runtime, callback)
 }
@@ -262,19 +267,24 @@ func (t *TimeoutSet) waitRun(runObj StatusKey, timeout time.Duration, startTime
 func (t *TimeoutSet) SetTaskRunTimer(tr *v1alpha1.TaskRun, d time.Duration) {
 	callback := t.taskRunCallbackFunc
 	if callback == nil {
+		t.logger.Errorf("attempted to set a timer for %q but no task run callback has been assigned", tr.Name)
 		return
 	}
 	t.setTimer(tr, d, callback)
 }
 
 func (t *TimeoutSet) setTimer(runObj StatusKey, timeout time.Duration, callback func(interface{})) {
 	finished := t.getOrCreateFinishedChan(runObj)
+	started := time.Now()
 	select {
 	case <-t.stopCh:
+		t.logger.Infof("stopping timer for %q", runObj.GetRunKey())
 		return
 	case <-finished:
+		t.logger.Infof("%q finished, stopping timer", runObj.GetRunKey())
 		return
 	case <-time.After(timeout):
+		t.logger.Infof("timer for %q has activated after %s", runObj.GetRunKey(), time.Since(started).String())
 		callback(runObj)
 	}
 }

pkg/reconciler/timeout_handler_test.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/tektoncd/pipeline/pkg/apis/config"
 	"github.com/tektoncd/pipeline/pkg/apis/pipeline/v1alpha1"
+	ttesting "github.com/tektoncd/pipeline/pkg/reconciler/testing"
 	"github.com/tektoncd/pipeline/test"
 	tb "github.com/tektoncd/pipeline/test/builder"
 	"go.uber.org/zap"
@@ -32,7 +33,6 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/util/wait"
 	"knative.dev/pkg/apis"
-	rtesting "knative.dev/pkg/reconciler/testing"
 )
 
 var (
@@ -95,7 +95,7 @@ func TestTaskRunCheckTimeouts(t *testing.T) {
 			},
 		}},
 	}
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	c, _ := test.SeedTestData(t, ctx, d)
 	stopCh := make(chan struct{})
 	defer close(stopCh)
@@ -221,7 +221,7 @@ func TestPipelinRunCheckTimeouts(t *testing.T) {
 		}},
 	}
 
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	c, _ := test.SeedTestData(t, ctx, d)
 	stopCh := make(chan struct{})
 	defer close(stopCh)
@@ -301,7 +301,7 @@ func TestWithNoFunc(t *testing.T) {
 			},
 		}},
 	}
-	ctx, _ := rtesting.SetupFakeContext(t)
+	ctx, _ := ttesting.SetupFakeContext(t)
 	c, _ := test.SeedTestData(t, ctx, d)
 	stopCh := make(chan struct{})
 	observer, _ := observer.New(zap.InfoLevel)