1717754 - Perma [tier 2] Btime-fis welcome raptor-browsertime Critical: TypeError [ERR_INVALID_URL]: Invalid URL: null

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=343436270&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/J0Wgdo6cQbuTkGskuvAAmw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-06-21T23:26:28.678Z] 23:26:28     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2021-06-21T23:26:32.523Z] 23:26:32     INFO -  raptor-browsertime Info: First-install test ended.
[task 2021-06-21T23:26:32.926Z] 23:26:32     INFO -  raptor-browsertime Info: about:welcome DOMContentLoaded: 65ms firstPaint: 99ms FCP: 118ms Load: 72ms
[task 2021-06-21T23:26:32.926Z] 23:26:32     INFO -  raptor-browsertime Info: about:welcome?browsertime_run=2 DOMContentLoaded: 35ms firstPaint: 51ms FCP: 76ms Load: 36ms
[task 2021-06-21T23:26:35.102Z] 23:26:35     INFO -  raptor-browsertime Info: Starting a first-install test
[task 2021-06-21T23:26:35.103Z] 23:26:35     INFO -  raptor-browsertime Info: Navigating to about:blank
[task 2021-06-21T23:26:35.103Z] 23:26:35     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 8
[task 2021-06-21T23:26:35.132Z] 23:26:35    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2021-06-21T23:26:35.151Z] 23:26:35    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2021-06-21T23:26:35.151Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at onParseError (internal/url.js:258:9)'
[task 2021-06-21T23:26:35.151Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at new URL (internal/url.js:334:5)'
[task 2021-06-21T23:26:35.152Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at SeleniumRunner.loadAndWait (/opt/worker/tasks/task_162431762964224/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:212:22)'
[task 2021-06-21T23:26:35.152Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at runMicrotasks (<anonymous>)'
[task 2021-06-21T23:26:35.152Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at processTicksAndRejections (internal/process/task_queues.js:97:5)'
[task 2021-06-21T23:26:35.153Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at async module.exports (/opt/worker/tasks/task_162431762964224/build/tests/raptor/browsertime/welcome.js:13:5)'
[task 2021-06-21T23:26:35.153Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at async /opt/worker/tasks/task_162431762964224/fetches/browsertime/node_modules/browsertime/lib/core/engine/run.js:7:9'
[task 2021-06-21T23:26:35.153Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at async Iteration.run (/opt/worker/tasks/task_162431762964224/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:191:9)'
[task 2021-06-21T23:26:35.153Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at async Engine.runByScript (/opt/worker/tasks/task_162431762964224/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:220:20)'
[task 2021-06-21T23:26:35.154Z] 23:26:35     INFO -  raptor-browsertime Info: b'    at async run (/opt/worker/tasks/task_162431762964224/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:50:22)'
[task 2021-06-21T23:26:35.154Z] 23:26:35 CRITICAL -  raptor-browsertime Critical: TypeError [ERR_INVALID_URL]: Invalid URL: null
[task 2021-06-21T23:26:35.154Z] 23:26:35     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2021-06-21T23:26:35.154Z] 23:26:35     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2021-06-21T23:26:35.155Z] 23:26:35     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 885
[task 2021-06-21T23:26:35.456Z] 23:26:35     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2021-06-21T23:26:35.457Z] 23:26:35     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2021-06-21T23:26:35.457Z] 23:26:35     INFO -  raptor-mitmproxy Info: writing: /opt/worker/tasks/task_162431762964224/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2021-06-21T23:26:35.458Z] 23:26:35    ERROR -  Traceback (most recent call last):
[task 2021-06-21T23:26:35.458Z] 23:26:35     INFO -    File "/opt/worker/tasks/task_162431762964224/build/tests/raptor/raptor/raptor.py", line 213, in <module>
[task 2021-06-21T23:26:35.458Z] 23:26:35     INFO -      main()
[task 2021-06-21T23:26:35.459Z] 23:26:35     INFO -    File "/opt/worker/tasks/task_162431762964224/build/tests/raptor/raptor/raptor.py", line 159, in main
[task 2021-06-21T23:26:35.459Z] 23:26:35     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2021-06-21T23:26:35.459Z] 23:26:35     INFO -    File "/opt/worker/tasks/task_162431762964224/build/tests/raptor/raptor/perftest.py", line 442, in run_tests
[task 2021-06-21T23:26:35.459Z] 23:26:35     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2021-06-21T23:26:35.460Z] 23:26:35     INFO -    File "/opt/worker/tasks/task_162431762964224/build/tests/raptor/raptor/browsertime/base.py", line 502, in run_test
[task 2021-06-21T23:26:35.460Z] 23:26:35     INFO -      raise Exception(self.browsertime_failure)
[task 2021-06-21T23:26:35.460Z] 23:26:35     INFO -  Exception: TypeError [ERR_INVALID_URL]: Invalid URL: null
[task 2021-06-21T23:26:35.626Z] 23:26:35    ERROR - Return code: 1
[task 2021-06-21T23:26:35.626Z] 23:26:35  WARNING - setting return code to 1
[task 2021-06-21T23:26:35.626Z] 23:26:35     INFO - Copying Raptor results to upload dir:
[task 2021-06-21T23:26:35.626Z] 23:26:35     INFO - /opt/worker/tasks/task_162431762964224/build/blobber_upload_dir/perfherder-data.json
[task 2021-06-21T23:26:35.626Z] 23:26:35     INFO - Copying raptor results from /opt/worker/tasks/task_162431762964224/build/raptor.json to /opt/worker/tasks/task_162431762964224/build/blobber_upload_dir/perfherder-data.json
[task 2021-06-21T23:26:35.626Z] 23:26:35 CRITICAL - Error copying results /opt/worker/tasks/task_162431762964224/build/raptor.json to upload dir /opt/worker/tasks/task_162431762964224/build/blobber_upload_dir/perfherder-data.json
[task 2021-06-21T23:26:35.626Z] 23:26:35     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_162431762964224/build/raptor.json'
[task 2021-06-21T23:26:35.627Z] 23:26:35     INFO - Running post-action listener: _package_coverage_data
[task 2021-06-21T23:26:35.627Z] 23:26:35     INFO - Running post-action listener: _resource_record_post_action
[task 2021-06-21T23:26:35.627Z] 23:26:35     INFO - Running post-action listener: process_java_coverage_data
[task 2021-06-21T23:26:35.627Z] 23:26:35     INFO - Running post-action listener: stop_device
[task 2021-06-21T23:26:35.628Z] 23:26:35     INFO - [mozharness: 2021-06-21 23:26:35.627960Z] Finished run-tests step (success)
[task 2021-06-21T23:26:35.628Z] 23:26:35     INFO - Running post-run listener: _resource_record_post_run
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - Total resource usage - Wall time: 315s; CPU: 6%; Read bytes: 117305344; Write bytes: 994287616; Read time: 1030; Write time: 2148
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: CPU usage<br/>5.8%
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: I/O read bytes / time<br/>117,305,344 / 1,030
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: I/O write bytes / time<br/>994,287,616 / 2,148
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: CPU idle<br/>3,567.6 (94.3%)
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: CPU system<br/>67.2 (1.8%)
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: CPU user<br/>150.4 (4.0%)
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - TinderboxPrint: Swap in / out<br/>709,644,288 / 0
[task 2021-06-21T23:26:35.705Z] 23:26:35     INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-06-21T23:26:35.706Z] 23:26:35     INFO - install - Wall time: 34s; CPU: 14%; Read bytes: 456746496; Write bytes: 461762560; Read time: 30793; Write time: 846
[task 2021-06-21T23:26:35.710Z] 23:26:35     INFO - run-tests - Wall time: 283s; CPU: 5%; Read bytes: 111812608; Write bytes: 522727424; Read time: 920; Write time: 1279
[task 2021-06-21T23:26:35.785Z] 23:26:35  WARNING - returning nonzero exit status 1
[taskcluster 2021-06-21T23:26:35.813Z]    Exit Code: 1
[taskcluster 2021-06-21T23:26:35.813Z]    User Time: 2m6.588884s
[taskcluster 2021-06-21T23:26:35.813Z]  Kernel Time: 23.434421s
[taskcluster 2021-06-21T23:26:35.813Z]    Wall Time: 6m1.374376s
[taskcluster 2021-06-21T23:26:35.813Z]       Result: FAILED
[taskcluster 2021-06-21T23:26:35.813Z] === Task Finished ===
[taskcluster 2021-06-21T23:26:35.813Z] Task Duration: 6m1.377688s
[taskcluster 2021-06-21T23:26:35.870Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:36.121Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/1.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/1.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:37.310Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/2.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/2.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:38.325Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/3.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/3.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:38.653Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/4.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/4.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:38.797Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/5.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/5.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:38.941Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/6.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/6.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:39.104Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/data/video/7.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/data/video/7.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:39.333Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/1.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/1.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:39.594Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/2.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/2.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:39.807Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/3.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/3.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:40.075Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/4.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/4.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:40.347Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/5.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/5.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:40.641Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/6.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/6.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:40.857Z] Uploading artifact public/test_info/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/7.mp4 from file build/blobber_upload_dir/browsertime-results/welcome/pages/welcome/query-6bc054f4/data/video/7.mp4 with content encoding "gzip", mime type "video/mp4" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:41.095Z] Uploading artifact public/test_info/mitm_netlocs_dump.json from file build/blobber_upload_dir/mitm_netlocs_dump.json with content encoding "gzip", mime type "application/json" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:41.195Z] Uploading artifact public/test_info/mitmproxy.log from file build/blobber_upload_dir/mitmproxy.log with content encoding "gzip", mime type "text/plain" and expiry 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:41.287Z] 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 2022-06-21T21:38:35.930Z
[taskcluster 2021-06-21T23:26:41.455Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/J0Wgdo6cQbuTkGskuvAAmw/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-06-21T21:38:35.930Z
[taskcluster:error] exit status 1

Comment 1

[Alexandru Michis [:malexandru]]

This issue started appearing on the 22nd of June on Btime-fis 'welcome' tests: https://treeherder.mozilla.org/jobs?repo=mozilla-central&group_state=expanded&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&fromchange=2ad6d795630df04703a887f12f2fdba219bf7f4f&searchStr=welcome&tochange=536a892dd51f394af6c0638166e8cb7e467ae88c&selectedTaskRun=a2xNCH6-TuW_CxfjbYsewg.0

sparky, could you please take a look?

Comment 2

[Intermittent Failures Robot]

58 failures in 3115 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #24 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 54
• autoland: 4

Platform and build breakdown:

• linux1804-64-shippable-qr: 21
  • opt: 21
• macosx1014-64-shippable-qr: 15
  • opt: 15
• macosx1015-64-shippable-qr: 22
  • opt: 22

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1717754&startday=2021-06-21&endday=2021-06-27&tree=all

Comment 3

[Andreea Pavel [:apavel]]

There are 53 total failures in the last 7 days on

• linux1804-64-shippable-qr opt
• macosx1014-64-shippable-qr opt
  Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=344049144&repo=mozilla-central&lineNumber=1212

task 2021-06-28T23:44:52.620Z] 23:44:52 INFO - raptor-browsertime Info: about:welcome DOMContentLoaded: 50ms firstPaint: 97ms FCP: 129ms Load: 105ms
[task 2021-06-28T23:44:52.622Z] 23:44:52 INFO - raptor-browsertime Info: about:welcome?browsertime_run=2 DOMContentLoaded: 54ms firstPaint: 72ms FCP: 100ms Load: 56ms
[task 2021-06-28T23:44:54.543Z] 23:44:54 INFO - raptor-browsertime Info: Starting a first-install test
[task 2021-06-28T23:44:54.543Z] 23:44:54 INFO - raptor-browsertime Info: Navigating to about:blank
[task 2021-06-28T23:44:54.543Z] 23:44:54 INFO - raptor-browsertime Info: Navigating to url about:blank iteration 11
[task 2021-06-28T23:44:54.624Z] 23:44:54 ERROR - raptor-browsertime Error: Browsertime failed to run
[task 2021-06-28T23:44:54.644Z] 23:44:54 ERROR - raptor-browsertime Error: Browsertime failed to run
[task 2021-06-28T23:44:54.644Z] 23:44:54 INFO - raptor-browsertime Info: b' at onParseError (internal/url.js:258:9)'
[task 2021-06-28T23:44:54.645Z] 23:44:54 INFO - raptor-browsertime Info: b' at new URL (internal/url.js:334:5)'
[task 2021-06-28T23:44:54.645Z] 23:44:54 INFO - raptor-browsertime Info: b' at SeleniumRunner.loadAndWait (/home/cltbld/tasks/task_162491765131175/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:212:22)'
[task 2021-06-28T23:44:54.645Z] 23:44:54 INFO - raptor-browsertime Info: b' at runMicrotasks (<anonymous>)'
[task 2021-06-28T23:44:54.645Z] 23:44:54 INFO - raptor-browsertime Info: b' at processTicksAndRejections (internal/process/task_queues.js:97:5)'
[task 2021-06-28T23:44:54.645Z] 23:44:54 INFO - raptor-browsertime Info: b' at async module.exports (/home/cltbld/tasks/task_162491765131175/build/tests/raptor/browsertime/welcome.js:13:5)'
[task 2021-06-28T23:44:54.646Z] 23:44:54 INFO - raptor-browsertime Info: b' at async /home/cltbld/tasks/task_162491765131175/fetches/browsertime/node_modules/browsertime/lib/core/engine/run.js:7:9'
[task 2021-06-28T23:44:54.646Z] 23:44:54 INFO - raptor-browsertime Info: b' at async Iteration.run (/home/cltbld/tasks/task_162491765131175/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:191:9)'
[task 2021-06-28T23:44:54.646Z] 23:44:54 INFO - raptor-browsertime Info: b' at async Engine.runByScript (/home/cltbld/tasks/task_162491765131175/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:220:20)'
[task 2021-06-28T23:44:54.646Z] 23:44:54 INFO - raptor-browsertime Info: b' at async run (/home/cltbld/tasks/task_162491765131175/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:50:22)'
[task 2021-06-28T23:44:54.646Z] 23:44:54 CRITICAL - raptor-browsertime Critical: TypeError [ERR_INVALID_URL]: Invalid URL: null
[task 2021-06-28T23:44:54.646Z] 23:44:54 INFO - raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2021-06-28T23:44:54.647Z] 23:44:54 INFO - raptor-mitmproxy Info: Mitmproxy stop!!
[task 2021-06-28T23:44:54.647Z] 23:44:54 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 2928
[task 2021-06-28T23:44:54.851Z] 23:44:54 INFO - raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2021-06-28T23:44:54.851Z] 23:44:54 INFO - raptor-mitmproxy Info: Turning off the browser proxy
[task 2021-06-28T23:44:54.852Z] 23:44:54 INFO - raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_162491765131175/build/application/firefox/distribution/policies.json
[task 2021-06-28T23:44:54.852Z] 23:44:54 ERROR - Traceback (most recent call last):
[task 2021-06-28T23:44:54.852Z] 23:44:54 INFO - File "/home/cltbld/tasks/task_162491765131175/build/tests/raptor/raptor/raptor.py", line 213, in <module>
[task 2021-06-28T23:44:54.852Z] 23:44:54 INFO - main()
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - File "/home/cltbld/tasks/task_162491765131175/build/tests/raptor/raptor/raptor.py", line 159, in main
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - File "/home/cltbld/tasks/task_162491765131175/build/tests/raptor/raptor/perftest.py", line 442, in run_tests
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - File "/home/cltbld/tasks/task_162491765131175/build/tests/raptor/raptor/browsertime/base.py", line 502, in run_test
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - raise Exception(self.browsertime_failure)
[task 2021-06-28T23:44:54.853Z] 23:44:54 INFO - Exception: TypeError [ERR_INVALID_URL]: Invalid URL: null
[task 2021-06-28T23:44:54.915Z] 23:44:54 ERROR - Return code: 1
[task 2021-06-28T23:44:54.915Z] 23:44:54 WARNING - setting return code to 1

