Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Find a threadsafe way to log in timeout_handler #1307

Closed
bobcatfish opened this issue Sep 13, 2019 · 0 comments · Fixed by #1335
Closed

Find a threadsafe way to log in timeout_handler #1307

bobcatfish opened this issue Sep 13, 2019 · 0 comments · Fixed by #1335
Labels
help wanted Denotes an issue that needs help from a contributor. Must meet "help wanted" guidelines. maybe-next-milestone For consideration when planning the next milestone

Comments

@bobcatfish
Copy link
Collaborator

Expected Behavior

We should be able to emit logs from the timeout_handler in a threadsafe manner. The logic in the timeout_handler is intended to be running in separate goroutines alongside the main reconcile loop execution, to manage actions like timing out and retrying.

Actual Behavior

We were using the same zap sugared logger that we were using everywhere else for logging, e.g.:

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)
}
}

However when we started running tests with newer versions of go (e.g. 1.13 v 1.11 see #1124 ) and the -race flag, we found there were data races.

Not 100% sure what the root cause is but uber-go/zap#99 suggests that zap logger writes are not protected and could have a race.

So in #1124 we're removing the logging, which is unfortunate b/c we used it previously to help us debug #731 and itd be great to have some logging for debugging any future issues.

Additional Info

(Is "threadsafe" the right word to use when we're talking about goroutines??)

@bobcatfish bobcatfish added help wanted Denotes an issue that needs help from a contributor. Must meet "help wanted" guidelines. maybe-next-milestone For consideration when planning the next milestone labels Sep 13, 2019
bobcatfish added a commit to bobcatfish/pipeline that referenced this issue Sep 13, 2019
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.
tekton-robot pushed a commit that referenced this issue Sep 15, 2019
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted Denotes an issue that needs help from a contributor. Must meet "help wanted" guidelines. maybe-next-milestone For consideration when planning the next milestone
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant