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

Status: RESOLVED INCOMPLETE

(Firefox :: Session Restore, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-02-02T17:21:09.583Z] 17:21:09     INFO - TEST-START | browser/components/sessionstore/test/browser_forget_async_closings.js
[task 2021-02-02T17:28:39.682Z] 17:28:38     INFO - Buffered messages logged at 17:21:09
[task 2021-02-02T17:28:43.841Z] 17:28:43     INFO - Entering test bound test_forget_closed_tab
[task 2021-02-02T17:28:50.026Z] 17:28:48     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | We should have 0 closed tabs being stored. - 
[task 2021-02-02T17:28:52.158Z] 17:28:51     INFO - Buffered messages logged at 17:21:10
[task 2021-02-02T17:28:56.623Z] 17:28:55     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should have forgotten the closed tab - 
[task 2021-02-02T17:29:01.629Z] 17:29:01     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should not have stored the forgotten closed tab - 
[task 2021-02-02T17:29:05.508Z] 17:29:04     INFO - Leaving test bound test_forget_closed_tab
[task 2021-02-02T17:29:15.934Z] 17:29:15     INFO - Entering test bound test_forget_closed_window
[task 2021-02-02T17:29:26.308Z] 17:29:25     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | We should have 0 closed windows being stored. - 
[task 2021-02-02T17:29:32.710Z] 17:29:31     INFO - Buffered messages logged at 17:21:21
[task 2021-02-02T17:29:36.513Z] 17:29:35     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should have forgotten the closed window - 
[task 2021-02-02T17:29:43.506Z] 17:29:42     INFO - Buffered messages logged at 17:21:26
[task 2021-02-02T17:29:48.517Z] 17:29:47     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | domwindowclosed should already be handled here - 
[task 2021-02-02T17:29:54.969Z] 17:29:54     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should not have stored the closed window - 
[task 2021-02-02T17:29:57.431Z] 17:29:56     INFO - Leaving test bound test_forget_closed_window
[task 2021-02-02T17:30:03.217Z] 17:30:02     INFO - Entering test bound test_forget_purged_tab
[task 2021-02-02T17:30:08.871Z] 17:30:08     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | We should have 0 closed tabs being stored. - 
[task 2021-02-02T17:30:13.290Z] 17:30:12     INFO - Buffered messages logged at 17:21:27
[task 2021-02-02T17:30:18.153Z] 17:30:17     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should have forgotten the closed tab - 
[task 2021-02-02T17:30:19.851Z] 17:30:18     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should not have stored the forgotten closed tab - 
[task 2021-02-02T17:30:24.653Z] 17:30:23     INFO - Leaving test bound test_forget_purged_tab
[task 2021-02-02T17:30:27.796Z] 17:30:27     INFO - Entering test bound test_forget_purged_window
[task 2021-02-02T17:30:30.800Z] 17:30:30     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | We should have 0 closed windows being stored. - 
[task 2021-02-02T17:30:34.035Z] 17:30:33     INFO - Buffered messages logged at 17:22:12
[task 2021-02-02T17:30:38.163Z] 17:30:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_forget_async_closings.js | Should have forgotten the closed window - 
[task 2021-02-02T17:30:40.190Z] 17:30:39     INFO - Buffered messages finished
[task 2021-02-02T17:30:41.743Z] 17:30:40    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/sessionstore/test/browser_forget_async_closings.js | application timed out after 370 seconds with no output
[task 2021-02-02T17:30:43.926Z] 17:30:42    ERROR - Force-terminating active process(es).
[task 2021-02-02T17:30:50.802Z] 17:30:49     INFO - Determining child pids from psutil...
[task 2021-02-02T17:31:06.786Z] 17:31:06     INFO - [1631, 1714, 1825, 1746, 1779, 1656]
[task 2021-02-02T17:31:09.428Z] 17:31:08     INFO - ==> process 1567 launched child process 1582
[task 2021-02-02T17:31:11.837Z] 17:31:10     INFO - ==> process 1567 launched child process 1631
[task 2021-02-02T17:31:14.097Z] 17:31:13     INFO - ==> process 1567 launched child process 1656
[task 2021-02-02T17:31:17.833Z] 17:31:17     INFO - ==> process 1567 launched child process 1714
[task 2021-02-02T17:31:19.802Z] 17:31:17     INFO - ==> process 1567 launched child process 1746
[task 2021-02-02T17:31:23.750Z] 17:31:22     INFO - ==> process 1567 launched child process 1779
[task 2021-02-02T17:31:27.095Z] 17:31:26     INFO - ==> process 1567 launched child process 1825
[task 2021-02-02T17:31:32.295Z] 17:31:31     INFO - Found child pids: set([1825, 1746, 1582, 1714, 1779, 1656, 1631])
[task 2021-02-02T17:31:37.992Z] 17:31:37     INFO - Failed to get child procs
[task 2021-02-02T17:31:39.713Z] 17:31:38     INFO - Killing process: 1825
[task 2021-02-02T17:31:43.206Z] 17:31:42     INFO - TEST-INFO | started process screentopng
[task 2021-02-02T17:37:17.442Z] 17:37:17     INFO - TEST-INFO | screentopng: exit 0
[task 2021-02-02T17:37:17.460Z] 17:37:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:37:47.420Z] 17:37:47     INFO - failed to kill pid 1825 after 30s
[task 2021-02-02T17:37:47.420Z] 17:37:47     INFO - Killing process: 1746
[task 2021-02-02T17:37:47.420Z] 17:37:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:37:47.420Z] 17:37:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:38:17.443Z] 17:38:17     INFO - failed to kill pid 1746 after 30s
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Killing process: 1582
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Error: Failed to kill process 1582: psutil.NoSuchProcess no process found with pid 1582
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Killing process: 1714
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:38:17.444Z] 17:38:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:38:47.464Z] 17:38:47     INFO - failed to kill pid 1714 after 30s
[task 2021-02-02T17:38:47.464Z] 17:38:47     INFO - Killing process: 1779
[task 2021-02-02T17:38:47.464Z] 17:38:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:38:47.464Z] 17:38:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:39:17.480Z] 17:39:17     INFO - failed to kill pid 1779 after 30s
[task 2021-02-02T17:39:17.481Z] 17:39:17     INFO - Killing process: 1656
[task 2021-02-02T17:39:17.481Z] 17:39:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:39:17.481Z] 17:39:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:39:47.502Z] 17:39:47     INFO - failed to kill pid 1656 after 30s
[task 2021-02-02T17:39:47.502Z] 17:39:47     INFO - Killing process: 1631
[task 2021-02-02T17:39:47.502Z] 17:39:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:39:47.502Z] 17:39:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:40:17.524Z] 17:40:17     INFO - failed to kill pid 1631 after 30s
[task 2021-02-02T17:40:17.524Z] 17:40:17     INFO - Killing process: 1567
[task 2021-02-02T17:40:17.525Z] 17:40:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:40:17.525Z] 17:40:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-02-02T17:40:47.539Z] 17:40:47     INFO - psutil found pid 1567 dead
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1779 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 2062 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1825 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1714 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1746 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 2064 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1631 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 1656 after 30s
[task 2021-02-02T17:40:47.540Z] 17:40:47     INFO - failed to kill pid 2089 after 30s
[task 2021-02-02T17:40:47.541Z] 17:40:47     INFO - psutil found pid 1567 dead
[task 2021-02-02T17:40:47.544Z] 17:40:47  WARNING - runtests.py | Failed to get app exit code - running/crashed?
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - TEST-INFO | Main app process: exit 0
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - runtests.py | Application ran for: 0:26:52.703634
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - zombiecheck | Reading PID log: /tmp/tmpZ0w92gpidlog
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - ==> process 1567 launched child process 1582
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - ==> process 1567 launched child process 1631
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - ==> process 1567 launched child process 1656
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - ==> process 1567 launched child process 1714
[task 2021-02-02T17:40:47.544Z] 17:40:47     INFO - ==> process 1567 launched child process 1746
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - ==> process 1567 launched child process 1779
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - ==> process 1567 launched child process 1825
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - ==> process 1567 launched child process 2064
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - ==> process 1567 launched child process 2089
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1825
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 2089
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1746
[task 2021-02-02T17:40:47.545Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1582
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 2064
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1714
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1779
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1656
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - zombiecheck | Checking for orphan process with PID: 1631
[task 2021-02-02T17:40:47.546Z] 17:40:47     INFO - Stopping web server
[task 2021-02-02T17:40:47.562Z] 17:40:47     INFO - Stopping web socket server
[task 2021-02-02T17:40:47.582Z] 17:40:47     INFO - Stopping ssltunnel
[task 2021-02-02T17:40:47.603Z] 17:40:47  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-02-02T17:40:47.603Z] 17:40:47     INFO - runtests.py | Running tests: end.
[task 2021-02-02T17:40:47.650Z] 17:40:47     INFO - Buffered messages finished
[task 2021-02-02T17:40:47.650Z] 17:40:47     INFO -  TEST-INFO | checking window state
[task 2021-02-02T17:40:47.650Z] 17:40:47     INFO -  Browser Chrome Test Summary
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO -  	Passed: 0
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO -  	Failed: 0
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO -  	Todo: 0
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO -  	Mode: e10s
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO -  *** End BrowserChrome Test Results ***
[task 2021-02-02T17:40:47.651Z] 17:40:47     INFO - Buffered messages finished
[task 2021-02-02T17:40:47.652Z] 17:40:47     INFO - SUITE-END | took 1614s
[task 2021-02-02T17:40:47.728Z] 17:40:47    ERROR - Return code: 1
[task 2021-02-02T17:40:47.729Z] 17:40:47     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>141/0/0
[task 2021-02-02T17:40:47.730Z] 17:40:47    ERROR - # TBPL FAILURE #
[task 2021-02-02T17:40:47.730Z] 17:40:47  WARNING - setting return code to 2
[task 2021-02-02T17:40:47.730Z] 17:40:47    ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2021-02-02T17:40:47.730Z] 17:40:47     INFO - Running post-action listener: _package_coverage_data
[task 2021-02-02T17:40:47.730Z] 17:40:47     INFO - Running post-action listener: _resource_record_post_action
[task 2021-02-02T17:40:47.730Z] 17:40:47     INFO - Running post-action listener: process_java_coverage_data
[task 2021-02-02T17:40:47.730Z] 17:40:47     INFO - [mozharness: 2021-02-02 17:40:47.730609Z] Finished run-tests step (success)
[task 2021-02-02T17:40:47.730Z] 17:40:47     INFO - Running post-run listener: _resource_record_post_run
[task 2021-02-02T17:40:47.919Z] 17:40:47     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 22.007262210796867}, {"name": "io_write_bytes", "value": 2204372992}, {"name": "io.read_bytes", "value": 302932615168}, {"name": "io_write_time", "value": 232088}, {"name": "io_read_time", "value": 30711436}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.022981882095336914}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 38.70131492614746}, {"name": "cpu_percent", "value": 25.2027027027027}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.0002040863037109375}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 1615.1089119911194}, {"name": "cpu_percent", "value": 21.89525709219853}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - Total resource usage - Wall time: 1654s; CPU: 22.0%; Read bytes: 302932615168; Write bytes: 2204372992; Read time: 30711436; Write time: 232088
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: CPU usage<br/>21.9%
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: I/O read bytes / time<br/>302,932,615,168 / 30,711,436
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: I/O write bytes / time<br/>2,204,372,992 / 232,088
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: CPU idle<br/>2,107.5 (32.2%)
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: CPU iowait<br/>3,341.9 (51.0%)
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: CPU system<br/>209.3 (3.2%)
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: CPU user<br/>896.2 (13.7%)
[task 2021-02-02T17:40:47.922Z] 17:40:47     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-02-02T17:40:47.923Z] 17:40:47     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-02-02T17:40:47.924Z] 17:40:47     INFO - install - Wall time: 39s; CPU: 25.0%; Read bytes: 4096; Write bytes: 1573310464; Read time: 0; Write time: 155080
[task 2021-02-02T17:40:47.924Z] 17:40:47     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-02-02T17:40:47.932Z] 17:40:47     INFO - run-tests - Wall time: 1615s; CPU: 22.0%; Read bytes: 302932094976; Write bytes: 476684288; Read time: 30711436; Write time: 53704
[task 2021-02-02T17:40:48.118Z] 17:40:48  WARNING - returning nonzero exit status 2```

Comment 1

[Intermittent Failures Robot]

1 failures in 3966 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=1690348&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 2

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 3

[Bogdan Tara[:bogdan_tara | bogdant]]

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=334655075&repo=autoland&lineNumber=2958

Comment 4

[Intermittent Failures Robot]

1 failures in 3967 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=1690348&startday=2021-03-22&endday=2021-03-28&tree=all

Comment 5

[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=1690348&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 6

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.