Closed Bug 1459784 Opened 7 years ago Closed 7 years ago

intermittent test-verify TinderboxPrint: Per-test run of .../unit/test_TelemetryHistograms.js<br/>: FAILURE

Categories

(Toolkit :: Telemetry, defect)

Product:
Toolkit
Component:
Telemetry
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1460666

People

(Reporter: tiberius_oros, Unassigned)

Details

[task 2018-05-07T19:30:11.455Z] 19:30:11 INFO - ::: Test verification summary for: /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryHistograms.js [task 2018-05-07T19:30:11.455Z] 19:30:11 INFO - ::: [task 2018-05-07T19:30:11.456Z] 19:30:11 INFO - ::: 1. Run each test 10 times, sequentially. : Pass [task 2018-05-07T19:30:11.457Z] 19:30:11 INFO - ::: 2. Run each test 10 times, sequentially, in chaos mode. : Pass [task 2018-05-07T19:30:11.457Z] 19:30:11 INFO - ::: [task 2018-05-07T19:30:11.458Z] 19:30:11 INFO - ::: Test verification PASSED [task 2018-05-07T19:30:11.458Z] 19:30:11 INFO - ::: [task 2018-05-07T19:30:11.474Z] 19:30:11 INFO - Return code: 0 [task 2018-05-07T19:30:11.474Z] 19:30:11 INFO - TinderboxPrint: xpcshell<br/>20/0/0 [task 2018-05-07T19:30:11.474Z] 19:30:11 INFO - ##### xpcshell log ends [task 2018-05-07T19:30:11.475Z] 19:30:11 INFO - # TBPL FAILURE # [task 2018-05-07T19:30:11.475Z] 19:30:11 INFO - TinderboxPrint: Per-test run of .../unit/test_TelemetryHistograms.js<br/>: FAILURE [task 2018-05-07T19:30:11.475Z] 19:30:11 INFO - Running post-action listener: _package_coverage_data [task 2018-05-07T19:30:11.475Z] 19:30:11 INFO - Running post-action listener: _resource_record_post_action [task 2018-05-07T19:30:11.475Z] 19:30:11 INFO - Running post-action listener: stop_emulator [task 2018-05-07T19:30:11.485Z] 19:30:11 INFO - Let's kill every process called emulator64-arm [task 2018-05-07T19:30:11.485Z] 19:30:11 INFO - Killing pid 904. [task 2018-05-07T19:30:11.485Z] 19:30:11 INFO - [mozharness: 2018-05-07 19:30:11.485666Z] Finished run-tests step (success) [task 2018-05-07T19:30:11.486Z] 19:30:11 INFO - Running post-run listener: _resource_record_post_run [task 2018-05-07T19:30:11.602Z] 19:30:11 INFO - Total resource usage - Wall time: 1742s; CPU: 25.0%; Read bytes: 287379456; Write bytes: 4269367296; Read time: 19644; Write time: 806388 [task 2018-05-07T19:30:11.603Z] 19:30:11 INFO - TinderboxPrint: CPU usage<br/>24.7% [task 2018-05-07T19:30:11.603Z] 19:30:11 INFO - TinderboxPrint: I/O read bytes / time<br/>287,379,456 / 19,644 [task 2018-05-07T19:30:11.603Z] 19:30:11 INFO - TinderboxPrint: I/O write bytes / time<br/>4,269,367,296 / 806,388 [task 2018-05-07T19:30:11.604Z] 19:30:11 INFO - TinderboxPrint: CPU idle<br/>5,164.4 (74.9%) [task 2018-05-07T19:30:11.604Z] 19:30:11 INFO - TinderboxPrint: CPU user<br/>1,674.0 (24.3%) [task 2018-05-07T19:30:11.604Z] 19:30:11 INFO - TinderboxPrint: Swap in / out<br/>0 / 0 [task 2018-05-07T19:30:11.609Z] 19:30:11 INFO - verify-emulator - Wall time: 345s; CPU: 28.0%; Read bytes: 5451776; Write bytes: 1234784256; Read time: 80; Write time: 304880 [task 2018-05-07T19:30:11.611Z] 19:30:11 INFO - install - Wall time: 51s; CPU: 36.0%; Read bytes: 0; Write bytes: 199348224; Read time: 0; Write time: 20880 [task 2018-05-07T19:30:11.625Z] 19:30:11 INFO - run-tests - Wall time: 1347s; CPU: 24.0%; Read bytes: 281526272; Write bytes: 2835234816; Read time: 19548; Write time: 480628 [task 2018-05-07T19:30:12.120Z] 19:30:12 INFO - Running post-run listener: copy_logs_to_upload_dir [task 2018-05-07T19:30:12.120Z] 19:30:12 INFO - Copying logs to upload dir... [task 2018-05-07T19:30:12.120Z] 19:30:12 INFO - mkdir: /builds/worker/workspace/build/upload/logs [task 2018-05-07T19:30:12.122Z] 19:30:12 INFO - Copying logs to upload dir... [task 2018-05-07T19:30:12.124Z] 19:30:12 WARNING - returning nonzero exit status 2 [task 2018-05-07T19:30:12.143Z] /builds/worker/bin/test-linux.sh: line 190: 80 Killed compiz 2>&1 [task 2018-05-07T19:30:12.143Z] cleanup [task 2018-05-07T19:30:12.143Z] + cleanup [task 2018-05-07T19:30:12.143Z] + local rv=2 [task 2018-05-07T19:30:12.143Z] + [[ -s /builds/worker/.xsession-errors ]] [task 2018-05-07T19:30:12.143Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log [task 2018-05-07T19:30:12.147Z] + true [task 2018-05-07T19:30:12.147Z] + cleanup_xvfb [task 2018-05-07T19:30:12.147Z] pidof Xvfb [task 2018-05-07T19:30:12.147Z] ++ pidof Xvfb [task 2018-05-07T19:30:12.151Z] + local xvfb_pid=26 [task 2018-05-07T19:30:12.151Z] + local vnc=false [task 2018-05-07T19:30:12.151Z] + local interactive=false [task 2018-05-07T19:30:12.151Z] + '[' -n 26 ']' [task 2018-05-07T19:30:12.151Z] + [[ false == false ]] [task 2018-05-07T19:30:12.151Z] + [[ false == false ]] [task 2018-05-07T19:30:12.151Z] + kill 26 [task 2018-05-07T19:30:12.151Z] + screen -XS xvfb quit [task 2018-05-07T19:30:12.350Z] No screen session found. [task 2018-05-07T19:30:12.351Z] + true [task 2018-05-07T19:30:12.351Z] + exit 2 [taskcluster 2018-05-07 19:30:12.774Z] === Task Finished === [taskcluster 2018-05-07 19:30:22.543Z] Unsuccessful task run with exit code: 2 completed in 2177.911 seconds
This is my first experience with tinderbox. Could you provide some information about what actions we can take to examine this failure?
Flags: needinfo?(toros)
:gfritzsche could you please help :chutten with some info? Thank you!
Flags: needinfo?(toros) → needinfo?(gfritzsche)
I'm not sure if i can add much here. Do you have any links you can add to specific tasks that failed and their logs?
Flags: needinfo?(gfritzsche) → needinfo?(toros)
Can you help me understand the log? Towards the bottom I see it running test_TelemetryHistogram.js 20 times without failure, then it says "Test verification PASSED"... but then there's a TBPL Failure without any interleaving logs. What does this mean? Does it mean one of the 20 test runs was actually a failure? I feel I'm lacking some basic context to understand what tinderbox is and how our tests might be failing it. The documentation I can find seems out-of-date (https://wiki.mozilla.org/Tinderbox says tinderbox was replaced, for instance).
Flags: needinfo?(toros)
(In reply to Chris H-C :chutten from comment #6) > Can you help me understand the log? Towards the bottom I see it running > test_TelemetryHistogram.js 20 times without failure, then it says "Test > verification PASSED"... but then there's a TBPL Failure without any > interleaving logs. > > What does this mean? Does it mean one of the 20 test runs was actually a > failure? I feel I'm lacking some basic context to understand what tinderbox > is and how our tests might be failing it. The documentation I can find seems > out-of-date (https://wiki.mozilla.org/Tinderbox says tinderbox was replaced, > for instance). In the log i see that the test suite ran 6 times, each test running 10 times. I don't think this means that at some point the test failed, being that each test suite has: [task 2018-05-07T19:30:11.458Z] 19:30:11 INFO - ::: Test verification PASSED [task 2018-05-07T19:30:11.458Z] 19:30:11 INFO - ::: [task 2018-05-07T19:30:11.474Z] 19:30:11 INFO - Return code: 0 ni? Aryx as he most likely can shed light on this. Thank you.
Flags: needinfo?(toros) → needinfo?(aryx.bugmail)
Status: NEW → RESOLVED
Closed: 7 years ago
Flags: needinfo?(aryx.bugmail)
Resolution: --- → DUPLICATE
(In reply to Chris H-C :chutten from comment #6) > Can you help me understand the log? Towards the bottom I see it running > test_TelemetryHistogram.js 20 times without failure, then it says "Test > verification PASSED"... but then there's a TBPL Failure without any > interleaving logs. Redirecting to Geoff. > The documentation I can find seems > out-of-date (https://wiki.mozilla.org/Tinderbox says tinderbox was replaced, > for instance). "TBPL" and "Tinderbox" are just markers for failures/log parsing which remained unchanged.
Flags: needinfo?(gbrown)
test-verify was broken for a while, producing these odd failures; I think this was fixed in bug 1460666.
Flags: needinfo?(gbrown)
You need to log in before you can comment on or make changes to this bug.