Fix race condition in plugin logs routine #2126
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
When we run a plugin, we start a go routine that captures logs from the plugin and forwards them to our traceLogger. I've found that there is a race condition where: 1. We close the plugin 2. The plugin emits a message saying that its closing 3. We cancel the context for the log go routine but ctx.Done doesn't immediately trigger on the go routine. 4. Instead the plugin connections's close function returns before the routine is stopped. 5. Porter moves on and closes our logger. 6. The log go routine then tries to forward the message to the logger which is now closed. I've added a wait group that ensures that the log go routine finishes before the plugin connection returns from Close. This ensures that all resources managed by the plugin connection are cleaned up before Close returns. Signed-off-by: Carolyn Van Slyck <[email protected]>
VinozzZ
reviewed
Jun 2, 2022
pkg/plugins/pluggable/connection.go
Outdated
| @@ -286,6 +293,9 @@ func (c *PluginConnection) setupLogCollector(ctx context.Context) { | |||
| // The best way to get that information is to instrument the plugin itself. This is mainly a fallback mechanism to | |||
| // collect logs from an uninstrumented plugin. | |||
| func (c *PluginConnection) collectPluginLogs(ctx context.Context) { | |||
| c.logsWaitGroup.Add(1) | |||
There was a problem hiding this comment.
What do u think moving this line to line 287?
That way we know where the goroutine is started
Signed-off-by: Carolyn Van Slyck <[email protected]>
|
@VinozzZ Fixed! |
joshuabezaleel
pushed a commit
to joshuabezaleel/porter
that referenced
this pull request
Jun 6, 2022
* Fix race condition in plugin logs routine When we run a plugin, we start a go routine that captures logs from the plugin and forwards them to our traceLogger. I've found that there is a race condition where: 1. We close the plugin 2. The plugin emits a message saying that its closing 3. We cancel the context for the log go routine but ctx.Done doesn't immediately trigger on the go routine. 4. Instead the plugin connections's close function returns before the routine is stopped. 5. Porter moves on and closes our logger. 6. The log go routine then tries to forward the message to the logger which is now closed. I've added a wait group that ensures that the log go routine finishes before the plugin connection returns from Close. This ensures that all resources managed by the plugin connection are cleaned up before Close returns. Signed-off-by: Carolyn Van Slyck <[email protected]> * Move when we add to the wait group Signed-off-by: Carolyn Van Slyck <[email protected]> Signed-off-by: joshuabezaleel <[email protected]>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
What does this change
When we run a plugin, we start a go routine that captures logs from the plugin and forwards them to our traceLogger. I've found that there is a race condition where:
I've added a wait group that ensures that the log go routine finishes before the plugin connection returns from Close. This ensures that all resources managed by the plugin connection are cleaned up before Close returns.
What issue does it fix
If someone is running in debug mode, a good percentage of the time, there would be a debug message saying that we couldn't write to the close log file at the end of the porter command. This removes that noise and ensures that if there is an error emitted by the plugin on close that we capture it.
Notes for the reviewer
N/A
Checklist
Reviewer Checklist