Capturing test output is flakey
Closed this issue · 1 comments
carolynvs commented
Describe the bug
Sometimes a test will fail because output from the porter cli was not properly captured by the test framework or the output emitted by our logger didn't make it to the console? Perhaps the log level for just that run of the CLI was wrong due to parallel test interference? I'm not sure which is the root cause.
To Reproduce
Here's an example of this flaking out in the integration tests
2023-04-13T15:33:24.7605160Z === RUN TestRebuild
2023-04-13T15:33:24.7612447Z build_test.go:49: porter create
2023-04-13T15:33:24.7613440Z 2023/04/13 15:17:35 exec: /tmp/porter3554847327/porter porter create
2023-04-13T15:33:24.7614372Z helpers.go:321: Editing porter.yaml
2023-04-13T15:33:24.7615037Z build_test.go:80: porter explain --autobuild-disabled
2023-04-13T15:33:24.7616058Z 2023/04/13 15:17:35 exec: /tmp/porter3554847327/porter porter explain --autobuild-disabled
2023-04-13T15:33:24.7616769Z build_test.go:85: porter explain
2023-04-13T15:33:24.7617317Z 2023/04/13 15:17:35 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7617867Z build_test.go:92: porter explain
2023-04-13T15:33:24.7618556Z 2023/04/13 15:17:51 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7619271Z build_test.go:92: porter explain
2023-04-13T15:33:24.7619829Z 2023/04/13 15:17:51 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7620335Z build_test.go:92: porter explain
2023-04-13T15:33:24.7620894Z 2023/04/13 15:17:51 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7621436Z build_test.go:92: porter explain
2023-04-13T15:33:24.7621980Z 2023/04/13 15:17:51 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7622516Z build_test.go:92: porter explain
2023-04-13T15:33:24.7626500Z 2023/04/13 15:17:51 exec: /tmp/porter3554847327/porter porter explain
2023-04-13T15:33:24.7633761Z helpers.go:67:
2023-04-13T15:33:24.7641307Z Error Trace: /home/vsts/work/1/s/tests/helpers.go:67
2023-04-13T15:33:24.7648872Z /home/vsts/work/1/s/tests/integration/build_test.go:93
2023-04-13T15:33:24.7652211Z Error: "Checking if the bundle is up-to-date...\nName: porter-hello\nDescription: An example Porter configuration\nVersion: 0.1.0\nPorter Version: v1.0.13-2-g7ebcc5e5\n\nThis bundle uses the following tools: exec, testmixin.\n\nTo install this bundle run the following command, passing --param KEY=VALUE for any parameters you want to customize:\nporter install\n" does not contain "Bundle is up-to-date!"
2023-04-13T15:33:24.7722400Z Test: TestRebuild
2023-04-13T15:33:24.7728777Z Messages: expected the previous build to be reused
2023-04-13T15:33:24.7735826Z helpers.go:69: Checking if the bundle is up-to-date...
2023-04-13T15:33:24.7736690Z Name: porter-hello
2023-04-13T15:33:24.7739516Z Description: An example Porter configuration
2023-04-13T15:33:24.7739934Z Version: 0.1.0
2023-04-13T15:33:24.7740444Z Porter Version: v1.0.13-2-g7ebcc5e5
2023-04-13T15:33:24.7740810Z
2023-04-13T15:33:24.7741245Z This bundle uses the following tools: exec, testmixin.
2023-04-13T15:33:24.7742329Z
2023-04-13T15:33:24.7743263Z To install this bundle run the following command, passing --param KEY=VALUE for any parameters you want to customize:
2023-04-13T15:33:24.7744589Z porter install
2023-04-13T15:33:24.7745119Z
2023-04-13T15:33:24.7746104Z does not contain
2023-04-13T15:33:24.7747085Z Bundle is up-to-date!
2023-04-13T15:33:24.7747889Z main.go:178: Removing temp test PORTER_HOME
2023-04-13T15:33:24.7748750Z main.go:181: Removing temp test directory
2023-04-13T15:33:24.7749249Z --- FAIL: TestRebuild (18.41s)
In the test above we are looking for "Bundle is up-to-date!" to be printed. There aren't any code paths where we don't print a debug message after entering that function.
Lines 163 to 164 in cdaf491
So it's not clear if we are dropping that message when trying to log it, or if the console output capture isn't working.
Expected behavior
The test should have passed.
ludfjig commented
Issue seems to be related to parallelism. I am unable to repro after many sequential runs using for run in {1..10}; do go test --run TestRebuild ./tests/integration/build_test.go; done. When running in parallel using parallel go test --run TestRebuild ./tests/integration/build_test.go ">" {}.out ::: {1..3} I get a similar error.
--- FAIL: TestRebuild (9.74s)
build_test.go:85: porter create
helpers.go:321: Editing porter.yaml
build_test.go:116: porter explain --autobuild-disabled
build_test.go:121: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
build_test.go:128: porter explain
helpers.go:69:
Error Trace: /home/ludde/porter/tests/helpers.go:69
/home/ludde/porter/tests/integration/build_test.go:129
Error: "Checking if the bundle is up-to-date...\nName: porter-hello\nDescription: An example Porter configuration\nVersion: 0.1.0\nPorter Version: v1.0.15-4-g39f47c89\n\nThis bundle uses the following tools: exec, testmixin.\n\nTo install this bundle run the following command, passing --param KEY=VALUE for any parameters you want to customize:\nporter install\n" does not contain "Bundle is up-to-date!"
Test: TestRebuild
Messages: expected the previous build to be reused
helpers.go:71: Checking if the bundle is up-to-date...
Name: porter-hello
Description: An example Porter configuration
Version: 0.1.0
Porter Version: v1.0.15-4-g39f47c89
This bundle uses the following tools: exec, testmixin.
To install this bundle run the following command, passing --param KEY=VALUE for any parameters you want to customize:
porter install
does not contain
Bundle is up-to-date!
main.go:178: Removing temp test PORTER_HOME
main.go:181: Removing temp test directory
FAIL
FAIL command-line-arguments 9.764s
FAIL