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

Extend the defer phase state checks in the unit test #1397

Merged
merged 2 commits into from
Apr 25, 2022

Conversation

ihcsim
Copy link
Contributor

@ihcsim ihcsim commented Apr 21, 2022

Change Overview

This PR attempts to fix the flakiness around the defer phase unit tests by extending the defer phase checks in the unit test to account for states with empty string value.

Following this log from one of the failed CI runs, notice that the defer phase of the test-actionset-sg4qq actionset is set to completed after the test has failed:

[36m[2022-04-21T20:11:25.785Z][0m {"ActionSet":"test-actionset-sg4qq","Container":"container","File":"pkg/output/stream.go","Function":"github.com/kanisterio/kanister/pkg/output.splitLines","Line":46,"Phase":"backupPhaseTwo","Pod":"kanister-job-v4jx8","Pod_Out":"###Phase-output###: {\"key\":\"value\",\"value\":\"mainValueTwo\"}","hostname":"a48311680e48","level":"info","msg":"","time":"2022-04-21T19:54:52.857077971Z"}
[36m[2022-04-21T20:11:25.785Z][0m {"ActionSet":"test-actionset-sg4qq","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).runAction.func1","Line":493,"Phase":"backupPhaseTwo","hostname":"a48311680e48","level":"info","msg":"Completed phase backupPhaseTwo","time":"2022-04-21T19:54:52.926249989Z"}
[36m[2022-04-21T20:11:25.785Z][0m {"ActionSet":"test-actionset-sg4qq","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).executeDeferPhase","Line":516,"Phase":"deferPhase","hostname":"a48311680e48","level":"info","msg":"Executing deferPhase deferPhase","time":"2022-04-21T19:54:52.926303491Z"}

[36m[2022-04-21T20:11:25.785Z][0m ----------------------------------------------------------------------
[36m[2022-04-21T20:11:25.785Z][0m FAIL: controller_test.go:656: ControllerSuite.TestDeferPhase

[36m[2022-04-21T20:11:25.785Z][0m controller_test.go:674:
[36m[2022-04-21T20:11:25.786Z][0m     c.Assert(err, IsNil)
[36m[2022-04-21T20:11:25.786Z][0m ... value *errors.withStack = State 'complete' never reached: Unexpected state:  ("State 'complete' never reached: Unexpected state: ")

[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:53.740559764Z"}

# ....
[36m[2022-04-21T20:11:25.786Z][0m {"Container":"container","File":"pkg/output/stream.go","Function":"github.com/kanisterio/kanister/pkg/output.splitLines","Line":46,"Pod":"kanister-job-4qk5f","Pod_Out":"###Phase-output###: {\"key\":\"value\",\"value\":\"deferValue\"}","hostname":"a48311680e48","level":"info","msg":"","time":"2022-04-21T19:54:59.564795915Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"ActionSet":"test-actionset-sg4qq","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).executeDeferPhase","Line":553,"Phase":"deferPhase","hostname":"a48311680e48","level":"info","msg":"Completed deferPhase deferPhase","time":"2022-04-21T19:54:59.62929645Z"}

Pull request type

Please check the type of change your PR introduces:

  • 🚧 Work in Progress
  • 🌈 Refactoring (no functional changes, no api changes)
  • 🐹 Trivial/Minor
  • 🐛 Bugfix
  • 🌻 Feature
  • 🗺️ Documentation
  • 🤖 Test

Test Plan

  • 💪 Manual
  • ⚡ Unit test
  • 💚 E2E

Since the defer phase is executed  a Go 'defer' statement of a separate
go routine, the test needs to account for racey scenarios where the
phase state is still empty.

Signed-off-by: Ivan Sim <ivan.sim@kasten.io>
@ihcsim
Copy link
Contributor Author

ihcsim commented Apr 21, 2022

@pavannd1 @viveksinghggits I don't quite understand why the controller log shows that the same blueprint is added multiple times. All of them say Added blueprint test-blueprint-defer-d5hlk. Any idea?

[36m[2022-04-21T20:11:25.785Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:46.738448315Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:53.740559764Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:54.644069197Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:56.373873872Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:59.714220153Z"}
[36m[2022-04-21T20:11:25.788Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:00.648875372Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:03.49233199Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:06.980262243Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:10.743418453Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:14.08697098Z"}

Copy link
Contributor

@viveksinghggits viveksinghggits left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@viveksinghggits
Copy link
Contributor

viveksinghggits commented Apr 22, 2022

@pavannd1 @viveksinghggits I don't quite understand why the controller log shows that the same blueprint is added multiple times. All of them say Added blueprint test-blueprint-defer-d5hlk. Any idea?

[36m[2022-04-21T20:11:25.785Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:46.738448315Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:53.740559764Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:54.644069197Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:56.373873872Z"}
[36m[2022-04-21T20:11:25.786Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:54:59.714220153Z"}
[36m[2022-04-21T20:11:25.788Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:00.648875372Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:03.49233199Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:06.980262243Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:10.743418453Z"}
[36m[2022-04-21T20:11:25.789Z][0m {"File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onAddBlueprint","Line":215,"hostname":"a48311680e48","level":"info","msg":"Added blueprint test-blueprint-defer-d5hlk","time":"2022-04-21T19:56:14.08697098Z"}

I think the problem is, in the handler of blueprint we are just logging that blueprint was added but not marking the object from queue to be done. That is the reason, we are able to see stale objects as well in the queue

func (c *Controller) onAddBlueprint(bp *crv1alpha1.Blueprint) {
	c.logAndSuccessEvent(context.TODO(), fmt.Sprintf("Added blueprint %s", bp.GetName()), "Added", bp)
}

I will raise a PR to fix this.

@viveksinghggits
Copy link
Contributor

It looks like we are not even maintaining the queue.

@ihcsim ihcsim added the kueue label Apr 25, 2022
@ihcsim
Copy link
Contributor Author

ihcsim commented Apr 25, 2022

Merging - got a 👍 from @pavannd1.

@mergify mergify bot merged commit 2640531 into master Apr 25, 2022
@mergify mergify bot deleted the fix-defer-phase-test branch April 25, 2022 19:58
akankshakumari393 pushed a commit that referenced this pull request May 9, 2022
Since the defer phase is executed  a Go 'defer' statement of a separate
go routine, the test needs to account for racey scenarios where the
phase state is still empty.

Signed-off-by: Ivan Sim <ivan.sim@kasten.io>

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants