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

Run unit and integration tests with gotestsum #22541

Merged
merged 34 commits into from
Jan 14, 2021

Conversation

urso
Copy link

@urso urso commented Nov 11, 2020

  • Enhancement

What does this PR do?

The PR introduces gotestsum to drive the go based unit and integration tests. This is meant as replacement for github.com/jstemmer/go-junit-report, which seems to be unmaintained for a while.

Only the GoTest mage helper is modified to use gotestsum instead of go-junit-reporter. In addition to the change we add unit tests for GoTest that do run actual tests. The output of these helper-tests is captured and validated against known regular expressions.

Why is it important?

We use go-junit-reporter in order to create a xunit like report that is uploaded after the tests have finished. Unfortunately the project seems to be unmaintained for at least a year.

We discovered that we have a few issues with our test output. For example lines have been missing, wrong tests have been marked as failed (on panic in a leaked go-routine), or failed tests have not been reported at all. The new unit tests try to cover most cases that have not been reported correctly, in order to validate that the change actually fixes reporting.

goroutinepanic handling

This one might be a little flaky. But it seems that a 'badly' scheduled unmanaged go-routine can bring down and flag unrelated tests. The stack trace in the failed test actually matches the original test that did spawn the go-routine.

We did try to reproduce the issue by running 2 tests. The first test creates a go-routine that sleeps for 2 seconds and finally panics. The second tests waits for 5 seconds. Depending on the order the test is run we did see the second test to be marked as "Failed". A sample output using go-junit-reporter shows false_positive_failure as failed:

Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic

[2020-11-11T14:33:13.939Z] Test:    TestWrongPanic

[2020-11-11T14:33:13.939Z] ----

