1848277 - Perma [tier 2] Btime raptor-browsertime Critical: Failed waiting on page https://www.linkedin.com/feed/ to finished loading, timed out after 120000 ms WebDriverError: Failed to decode response from marionette

Status: NEW

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-08-11T06:03:15.953Z] 06:03:15     INFO -  raptor-browsertime Info: timeout (s): 60000
[task 2023-08-11T06:03:15.953Z] 06:03:15     INFO -  raptor-browsertime Info: browsertime cwd: /home/cltbld/tasks/task_169173366118785/build
[task 2023-08-11T06:03:15.956Z] 06:03:15     INFO -  raptor-browsertime Info: browsertime cmd: /home/cltbld/tasks/task_169173366118785/fetches/node/bin/node /home/cltbld/tasks/task_169173366118785/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath /home/cltbld/tasks/task_169173366118785/fetches/geckodriver /home/cltbld/tasks/task_169173366118785/build/tests/raptor/raptor/browsertime/../../browsertime/browsertime_pageload.js --firefox.noDefaultPrefs --browsertime.page_cycle_delay 1000 --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --beforePageCompleteWaitTime 2000 --timeouts.pageLoad 60000 --timeouts.script 120000 --browsertime.page_cycles 2 --pageCompleteWaitTime 5000 --browsertime.url https://www.linkedin.com/feed/ --browsertime.post_startup_delay 1000 --iterations 25 --browsertime.chimera true --browsertime.test_bytecode_cache false --firefox.perfStats false --browsertime.moz_fetch_dir /home/cltbld/tasks/task_169173366118785/fetches --browsertime.expose_profiler false --browsertime.secondary_url https://www.linkedin.com/in/thommy-harris-hk-385723106/ --browsertime.commands  --viewPort 1280x1024 --browser firefox --firefox.binaryPath /home/cltbld/tasks/task_169173366118785/build/application/firefox/firefox --resultDir /home/cltbld/tasks/task_169173366118785/build/blobber_upload_dir/browsertime-results/linkedin --firefox.profileTemplate /tmp/tmpf3oq0mbu/profile --video true --visualMetrics true --visualMetricsContentful true --visualMetricsPerceptual true --visualMetricsPortable true --videoParams.keepOriginalVideo true --firefox.windowRecorder true --browsertime.testName linkedin --browsertime.liveSite False --browsertime.loginRequired True
[task 2023-08-11T06:03:15.956Z] 06:03:15     INFO -  raptor-browsertime Info: browsertime_ffmpeg: /home/cltbld/tasks/task_169173366118785/fetches/ffmpeg-4.4.1-i686-static/ffmpeg
[task 2023-08-11T06:03:15.957Z] 06:03:15     INFO -  raptor-browsertime Info: PATH: b'/home/cltbld/tasks/task_169173366118785/fetches/ffmpeg-4.4.1-i686-static:/home/cltbld/tasks/task_169173366118785/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin'
[task 2023-08-11T06:03:15.957Z] 06:03:15     INFO -  raptor-browsertime Info: Calling browsertime with proc_timeout=5025, and output_timeout=120
[task 2023-08-11T06:03:16.708Z] 06:03:16     INFO -  raptor-browsertime Info: Running tests using Firefox - 25 iteration(s)
[task 2023-08-11T06:03:16.734Z] 06:03:16     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2023-08-11T06:03:19.405Z] 06:03:19     INFO -  raptor-browsertime Info: Starting a browsertime pageload
[task 2023-08-11T06:03:19.405Z] 06:03:19     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2023-08-11T06:03:20.407Z] 06:03:20     INFO -  raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2023-08-11T06:03:20.408Z] 06:03:20     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2023-08-11T06:03:25.458Z] 06:03:25     INFO -  raptor-browsertime Info: Navigating to primary url:https://www.linkedin.com/feed/
[task 2023-08-11T06:03:25.459Z] 06:03:25     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2023-08-11T06:03:26.459Z] 06:03:26     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2023-08-11T06:03:26.460Z] 06:03:26     INFO -  raptor-browsertime Info: Testing url https://www.linkedin.com/feed/ iteration 1
[task 2023-08-11T06:03:26.463Z] 06:03:26     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2023-08-11T06:03:32.355Z] 06:03:32    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2023-08-11T06:03:32.377Z] 06:03:32     INFO -  raptor-browsertime Info:     at Object.throwDecodedError (/home/cltbld/tasks/task_169173366118785/fetches/browsertime/node_modules/selenium-webdriver/lib/error.js:524:15)
[task 2023-08-11T06:03:32.378Z] 06:03:32     INFO -  raptor-browsertime Info:     at parseHttpResponse (/home/cltbld/tasks/task_169173366118785/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:601:13)
[task 2023-08-11T06:03:32.380Z] 06:03:32     INFO -  raptor-browsertime Info:     at Executor.execute (/home/cltbld/tasks/task_169173366118785/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:529:28)
[task 2023-08-11T06:03:32.381Z] 06:03:32     INFO -  raptor-browsertime Info:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
[task 2023-08-11T06:03:32.382Z] 06:03:32     INFO -  raptor-browsertime Info:     at async Driver.execute (/home/cltbld/tasks/task_169173366118785/fetches/browsertime/node_modules/selenium-webdriver/lib/webdriver.js:745:17)
[task 2023-08-11T06:03:32.384Z] 06:03:32     INFO -  raptor-browsertime Info: URL failed to load, trying 5 more time(s): Failed waiting on page https://www.linkedin.com/feed/  to finished loading, timed out after 120000 ms
[task 2023-08-11T06:03:32.385Z] 06:03:32 CRITICAL -  raptor-browsertime Critical: Failed waiting on page https://www.linkedin.com/feed/ to finished loading, timed out after 120000 ms WebDriverError: Failed to decode response from marionette
[task 2023-08-11T06:03:32.386Z] 06:03:32     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2023-08-11T06:03:32.386Z] 06:03:32     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2023-08-11T06:03:32.387Z] 06:03:32     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 3190
[task 2023-08-11T06:03:32.599Z] 06:03:32     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2023-08-11T06:03:32.599Z] 06:03:32     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2023-08-11T06:03:32.600Z] 06:03:32     INFO -  raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_169173366118785/build/application/firefox/distribution/policies.json
[task 2023-08-11T06:03:32.600Z] 06:03:32     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpf3oq0mbu
[task 2023-08-11T06:03:32.609Z] 06:03:32    ERROR -  Traceback (most recent call last):
[task 2023-08-11T06:03:32.609Z] 06:03:32     INFO -    File "/home/cltbld/tasks/task_169173366118785/build/tests/raptor/raptor/raptor.py", line 190, in <module>
[task 2023-08-11T06:03:32.609Z] 06:03:32     INFO -      main()
[task 2023-08-11T06:03:32.609Z] 06:03:32     INFO -    File "/home/cltbld/tasks/task_169173366118785/build/tests/raptor/raptor/raptor.py", line 136, in main
[task 2023-08-11T06:03:32.610Z] 06:03:32     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2023-08-11T06:03:32.610Z] 06:03:32     INFO -    File "/home/cltbld/tasks/task_169173366118785/build/tests/raptor/raptor/perftest.py", line 468, in run_tests
[task 2023-08-11T06:03:32.610Z] 06:03:32     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2023-08-11T06:03:32.610Z] 06:03:32     INFO -    File "/home/cltbld/tasks/task_169173366118785/build/tests/raptor/raptor/browsertime/base.py", line 890, in run_test
[task 2023-08-11T06:03:32.610Z] 06:03:32     INFO -      raise Exception(self.browsertime_failure)
[task 2023-08-11T06:03:32.611Z] 06:03:32     INFO -  Exception: Failed waiting on page https://www.linkedin.com/feed/ to finished loading, timed out after 120000 ms WebDriverError: Failed to decode response from marionette
[task 2023-08-11T06:03:32.662Z] 06:03:32     INFO - Return code: 1
[task 2023-08-11T06:03:32.662Z] 06:03:32  WARNING - setting return code to 1
[task 2023-08-11T06:03:32.662Z] 06:03:32     INFO - Copying Raptor results to upload dir:
[task 2023-08-11T06:03:32.662Z] 06:03:32     INFO - /home/cltbld/tasks/task_169173366118785/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-11T06:03:32.662Z] 06:03:32     INFO - Copying raptor results from /home/cltbld/tasks/task_169173366118785/build/raptor.json to /home/cltbld/tasks/task_169173366118785/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-11T06:03:32.662Z] 06:03:32 CRITICAL - Error copying results /home/cltbld/tasks/task_169173366118785/build/raptor.json to upload dir /home/cltbld/tasks/task_169173366118785/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-11T06:03:32.662Z] 06:03:32     INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_169173366118785/build/raptor.json'
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - Running post-action listener: _package_coverage_data
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - Running post-action listener: _resource_record_post_action
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - Running post-action listener: process_java_coverage_data
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - Running post-action listener: stop_device
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - [mozharness: 2023-08-11 06:03:32.663649Z] Finished run-tests step (success)
[task 2023-08-11T06:03:32.663Z] 06:03:32     INFO - Running post-run listener: _resource_record_post_run
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - Total resource usage - Wall time: 64s; CPU: 6%; Read bytes: 220028928; Write bytes: 835989504; Read time: 1016; Write time: 9096
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: CPU usage<br/>5.9%
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: I/O read bytes / time<br/>220,028,928 / 1,016
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: I/O write bytes / time<br/>835,989,504 / 9,096
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: CPU idle<br/>480.3 (93.6%)
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: CPU user<br/>26.3 (5.1%)
[task 2023-08-11T06:03:32.743Z] 06:03:32     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-08-11T06:03:32.744Z] 06:03:32     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 2023-08-11T06:03:32.744Z] 06:03:32     INFO - install - Wall time: 10s; CPU: 13%; Read bytes: 0; Write bytes: 19963904; Read time: 0; Write time: 116
[task 2023-08-11T06:03:32.746Z] 06:03:32     INFO - run-tests - Wall time: 54s; CPU: 5%; Read bytes: 217538560; Write bytes: 816009216; Read time: 1016; Write time: 8980
[task 2023-08-11T06:03:32.778Z] 06:03:32  WARNING - returning nonzero exit status 1
[taskcluster 2023-08-11T06:03:32.815Z]    Exit Code: 1
[taskcluster 2023-08-11T06:03:32.815Z]    User Time: 1m37.870128s
[taskcluster 2023-08-11T06:03:32.815Z]  Kernel Time: 7.963213s
[taskcluster 2023-08-11T06:03:32.815Z]    Wall Time: 2m30.1614287s
[taskcluster 2023-08-11T06:03:32.815Z]       Result: FAILED
[taskcluster 2023-08-11T06:03:32.815Z] === Task Finished ===
[taskcluster 2023-08-11T06:03:32.815Z] Task Duration: 2m30.163171695s
[taskcluster 2023-08-11T06:03:33.311Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-08-10T05:56:42.837Z
[taskcluster 2023-08-11T06:03:33.618Z] 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 2024-08-10T05:56:42.837Z
[taskcluster 2023-08-11T06:03:33.860Z] 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-08-10T05:56:42.837Z
[taskcluster 2023-08-11T06:03:34.141Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-08-10T05:56:42.837Z
[taskcluster:error] exit status 1

Comment 1

[Cristian Tuns]

Backfills link: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&fromchange=516ee21f6fadeeeebc38630ed354e94ada9da2f4&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Cshippable%2Copt%2Cbrowsertime%2Cperformance%2Ctests%2Con%2Cfirefox%2Ctest-linux1804-64-shippable-qr%2Fopt-browsertime-tp6-firefox-linkedin%2Clinkedin&tochange=fae9c8496544fb4597f4094d95b81fdefec01628&selectedTaskRun=XzL0n-WaQfWIVy8lS18JeA.0

Comment 2

[Cristian Tuns]

Hi, can you please take a look at this? we don't know what caused we only have a range above ^ . Maybe you know what caused it, or maybe someone who can help. Thanks!

Comment 3

[Alastor Wu [:alwu]]

The error seems related with webdriver, and I didn't see any bug directly related with that... Not sure if bug 1824051 would be related with that or not. The error also seems happening while running browsertime_ffmpeg. I wonder if there is any media in that page which couldn't finish loading, then causing the test failed.

Paul, do you have any idea about this? Thanks!

Comment 4

[Greg Mierzwinski [:sparky]]

This test is using the Firefox Window Recorder: https://treeherder.mozilla.org/logviewer?job_id=425651534&repo=autoland&lineNumber=1358
The FFMPEG path is always printed since we pass it for visual-metric calculations.

Comment 5

[Intermittent Failures Robot]

30 failures in 493 pushes (0.061 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 23
• mozilla-central: 7

Platform and build breakdown:

• linux1804-64-shippable-qr: 13
  • opt: 13
• macosx1015-64-shippable-qr: 8
  • opt: 8
• windows10-64-shippable-qr: 8
  • opt: 8
• linux1804-64-clang-trunk-qr: 1
  • opt: 1

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

Comment 6

[Intermittent Failures Robot]

56 failures in 3341 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #16 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:

• autoland: 48
• mozilla-central: 8

Platform and build breakdown:

• linux1804-64-shippable-qr: 24
  • opt: 24
• macosx1015-64-shippable-qr: 17
  • opt: 17
• windows10-64-shippable-qr: 14
  • opt: 14
• linux1804-64-clang-trunk-qr: 1
  • opt: 1

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

Comment 7

[Paul Adenot (:padenot)]

This seems to work now? How can I repro this otherwise?

Comment 8

[Greg Mierzwinski [:sparky]]

It seems to have been resolved on this commit: https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=linkedin&revision=807120c9e29aa700f975e2739512c1934aa7722a

You should be able to reproduce by updating to this commit: https://treeherder.mozilla.org/jobs?repo=mozilla-central&revision=2be0ee236a5cef53847ab52c806c55bfd6b4ae6b&selectedTaskRun=FxcuU3GDRbSKOZVDURj4vQ.0

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

:dthayer, since you are the author of the regressor, bug 1824051, could you take a look?

For more information, please visit BugBot documentation.

Comment 10

[Paul Adenot (:padenot)]

Thanks, I've posted there, I don't think we have anything to do in the media team for this one, but we're around if need be.

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 12

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 13

[Intermittent Failures Robot]

1 failures in 4018 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1848277&startday=2023-10-02&endday=2023-10-08&tree=all

Comment 14

[Intermittent Failures Robot]

2 failures in 3764 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• linux64: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1848277&startday=2023-10-09&endday=2023-10-15&tree=all

Comment 15

[Intermittent Failures Robot]

2 failures in 3791 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1848277&startday=2024-03-18&endday=2024-03-24&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 3649 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1848277&startday=2024-06-03&endday=2024-06-09&tree=all

Comment 17

[Intermittent Failures Robot]

3 failures in 3459 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• macosx1015-64-shippable-qr: 3
  • opt: 3

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