Closed Bug 1834895 Opened 1 year ago Closed 4 days ago

Intermittent TVw TinderboxPrint: Per-test run of .../RTCRtpReceiver-jitterBufferTarget-stats.html<br/>: FAILURE

Categories

(Core :: WebRTC, defect, P5)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
firefox-esr102 --- unaffected
firefox113 --- unaffected
firefox114 --- unaffected
firefox115 --- affected
firefox116 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=416931677&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W5p_uPtKSOC6QXGQ7NqD0Q/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W5p_uPtKSOC6QXGQ7NqD0Q/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2023-05-24T21:36:54.577Z] 21:36:54     INFO - TEST-OK | /webrtc-extensions/RTCRtpReceiver-jitterBufferTarget-stats.html | took 6346ms
[task 2023-05-24T21:36:54.578Z] 21:36:54     INFO - No more tests
[task 2023-05-24T21:36:54.579Z] 21:36:54     INFO - PID 1142 | 1684964214576	Marionette	INFO	Stopped listening on port 49276
[task 2023-05-24T21:36:54.909Z] 21:36:54     INFO - PID 1142 | [Child 1153: Socket Thread]: I/mtransport NrIceCtx(PC:{e92e2b79-4ec1-4575-9e54-e1f8211240d0} 1684964202139348 (id=6442450990 url=http://web-platform.test:8000/webrtc-extensions/RTCRtpReceiver-jitterBufferTarget-stats.html)): Destroy
[task 2023-05-24T21:36:54.910Z] 21:36:54     INFO - PID 1142 | [Child 1153: Socket Thread]: I/mtransport NrIceCtx(PC:{4ab7553e-1d44-43f0-9155-961e43a000c3} 1684964202015329 (id=6442450990 url=http://web-platform.test:8000/webrtc-extensions/RTCRtpReceiver-jitterBufferTarget-stats.html)): Destroy
[task 2023-05-24T21:36:54.911Z] 21:36:54     INFO - PID 1142 | [Child 1153: Socket Thread]: I/mtransport NrIceCtx(PC:{b07d00e8-9e76-4c22-b3b5-d9bbbcd1545b} 1684964202141223 (id=6442450990 url=http://web-platform.test:8000/webrtc-extensions/RTCRtpReceiver-jitterBufferTarget-stats.html)): Destroy
[task 2023-05-24T21:36:54.911Z] 21:36:54     INFO - PID 1142 | [Child 1153: Socket Thread]: I/mtransport NrIceCtx(PC:{1c36a002-95b3-477a-b67a-a87115e455e7} 1684964202140345 (id=6442450990 url=http://web-platform.test:8000/webrtc-extensions/RTCRtpReceiver-jitterBufferTarget-stats.html)): Destroy
[task 2023-05-24T21:36:55.237Z] 21:36:55     INFO - Browser exited with return code 0
[task 2023-05-24T21:36:55.240Z] 21:36:55     INFO - Closing logging queue
[task 2023-05-24T21:36:55.240Z] 21:36:55     INFO - queue closed
[task 2023-05-24T21:36:55.260Z] Exception in thread ProcessReader:
[task 2023-05-24T21:36:55.260Z] Traceback (most recent call last):
[task 2023-05-24T21:36:55.260Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 926, in _bootstrap_inner
[task 2023-05-24T21:36:55.260Z]     self.run()
[task 2023-05-24T21:36:55.260Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 870, in run
[task 2023-05-24T21:36:55.260Z]     self._target(*self._args, **self._kwargs)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/mozharness/mozprocess/processhandler.py", line 1160, in _read
[task 2023-05-24T21:36:55.260Z]     callback(line.rstrip())
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/mozharness/mozprocess/processhandler.py", line 1066, in __call__
[task 2023-05-24T21:36:55.260Z]     e(*args, **kwargs)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/mozharness/mozharness/base/script.py", line 1600, in processOutput
[task 2023-05-24T21:36:55.260Z]     parser.add_lines(line)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/mozharness/mozharness/base/log.py", line 371, in add_lines
[task 2023-05-24T21:36:55.260Z]     self.parse_single_line(line)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/mozharness/mozharness/mozilla/structuredlog.py", line 124, in parse_single_line
[task 2023-05-24T21:36:55.260Z]     log_data = self.formatter(data)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/build/venv/lib/python3.7/site-packages/mozlog/formatters/tbplformatter.py", line 47, in __call__
[task 2023-05-24T21:36:55.260Z]     return super(TbplFormatter, self).__call__(data)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/build/venv/lib/python3.7/site-packages/mozlog/reader.py", line 72, in __call__
[task 2023-05-24T21:36:55.260Z]     return handler(data)
[task 2023-05-24T21:36:55.260Z]   File "/opt/worker/tasks/task_168496397948092/build/venv/lib/python3.7/site-packages/mozlog/formatters/tbplformatter.py", line 311, in suite_end
[task 2023-05-24T21:36:55.260Z]     time = int((data["time"] - start_time) / 1000)
[task 2023-05-24T21:36:55.260Z] TypeError: unsupported operand type(s) for -: 'int' and 'NoneType'
[task 2023-05-24T21:36:55.260Z] 
[task 2023-05-24T21:54:32.413Z] 21:54:32     INFO - Return code: 1
[task 2023-05-24T21:54:32.413Z] 21:54:32  WARNING - setting return code to 2
[task 2023-05-24T21:54:32.413Z] 21:54:32    ERROR - TinderboxPrint: Per-test run of .../RTCRtpReceiver-jitterBufferTarget-stats.html<br/>: FAILURE
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - Running post-action listener: _package_coverage_data
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - Running post-action listener: _resource_record_post_action
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - Running post-action listener: process_java_coverage_data
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - Running post-action listener: stop_device
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - [mozharness: 2023-05-24 21:54:32.414293Z] Finished run-tests step (success)
[task 2023-05-24T21:54:32.414Z] 21:54:32     INFO - Running post-run listener: _resource_record_post_run
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - Total resource usage - Wall time: 1170s; CPU: 3%; Read bytes: 308449280; Write bytes: 954982400; Read time: 3313; Write time: 3668
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: CPU usage<br/>3.3%
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: I/O read bytes / time<br/>308,449,280 / 3,313
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: I/O write bytes / time<br/>954,982,400 / 3,668
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: CPU idle<br/>13,471.3 (96.0%)
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: CPU system<br/>184.3 (1.3%)
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: CPU user<br/>380.8 (2.7%)
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - TinderboxPrint: Swap in / out<br/>684,593,152 / 0
[task 2023-05-24T21:54:32.561Z] 21:54:32     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-05-24T21:54:32.562Z] 21:54:32     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-05-24T21:54:32.562Z] 21:54:32     INFO - verify-device - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-05-24T21:54:32.563Z] 21:54:32     INFO - install - Wall time: 21s; CPU: 13%; Read bytes: 311703040; Write bytes: 250920960; Read time: 17474; Write time: 426
[task 2023-05-24T21:54:32.578Z] 21:54:32     INFO - run-tests - Wall time: 1149s; CPU: 3%; Read bytes: 243388416; Write bytes: 688222208; Read time: 2788; Write time: 3203
[task 2023-05-24T21:54:32.847Z] 21:54:32  WARNING - returning nonzero exit status 2
[taskcluster 2023-05-24T21:54:33.179Z]    Exit Code: 2
[taskcluster 2023-05-24T21:54:33.179Z]    User Time: 5m58.699519s
[taskcluster 2023-05-24T21:54:33.179Z]  Kernel Time: 2m43.796916s
[taskcluster 2023-05-24T21:54:33.179Z]    Wall Time: 21m29.029549s
[taskcluster 2023-05-24T21:54:33.179Z]       Result: FAILED
[taskcluster 2023-05-24T21:54:33.179Z] === Task Finished ===
[taskcluster 2023-05-24T21:54:33.179Z] Task Duration: 21m29.034057s
[taskcluster 2023-05-24T21:54:33.237Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-05-23T21:08:38.872Z
[taskcluster 2023-05-24T21:54:33.569Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2024-05-23T21:08:38.872Z
[taskcluster 2023-05-24T21:54:34.782Z] Uploading artifact public/test_info/wpt-test1_errorsummary.log from file build/blobber_upload_dir/wpt-test1_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2024-05-23T21:08:38.872Z
[taskcluster 2023-05-24T21:54:34.892Z] Uploading artifact public/test_info/wpt_instruments.txt from file build/blobber_upload_dir/wpt_instruments.txt with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2024-05-23T21:08:38.872Z
[taskcluster 2023-05-24T21:54:34.986Z] Uploading artifact public/test_info/wptreport.json from file build/blobber_upload_dir/wptreport.json with content encoding "gzip", mime type "application/json" and expiry 2024-05-23T21:08:38.872Z
[taskcluster 2023-05-24T21:54:35.081Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W5p_uPtKSOC6QXGQ7NqD0Q/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2024-05-23T21:08:38.872Z
[taskcluster:error] exit status 2

:dbaker, since you are the author of the regressor, bug 1834531, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(dbaker)

Set release status flags based on info from the regressing bug 1834531

status-firefox113: --- → unaffected
status-firefox114: --- → unaffected
status-firefox115: --- → affected
status-firefox-esr102: --- → unaffected

Set release status flags based on info from the regressing bug 1834531

status-firefox116: --- → affected

My understanding is that test verify wont look at the metadata for a test. If this is true then this will continue to be an issue as something with the performance when running this test under the beta simulation fails intermittently on linux. There is hope that with some upstream libwebrtc improvements this test could pass consistently. I'm tracking to verify if this is the case here bug 1839229.

Flags: needinfo?(dbaker)

This test does not seem to exist anymore.

Status: NEW → RESOLVED
Closed: 4 days ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.