[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic

[2020-11-11T14:33:13.939Z] Test:    TestWrongPanic/setup_failing_go-routine

[2020-11-11T14:33:13.939Z] ----

[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic

[2020-11-11T14:33:13.939Z] Test:    TestWrongPanic/false_positive_failure

[2020-11-11T14:33:13.939Z] /var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a

[2020-11-11T14:33:13.939Z] /var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b

[2020-11-11T14:33:13.939Z] /var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78

[2020-11-11T14:33:13.939Z] /var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:12 +0x76

[2020-11-11T14:33:13.939Z] /var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:10 +0x3f

Unfortunately the problem is not solved by switching to gotestsum (or running go test). Here it is up to us to ensure we never leak go-routines when a test returns. For example in auditbeat we found tests like:

go func() {
  err := create files
  if err != nil { panic }
}()

wait and validate files (max 30s wait)

The tests did fail (especially on windows) and the go routine did bring down another unrelated test.

testify assert output missing

We use the testify package for validation. The package adds a newline before the actual report. Unfortunately the assert output was missing from all test output in jenkins. We finally tracked down the problem to go-junit-reporter "eating" our test output.

We did create some failing sample tests in order debug the issue. The expected output was:

--- FAIL: TestSimpleAssertFails (0.00s)
    run_test.go:11: 
        	Error Trace:	run_test.go:11
        	Error:      	Should be true
        	Test:       	TestSimpleAssertFails
--- FAIL: TestSimpleAssertWithMessage (0.00s)
    run_test.go:15: 
        	Error Trace:	run_test.go:15
        	Error:      	Should be true
        	Test:       	TestSimpleAssertWithMessage
        	Messages:   	My message
--- FAIL: TestSimpleAssertWithMessagef (0.00s)
    run_test.go:19: 
        	Error Trace:	run_test.go:19
        	Error:      	Should be true
        	Test:       	TestSimpleAssertWithMessagef
        	Messages:   	My message with arguments: 42
--- FAIL: TestSimpleRequireFails (0.00s)
    run_test.go:23: 
        	Error Trace:	run_test.go:23
        	Error:      	Should be true
        	Test:       	TestSimpleRequireFails
--- FAIL: TestSimpleRequireWithMessage (0.00s)
    run_test.go:27: 
        	Error Trace:	run_test.go:27
        	Error:      	Should be true
        	Test:       	TestSimpleRequireWithMessage
        	Messages:   	My message
--- FAIL: TestSimpleRequireWithMessagef (0.00s)
    run_test.go:31: 
        	Error Trace:	run_test.go:31
        	Error:      	Should be true
        	Test:       	TestSimpleRequireWithMessagef
        	Messages:   	My message with arguments: 42
--- FAIL: TestFailEqualMaps (0.00s)
    run_test.go:50: 
        	Error Trace:	run_test.go:50
        	Error:      	Not equal: 
        	            	expected: map[string]interface {}{"a":1, "b":true, "c":"test", "e":map[string]interface {}{"x":"y"}}
        	            	actual  : map[string]interface {}{"a":42, "b":false, "c":"test"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,8 +1,5 @@
        	            	-(map[string]interface {}) (len=4) {
        	            	- (string) (len=1) "a": (int) 1,
        	            	- (string) (len=1) "b": (bool) true,
        	            	- (string) (len=1) "c": (string) (len=4) "test",
        	            	- (string) (len=1) "e": (map[string]interface {}) (len=1) {
        	            	-  (string) (len=1) "x": (string) (len=1) "y"
        	            	- }
        	            	+(map[string]interface {}) (len=3) {
        	            	+ (string) (len=1) "a": (int) 42,
        	            	+ (string) (len=1) "b": (bool) false,
        	            	+ (string) (len=1) "c": (string) (len=4) "test"
        	            	 }
        	Test:       	TestFailEqualMaps
FAIL
exit status 1

Unfortunately the actual output was missing the failed assertions:

[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleAssertFails
[2020-11-11T14:33:13.939Z]     run_test.go:11: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleAssertWithMessage
[2020-11-11T14:33:13.939Z]     run_test.go:15: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleAssertWithMessagef
[2020-11-11T14:33:13.939Z]     run_test.go:19: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleRequireFails
[2020-11-11T14:33:13.939Z]     run_test.go:23: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleRequireWithMessage
[2020-11-11T14:33:13.939Z]     run_test.go:27: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestSimpleRequireWithMessagef
[2020-11-11T14:33:13.939Z]     run_test.go:31: 
[2020-11-11T14:33:13.939Z] ----
[2020-11-11T14:33:13.939Z] Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
[2020-11-11T14:33:13.939Z] Test:    TestFailEqualMaps
[2020-11-11T14:33:13.939Z]     run_test.go:50: 
[2020-11-11T14:33:13.939Z] ----

The new unit tests for GoTest show that the problem is solved by gotestsum

Checklist

  • My code follows the style guidelines of this project
  • I have commented my code, particularly in hard-to-understand areas
    - [ ] I have made corresponding changes to the documentation
    - [ ] I have made corresponding change to the default configuration files
  • I have added tests that prove my fix is effective or that my feature works
    - [ ] I have added an entry in CHANGELOG.next.asciidoc or CHANGELOG-developer.next.asciidoc.

How to test this PR locally

make test and the different mage testing commands will use gotestsum now.

Limitations

Tests must not print directly or indirectly to stdout/stdout. The go test -json command does not mark a test as passed/failed in that case, which will subsequently mark the test as failed (unknown state) in the junit report. The test run itself succeeds, though.

Related issues

@botelastic botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Nov 11, 2020
@elasticmachine
Copy link
Collaborator

🐛 Flaky test report

❕ There are test failures but not known flaky tests.

Expand to view the summary

Test stats 🧪

Test Results
Failed 28
Passed 1290
Skipped 6
Total 1324

Genuine test errors 28

💔 There are test failures but not known flaky tests, most likely a genuine test failure.

  • Name: Build&Test / filebeat-build / TestWrongPanic – goroutinepanic
  • Name: Build&Test / filebeat-build / TestWrongPanic/setup_failing_go-routine – goroutinepanic
  • Name: Build&Test / filebeat-build / TestWrongPanic/false_positive_failure – goroutinepanic
  • Name: Build&Test / filebeat-build / TestSimpleAssertFails – withassert
  • Name: Build&Test / filebeat-build / TestSimpleAssertWithMessage – withassert
  • Name: Build&Test / filebeat-build / TestSimpleAssertWithMessagef – withassert
  • Name: Build&Test / filebeat-build / TestSimpleRequireFails – withassert
  • Name: Build&Test / filebeat-build / TestSimpleRequireWithMessage – withassert
  • Name: Build&Test / filebeat-build / TestSimpleRequireWithMessagef – withassert
  • Name: Build&Test / filebeat-build / TestFailEqualMaps – withassert
  • Name: Build&Test / filebeat-build / TestLogIsPrintedOnError – withtestlog
  • Name: Build&Test / filebeat-build / TestLogIsPrintedOnFatal – withtestlog
  • Name: Build&Test / filebeat-build / TestLogIsPrintedOnFatalf – withtestlog
  • Name: Build&Test / filebeat-build / TestLogsWithNewlines – withtestlog
  • Name: Build&Test / filebeat-windows-windows-2019 / TestWrongPanic – goroutinepanic
  • Name: Build&Test / filebeat-windows-windows-2019 / TestWrongPanic/setup_failing_go-routine – goroutinepanic
  • Name: Build&Test / filebeat-windows-windows-2019 / TestWrongPanic/false_positive_failure – goroutinepanic
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleAssertFails – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleAssertWithMessage – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleAssertWithMessagef – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleRequireFails – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleRequireWithMessage – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestSimpleRequireWithMessagef – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestFailEqualMaps – withassert
  • Name: Build&Test / filebeat-windows-windows-2019 / TestLogIsPrintedOnError – withtestlog
  • Name: Build&Test / filebeat-windows-windows-2019 / TestLogIsPrintedOnFatal – withtestlog
  • Name: Build&Test / filebeat-windows-windows-2019 / TestLogIsPrintedOnFatalf – withtestlog
  • Name: Build&Test / filebeat-windows-windows-2019 / TestLogsWithNewlines – withtestlog

@elasticmachine
Copy link
Collaborator

elasticmachine commented Nov 11, 2020

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts preview

Expand to view the summary

Build stats

  • Build Cause: Pull request #22541 updated

    • Start Time: 2021-01-13T16:19:43.783+0000
  • Duration: 102 min 4 sec

  • Commit: 69b3387

Test stats 🧪

Test Results
Failed 0
Passed 17387
Skipped 1345
Total 18732

Steps errors 2

Expand to view the steps failures

journalbeat-unitTest - Install Go/Mage/Python/Docker/Terraform 1.14.12
  • Took 2 min 27 sec . View more details on here
  • Description: .ci/scripts/install-tools.sh
x-pack/functionbeat-Lint - Install Go/Mage/Python/Docker/Terraform 1.14.12
  • Took 2 min 22 sec . View more details on here
  • Description: .ci/scripts/install-tools.sh

💚 Flaky test report

Tests succeeded.

Expand to view the summary

Test stats 🧪

Test Results
Failed 0
Passed 17387
Skipped 1345
Total 18732

@v1v
Copy link
Member

v1v commented Nov 11, 2020

I managed to spin up a new VM to run the commands directly there

vmartinez@vmartinez-vm-linux-2020-11-11-15-34-00:~/src/github.com/elastic/beats/filebeat$ mage build test
>> build: Building filebeat


>> go test: Unit Testing
FAILURES:
Package: github.com/elastic/beats/v7/filebeat/config
Test:    TestReadConfig2
    config_test.go:43: 
----
Package: github.com/elastic/beats/v7/filebeat/config
Test:    TestMergeConfigFiles
    config_test.go:113: 
    config_test.go:115: 
----
Package: github.com/elastic/beats/v7/filebeat/fileset
Test:    TestLoadManifestNginx
    fileset_test.go:57: 
panic: runtime error: invalid memory address or nil pointer dereference
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:988 +0x30d
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:991 +0x3f9
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/runtime/panic.go:969 +0x166
/home/vmartinez/src/github.com/elastic/beats/filebeat/fileset/fileset_test.go:58 +0xa1
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:1039 +0xdc
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:1090 +0x372
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic
Test:    TestWrongPanic
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic
Test:    TestWrongPanic/setup_failing_go-routine
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic
Test:    TestWrongPanic/false_positive_failure
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b
/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78
/home/vmartinez/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:12 +0x76
/home/vmartinez/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:10 +0x3f
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleAssertFails
    run_test.go:11: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleAssertWithMessage
    run_test.go:15: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleAssertWithMessagef
    run_test.go:19: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleRequireFails
    run_test.go:23: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleRequireWithMessage
    run_test.go:27: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestSimpleRequireWithMessagef
    run_test.go:31: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
Test:    TestFailEqualMaps
    run_test.go:50: 
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withtestlog
Test:    TestLogIsPrintedOnError
    run_test.go:6: Log message should be printed
    run_test.go:7: printf style log message: 42
    run_test.go:8: Log should fail
    run_test.go:9: Log should fail with printf style log: 23
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withtestlog
Test:    TestLogIsPrintedOnFatal
    run_test.go:13: Log message should be printed
    run_test.go:14: printf style log message: 42
    run_test.go:15: Log should fail
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withtestlog
Test:    TestLogIsPrintedOnFatalf
    run_test.go:19: Log message should be printed
    run_test.go:20: printf style log message: 42
    run_test.go:21: Log should fail with printf style log: 42
----
Package: github.com/elastic/beats/v7/filebeat/placeholder/withtestlog
Test:    TestLogsWithNewlines
    run_test.go:25: Log
        message
        should
        be
        printed
    run_test.go:26: printf
        style
        log
        message:
        42
    run_test.go:27: Log
        should
        fail
        with
        printf
        style
        log:
        42
----
SUMMARY:
  Fail:     17
  Skip:     0
  Pass:     602
  Packages: 29
  Duration: 1m4.684273816s
  JUnit Report: /home/vmartinez/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.xml
  Output File:  /home/vmartinez/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.out
>> go test: Unit Test Failed
Error: go test failed: 17 test failures

And I diff with the Jenkins builds and it's shown below

diff --git a/jenkins.txt b/cli.txt
index b7f6f47ef..b59b0ee2d 100644
--- a/jenkins.txt
+++ b/cli.txt
@@ -2,6 +2,26 @@ mage build test
 >> build: Building filebeat
 >> go test: Unit Testing
 FAILURES:
+Package: github.com/elastic/beats/v7/filebeat/config
+Test:    TestReadConfig2
+    config_test.go:43: 
+----
+Package: github.com/elastic/beats/v7/filebeat/config
+Test:    TestMergeConfigFiles
+    config_test.go:113: 
+    config_test.go:115: 
+----
+Package: github.com/elastic/beats/v7/filebeat/fileset
+Test:    TestLoadManifestNginx
+    fileset_test.go:57: 
+panic: runtime error: invalid memory address or nil pointer dereference
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:988 +0x30d
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:991 +0x3f9
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/runtime/panic.go:969 +0x166
+/home/vmartinez/src/github.com/elastic/beats/filebeat/fileset/fileset_test.go:58 +0xa1
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:1039 +0xdc
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:1090 +0x372
+----
 Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic
 Test:    TestWrongPanic
 ----
@@ -10,11 +30,11 @@ Test:    TestWrongPanic/setup_failing_go-routine
 ----
 Package: github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic
 Test:    TestWrongPanic/false_positive_failure
-/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a
-/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b
-/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78
-/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:12 +0x76
-/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:10 +0x3f
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b
+/home/vmartinez/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78
+/home/vmartinez/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:12 +0x76
+/home/vmartinez/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:10 +0x3f
 ----
 Package: github.com/elastic/beats/v7/filebeat/placeholder/withassert
 Test:    TestSimpleAssertFails
@@ -85,13 +105,12 @@ Test:    TestLogsWithNewlines
         42
 ----
 SUMMARY:
-  Fail:     14
-  Skip:     1
-  Pass:     659
+  Fail:     17
+  Skip:     0
+  Pass:     602
   Packages: 29
-  Duration: 50.947041551s
-  Coverage Report: /var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.html
-  JUnit Report:    /var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.xml
-  Output File:     /var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.out
+  Duration: 1m4.684273816s
+  JUnit Report: /home/vmartinez/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.xml
+  Output File:  /home/vmartinez/src/github.com/elastic/beats/filebeat/build/TEST-go-unit.out
 >> go test: Unit Test Failed
-Error: go test failed: 14 test failures
\ No newline at end of file
+Error: go test failed: 17 test failures

@andresrc andresrc added the Team:Services (Deprecated) Label for the former Integrations-Services team label Nov 11, 2020
@botelastic botelastic bot removed the needs_team Indicates that the issue/PR needs a Team:* label label Nov 11, 2020
@urso
Copy link
Author

urso commented Nov 16, 2020

So far I tracked down the issue to a custom test result parser in our mage tools. The VM/Jenkins setup seems to be ok.

@urso
Copy link
Author

urso commented Nov 16, 2020

I'm trying if I can improve/fix reporting using another project.

The current approach tries to capture stdout,stderr and then tries to parse the final test output using https://github.com/jstemmer/go-junit-report. This project seems to be somewhat unmaintained and has quite a few open PRs and issues trying to improve parsing.

Instead of trying to fix go-junit-reporer, I'm giving https://github.com/gotestyourself/gotestsum#json-file-output a try. The tool is a go test wrapper, invoking go test -json. The json report generated by go test contains the action type and actual test name for each single line being printed. This should make parsing much more robust. In addition does the the tool already write xml unit files, and can even colorize the output (I disabled colorization for now).

mage unitTest will now run gotestsum -f standard-quiet --no-color --junitfile build/TEST-go-unit.xml --jsonfile build/TEST-go-unit.out.json -- ./.... This write the shortened test output to a buffer and to build/Test-go-unit.out. The original JSON logs generated by go test -json are written to build/TEST-go-unit.out.json (the tools provides a testjson package that can be used to parse the result if we want to). The junit file is still written to build/TEST-go-unit.xml.

This is just a "test". Running the changes locally, logs are correctly captured. Only problem is still the panics, which the go test -json command already marks wrong. I guess there is not much we can do about the panics, besides mandating clean tests that do not leak go-routines that can panic.

@urso
Copy link
Author

urso commented Nov 20, 2020

Something is still wrong with the package selection. Right now all unit tests are executed per Beat it seems. But the output with gotestsum looks somewhat sane.

Case 1 (goroutine panic):

The output is still somewhat missleading. If a leaked go-routine panics the wrong test is still marked as failed. As there is no panic handler, the full test suite of the current package is put to a halt. All in all this is to be expected. On the positive side, the original Test that did leak the routine failing late was also marked as failed. This has not been the case before.

All in I would say this case is reported as good as possible.

[2020-11-19T14:30:04.801Z] === Failed

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/goroutinepanic TestWrongPanic (unknown)

[2020-11-19T14:30:04.801Z] panic: Fail in goroutine after TestWrongPanic/setup_failing_go-routine has completed

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] goroutine 20 [running]:

[2020-11-19T14:30:04.801Z] testing.(*common).Fail(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a

[2020-11-19T14:30:04.801Z] testing.(*common).FailNow(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b

[2020-11-19T14:30:04.801Z] testing.(*common).Fatal(0xc000144240, 0xc000034fb8, 0x1, 0x1)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78

[2020-11-19T14:30:04.801Z] github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic.TestWrongPanic.func1.1(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:29 +0x76

[2020-11-19T14:30:04.801Z] created by github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic.TestWrongPanic.func1

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:27 +0x3f

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/goroutinepanic TestWrongPanic/setup_failing_go-routine (unknown)

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/goroutinepanic TestWrongPanic/false_positive_failure (unknown)

[2020-11-19T14:30:04.801Z] panic: Fail in goroutine after TestWrongPanic/setup_failing_go-routine has completed

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] goroutine 20 [running]:

[2020-11-19T14:30:04.801Z] testing.(*common).Fail(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:654 +0x11a

[2020-11-19T14:30:04.801Z] testing.(*common).FailNow(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:676 +0x2b

[2020-11-19T14:30:04.801Z] testing.(*common).Fatal(0xc000144240, 0xc000034fb8, 0x1, 0x1)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/.gvm/versions/go1.14.7.linux.amd64/src/testing/testing.go:766 +0x78

[2020-11-19T14:30:04.801Z] github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic.TestWrongPanic.func1.1(0xc000144240)

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:29 +0x76

[2020-11-19T14:30:04.801Z] created by github.com/elastic/beats/v7/filebeat/placeholder/goroutinepanic.TestWrongPanic.func1

[2020-11-19T14:30:04.801Z] 	/var/lib/jenkins/workspace/Beats_beats_PR-22541/src/github.com/elastic/beats/filebeat/placeholder/goroutinepanic/run_test.go:27 +0x3f

Case 2 (with assert):

Success. All logs, failures, and newlines are printed correctly:

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleAssertFails (0.00s)

[2020-11-19T14:30:04.801Z]     run_test.go:28: 

[2020-11-19T14:30:04.801Z]         	Error Trace:	run_test.go:28

[2020-11-19T14:30:04.801Z]         	Error:      	Should be true

[2020-11-19T14:30:04.801Z]         	Test:       	TestSimpleAssertFails

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleAssertWithMessage (0.00s)

[2020-11-19T14:30:04.801Z]     run_test.go:32: 

[2020-11-19T14:30:04.801Z]         	Error Trace:	run_test.go:32

[2020-11-19T14:30:04.801Z]         	Error:      	Should be true

[2020-11-19T14:30:04.801Z]         	Test:       	TestSimpleAssertWithMessage

[2020-11-19T14:30:04.801Z]         	Messages:   	My message

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleAssertWithMessagef (0.00s)

[2020-11-19T14:30:04.801Z]     run_test.go:36: 

[2020-11-19T14:30:04.801Z]         	Error Trace:	run_test.go:36

[2020-11-19T14:30:04.801Z]         	Error:      	Should be true

[2020-11-19T14:30:04.801Z]         	Test:       	TestSimpleAssertWithMessagef

[2020-11-19T14:30:04.801Z]         	Messages:   	My message with arguments: 42

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleRequireFails (0.00s)

[2020-11-19T14:30:04.801Z]     run_test.go:40: 

[2020-11-19T14:30:04.801Z]         	Error Trace:	run_test.go:40

[2020-11-19T14:30:04.801Z]         	Error:      	Should be true

[2020-11-19T14:30:04.801Z]         	Test:       	TestSimpleRequireFails

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleRequireWithMessage (0.00s)

[2020-11-19T14:30:04.801Z]     run_test.go:44: 

[2020-11-19T14:30:04.801Z]         	Error Trace:	run_test.go:44

[2020-11-19T14:30:04.801Z]         	Error:      	Should be true

[2020-11-19T14:30:04.801Z]         	Test:       	TestSimpleRequireWithMessage

[2020-11-19T14:30:04.801Z]         	Messages:   	My message

[2020-11-19T14:30:04.801Z] 

[2020-11-19T14:30:04.801Z] === FAIL: filebeat/placeholder/withassert TestSimpleRequireWithMessagef (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:48: 

[2020-11-19T14:30:04.802Z]         	Error Trace:	run_test.go:48

[2020-11-19T14:30:04.802Z]         	Error:      	Should be true

[2020-11-19T14:30:04.802Z]         	Test:       	TestSimpleRequireWithMessagef

[2020-11-19T14:30:04.802Z]         	Messages:   	My message with arguments: 42

[2020-11-19T14:30:04.802Z] 

[2020-11-19T14:30:04.802Z] === FAIL: filebeat/placeholder/withassert TestFailEqualMaps (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:67: 

[2020-11-19T14:30:04.802Z]         	Error Trace:	run_test.go:67

[2020-11-19T14:30:04.802Z]         	Error:      	Not equal: 

[2020-11-19T14:30:04.802Z]         	            	expected: map[string]interface {}{"a":1, "b":true, "c":"test", "e":map[string]interface {}{"x":"y"}}

[2020-11-19T14:30:04.802Z]         	            	actual  : map[string]interface {}{"a":42, "b":false, "c":"test"}

[2020-11-19T14:30:04.802Z]         	            	

[2020-11-19T14:30:04.802Z]         	            	Diff:

[2020-11-19T14:30:04.802Z]         	            	--- Expected

[2020-11-19T14:30:04.802Z]         	            	+++ Actual

[2020-11-19T14:30:04.802Z]         	            	@@ -1,8 +1,5 @@

[2020-11-19T14:30:04.802Z]         	            	-(map[string]interface {}) (len=4) {

[2020-11-19T14:30:04.802Z]         	            	- (string) (len=1) "a": (int) 1,

[2020-11-19T14:30:04.802Z]         	            	- (string) (len=1) "b": (bool) true,

[2020-11-19T14:30:04.802Z]         	            	- (string) (len=1) "c": (string) (len=4) "test",

[2020-11-19T14:30:04.802Z]         	            	- (string) (len=1) "e": (map[string]interface {}) (len=1) {

[2020-11-19T14:30:04.802Z]         	            	-  (string) (len=1) "x": (string) (len=1) "y"

[2020-11-19T14:30:04.802Z]         	            	- }

[2020-11-19T14:30:04.802Z]         	            	+(map[string]interface {}) (len=3) {

[2020-11-19T14:30:04.802Z]         	            	+ (string) (len=1) "a": (int) 42,

[2020-11-19T14:30:04.802Z]         	            	+ (string) (len=1) "b": (bool) false,

[2020-11-19T14:30:04.802Z]         	            	+ (string) (len=1) "c": (string) (len=4) "test"

[2020-11-19T14:30:04.802Z]         	            	 }

[2020-11-19T14:30:04.802Z]         	Test:       	TestFailEqualMaps

[2020-11-19T14:30:04.802Z] 

Case 3:

The logs output looks correct. CI output:

[2020-11-19T14:30:04.802Z] === FAIL: filebeat/placeholder/withtestlog TestLogIsPrintedOnError (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:23: Log message should be printed

[2020-11-19T14:30:04.802Z]     run_test.go:24: printf style log message: 42

[2020-11-19T14:30:04.802Z]     run_test.go:25: Log should fail

[2020-11-19T14:30:04.802Z]     run_test.go:26: Log should fail with printf style log: 23

[2020-11-19T14:30:04.802Z] 

[2020-11-19T14:30:04.802Z] === FAIL: filebeat/placeholder/withtestlog TestLogIsPrintedOnFatal (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:30: Log message should be printed

[2020-11-19T14:30:04.802Z]     run_test.go:31: printf style log message: 42

[2020-11-19T14:30:04.802Z]     run_test.go:32: Log should fail

[2020-11-19T14:30:04.802Z] 

[2020-11-19T14:30:04.802Z] === FAIL: filebeat/placeholder/withtestlog TestLogIsPrintedOnFatalf (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:36: Log message should be printed

[2020-11-19T14:30:04.802Z]     run_test.go:37: printf style log message: 42

[2020-11-19T14:30:04.802Z]     run_test.go:38: Log should fail with printf style log: 42

[2020-11-19T14:30:04.802Z] 

[2020-11-19T14:30:04.802Z] === FAIL: filebeat/placeholder/withtestlog TestLogsWithNewlines (0.00s)

[2020-11-19T14:30:04.802Z]     run_test.go:42: Log

[2020-11-19T14:30:04.802Z]         message

[2020-11-19T14:30:04.802Z]         should

[2020-11-19T14:30:04.802Z]         be

[2020-11-19T14:30:04.802Z]         printed

[2020-11-19T14:30:04.802Z]     run_test.go:43: printf

[2020-11-19T14:30:04.802Z]         style

[2020-11-19T14:30:04.802Z]         log

[2020-11-19T14:30:04.802Z]         message:

[2020-11-19T14:30:04.802Z]         42

[2020-11-19T14:30:04.802Z]     run_test.go:44: Log

[2020-11-19T14:30:04.802Z]         should

[2020-11-19T14:30:04.802Z]         fail

[2020-11-19T14:30:04.802Z]         with

[2020-11-19T14:30:04.802Z]         printf

[2020-11-19T14:30:04.802Z]         style

[2020-11-19T14:30:04.802Z]         log:

[2020-11-19T14:30:04.802Z]         42

return c
}

// GoTestSummary is a summary of test results.
type GoTestSummary struct {
Copy link
Author

Choose a reason for hiding this comment

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

GoTestSummary is not used anymore. gotestsum prints it's own summary, not as rich as this one, but should be good enough.

@jsoriano jsoriano self-requested a review January 5, 2021 15:00
Copy link
Member

@jsoriano jsoriano left a comment

Choose a reason for hiding this comment

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

Thanks for fixing this! And great to have tests covering these problems 👍

I think we need to pin the version of gotestsum used to avoid surprises if something changes in upstream.
I have added some comments about this, but summarizing it would be to:

  • Add gotestsum to tools/tools.go as we do with other external tools so they are managed by go modules.
  • Install it with go install instead of go get.
  • If possible, install it only as a dependency of the mage target that uses it, so we don't need to keep track of its installation along all the build scripts and Dockerfiles.

@@ -4,4 +4,5 @@ set -exuo pipefail
.ci/scripts/install-go.sh
.ci/scripts/install-docker-compose.sh
.ci/scripts/install-terraform.sh
(cd /tmp && go get gotest.tools/gotestsum)
Copy link
Member

Choose a reason for hiding this comment

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

Installing tools with go get has lead to unexpected failures in the past, could we include this tool in tools/tools.go, add it to go.mod, and install it with go install when needed?

Copy link
Author

Choose a reason for hiding this comment

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

I originally tried with go install and it failed 👍

Sure, I can add it to go.mod and make the go install a build dependency.

@@ -189,34 +185,65 @@ func GoTestIntegrationForModule(ctx context.Context) error {
func GoTest(ctx context.Context, params GoTestArgs) error {
Copy link
Member

Choose a reason for hiding this comment

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

Could we create a InstallGotestsum target and add it here as dependency?

Suggested change
func GoTest(ctx context.Context, params GoTestArgs) error {
func GoTest(ctx context.Context, params GoTestArgs) error {
mg.Deps(InstallGotestsum)

We do this with InstallGoLicenser for example.

Copy link
Author

Choose a reason for hiding this comment

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

Will give this a try. Thanks.

@@ -14,6 +14,7 @@ RUN \
RUN pip3 install --upgrade pip==20.1.1
RUN pip3 install --upgrade setuptools==47.3.2
RUN pip3 install --upgrade docker-compose==1.23.2
RUN go get gotest.tools/gotestsum
Copy link
Member

Choose a reason for hiding this comment

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

I think we need to control the version of this tool, if we do something like adding the installation as dependency of the mage targets we wouldn't need to add it here in docker images and other build scripts.

@urso
Copy link
Author

urso commented Jan 12, 2021

I think we need to pin the version of gotestsum used to avoid surprises if something changes in upstream.
I have added some comments about this, but summarizing it would be to:

Will do, thanks.

In general I'm not a big fan of us building and installing development and build dependencies over and over again. if we haven't tools/tools.go (or are not disciplined in using it), dependencies are buried in mage files and others. Plus, dependencies added to go.mod automatically become Beats dependencies and must be mentioned in the notice file. License wise this also restricts what can be used for development.

Long term I would prefer if we require a specific set of tools to be available (plus version) and provide build images + docker containers for testing that have the dependencies preinstalled. We should not be required to install debian packages or use go install at build or packaging time every single time. Rather auto-update the build images once a week.

@urso
Copy link
Author

urso commented Jan 12, 2021

Updated the PR to install gotestsum via mage + add the dependency to go.mod. Now I remember why I installed the tool into a temporary directory. gotestsum has some dependencies in common with Beats, but different versions. The x/sys package did lead to conflicts (looks like breaking change in x/sys package) with some other dependencies. Let's see how it goes this time.

I wonder if it would help if we have had a separate go.mod for test dependencies only.

@jsoriano jsoriano dismissed their stale review January 13, 2021 10:53

Main issues addressed

Copy link
Member

@jsoriano jsoriano left a comment

Choose a reason for hiding this comment

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

Looks good, thanks for addressing my comments. There seems to be a linting issue with the latest changes in gotest.go.

@jsoriano
Copy link
Member

In general I'm not a big fan of us building and installing development and build dependencies over and over again. if we haven't tools/tools.go (or are not disciplined in using it), dependencies are buried in mage files and others.

Yep, I agree that always running go install for every tool doesn't sound ideal. But this way it is easier to be sure that you are using the expected versions when running commands that generate files or do checks. Without this, any developer or contributor would need to remember to update their tools (and the command to do that) before committing anything, or expect incoherent behaviours or failures with CI. In my opinion developer UX is better if proper versions of tools are used automatically.

Plus, dependencies added to go.mod automatically become Beats dependencies and must be mentioned in the notice file. License wise this also restricts what can be used for development.

What you mention about using a separated go.mod for tools sounds good to me if we have conflicts because of that.

Long term I would prefer if we require a specific set of tools to be available (plus version) and provide build images + docker containers for testing that have the dependencies preinstalled. We should not be required to install debian packages or use go install at build or packaging time every single time. Rather auto-update the build images once a week.

Yep, this can be a good idea, specially for dependencies that cannot be installed with go install. The versions of these images should still be pinned in the repository. And possibly mage targets should be able to use them automatically, so if you change the version in your working copy you are certain that the development commands use the proper set of versions of the tools they need.

@urso
Copy link
Author

urso commented Jan 13, 2021

@jsoriano Have had to update some dependencies in go.mod, but it seems beats-ci is still happy. Any idea about the E2E-tests? Are the failures known or is there some other problem we need to fix in the Beats repo?

@urso
Copy link
Author

urso commented Jan 13, 2021

The versions of these images should still be pinned in the repository. And possibly mage targets should be able to use them automatically, so if you change the version in your working copy you are certain that the development commands use the proper set of versions of the tools they need.

Yes, fully agree. Some scripts for users/developers to install and update their dev environment should be available.

@jsoriano
Copy link
Member

@jsoriano Have had to update some dependencies in go.mod, but it seems beats-ci is still happy. Any idea about the E2E-tests? Are the failures known or is there some other problem we need to fix in the Beats repo?

Umm, I don't think these changes affect E2E testing, but just in case, @mdelapenya do you know if these failures in E2E tests are known?

@mdelapenya
Copy link
Contributor

About the two failures on the E2E side:

  1. The error in Fleet is some how flaky: it happens when the agent is not listed in the desired status. Taking a deep look to the errors, it failed on Debian and passed on Centos, which makes me think that it failed only this time, as they run exactly the same code.
[2021-01-13T18:27:01.519Z]     <testcase name="Un-installing the installed centos agent" status="passed" time="144.109955588"></testcase>
[2021-01-13T18:27:01.519Z]     <testcase name="Un-installing the installed debian agent" status="failed" time="364.552613125">
[2021-01-13T18:27:01.519Z]       <failure message="Step the agent is listed in Fleet as &#34;offline&#34;: The Agent is not in the offline status yet"></failure>
[2021-01-13T18:27:01.519Z]     </testcase>
  1. For the Ceph error, I'd say exactly the same: it failed for Ceph:master-97985eb-nautilus-centos-7-x86_64 and passed on Ceph:master-6373c6a-jewel-centos-7-x86_64, as they run exactly the same code.
[2021-01-13T18:09:33.847Z]     <testcase name="ceph-master-6373c6a-jewel-centos-7-x86_64 sends metrics to Elasticsearch without errors" status="passed" time="66.902762067"></testcase>
[2021-01-13T18:09:33.847Z]     <testcase name="ceph-master-97985eb-nautilus-centos-7-x86_64 sends metrics to Elasticsearch without errors" status="failed" time="66.447324996">
[2021-01-13T18:09:33.847Z]       <failure message="Step there are no errors in the index: Errors where found for ceph-pr-22541 on Metricbeat&#39;s metricbeat-pr-22541-ceph-master-97985eb-nautilus-centos-7-x86_64-mrhlqrhs index: 10 error/s out of 10"></failure>
[2021-01-13T18:09:33.847Z]     </testcase>

@urso
Copy link
Author

urso commented Jan 14, 2021

@mdelapenya Thank you!

@urso urso merged commit 2eb3c29 into elastic:master Jan 14, 2021
@urso urso deleted the test_reports_incomplete branch January 14, 2021 16:03
urso pushed a commit to urso/beats that referenced this pull request Jan 14, 2021
The PR introduces gotestsum to drive the go based unit and integration tests. This is meant as replacement for github.com/jstemmer/go-junit-report, which seems to be unmaintained for a while.

Only the GoTest mage helper is modified to use gotestsum instead of go-junit-reporter. In addition to the change we add unit tests for GoTest that do run actual tests. The output of these helper-tests is captured and validated against known regular expressions.

(cherry picked from commit 2eb3c29)
@urso urso added the v7.12.0 label Jan 14, 2021
urso pushed a commit that referenced this pull request Jan 14, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Team:Automation Label for the Observability productivity team Team:Services (Deprecated) Label for the former Integrations-Services team v7.12.0
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Test output of go tests is not printed in CI
8 participants