Fix and work around timeout handler data races #1308

bobcatfish · 2019-09-13T19:00:01Z

Changes

This mostly fixes #1124, will still need to update the gcr.io/tekton-releases/tests/test-runner to use a newer version of go which can catch this race.

Will re-add logging to the timeout handler in #1307

Remove logging from timeout handler ✏️

Logging in the timeout handler was added as part of #731 cuz it helped
us debug when the timeout handler didn't work as expected. Unfortunately
it looks like the logger we're using can't be used in multiple go
routines (uber-go/zap#99 may be related).
Removing this logging to fix #1124, hopefully can find a safe way to add
logging back in #1307.

Make GetRunKey threadsafe 🔒

GetRunKey is accessed in goroutines via the timeout_handler; accessing
attributes of an object in a goroutine is not threadsafe. This is used
as a key in a map, so for now replacing this with a value that should be
unique but also threadsafe to fix #1124

Remove unused function 👻

The function GetLogMessages isn't used anywhere. I had tried to remove
it to see if it was causing the data race in #1124 - it isnt but still
it's not being used anywhere so why not remove :)

Submitter Checklist

These are the criteria that every PR should meet, please check them off as you
review them:

Includes tests (if functionality changed/added)
[n/a] Includes docs (if user facing)
Commit messages follow commit message best practices

See the contribution guide for more details.

Double check this list of stuff that's easy to miss:

If you are adding a new binary/image to the cmd dir, please update
the release Task and TaskRun to build and release this image

Reviewer Notes

If API changes
are included, additive changes
must be approved by at least two OWNERS
and backwards incompatible changes
must be approved by more than 50% of the OWNERS,
and they must first be added
in a backwards compatible way.

Release Notes

Removes potential race conditions in timeout handler

The function `GetLogMessages` isn't used anywhere. I had tried to remove it to see if it was causing the data race in tektoncd#1124 - it _isnt_ but still it's not being used anywhere so why not remove :)

Logging in the timeout handler was added as part of tektoncd#731 cuz it helped us debug when the timeout handler didn't work as expected. Unfortunately it looks like the logger we're using can't be used in multiple go routines (uber-go/zap#99 may be related). Removing this logging to fix tektoncd#1124, hopefully can find a safe way to add logging back in tektoncd#1307.

GetRunKey is accessed in goroutines via the timeout_handler; accessing attributes of an object in a goroutine is not threadsafe. This is used as a key in a map, so for now replacing this with a value that should be unique but also threadsafe to fix tektoncd#1124

tekton-robot · 2019-09-13T19:02:13Z

The following is the coverage report on pkg/.
Say /test pull-tekton-pipeline-go-coverage to re-run this coverage report

File	Old Coverage	New Coverage	Delta
pkg/reconciler/timeout_handler.go	75.2%	79.1%	3.9
test/controller.go	34.6%	37.5%	2.9

afrittoli · 2019-09-13T19:16:25Z

I cannot reproduce the races with this code, nice!

dibyom · 2019-09-13T19:32:25Z

pkg/apis/pipeline/v1alpha1/pipelinerun_types.go

@@ -246,7 +246,8 @@ func (pr *PipelineRun) IsCancelled() bool {

 // GetRunKey return the pipelinerun key for timeout handler map
 func (pr *PipelineRun) GetRunKey() string {
-	return fmt.Sprintf("%s/%s/%s", pipelineRunControllerName, pr.Namespace, pr.Name)
+	// The address of the pointer is a threadsafe unique identifier for the pipelinerun
+	return fmt.Sprintf("%s/%p", pipelineRunControllerName, pr)


afrittoli · 2019-09-13T20:08:39Z

test/controller.go

@@ -86,7 +76,6 @@ type Informers struct {
 // TestAssets holds references to the controller, logs, clients, and informers.
 type TestAssets struct {
 	Controller *controller.Impl
-	Logs       *observer.ObservedLogs


This is strange - I remember using Logs to debug a test in the past, before the controller refactor.
I might be nice to have GetLogMessages populate the Logs field here, which would give tests access to logs and would enable testing on seeing a certain log message.

But I agree since it's not used now we can remove it and add it back if needed in future.

afrittoli

Thank you for this work!
/lgtm

afrittoli · 2019-09-15T13:27:28Z

pkg/reconciler/timeout_handler.go

@@ -170,7 +170,6 @@ 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)


I'm not super-happy to remove logging just ahead of a release - it may make troubleshooting harder for folks. That said, removing non-thread safe behavior is probably more important, so I'm ok with this - and we still have a chance to bring logging back before the release anyways.

tekton-robot · 2019-09-15T13:28:07Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: afrittoli, bobcatfish, dibyom

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [afrittoli,bobcatfish,dibyom]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

bobcatfish added 3 commits September 13, 2019 14:34

Remove unused function 👻

71bd601

The function `GetLogMessages` isn't used anywhere. I had tried to remove it to see if it was causing the data race in tektoncd#1124 - it _isnt_ but still it's not being used anywhere so why not remove :)

tekton-robot requested review from abayer and vdemeester September 13, 2019 19:00

tekton-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Sep 13, 2019

googlebot added the cla: yes Trying to make the CLA bot happy with ppl from different companies work on one commit label Sep 13, 2019

tekton-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Sep 13, 2019

dibyom approved these changes Sep 13, 2019

View reviewed changes

afrittoli reviewed Sep 13, 2019

View reviewed changes

bobcatfish mentioned this pull request Sep 13, 2019

Update version of go in base image tektoncd/plumbing#71

Closed

afrittoli approved these changes Sep 15, 2019

View reviewed changes

tekton-robot assigned afrittoli Sep 15, 2019

tekton-robot added the lgtm Indicates that a PR is ready to be merged. label Sep 15, 2019

tekton-robot merged commit 10b6427 into tektoncd:master Sep 15, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix and work around timeout handler data races #1308

Fix and work around timeout handler data races #1308

bobcatfish commented Sep 13, 2019

tekton-robot commented Sep 13, 2019

afrittoli commented Sep 13, 2019

dibyom Sep 13, 2019

afrittoli Sep 13, 2019

afrittoli left a comment

afrittoli Sep 15, 2019

tekton-robot commented Sep 15, 2019

Fix and work around timeout handler data races #1308

Fix and work around timeout handler data races #1308

Conversation

bobcatfish commented Sep 13, 2019

Changes

Remove logging from timeout handler ✏️

Make GetRunKey threadsafe 🔒

Remove unused function 👻

Submitter Checklist

Reviewer Notes

Release Notes

tekton-robot commented Sep 13, 2019

afrittoli commented Sep 13, 2019

dibyom Sep 13, 2019

Choose a reason for hiding this comment

afrittoli Sep 13, 2019

Choose a reason for hiding this comment

afrittoli left a comment

Choose a reason for hiding this comment

afrittoli Sep 15, 2019

Choose a reason for hiding this comment

tekton-robot commented Sep 15, 2019