Comment 4

[Intermittent Failures Robot]

42 failures in 723 pushes (0.058 failures/push) were associated with this bug in the last 7 days.

This is the #11 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 40
• autoland: 2

Platform and build breakdown:

• linux1804-64-shippable-qr: 13
  • opt: 13
• macosx1015-64-shippable-qr: 16
  • opt: 16
• macosx1014-64-shippable-qr: 12
  • opt: 12
• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1717754&startday=2021-06-28&endday=2021-07-04&tree=all

Comment 5

[Greg Mierzwinski [:sparky]]

So the issue here is that this line in browsertime seems to intermittently return null when it should be either the about:blank or about:welcome pages: https://github.com/sitespeedio/browsertime/blob/51a59f0e62328e995903436918ee9a1ccb5fc28c/lib/core/seleniumRunner.js#L213

Comment 6

[Greg Mierzwinski [:sparky]]

The fact that we haven't seen this error elsewhere suggests to me that there's a race condition during the Firefox startup which is causing this. The reason I think this is happening is because we have no delay between when we start the browser and the test and when we navigate. In our other pageload tests we have at least 1 second before we start any navigations.

Comment 7

[Greg Mierzwinski [:sparky]]

I have a couple try runs here that might have a fix in them:
(1) https://treeherder.mozilla.org/jobs?repo=try&revision=8926a4cb2f01d49a7ec6654a3512c06da0d0f8bf
(2) https://treeherder.mozilla.org/jobs?repo=try&revision=2f33b50abd9b82e1c0ddddba5e93ef00fcaefdb1

