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

Output reloading flaky test: Log when test fails #18071

Merged
merged 7 commits into from
May 26, 2020

Conversation

ycombinator
Copy link
Contributor

@ycombinator ycombinator commented Apr 28, 2020

What does this PR do?

Add logging when output reloading test fails.

Why is it important?

While we made some concurrency fixes to the output reloading code path in #17381, it appears there might still be a race condition somewhere. So far we have only seen this show up occasionally in CI (see test failures captured in #17965) and have not been able to reproduce it locally. So this PR will allow us to see logs of what was happening when the output reloading test fails.

Related issues

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

elasticmachine commented Apr 29, 2020

❕ Build Aborted

Either there was a build timeout or someone aborted the build.'}

Pipeline View Test View Changes Artifacts preview

Expand to view the summary

Build stats

Test stats 🧪

Test Results
Failed 0
Passed 7754
Skipped 1240
Total 8994

Log output

Expand to view the last 100 lines of log output

[2020-05-15T13:29:27.518Z] + [ -f libbeat/build/coverage/full.cov ]
[2020-05-15T13:29:27.518Z] + FILE=metricbeat/build/coverage/full.cov
[2020-05-15T13:29:27.518Z] + [ -f metricbeat/build/coverage/full.cov ]
[2020-05-15T13:29:27.518Z] + FILE=packetbeat/build/coverage/full.cov
[2020-05-15T13:29:27.518Z] + [ -f packetbeat/build/coverage/full.cov ]
[2020-05-15T13:29:27.518Z] + FILE=winlogbeat/build/coverage/full.cov
[2020-05-15T13:29:27.518Z] + [ -f winlogbeat/build/coverage/full.cov ]
[2020-05-15T13:29:27.518Z] + FILE=journalbeat/build/coverage/full.cov
[2020-05-15T13:29:27.518Z] + [ -f journalbeat/build/coverage/full.cov ]
[2020-05-15T13:29:28.785Z] Failed in branch Auditbeat x-pack
[2020-05-15T13:29:28.903Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats
[2020-05-15T13:29:29.216Z] + find . -type f -name TEST*.xml -path */build/* -delete
[2020-05-15T13:29:29.233Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Lint
[2020-05-15T13:29:29.317Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Elastic-Agent-Mac-OS-X
[2020-05-15T13:29:29.409Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Winlogbeat-oss
[2020-05-15T13:29:29.487Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Elastic-Agent-x-pack
[2020-05-15T13:29:29.567Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Dockerlogbeat
[2020-05-15T13:29:29.660Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Journalbeat-oss
[2020-05-15T13:29:29.737Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Generators-Metricbeat-Linux
[2020-05-15T13:29:29.817Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Functionbeat-x-pack
[2020-05-15T13:29:29.900Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Filebeat-Mac-OS-X
[2020-05-15T13:29:30.026Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-Mac-OS-X
[2020-05-15T13:29:30.109Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Elastic-Agent-x-pack-Windows
[2020-05-15T13:29:30.189Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Heartbeat-oss
[2020-05-15T13:29:30.269Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-crosscompile
[2020-05-15T13:29:30.342Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-OSS-Unit-tests
[2020-05-15T13:29:30.421Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Functionbeat-Mac-OS-X-x-pack
[2020-05-15T13:29:30.498Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Libbeat-x-pack
[2020-05-15T13:29:30.570Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Winlogbeat-Windows-x-pack
[2020-05-15T13:29:30.645Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Packetbeat-oss
[2020-05-15T13:29:30.722Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Heartbeat-Mac-OS-X
[2020-05-15T13:29:30.814Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Auditbeat-Linux
[2020-05-15T13:29:30.897Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Filebeat-Windows
[2020-05-15T13:29:30.974Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Auditbeat-crosscompile
[2020-05-15T13:29:31.051Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Winlogbeat-Windows
[2020-05-15T13:29:31.135Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-Windows
[2020-05-15T13:29:31.244Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Filebeat-x-pack
[2020-05-15T13:29:31.318Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Generators-Beat-Linux
[2020-05-15T13:29:31.395Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Auditbeat-Mac-OS-X
[2020-05-15T13:29:31.470Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Functionbeat-Windows
[2020-05-15T13:29:31.547Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Heartbeat-Windows
[2020-05-15T13:29:31.617Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Filebeat-oss
[2020-05-15T13:29:31.691Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-OSS-Integration-tests
[2020-05-15T13:29:31.770Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Libbeat-oss
[2020-05-15T13:29:31.841Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Generators-Metricbeat-Mac-OS-X
[2020-05-15T13:29:31.905Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Auditbeat-Windows
[2020-05-15T13:29:31.968Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Libbeat-crosscompile
[2020-05-15T13:29:32.038Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Libbeat-stress-tests
[2020-05-15T13:29:32.109Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-Python-integration-tests
[2020-05-15T13:29:32.183Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Generators-Beat-Mac-OS-X
[2020-05-15T13:29:32.251Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack
[2020-05-15T13:29:32.321Z] Running in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Auditbeat-x-pack
[2020-05-15T13:29:32.678Z] + cat
[2020-05-15T13:29:32.678Z] + /usr/local/bin/runbld ./runbld-script
[2020-05-15T13:29:32.678Z] Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF8
[2020-05-15T13:29:40.837Z] runbld>>> runbld started
[2020-05-15T13:29:40.837Z] runbld>>> 1.6.11/a66728ff8f4356963772e6e6d2069392fa06acbe
[2020-05-15T13:29:41.414Z] runbld>>> The following profiles matched the job 'Beats/beats-beats-mbp/PR-18071' in order of occurrence in the config (last value wins).
[2020-05-15T13:29:42.804Z] runbld>>> Debug logging enabled.
[2020-05-15T13:29:42.804Z] runbld>>> Storing result
[2020-05-15T13:29:43.077Z] runbld>>> Store result: created {:total 2, :successful 2, :failed 0} 1
[2020-05-15T13:29:43.077Z] runbld>>> BUILD: https://c150076387b5421f9154dfbf536e5c60.us-west1.gcp.cloud.es.io:9243/build-1587637540455/t/20200515132942-0C71F9F4
[2020-05-15T13:29:43.077Z] runbld>>> Adding system facts.
[2020-05-15T13:29:44.024Z] runbld>>> Adding vcs info for the latest commit:  159e8297cc3b99e11d24203bd369d7b62660ba16
[2020-05-15T13:29:44.024Z] runbld>>> >>>>>>>>>>>> SCRIPT EXECUTION BEGIN >>>>>>>>>>>>
[2020-05-15T13:29:44.024Z] runbld>>> Adding /usr/lib/jvm/java-8-openjdk-amd64/bin to the path.
[2020-05-15T13:29:44.285Z] + echo 'Processing JUnit reports with runbld...'
[2020-05-15T13:29:44.285Z] Processing JUnit reports with runbld...
[2020-05-15T13:29:44.548Z] runbld>>> <<<<<<<<<<<< SCRIPT EXECUTION END <<<<<<<<<<<<
[2020-05-15T13:29:44.548Z] runbld>>> DURATION: 30ms
[2020-05-15T13:29:44.548Z] runbld>>> STDOUT: 40 bytes
[2020-05-15T13:29:44.548Z] runbld>>> STDERR: 49 bytes
[2020-05-15T13:29:44.548Z] runbld>>> WRAPPED PROCESS: SUCCESS (0)
[2020-05-15T13:29:44.548Z] runbld>>> Searching for build metadata in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats
[2020-05-15T13:29:45.938Z] runbld>>> Storing build metadata: 
[2020-05-15T13:29:45.938Z] runbld>>> Adding test report.
[2020-05-15T13:29:45.938Z] runbld>>> Searching for junit test output files with the pattern: TEST-.*\.xml$ in: /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats
[2020-05-15T13:29:47.329Z] runbld>>> Found 102 test output files
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-openmetrics.xml
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-istio.xml
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-iis.xml
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-activemq.xml
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-tomcat.xml
[2020-05-15T13:29:47.907Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-x-pack/x-pack/metricbeat/build/TEST-go-integration-cloudfoundry.xml
[2020-05-15T13:29:48.859Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-OSS-Integration-tests/metricbeat/build/TEST-go-integration-windows.xml
[2020-05-15T13:29:48.859Z] runbld>>> No testsuite node found in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071/src/github.com/elastic/beats/Metricbeat-OSS-Integration-tests/metricbeat/build/TEST-go-integration-graphite.xml
[2020-05-15T13:29:49.121Z] runbld>>> Test output logs contained: Errors: 0 Failures: 0 Tests: 8844 Skipped: 1020
[2020-05-15T13:29:49.383Z] runbld>>> Storing result
[2020-05-15T13:29:49.383Z] runbld>>> FAILURES: 0
[2020-05-15T13:29:49.645Z] runbld>>> Store result: updated {:total 2, :successful 2, :failed 0} 2
[2020-05-15T13:29:49.645Z] runbld>>> BUILD: https://c150076387b5421f9154dfbf536e5c60.us-west1.gcp.cloud.es.io:9243/build-1587637540455/t/20200515132942-0C71F9F4
[2020-05-15T13:29:49.645Z] runbld>>> Email notification disabled by environment variable.
[2020-05-15T13:29:49.645Z] runbld>>> Slack notification disabled by environment variable.
[2020-05-15T13:29:55.268Z] Running on Jenkins in /var/lib/jenkins/workspace/Beats_beats-beats-mbp_PR-18071
[2020-05-15T13:29:55.379Z] [INFO] getVaultSecret: Getting secrets
[2020-05-15T13:29:55.444Z] Masking supported pattern matches of $VAULT_ADDR or $VAULT_ROLE_ID or $VAULT_SECRET_ID
[2020-05-15T13:29:56.356Z] + chmod 755 generate-build-data.sh
[2020-05-15T13:29:56.357Z] + ./generate-build-data.sh https://beats-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/Beats/beats-beats-mbp/PR-18071/ https://beats-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/Beats/beats-beats-mbp/PR-18071/runs/12 ABORTED 7387015
[2020-05-15T13:29:56.907Z] INFO: curl https://beats-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/Beats/beats-beats-mbp/PR-18071/runs/12/steps/?limit=10000 -o steps-info.json
[2020-05-15T13:29:58.251Z] INFO: curl https://beats-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/Beats/beats-beats-mbp/PR-18071/runs/12/tests/?status=FAILED -o tests-errors.json

@andresrc andresrc added Team:Services (Deprecated) Label for the former Integrations-Services team and removed needs_team Indicates that the issue/PR needs a Team:* label labels May 2, 2020
@elasticmachine
Copy link
Collaborator

Pinging @elastic/integrations-services (Team:Services)

@ycombinator ycombinator force-pushed the lb-reload-output-log branch from 471648c to f6dd27d Compare May 8, 2020 19:21
@ycombinator ycombinator marked this pull request as ready for review May 8, 2020 19:35
@ycombinator ycombinator requested a review from urso May 8, 2020 19:35
@ycombinator
Copy link
Contributor Author

jenkins, test this please

t.Errorf("expected %d traces, got %d", numBatches, len(transactions))
}
}

type bufLogger struct {
Copy link

Choose a reason for hiding this comment

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

why introduce a buffer instead of directly logging to t? In order to minimize noise in test output? In that case maybe add a comment explaining the why.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, exactly. So we only emit the log entries if the test fails, not if it succeeds. I will add the comment, thanks!

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done in 96b39e7.

@ycombinator ycombinator merged commit d5c7749 into elastic:master May 26, 2020
@ycombinator ycombinator added needs_backport PR is waiting to be backported to other branches. v7.9.0 v8.0.0 labels May 26, 2020
@zube zube bot added [zube]: Done and removed [zube]: In Review needs_backport PR is waiting to be backported to other branches. v7.9.0 v8.0.0 labels May 26, 2020
ycombinator added a commit that referenced this pull request Jun 1, 2020
* Log numbers if test fails

* Logging counts when test fails

* Introducing a buffered logger for testing

* Adding mutex to logger

* Fleshing out logger interface a bit more

* Pass down test logger

* Adding comment
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Team:Services (Deprecated) Label for the former Integrations-Services team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants