TestTaskRunTimeout is flakey : fix timeouts

[vdemeester]

Expected Behavior

TestTaskRunTimeout should pass all the time 💯

Actual Behavior

TestTaskRunTimeout is failing a lot. I'll skip it so that

Here are some examples of failures:

• From Remove @tejal29 as owner and add alumni 🎓 #713:
  • https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/713/pull-tekton-pipeline-integration-tests/1113345177981816832/
  • https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/713/pull-tekton-pipeline-integration-tests/1113137811692720130/
  • https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/713/pull-tekton-pipeline-integration-tests/1113331336749256704/
• From Hide e2e test's example_test under a build tag #711:
  • https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/711/pull-tekton-pipeline-integration-tests/1113053757723119616/
• From wip: e2e: safer timeout test (less flakey 🙏) #691:
  • https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/691/pull-tekton-pipeline-integration-tests/1116632841082376194/

Steps to Reproduce the Problem

1. Open a PR
2. See it fail 💩
3. Run /retest and 🙏

I'm working on it in #691 but it's at a point where it makes a lot of build fail, and I'm really thinking of marking the test as skip and track the re-enablement of it here

cc @bobcatfish

/kind bug
/assign

[bobcatfish]

@vdemeester just let me know if you want a break from the investigation for a while, I'd be happy to take it on for a while 💃

[vdemeester]

/assign @bobcatfish

The more the merrier (especially as I'm running out of time this week)

[bobcatfish]

tl;dr: The timeout handle and the reconciler disagree about when a Run has timed out.

Okay I have a theory about what's going on. In #771 I ran the timeout test 10 times (and p.s. this seems to reproduce the issue locally as well), and in https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/771/pull-tekton-pipeline-integration-tests/1118981945099816962/ we have 2/10 of those timing out.

I also added a lot of (terrible) logs so I could see what was going on and I noticed some interesting things:

• The failed Runs were considered timed out in the timeout handler (i.e. case <-time.After(timeout) occurred) for all 10 Runs (and one of them twice haha)
• But for run-giraffe-0 and run-giraffe-6, the subsequent reconcile did NOT consider them timed out

For example for run-giraffe-0, this is from the timeout handler:

I0418 21:17:16.127] {"level":"info","logger":"controller.taskrun-controller","caller":"reconciler/timeout_handler.go:203","msg":"TIMEOUT timed out for run-giraffe-0","knative.dev/controller":"taskrun-controller"}                    
I0418 21:17:16.127] {"level":"info","logger":"controller.taskrun-controller","caller":"reconciler/timeout_handler.go:200","msg":"TIMEOUT finished for run-giraffe-0","knative.dev/controller":"taskrun-controller"}

This would then trigger the reconcile loop, and the logs from that look like:

I0418 21:17:16.128] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:248","msg":"TIMEOUT about to check if timeout for run-giraffe-0","knative.dev/controller":"taskrun-controller"}               
I0418 21:17:16.128] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:531","msg":"TIMEOUT checking timeout for run-giraffe-0, starttime 2019-04-18 21:07:13 +0000 UTC","knative.dev/controller":"taskrun-controller"}
I0418 21:17:16.128] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:537","msg":"TIMEOUT check if nil run-giraffe-0","knative.dev/controller":"taskrun-controller"}                                
I0418 21:17:16.128] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:541","msg":"TIMEOUT not nil run-giraffe-0 timeout 30s runtime 29.98450907s","knative.dev/controller":"taskrun-controller"}

As far as the reconcile loop is concerned, the timeout is 30s but the runtime is 29.98450907s - right on the edge!

And the same thing for run-giraffe-6:

I0418 21:17:16.033] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:541","msg":"TIMEOUT not nil run-giraffe-6 timeout 30s runtime 29.843298838s","knative.dev/controller":"taskrun-controller"}

So ∴ the theory is that the timeout handler and the reconcile loop are slightly out of sync in their logic to determine when a timeout has occurred, i.e. <-time.After(timeout) is happening, but the reonciler's logic is slightly different.

Anyway I don't know what the fix is haha - at a glance they SEEM to be doing the same thing. But the key imo is in making sure that exactly the same logic is being applied in both places OR in moving the logic to handle the timeout case into the timeout handler itself (instead of triggering an entire reconcile).

Whew! (maybe 🤞🤞 🤞 )

We need to:

• Figure out a fix for this (haha)
• Add more logs to track how timeouts are being applied (for any future debugging)

[bobcatfish]

Can see similar stuff happening in https://storage.googleapis.com/tekton-prow/pr-logs/pull/tektoncd_pipeline/771/pull-tekton-pipeline-integration-tests/1118995157169999873/build-log.txt as well (with "improved" logs):

I0418 22:09:34.153] {"level":"info","logger":"controller.taskrun-controller","caller":"controller/controller.go:288","msg":"Reconcile succeeded. Time taken: 47.002µs.","knative.dev/controller":"taskrun-controller","knative.dev/key":"arendelle-vs2m2/run-giraffe-0"}
I0418 22:09:34.153] {"level":"info","logger":"controller.taskrun-controller","caller":"reconciler/timeout_handler.go:203","msg":"TIMEOUT HANDLER timed out for run-giraffe-5","knative.dev/controller":"taskrun-controller"}
I0418 22:09:34.153] {"level":"info","logger":"controller.taskrun-controller","caller":"reconciler/timeout_handler.go:200","msg":"TIMEOUT HANDLER finished for run-giraffe-5","knative.dev/controller":"taskrun-controller"}
I0418 22:09:34.154] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:248","msg":"TIMEOUT RECONCILER about to check if timeout for run-giraffe-5","knative.dev/controller":"taskrun-controller"}
I0418 22:09:34.154] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:531","msg":"TIMEOUT RECONCILER checking timeout for run-giraffe-5, starttime 2019-04-18 21:59:31 +0000 UTC","knative.dev/controller":"taskrun-controller"}
I0418 22:09:34.154] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:537","msg":"TIMEOUT RECONCILER check if nil run-giraffe-5","knative.dev/controller":"taskrun-controller"}
I0418 22:09:34.154] {"level":"info","logger":"controller.taskrun-controller","caller":"taskrun/taskrun.go:541","msg":"TIMEOUT RECONCILER not nil run-giraffe-5 timeout 30s runtime 29.943341324s","knative.dev/controller":"taskrun-controller"}

timeout 30s runtime 29.943341324s DUN DUN DUUUUN