1696548 - Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/sessionstore/test/browser_reopen_all_windows.js | application timed out after 370 seconds with no output

Status: RESOLVED DUPLICATE of bug 1696137

(Firefox :: Session Restore, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-03-04T21:23:03.569Z] 21:23:03     INFO - TEST-START | browser/components/sessionstore/test/browser_reopen_all_windows.js
[task 2021-03-04T21:29:34.044Z] 21:29:33     INFO - Buffered messages logged at 21:23:03
[task 2021-03-04T21:29:35.033Z] 21:29:34     INFO - Entering test bound 
[task 2021-03-04T21:29:35.801Z] 21:29:35     INFO - TEST-PASS | browser/components/sessionstore/test/browser_reopen_all_windows.js | starting with no closed windows - 
[task 2021-03-04T21:29:36.733Z] 21:29:36     INFO - Buffered messages logged at 21:23:06
[task 2021-03-04T21:29:37.917Z] 21:29:36     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.com/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:39.220Z] 21:29:38     INFO - Buffered messages logged at 21:23:07
[task 2021-03-04T21:29:42.260Z] 21:29:41     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.org/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:44.134Z] 21:29:43     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://test1.mochi.test:8888/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:45.429Z] 21:29:45     INFO - Buffered messages logged at 21:23:08
[task 2021-03-04T21:29:46.412Z] 21:29:45     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://test1.example.com/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:47.170Z] 21:29:46     INFO - Buffered messages logged at 21:23:11
[task 2021-03-04T21:29:48.243Z] 21:29:47     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://sub1.test1.mochi.test:8888/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:49.297Z] 21:29:48     INFO - Buffered messages logged at 21:23:12
[task 2021-03-04T21:29:50.635Z] 21:29:49     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://sub2.xn--lt-uia.mochi.test:8888/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:52.485Z] 21:29:50     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://test2.mochi.test:8888/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:54.107Z] 21:29:53     INFO - Buffered messages logged at 21:23:13
[task 2021-03-04T21:29:55.791Z] 21:29:55     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://sub1.test2.example.org/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:57.352Z] 21:29:57     INFO - Buffered messages logged at 21:23:14
[task 2021-03-04T21:29:58.625Z] 21:29:57     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://sub2.test1.example.org/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:29:59.720Z] 21:29:57     INFO - Buffered messages logged at 21:23:15
[task 2021-03-04T21:30:00.529Z] 21:29:58     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://test2.example.com/browser/browser/components/sessionstore/test/empty.html" line: 0}]
[task 2021-03-04T21:30:02.380Z] 21:30:01     INFO - TEST-PASS | browser/components/sessionstore/test/browser_reopen_all_windows.js | The closed windows was added to Recently Closed Windows - 
[task 2021-03-04T21:30:05.754Z] 21:30:05     INFO - About to open the PanelUI menu
[task 2021-03-04T21:30:09.335Z] 21:30:08     INFO - Buffered messages logged at 21:23:16
[task 2021-03-04T21:30:11.402Z] 21:30:10     INFO - About to click on the Library option
[task 2021-03-04T21:30:13.441Z] 21:30:11     INFO - About to click on the History option
[task 2021-03-04T21:30:18.882Z] 21:30:18     INFO - Global property added while loading chrome://browser/content/places/browserPlacesViews.js: PlacesViewBase
[task 2021-03-04T21:30:20.744Z] 21:30:19     INFO - Buffered messages logged at 21:23:17
[task 2021-03-04T21:30:22.390Z] 21:30:20     INFO - About to click on 'Recently Closed Windows'
[task 2021-03-04T21:30:27.394Z] 21:30:26     INFO - Buffered messages logged at 21:23:23
[task 2021-03-04T21:30:30.693Z] 21:30:29     INFO - About to add an event listener for SSTabRestored
[task 2021-03-04T21:30:32.937Z] 21:30:32     INFO - About to wait for tabs to be restored
[task 2021-03-04T21:30:35.321Z] 21:30:34     INFO - Buffered messages finished
[task 2021-03-04T21:30:39.389Z] 21:30:38    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/sessionstore/test/browser_reopen_all_windows.js | application timed out after 370 seconds with no output
[task 2021-03-04T21:30:42.219Z] 21:30:41    ERROR - Force-terminating active process(es).
[task 2021-03-04T21:30:45.146Z] 21:30:44     INFO - Determining child pids from psutil...
[task 2021-03-04T21:30:54.207Z] 21:30:53     INFO - [1629, 1653, 1723, 1759, 1802, 1829, 2099]
[task 2021-03-04T21:31:01.416Z] 21:30:59     INFO - ==> process 1563 launched child process 1578
[task 2021-03-04T21:31:09.121Z] 21:31:07     INFO - ==> process 1563 launched child process 1629
[task 2021-03-04T21:31:14.491Z] 21:31:13     INFO - ==> process 1563 launched child process 1653
[task 2021-03-04T21:31:17.186Z] 21:31:16     INFO - ==> process 1563 launched child process 1723
[task 2021-03-04T21:31:20.497Z] 21:31:19     INFO - ==> process 1563 launched child process 1759
[task 2021-03-04T21:31:25.868Z] 21:31:25     INFO - ==> process 1563 launched child process 1802
[task 2021-03-04T21:31:29.070Z] 21:31:27     INFO - ==> process 1563 launched child process 1829
[task 2021-03-04T21:31:33.187Z] 21:31:32     INFO - Found child pids: set([1578, 1829, 1802, 2099, 1653, 1723, 1629, 1759])
[task 2021-03-04T21:31:38.037Z] 21:31:37     INFO - Failed to get child procs
[task 2021-03-04T21:31:39.788Z] 21:31:38     INFO - Killing process: 1578
[task 2021-03-04T21:31:42.200Z] 21:31:39     INFO - TEST-INFO | started process screentopng
[task 2021-03-04T21:48:29.160Z] 21:48:29     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', u'browser/components/sessionstore/test/browser.ini', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', u'--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LmeFtZtPRfGXQWXmZafMXg/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2021-03-04T21:48:29.177Z] 21:48:29    ERROR - timed out after 1000 seconds of no output
[task 2021-03-04T21:48:29.177Z] 21:48:29    ERROR - Return code: -15
[task 2021-03-04T21:48:29.177Z] 21:48:29    ERROR - No suite end message was emitted by this harness.
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>152/0/0
[task 2021-03-04T21:48:29.177Z] 21:48:29    ERROR - # TBPL FAILURE #
[task 2021-03-04T21:48:29.177Z] 21:48:29  WARNING - setting return code to 2
[task 2021-03-04T21:48:29.177Z] 21:48:29    ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - Running post-action listener: _package_coverage_data
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - Running post-action listener: _resource_record_post_action
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - Running post-action listener: process_java_coverage_data
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - [mozharness: 2021-03-04 21:48:29.043099Z] Finished run-tests step (success)
[task 2021-03-04T21:48:29.177Z] 21:48:29     INFO - Running post-run listener: _resource_record_post_run
[task 2021-03-04T21:48:29.842Z] 21:48:29     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-03-04T21:48:29.849Z] 21:48:29     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 24.28754355400698}, {"name": "io_write_bytes", "value": 2251579392}, {"name": "io.read_bytes", "value": 474492604416}, {"name": "io_write_time", "value": 276392}, {"name": "io_read_time", "value": 52371112}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.02124190330505371}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 41.755465030670166}, {"name": "cpu_percent", "value": 25.181874999999998}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.0003020763397216797}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 2119.883061170578}, {"name": "cpu_percent", "value": 24.26010409188802}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2021-03-04T21:48:29.849Z] 21:48:29     INFO - Total resource usage - Wall time: 2162s; CPU: 24.0%; Read bytes: 474492604416; Write bytes: 2251579392; Read time: 52371112; Write time: 276392
[task 2021-03-04T21:48:29.849Z] 21:48:29     INFO - TinderboxPrint: CPU usage<br/>24.3%
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: I/O read bytes / time<br/>474,492,604,416 / 52,371,112
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: I/O write bytes / time<br/>2,251,579,392 / 276,392
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: CPU idle<br/>1,898.0 (22.2%)
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: CPU iowait<br/>5,105.8 (59.7%)
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: CPU system<br/>348.0 (4.1%)
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: CPU user<br/>1,206.8 (14.1%)
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - install - Wall time: 42s; CPU: 25.0%; Read bytes: 143360; Write bytes: 1720967168; Read time: 0; Write time: 208536
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-03-04T21:48:29.850Z] 21:48:29     INFO - run-tests - Wall time: 2120s; CPU: 24.0%; Read bytes: 474492125184; Write bytes: 410476544; Read time: 52371064; Write time: 53536
[task 2021-03-04T21:48:30.170Z] 21:48:30  WARNING - returning nonzero exit status 2
[task 2021-03-04T21:48:30.251Z] cleanup
[task 2021-03-04T21:48:30.251Z] + cleanup
[task 2021-03-04T21:48:30.251Z] + local rv=2
[task 2021-03-04T21:48:30.251Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-03-04T21:48:30.251Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-03-04T21:48:30.406Z] + '[' ']'
[task 2021-03-04T21:48:30.406Z] + true
[task 2021-03-04T21:48:30.406Z] + cleanup_xvfb
[task 2021-03-04T21:48:30.406Z] ++ pidof Xvfb
[task 2021-03-04T21:48:30.423Z] + local xvfb_pid=51
[task 2021-03-04T21:48:30.423Z] + local vnc=false
[task 2021-03-04T21:48:30.423Z] + local interactive=false
[task 2021-03-04T21:48:30.423Z] + '[' -n 51 ']'
[task 2021-03-04T21:48:30.423Z] + [[ false == false ]]
[task 2021-03-04T21:48:30.423Z] + [[ false == false ]]
[task 2021-03-04T21:48:30.423Z] + kill 51
[task 2021-03-04T21:48:30.423Z] + screen -XS xvfb quit
[task 2021-03-04T21:48:30.691Z] + exit 2
[taskcluster 2021-03-04 21:48:32.207Z] === Task Finished ===
[taskcluster 2021-03-04 21:48:36.030Z] Unsuccessful task run with exit code: 2 completed in 2257.828 seconds```

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1696548&startday=2021-03-29&endday=2021-04-04&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

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

Comment 5

[u608768]

Will likely be fixed by bug 1703556.