Open Bug 1873581 Opened 2 years ago Updated 6 days ago

Intermittent raptor-browsertime Critical: Failed waiting on page https://<URL>/ to finished loading, timed out after 120000 ms Error: Running page complete check

Categories

(Testing :: Raptor, defect, P5)

Product:
Testing
Component:
Raptor
Type:
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

[task 2024-01-09T01:15:22.566Z] 01:15:22     INFO -  raptor-browsertime Info: IndexedDB write data format Array
[task 2024-01-09T01:15:22.567Z] 01:15:22     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2024-01-09T01:15:22.567Z] 01:15:22     INFO -  raptor-browsertime Info: Navigating to url https://www.example.com iteration 1
[task 2024-01-09T01:17:27.524Z] 01:17:27    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2024-01-09T01:17:27.524Z] 01:17:27     INFO -  raptor-browsertime Info: return (function(waitTime) {
[task 2024-01-09T01:17:27.525Z] 01:17:27     INFO -  raptor-browsertime Info:     try {
[task 2024-01-09T01:17:27.525Z] 01:17:27     INFO -  raptor-browsertime Info:             var end = window.performance.timing.loadEventEnd;
[task 2024-01-09T01:17:27.525Z] 01:17:27     INFO -  raptor-browsertime Info:             var start= window.performance.timing.navigationStart;
[task 2024-01-09T01:17:27.526Z] 01:17:27     INFO -  raptor-browsertime Info:             return (end > 0) && (performance.now() > end - start + waitTime);
[task 2024-01-09T01:17:27.526Z] 01:17:27     INFO -  raptor-browsertime Info:     }
[task 2024-01-09T01:17:27.526Z] 01:17:27     INFO -  raptor-browsertime Info:     catch(e) {
[task 2024-01-09T01:17:27.527Z] 01:17:27     INFO -  raptor-browsertime Info:         return true;
[task 2024-01-09T01:17:27.527Z] 01:17:27     INFO -  raptor-browsertime Info:     }
[task 2024-01-09T01:17:27.527Z] 01:17:27     INFO -  raptor-browsertime Info: })(arguments[arguments.length - 1]);
[task 2024-01-09T01:17:27.528Z] 01:17:27     INFO -  raptor-browsertime Info:  took too long
[task 2024-01-09T01:17:27.528Z] 01:17:27     INFO -  raptor-browsertime Info: return (function(waitTime) {
[task 2024-01-09T01:17:27.528Z] 01:17:27     INFO -  raptor-browsertime Info:     try {
[task 2024-01-09T01:17:27.528Z] 01:17:27     INFO -  raptor-browsertime Info:             var end = window.performance.timing.loadEventEnd;
[task 2024-01-09T01:17:27.529Z] 01:17:27     INFO -  raptor-browsertime Info:             var start= window.performance.timing.navigationStart;
[task 2024-01-09T01:17:27.529Z] 01:17:27     INFO -  raptor-browsertime Info:             return (end > 0) && (performance.now() > end - start + waitTime);
[task 2024-01-09T01:17:27.529Z] 01:17:27     INFO -  raptor-browsertime Info:     }
[task 2024-01-09T01:17:27.530Z] 01:17:27     INFO -  raptor-browsertime Info:     catch(e) {
[task 2024-01-09T01:17:27.530Z] 01:17:27     INFO -  raptor-browsertime Info:         return true;
[task 2024-01-09T01:17:27.530Z] 01:17:27     INFO -  raptor-browsertime Info:     }
[task 2024-01-09T01:17:27.530Z] 01:17:27     INFO -  raptor-browsertime Info: })(arguments[arguments.length - 1]);
[task 2024-01-09T01:17:27.531Z] 01:17:27     INFO -  raptor-browsertime Info:  took too long
[task 2024-01-09T01:17:27.531Z] 01:17:27     INFO -  raptor-browsertime Info:     at Timeout.<anonymous> (file:///home/cltbld/tasks/task_170476278438531/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:45:16)
[task 2024-01-09T01:17:27.531Z] 01:17:27     INFO -  raptor-browsertime Info:     at listOnTimeout (node:internal/timers:559:17)
[task 2024-01-09T01:17:27.532Z] 01:17:27     INFO -  raptor-browsertime Info:     at processTimers (node:internal/timers:502:7)
[task 2024-01-09T01:17:27.532Z] 01:17:27     INFO -  raptor-browsertime Info: URL failed to load, trying 5 more time(s): Failed waiting on page https://www.example.com/  to finished loading, timed out after 120000 ms
[task 2024-01-09T01:17:27.532Z] 01:17:27 CRITICAL -  raptor-browsertime Critical: Failed waiting on page https://www.example.com/ to finished loading, timed out after 120000 ms Error: Running page complete check
[task 2024-01-09T01:17:27.533Z] 01:17:27     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2024-01-09T01:17:27.533Z] 01:17:27     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2024-01-09T01:17:27.533Z] 01:17:27     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 3162
[task 2024-01-09T01:17:27.673Z] 01:17:27     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2024-01-09T01:17:27.673Z] 01:17:27     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2024-01-09T01:17:27.673Z] 01:17:27     INFO -  raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_170476278438531/build/application/firefox/distribution/policies.json
[task 2024-01-09T01:17:27.674Z] 01:17:27     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmptz7nv4ev
[task 2024-01-09T01:17:27.681Z] 01:17:27    ERROR -  Traceback (most recent call last):
[task 2024-01-09T01:17:27.681Z] 01:17:27     INFO -    File "/home/cltbld/tasks/task_170476278438531/build/tests/raptor/raptor/raptor.py", line 186, in <module>
[task 2024-01-09T01:17:27.681Z] 01:17:27     INFO -      main()
[task 2024-01-09T01:17:27.682Z] 01:17:27     INFO -    File "/home/cltbld/tasks/task_170476278438531/build/tests/raptor/raptor/raptor.py", line 135, in main
[task 2024-01-09T01:17:27.682Z] 01:17:27     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2024-01-09T01:17:27.682Z] 01:17:27     INFO -    File "/home/cltbld/tasks/task_170476278438531/build/tests/raptor/raptor/perftest.py", line 484, in run_tests
[task 2024-01-09T01:17:27.682Z] 01:17:27     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2024-01-09T01:17:27.683Z] 01:17:27     INFO -    File "/home/cltbld/tasks/task_170476278438531/build/tests/raptor/raptor/browsertime/base.py", line 1005, in run_test
[task 2024-01-09T01:17:27.683Z] 01:17:27     INFO -      raise Exception(self.browsertime_failure)
[task 2024-01-09T01:17:27.683Z] 01:17:27     INFO -  Exception: Failed waiting on page https://www.example.com/ to finished loading, timed out after 120000 ms Error: Running page complete check
[task 2024-01-09T01:17:27.732Z] 01:17:27     INFO - Return code: 1
[task 2024-01-09T01:17:27.732Z] 01:17:27  WARNING - setting return code to 1
[task 2024-01-09T01:17:27.732Z] 01:17:27     INFO - Copying Raptor results to upload dir:
[task 2024-01-09T01:17:27.732Z] 01:17:27     INFO - /home/cltbld/tasks/task_170476278438531/build/blobber_upload_dir/perfherder-data.json
[task 2024-01-09T01:17:27.732Z] 01:17:27     INFO - Copying raptor results from /home/cltbld/tasks/task_170476278438531/build/raptor.json to /home/cltbld/tasks/task_170476278438531/build/blobber_upload_dir/perfherder-data.json
[task 2024-01-09T01:17:27.732Z] 01:17:27 CRITICAL - Error copying results /home/cltbld/tasks/task_170476278438531/build/raptor.json to upload dir /home/cltbld/tasks/task_170476278438531/build/blobber_upload_dir/perfherder-data.json
[task 2024-01-09T01:17:27.732Z] 01:17:27     INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_170476278438531/build/raptor.json'
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - Running post-action listener: _package_coverage_data
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - Running post-action listener: _resource_record_post_action
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - Running post-action listener: process_java_coverage_data
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - Running post-action listener: stop_device
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - [mozharness: 2024-01-09 01:17:27.733538Z] Finished run-tests step (success)
[task 2024-01-09T01:17:27.733Z] 01:17:27     INFO - Running post-run listener: _resource_record_post_run
[task 2024-01-09T01:17:27.958Z] 01:17:27     INFO - Total resource usage - Wall time: 176s; CPU: 3%; Read bytes: 201302016; Write bytes: 1638387712; Read time: 1352; Write time: 47104
[task 2024-01-09T01:17:27.958Z] 01:17:27     INFO - TinderboxPrint: CPU usage<br/>2.6%
[task 2024-01-09T01:17:27.958Z] 01:17:27     INFO - TinderboxPrint: I/O read bytes / time<br/>201,302,016 / 1,352
[task 2024-01-09T01:17:27.958Z] 01:17:27     INFO - TinderboxPrint: I/O write bytes / time<br/>1,638,387,712 / 47,104
[task 2024-01-09T01:17:27.959Z] 01:17:27     INFO - TinderboxPrint: CPU idle<br/>1,362.7 (97.1%)
[task 2024-01-09T01:17:27.959Z] 01:17:27     INFO - TinderboxPrint: CPU user<br/>31.4 (2.2%)
[task 2024-01-09T01:17:27.959Z] 01:17:27     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2024-01-09T01:17:27.960Z] 01:17:27     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 2024-01-09T01:17:27.964Z] 01:17:27     INFO - install - Wall time: 11s; CPU: 13%; Read bytes: 49152; Write bytes: 20766720; Read time: 0; Write time: 112
[task 2024-01-09T01:17:28.019Z] 01:17:28     INFO - run-tests - Wall time: 164s; CPU: 2%; Read bytes: 201252864; Write bytes: 1617620992; Read time: 1352; Write time: 46992
[task 2024-01-09T01:17:29.140Z] 01:17:29  WARNING - returning nonzero exit status 1
[taskcluster 2024-01-09T01:17:29.199Z]    Exit Code: 1
[taskcluster 2024-01-09T01:17:29.199Z]    User Time: 1m43.863931s
[taskcluster 2024-01-09T01:17:29.199Z]  Kernel Time: 9.496539s
[taskcluster 2024-01-09T01:17:29.199Z]    Wall Time: 4m23.079014181s
[taskcluster 2024-01-09T01:17:29.199Z]       Result: FAILED
[taskcluster 2024-01-09T01:17:29.199Z] === Task Finished ===
[taskcluster 2024-01-09T01:17:29.200Z] Task Duration: 4m23.082542391s
[taskcluster 2024-01-09T01:17:29.317Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-04-07T21:38:14.514Z
[taskcluster 2024-01-09T01:17:29.625Z] 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-04-07T21:38:14.514Z
[taskcluster 2024-01-09T01:17:29.904Z] Uploading artifact public/test_info/profile_resource-usage.json from file build/blobber_upload_dir/profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2024-04-07T21:38:14.514Z
[taskcluster 2024-01-09T01:17:30.182Z] 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-04-07T21:38:14.514Z
[taskcluster 2024-01-09T01:17:30.506Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-04-07T21:38:14.514Z
[taskcluster:error] exit status 1

:jari, there are a lot of failures happening for the indexeddb tests here, could you take a look?

Flags: needinfo?(jjalkanen)
See Also: → 1774954
Assignee: nobody → jjalkanen
Flags: needinfo?(jjalkanen)

As an update:
There are 158 failures in the last 7 days.
All of them are on linux1804-64-shippable-qr / opt

Flags: needinfo?(jjalkanen)

Jari, have you had a chance to look into this issue? Let us know if you need any help with it.

Flags: needinfo?(jjalkanen)
Flags: needinfo?(jjalkanen)

Looks like the linux failures here were related to bug 1877314. There are still a few mac failures though on the indexeddb tests.

Flags: needinfo?(jjalkanen)

Hi Jari! Have you had a chance to look into the remaining mac issues ?

Flags: needinfo?(jjalkanen)

We used to have a platform specific timeout which was throwing from the script when the limit was exceeded. Instead of that, for the sake of simplicity, we then decided to vary the amount of processing that gets done in the same time, and use a single timeout constant. This has now the downside that it's hard to tell whether the script takes too long, or if is it hanging before that. I think I will add back some kind of exception to the script to help with fault isolation.

Flags: needinfo?(jjalkanen)

Hi Jari, this failure spiked to 21 failures in the last week - have you had a chance to look for a fix for this issue?

Flags: needinfo?(jjalkanen)
Summary: Intermittent [tier 2] raptor-browsertime Critical: Failed waiting on page https://www.example.com/ to finished loading, timed out after 120000 ms Error: Running page complete check → Intermittent [tier 2] raptor-browsertime Critical: Failed waiting on page https://<URL>/ to finished loading, timed out after 120000 ms Error: Running page complete check
Duplicate of this bug: 1934171

Hi :agoloman, can you backfill to see if we could find a culprit commit for the increase in failures?

Assignee: jjalkanen → nobody
Flags: needinfo?(jjalkanen) → needinfo?(agoloman)

(In reply to Greg Mierzwinski [:sparky] from comment #62)

Hi :agoloman, can you backfill to see if we could find a culprit commit for the increase in failures?

Hi, on it!

Flags: needinfo?(agoloman)

Hi Greg! We did some retriggers and backfills but we didn't find something relevant. Here's an example from that period when there was a more recent spike. In addition, from the orange factor, there does not necessarily seem to be an increase in the number of failures, it seems a normal activity, in accordance with the number of occurrences of this bug since it was first spotted.

Flags: needinfo?(gmierz2)

Thanks for checking :serbans!

Flags: needinfo?(gmierz2)
Duplicate of this bug: 1902144
Whiteboard: [stockwell disable-recommended]
Summary: Intermittent [tier 2] raptor-browsertime Critical: Failed waiting on page https://<URL>/ to finished loading, timed out after 120000 ms Error: Running page complete check → Intermittent raptor-browsertime Critical: Failed waiting on page https://<URL>/ to finished loading, timed out after 120000 ms Error: Running page complete check

Hi Ryan, it looks like there's a cache folder issue in some of the failing tests in this bug. Do you know what might be causing this?

[task 2025-04-30T23:49:34.430Z] 23:49:34     INFO -  INFO - File mitmproxy-8.1.1-osx.tar.gz not present in local cache folder /builds/tooltool_cache
[task 2025-04-30T23:49:34.431Z] 23:49:34     INFO -  INFO - Attempting to fetch from 'http://localhost:8080/tooltool.mozilla-releng.net/'...
[task 2025-04-30T23:49:35.873Z] 23:49:35     INFO -  INFO - File mitmproxy-8.1.1-osx.tar.gz fetched from http://localhost:8080/tooltool.mozilla-releng.net/ as /opt/worker/tasks/task_174605687221569/testing/mozproxy/mitmdump-8.1.1/tmp_zgy28fm
[task 2025-04-30T23:49:35.941Z] 23:49:35     INFO -  INFO - File integrity verified, renaming tmp_zgy28fm to mitmproxy-8.1.1-osx.tar.gz
[task 2025-04-30T23:49:35.941Z] 23:49:35     INFO -  INFO - Updating local cache /builds/tooltool_cache...
[task 2025-04-30T23:49:35.941Z] 23:49:35     INFO -  INFO - Creating cache in /builds/tooltool_cache...
[task 2025-04-30T23:49:35.942Z] 23:49:35     INFO -  WARNING - Impossible to add file mitmproxy-8.1.1-osx.tar.gz to cache folder /builds/tooltool_cache
[task 2025-04-30T23:49:35.943Z] 23:49:35     INFO -  INFO - untarring "mitmproxy-8.1.1-osx.tar.gz"
[task 2025-04-30T23:49:36.097Z] 23:49:36     INFO -  raptor-mitmproxy Info: downloading mitmproxy pageset
[task 2025-04-30T23:49:36.210Z] 23:49:36     INFO -  INFO - File mitm8-linux-firefox-example.zip not present in local cache folder /builds/tooltool_cache
[task 2025-04-30T23:49:36.210Z] 23:49:36     INFO -  INFO - Attempting to fetch from 'http://localhost:8080/tooltool.mozilla-releng.net/'...
[task 2025-04-30T23:49:36.523Z] 23:49:36     INFO -  INFO - File mitm8-linux-firefox-example.zip fetched from http://localhost:8080/tooltool.mozilla-releng.net/ as /opt/worker/tasks/task_174605687221569/testing/mozproxy/tmpgx1sow4x
[task 2025-04-30T23:49:36.523Z] 23:49:36     INFO -  INFO - File integrity verified, renaming tmpgx1sow4x to mitm8-linux-firefox-example.zip
[task 2025-04-30T23:49:36.523Z] 23:49:36     INFO -  INFO - Updating local cache /builds/tooltool_cache...
[task 2025-04-30T23:49:36.523Z] 23:49:36     INFO -  INFO - Creating cache in /builds/tooltool_cache...
[task 2025-04-30T23:49:36.524Z] 23:49:36     INFO -  WARNING - Impossible to add file mitm8-linux-firefox-example.zip to cache folder /builds/tooltool_cache

Here's a link to the failure: https://treeherder.mozilla.org/jobs?repo=mozilla-central&selectedTaskRun=UP0JJF0dQoqZKKXGNpkAGw.0&searchStr=test-macosx1470-64-shippable%2Fopt-browsertime-indexeddb-firefox-idb-open-few-par&revision=9ce66cc9e864ac6752aff8b8ec1db28fc6eed391

It's something related to the /builds/tooltool_cache folder. We had an issue related to a .cache folder a while ago, and I wonder if this is related: https://phabricator.services.mozilla.com/D239172

Flags: needinfo?(rcurran)

Hi :sparky

I do not think writing directly to / anymore (even with SIP disabled) is permitted.

[root@macmini-m4-8.local ~]# csrutil status
System Integrity Protection status: disabled.
[root@macmini-m4-8.local ~]# mkdir /builds
mkdir: /builds: Read-only file system
[root@macmini-m4-8.local ~]#

Let me know if you need more info

Flags: needinfo?(rcurran)
You need to log in before you can comment on or make changes to this bug.