Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=303645903&repo=mozilla-release
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aqjucz5LT3axG8euz0finw/runs/0/artifacts/public/logs/live_backing.log

[task 2020-05-25T15:00:31.839Z] 15:00:31 INFO - TEST-START | browser/base/content/test/forms/browser_selectpopup_searchfocus.js
[task 2020-05-25T15:00:32.628Z] 15:00:32 INFO - GECKO(9572) | MEMORY STAT | vsize 19406167MB | vsizeMaxContiguous 65858581MB | residentFast 1245MB
[task 2020-05-25T15:00:32.628Z] 15:00:32 INFO - TEST-OK | browser/base/content/test/forms/browser_selectpopup_searchfocus.js | took 784ms
[task 2020-05-25T15:00:32.658Z] 15:00:32 INFO - checking window state
[task 2020-05-25T15:00:34.549Z] 15:00:34 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 9140
[task 2020-05-25T15:00:34.549Z] 15:00:34 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 2324
[task 2020-05-25T15:00:34.549Z] 15:00:34 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 10392
[task 2020-05-25T15:00:34.578Z] 15:00:34 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 3916
[task 2020-05-25T15:00:34.637Z] 15:00:34 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 7924
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - GECKO(9572) | Completed ShutdownLeaks collections in process 7016
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - TEST-START | Shutdown
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - Browser Chrome Test Summary
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - Passed: 556
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - Failed: 0
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - Todo: 0
[task 2020-05-25T15:00:35.693Z] 15:00:35 INFO - Mode: e10s
[task 2020-05-25T15:00:35.694Z] 15:00:35 INFO - *** End BrowserChrome Test Results ***
[task 2020-05-25T15:00:36.017Z] 15:00:36 INFO - GECKO(9572) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-25T15:00:36.178Z] 15:00:36 INFO - GECKO(9572) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-25T15:00:36.178Z] 15:00:36 INFO - GECKO(9572) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-25T15:00:36.196Z] 15:00:36 INFO - GECKO(9572) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-25T15:00:36.663Z] 15:00:36 INFO - GECKO(9572) | 1590418836659 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-05-25T15:00:36.663Z] 15:00:36 INFO - GECKO(9572) | 1590418836659 Marionette INFO Stopped listening on port 2828
[task 2020-05-25T15:00:36.663Z] 15:00:36 INFO - GECKO(9572) | 1590418836660 Marionette DEBUG Marionette stopped listening
[task 2020-05-25T15:00:36.682Z] 15:00:36 INFO - GECKO(9572) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-05-25T15:00:37.898Z] 15:00:37 INFO - TEST-INFO | Main app process: exit 0
[task 2020-05-25T15:00:37.899Z] 15:00:37 INFO - runtests.py | Application ran for: 0:00:49.570000