The first one is just calling return document.documentURI; before the about:blank navigation and the second one uses a 1 second delay before navigating along with the call.

Comment 8

[Intermittent Failures Robot]

15 failures in 444 pushes (0.034 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 15

Platform and build breakdown:

• linux1804-64-shippable-qr: 6
  • opt: 6
• macosx1014-64-shippable-qr: 5
  • opt: 5
• macosx1015-64-shippable-qr: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1717754&startday=2021-07-08&endday=2021-07-08&tree=all

Comment 9

[Greg Mierzwinski [:sparky]]

Attachment: Bug 1717754 - Call document.documentURI before navigating during first-install test. r?#perftest

Comment 10

[Greg Mierzwinski [:sparky]]

So the solution to this issue is pretty odd. For some reason, if I call return document.documentURI within the test script, the SeleniumRunner in browsertime that runs the command never has any issues with it. I'm unsure if this is an issue in Firefox or in Geckodriver/Selenium.

Comment 11

[Florin Strugariu [:Bebe]]

Maybe Henrik know more about this.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+1]]

We have never seen something like that. If you could provide a geckodriver trace log I might be able to see something.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/30e2dd167637
Call document.documentURI before navigating during first-install test. r=perftest-reviewers,Bebe

Comment 14

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/30e2dd167637

Comment 15

[Intermittent Failures Robot]

51 failures in 2387 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #21 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 49
• autoland: 2

Platform and build breakdown:

• linux1804-64-shippable-qr: 17
  • opt: 17
• macosx1014-64-shippable-qr: 19
  • opt: 19
• macosx1015-64-shippable-qr: 15
  • opt: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1717754&startday=2021-07-05&endday=2021-07-11&tree=all