1860719 - HighFreq BC Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_169812189975612/build/venv/bin/python', '-u', '/opt/worker/tasks/task_169812189975612/build/tests/mochitest/runtests.py', 'browser | single tracking bug

Status: RESOLVED FIXED

(Firefox :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-10-24T05:19:58.649Z] 05:19:58     INFO - GECKO(5286) | [Parent 5286, Main Thread] WARNING: NS_ENSURE_TRUE(she && she->mInfo->mSharedState.Get()) failed: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:1159
[task 2023-10-24T05:19:58.840Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2023-10-24T05:19:58.840Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: APZ flush done in parent proc
[task 2023-10-24T05:19:58.841Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2023-10-24T05:19:58.843Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: done promiseFocus
[task 2023-10-24T05:19:58.845Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2023-10-24T05:19:58.846Z] 05:19:58     INFO - GECKO(5286) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2023-10-24T05:19:58.847Z] 05:19:58     INFO - GECKO(5286) | PromiseApzRepaintsFlushed: APZ flush done
[task 2023-10-24T05:19:58.848Z] 05:19:58     INFO - GECKO(5286) | WaitUntilApzStable: all done
[task 2023-10-24T05:19:58.859Z] 05:19:58     INFO - GECKO(5286) | [Child 5343: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 10c076000 == 1 [pid = 5343] [id = 0]
[task 2023-10-24T05:19:58.859Z] 05:19:58     INFO - GECKO(5286) | [Child 5343: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (108b3e3e0) [pid = 5343] [serial = 1] [outer = 0]
[task 2023-10-24T05:19:58.860Z] 05:19:58     INFO - GECKO(5286) | [Parent 5286, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3103
[task 2023-10-24T05:19:58.860Z] 05:19:58     INFO - GECKO(5286) | [Child 5343: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (10c07bc00) [pid = 5343] [serial = 2] [outer = 108b3e3e0]
[task 2023-10-24T05:19:58.884Z] 05:19:58     INFO - GECKO(5286) | [Child 5343: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (10c07d400) [pid = 5343] [serial = 3] [outer = 108b3e3e0]
[task 2023-10-24T05:19:58.885Z] 05:19:58     INFO - GECKO(5286) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/7c/pf5gtst92v9bdx689246zdd4000014/T/tmp_9_80fcg.mozrunner/runtests_leaks_tab_pid5344.log
[task 2023-10-24T05:19:58.893Z] 05:19:58     INFO - GECKO(5286) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/7c/pf5gtst92v9bdx689246zdd4000014/T/tmp_9_80fcg.mozrunner/runtests_leaks_tab_pid5345.log
[task 2023-10-24T05:19:58.934Z] 05:19:58     INFO - GECKO(5286) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/7c/pf5gtst92v9bdx689246zdd4000014/T/tmp_9_80fcg.mozrunner/runtests_leaks_tab_pid5346.log
[task 2023-10-24T05:19:59.131Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2023-10-24T05:19:59.131Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: APZ flush done in parent proc
[task 2023-10-24T05:19:59.131Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2023-10-24T05:19:59.132Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: done promiseFocus
[task 2023-10-24T05:19:59.133Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2023-10-24T05:19:59.133Z] 05:19:59     INFO - GECKO(5286) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2023-10-24T05:19:59.135Z] 05:19:59     INFO - GECKO(5286) | PromiseApzRepaintsFlushed: APZ flush done
[task 2023-10-24T05:19:59.135Z] 05:19:59     INFO - GECKO(5286) | WaitUntilApzStable: all done
[task 2023-10-24T05:20:01.384Z] 05:20:01     INFO - GECKO(5286) | [Child 5296: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (122c78400) [pid = 5296] [serial = 12] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:01.385Z] 05:20:01     INFO - GECKO(5286) | [Child 5296: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (122c81800) [pid = 5296] [serial = 14] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:01.403Z] 05:20:01     INFO - GECKO(5286) | [Child 5297: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 12836d000 == 0 [pid = 5297] [id = 4] [url = about:blank]
[task 2023-10-24T05:20:01.584Z] 05:20:01     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 116584c00 == 2 [pid = 5288] [id = 4] [url = about:blank]
[task 2023-10-24T05:20:01.584Z] 05:20:01     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 116584800 == 1 [pid = 5288] [id = 5] [url = about:blank]
[task 2023-10-24T05:20:01.745Z] 05:20:01     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (10fd3e7a0) [pid = 5288] [serial = 15] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:01.745Z] 05:20:01     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (10fd3e3e0) [pid = 5288] [serial = 13] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:05.962Z] 05:20:05     INFO - GECKO(5286) | [Child 5297: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (10e83e5c0) [pid = 5297] [serial = 11] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:06.247Z] 05:20:06     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (116585c00) [pid = 5288] [serial = 14] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:06.248Z] 05:20:06     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (116589000) [pid = 5288] [serial = 18] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:06.249Z] 05:20:06     INFO - GECKO(5286) | [Child 5288: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (116585400) [pid = 5288] [serial = 16] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:07.275Z] 05:20:07     INFO - GECKO(5286) | [Child 5342: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 122b81800 == 1 [pid = 5342] [id = 1] [url = about:blank]
[task 2023-10-24T05:20:07.287Z] 05:20:07     INFO - GECKO(5286) | [Child 5342: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (10903ed40) [pid = 5342] [serial = 4] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:08.242Z] 05:20:08     INFO - GECKO(5286) | JavaScript error: eval, line 4: TypeError: (destructured parameter) is not iterable
[task 2023-10-24T05:20:10.779Z] 05:20:10     INFO - GECKO(5286) | [Child 5297: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (128368400) [pid = 5297] [serial = 13] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:11.808Z] 05:20:11     INFO - GECKO(5286) | [Child 5342: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (122b7ac00) [pid = 5342] [serial = 2] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:11.809Z] 05:20:11     INFO - GECKO(5286) | [Child 5342: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (122b81c00) [pid = 5342] [serial = 5] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:12.077Z] 05:20:12     INFO - GECKO(5286) | [Child 5343: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (10c07bc00) [pid = 5343] [serial = 2] [outer = 0] [url = about:blank]
[task 2023-10-24T05:20:22.853Z] 05:20:22     INFO - GECKO(5286) | [Child 5298: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (116d61800) [pid = 5298] [serial = 11] [outer = 0] [url = about:blank]
[task 2023-10-24T05:37:02.873Z] 05:37:02     INFO - Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_169812189975612/build/venv/bin/python', '-u', '/opt/worker/tasks/task_169812189975612/build/tests/mochitest/runtests.py', 'browser/base/content/test/captivePortal/browser.toml', 'browser/base/content/test/notificationbox/browser.toml', 'browser/base/content/test/privateBrowsing/browser.toml', 'browser/base/content/test/tabs/browser.toml', 'browser/components/downloads/test/browser/browser.toml', 'browser/components/extensions/test/browser/browser.toml', 'browser/components/pocket/test/browser.toml', 'browser/components/search/test/browser/google_codes/browser.toml', 'browser/components/urlbar/tests/browser-tips/browser.toml', 'browser/extensions/formautofill/test/browser/heuristics/third_party/browser.toml', 'dom/base/test/fullscreen/browser.toml', 'dom/ipc/tests/browser.toml', 'dom/security/test/mixedcontentblocker/browser.toml', 'gfx/layers/apz/test/mochitest/browser.toml', 'layout/tools/layout-debug/tests/browser/browser.toml', 'toolkit/components/aboutprocesses/tests/browser/browser.toml', 'toolkit/components/credentialmanagement/tests/browser/browser.toml', 'toolkit/components/normandy/test/browser/browser.toml', 'toolkit/components/shopping/test/browser/browser.toml', 'toolkit/crashreporter/test/browser/browser.toml', '--setpref=layout.css.stylo-threads=4', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--appname=/opt/worker/tasks/task_169812189975612/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=/opt/worker/tasks/task_169812189975612/build/symbols', '--certificate-path=tests/certs', '--quiet', '--log-errorsummary=/opt/worker/tasks/task_169812189975612/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/opt/worker/tasks/task_169812189975612/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[taskcluster:error] Aborting task...
[taskcluster:warn 2023-10-24T06:01:47.335Z] no such process
[taskcluster 2023-10-24T06:01:47.336Z] === Task Finished ===
[taskcluster 2023-10-24T06:01:47.336Z] Task Duration: 1h30m0.196359s
[taskcluster 2023-10-24T06:01:47.411Z] Uploading artifact public/logs/localconfig.json from file /opt/worker/tasks/task_169812189975612/logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-01-22T04:01:41.845Z
[taskcluster 2023-10-24T06:01:47.739Z] Uploading artifact public/test_info/manifests.list from file /opt/worker/tasks/task_169812189975612/build/blobber_upload_dir/manifests.list with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2024-01-22T04:01:41.845Z
[taskcluster 2023-10-24T06:01:48.007Z] Uploading artifact public/test_info/mochitest-browser-chrome_errorsummary.log from file /opt/worker/tasks/task_169812189975612/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2024-01-22T04:01:41.845Z
[taskcluster 2023-10-24T06:01:48.342Z] Uploading artifact public/test_info/system-info.log from file /opt/worker/tasks/task_169812189975612/build/blobber_upload_dir/system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2024-01-22T04:01:41.845Z
[taskcluster 2023-10-24T06:01:48.616Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-01-22T04:01:41.845Z
[taskcluster:error] Task aborted - max run time exceeded

Comment 1

[Intermittent Failures Robot]

52 failures in 706 pushes (0.074 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 14
• autoland: 28
• try: 10

Platform and build breakdown:

• windows11-64-2009-qr: 30
  • debug: 30
• macosx1015-64-qr: 13
  • debug: 13
• windows11-64-2009-asan-qr: 7
  • opt: 7
• linux1804-64-qr: 2
  • debug: 2

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

Comment 2

[Cosmin Sabou [:CosminS]]

Fixed by this backout: https://bugzilla.mozilla.org/show_bug.cgi?id=1421651#c26

Comment 3

[Intermittent Failures Robot]

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

This is the #17 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: 22
• autoland: 39
• try: 10

Platform and build breakdown:

• windows11-64-2009-qr: 36
  • debug: 36
• windows11-64-2009-asan-qr: 8
  • opt: 8
• macosx1015-64-qr: 25
  • debug: 25
• linux1804-64-qr: 2
  • debug: 2

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

Comment 4

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

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