[task 2020-05-25T15:00:40.137Z] 15:00:40 INFO - runtests.py | Running tests: start.
[task 2020-05-25T15:00:40.138Z] 15:00:40 INFO -
[task 2020-05-25T15:00:40.259Z] 15:00:40 INFO - Application command: Z:\task_1590416495\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile c:\users\task_1590416495\appdata\local\temp\tmpbk1msn.mozrunner
[task 2020-05-25T15:00:40.259Z] 15:00:40 INFO - runtests.py | Application pid: 2856
[task 2020-05-25T15:00:40.259Z] 15:00:40 INFO - TEST-INFO | started process GECKO(2856)
[task 2020-05-25T15:00:42.823Z] 15:00:42 INFO - GECKO(2856) | 1590418842818 Marionette TRACE Marionette enabled
[task 2020-05-25T15:00:43.052Z] 15:00:43 INFO - GECKO(2856) | 1590418843047 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-05-25T15:00:46.430Z] 15:00:46 INFO - GECKO(2856) | JavaScript error: resource://gre/modules/XULStore.jsm, line 66: Error: Can't find profile directory.
[task 2020-05-25T15:00:49.536Z] 15:00:49 INFO - GECKO(2856) | 1590418849532 Marionette TRACE Received observer notification marionette-startup-requested
[task 2020-05-25T15:00:49.536Z] 15:00:49 INFO - GECKO(2856) | 1590418849532 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2020-05-25T15:00:49.660Z] 15:00:49 INFO - GECKO(2856) | 1590418849657 Marionette TRACE All scripts recorded.
[task 2020-05-25T15:00:49.943Z] 15:00:49 INFO - GECKO(2856) | 1590418849940 Marionette INFO Listening on port 2828
[task 2020-05-25T15:00:49.944Z] 15:00:49 INFO - GECKO(2856) | 1590418849941 Marionette DEBUG Marionette is listening
[task 2020-05-25T15:00:50.290Z] 15:00:50 INFO - GECKO(2856) | 1590418850280 Marionette DEBUG Accepted connection 0 from 127.0.0.1:50424
[task 2020-05-25T15:00:50.389Z] 15:00:50 INFO - GECKO(2856) | 1590418850379 Marionette DEBUG Closed connection 0
[task 2020-05-25T15:00:50.389Z] 15:00:50 INFO - GECKO(2856) | 1590418850381 Marionette DEBUG Accepted connection 1 from 127.0.0.1:50425
[task 2020-05-25T15:00:50.487Z] 15:00:50 INFO - GECKO(2856) | 1590418850480 Marionette DEBUG Accepted connection 2 from 127.0.0.1:50426
[task 2020-05-25T15:00:50.487Z] 15:00:50 INFO - GECKO(2856) | 1590418850484 Marionette DEBUG Closed connection 2
[task 2020-05-25T15:00:50.487Z] 15:00:50 INFO - GECKO(2856) | 1590418850485 Marionette DEBUG Closed connection 1
[task 2020-05-25T15:00:50.489Z] 15:00:50 INFO - GECKO(2856) | 1590418850487 Marionette DEBUG Accepted connection 3 from 127.0.0.1:50427
[task 2020-05-25T15:00:50.494Z] 15:00:50 INFO - GECKO(2856) | 1590418850492 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-05-25T15:06:50.657Z] 15:06:50 INFO - runtests.py | Waiting for browser...
[task 2020-05-25T15:06:50.675Z] 15:06:50 INFO - GECKO(2856) | 1590419210663 Marionette DEBUG Closed connection 3
[task 2020-05-25T15:13:00.688Z] 15:13:00 INFO - Buffered messages finished
[task 2020-05-25T15:13:00.688Z] 15:13:00 ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
[task 2020-05-25T15:13:00.688Z] 15:13:00 ERROR - Force-terminating active process(es).
[task 2020-05-25T15:13:00.688Z] 15:13:00 INFO - Determining child pids from psutil...
[task 2020-05-25T15:13:00.693Z] 15:13:00 INFO - [3100]
[task 2020-05-25T15:13:00.693Z] 15:13:00 INFO - ==> process 3100 launched child process 5796 ("Z:\task_1590416495\build\application\firefox\firefox.exe" -contentproc --channel="3100.0.1755764366\1569690397" -parentBuildID 20200525134724 -prefsHandle 2196 -prefMapHandle 2192 -prefsLen 1 -prefMapSize 231176 -appdir "Z:\task_1590416495\build\application\firefox\browser" - 3100 gpu)
[task 2020-05-25T15:13:00.693Z] 15:13:00 INFO - ==> process 3100 launched child process 1188 ("Z:\task_1590416495\build\application\firefox\firefox.exe" -contentproc --channel="3100.6.1355599570\1375181536" -childID 1 -isForBrowser -prefsHandle 2892 -prefMapHandle 2888 -prefsLen 1596 -prefMapSize 231176 -parentBuildID 20200525134724 -appdir "Z:\task_1590416495\build\application\firefox\browser" - 3100 tab)
[task 2020-05-25T15:13:00.693Z] 15:13:00 INFO - ==> process 3100 launched child process 7804 ("Z:\task_1590416495\build\application\firefox\firefox.exe" -contentproc --channel="3100.13.740755953\353083137" -childID 2 -isForBrowser -prefsHandle 5040 -prefMapHandle 5036 -prefsLen 2009 -prefMapSize 231176 -parentBuildID 20200525134724 -appdir "Z:\task_1590416495\build\application\firefox\browser" - 3100 tab)
[task 2020-05-25T15:13:00.693Z] 15:13:00 INFO - ==> process 3100 launched child process 5780 ("Z:\task_1590416495\build\application\firefox\firefox.exe" -contentproc --channel="3100.20.1235493690\2014394396" -childID 3 -isForBrowser -prefsHandle 5036 -prefMapHandle 5040 -prefsLen 2049 -prefMapSize 231176 -parentBuildID 20200525134724 -appdir "Z:\task_1590416495\build\application\firefox\browser" - 3100 tab)
[task 2020-05-25T15:13:00.694Z] 15:13:00 INFO - Found child pids: set([5796, 5780, 1188, 3100, 7804])
[task 2020-05-25T15:13:00.694Z] 15:13:00 INFO - Killing process: 5796
[task 2020-05-25T15:13:00.694Z] 15:13:00 INFO - TEST-INFO | started process screenshot
[task 2020-05-25T15:13:00.918Z] 15:13:00 INFO - TEST-INFO | screenshot: exit 0
[task 2020-05-25T15:13:00.918Z] 15:13:00 INFO - Can't trigger Breakpad, just killing process
[task 2020-05-25T15:13:00.976Z] 15:13:00 INFO - psutil found pid 5796 dead
[task 2020-05-25T15:13:00.976Z] 15:13:00 INFO - Killing process: 5780
[task 2020-05-25T15:13:00.976Z] 15:13:00 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T15:13:00.976Z] 15:13:00 INFO - Can't trigger Breakpad, just killing process
[task 2020-05-25T15:13:01.015Z] 15:13:01 INFO - psutil found pid 5780 dead
[task 2020-05-25T15:13:01.015Z] 15:13:01 INFO - Killing process: 1188
[task 2020-05-25T15:13:01.015Z] 15:13:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T15:13:01.015Z] 15:13:01 INFO - Can't trigger Breakpad, just killing process