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

Test failure output improvements #316

Merged
merged 2 commits into from
Sep 1, 2021

Conversation

jrajahalme
Copy link
Member

@jrajahalme jrajahalme commented Jun 14, 2021

  • Move pause from test to action so that new no test traffic will be generated after the failing action
  • Suppress logs for 0 flows received

@jrajahalme jrajahalme added the kind/feature New feature or request label Jun 14, 2021
@jrajahalme jrajahalme requested review from a team and twpayne June 14, 2021 19:51
@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from 9fd99f0 to ae91f98 Compare June 14, 2021 19:51
@jrajahalme jrajahalme requested a review from ti-mo June 14, 2021 19:51
@jrajahalme jrajahalme temporarily deployed to ci June 14, 2021 19:51 Inactive
}
} else {
if !a.shouldSucceed() {
a.Failf("command %q succeeded while it should have failed: %s", cmdStr, stdout.String())
}
}
if a.failed {
if stderr.Len() > 0 {
a.Warnf("%s stderr: %s", cmdName, stderr.String())
Copy link
Contributor

Choose a reason for hiding this comment

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

Warn is for bringing unexpected events to the user's attention that are not fatal to test execution, and they are logged separately at the end of the test run to make sure they're not missed in a flood of output.

I'd prefer to have Infof() (or even Failf()) here instead, which will be kept in line with the test results, and is more suited to multi-line output. (which is generally the case for stdout/err) Unexpected stderr is a failure, not a warning.

Copy link
Contributor

Choose a reason for hiding this comment

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

Failf() sounds good to me ✅

Copy link
Member Author

Choose a reason for hiding this comment

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

I was thinking the exit code of the execution would be sufficient to indicate the success/fail status of the command. No trouble to make this a Failf() though, will add a comment that we consider any stderr output to indicate a failing test as well.

Copy link
Member Author

Choose a reason for hiding this comment

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

Making both stderr and stdout logs as Failfs, we are not logging these only if the command failed, after all.

Copy link
Member Author

Choose a reason for hiding this comment

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

Was considering if we'd still need to log these at debug level if the action did not fail, though. Thoughts?

Copy link
Member Author

Choose a reason for hiding this comment

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

Changed this to log stderr and stdout at fail level if the action failed (i.e., command succeeded when it should not have, or failed when it should have succeeded), and at debug level otherwise (to always see the output, if any, with --debug).

@@ -345,11 +345,12 @@ func (a *Action) Infof(format string, s ...interface{}) {
}

// Warn must be called when a warning is detected performing the Action.
//
// Warnings are logged both inline and at the end of a test.
Copy link
Contributor

Choose a reason for hiding this comment

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

Could we keep the Warn*() family of functions as-is? See my comment above, unexpected stderr is not a warning, it's a failure.

Copy link
Member Author

Choose a reason for hiding this comment

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

@ti-mo I find it odd that one logging level is not logged inline while every other level is. Maybe my bad that I'm thinking of these logging functions in terms of "loglevels". I have nothing against highlighting specific log levels separately, but I think all logs should appear in the output in the order in which they were generated.

If we need warning functions that do not log inline we should call them something else instead to not cause confusion with usage of Warn() and Warnf() from other Go packages.

Copy link
Contributor

@ti-mo ti-mo Jun 16, 2021

Choose a reason for hiding this comment

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

Sure, I can see how echoing them inline in the test's log would be useful as well, but we need to keep in mind they are also repeated at the end of the test run. They're not supposed to be used frequently and we should avoid using them for multi-line output.

Or maybe we should just remove Warn() altogether. :) Being indecisive about events ("it's a failure but not really") is a slippery slope because that's how things start rotting. If it doesn't fail, no one looks at it in CI. It was originally intended to be used for flagging deprecated things etc., but currently it's only used for the Unable to contact Hubble Relay... warning. If it causes more trouble/confusion than it's worth, let's remove it.

Copy link
Member Author

@jrajahalme jrajahalme Jun 16, 2021

Choose a reason for hiding this comment

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

I'll separate this change to a PR of its own.

@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from ae91f98 to aba3152 Compare June 16, 2021 16:09
@jrajahalme jrajahalme requested a review from a team as a code owner June 16, 2021 16:09
@maintainer-s-little-helper maintainer-s-little-helper bot requested review from ti-mo and removed request for a team June 16, 2021 16:09
@jrajahalme jrajahalme temporarily deployed to ci June 16, 2021 16:09 Inactive
@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from aba3152 to e976e72 Compare June 18, 2021 15:20
@jrajahalme jrajahalme temporarily deployed to ci June 18, 2021 15:20 Inactive
Copy link
Contributor

@ti-mo ti-mo left a comment

Choose a reason for hiding this comment

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

LGTM! Few nits.

connectivity/check/action.go Outdated Show resolved Hide resolved
connectivity/check/action.go Outdated Show resolved Hide resolved
connectivity/check/action.go Outdated Show resolved Hide resolved
@ti-mo
Copy link
Contributor

ti-mo commented Jul 13, 2021

@jrajahalme btw, I already proposed something similar in #251 (0c690f9)

@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from e976e72 to 5cf1487 Compare July 20, 2021 09:53
@jrajahalme jrajahalme temporarily deployed to ci July 20, 2021 09:53 Inactive
@jrajahalme
Copy link
Member Author

@jrajahalme btw, I already proposed something similar in #251 (0c690f9)

Rebased due to this.

Copy link
Contributor

@ti-mo ti-mo left a comment

Choose a reason for hiding this comment

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

Few nits, but 🚀

connectivity/check/action.go Outdated Show resolved Hide resolved
connectivity/check/action.go Outdated Show resolved Hide resolved
@jrajahalme jrajahalme added the area/CI Continuous Integration testing issue or flake label Jul 21, 2021
@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from 5cf1487 to 42d454c Compare July 21, 2021 15:47
@jrajahalme jrajahalme temporarily deployed to ci July 21, 2021 15:47 Inactive
@jrajahalme jrajahalme force-pushed the pr/jrajahalme/test-failure-output-improvements branch from 42d454c to 2e38c0b Compare August 11, 2021 11:51
@jrajahalme jrajahalme temporarily deployed to ci August 11, 2021 11:51 Inactive
@jrajahalme
Copy link
Member Author

Rebased

@jrajahalme jrajahalme added the ready-to-merge This PR has passed all tests and received consensus from code owners to merge. label Sep 1, 2021
Move the pause on fail wait from test to action, so that nothing
happens after the failed action.

Signed-off-by: Jarno Rajahalme <[email protected]>
Suppress repeated output that occurs when no flow have been received
yet, i.e., the first two lines of:

Validating 0 flows against 2 requirements
Validating 0 flows against 2 requirements
Validating 23 flows against 2 requirements

Signed-off-by: Jarno Rajahalme <[email protected]>
@tklauser tklauser force-pushed the pr/jrajahalme/test-failure-output-improvements branch from 2e38c0b to d9c6807 Compare September 1, 2021 11:36
@tklauser tklauser temporarily deployed to ci September 1, 2021 11:36 Inactive
@tklauser tklauser merged commit 4fdacae into master Sep 1, 2021
@tklauser tklauser deleted the pr/jrajahalme/test-failure-output-improvements branch September 1, 2021 12:20
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/CI Continuous Integration testing issue or flake kind/feature New feature or request ready-to-merge This PR has passed all tests and received consensus from code owners to merge.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants