14:05:50 INFO - TEST-SKIP | test_click_scrolling.py TestClickScrolling.test_should_not_scroll_if_already_scrolled_and_element_is_in_view | took 1ms 14:05:50 INFO - TEST-START | test_click_scrolling.py TestClickScrolling.test_should_not_scroll_overflow_elements_which_are_visible 14:05:50 INFO - TEST-PASS | test_click_scrolling.py TestClickScrolling.test_should_not_scroll_overflow_elements_which_are_visible | took 409ms 14:05:50 INFO - TEST-START | test_click_scrolling.py TestClickScrolling.test_should_scroll_elements_if_click_point_is_out_of_view_but_element_is_in_view 14:05:51 INFO - TEST-PASS | test_click_scrolling.py TestClickScrolling.test_should_scroll_elements_if_click_point_is_out_of_view_but_element_is_in_view | took 1092ms 14:05:51 INFO - TEST-START | test_click_scrolling.py TestClickScrolling.test_should_scroll_overflow_elements_if_click_point_is_out_of_view_but_element_is_in_view 14:05:51 INFO - TEST-SKIP | test_click_scrolling.py TestClickScrolling.test_should_scroll_overflow_elements_if_click_point_is_out_of_view_but_element_is_in_view | took 0ms 14:05:51 INFO - TEST-START | test_click_scrolling.py TestClickScrolling.test_should_scroll_to_click_on_an_element_hidden_by_overflow 14:05:52 INFO - TEST-PASS | test_click_scrolling.py TestClickScrolling.test_should_scroll_to_click_on_an_element_hidden_by_overflow | took 467ms 14:05:52 INFO - TEST-START | test_profile_management.py TestLog.test_can_restart_the_browser 14:05:52 INFO - ERROR:root:[Errno 10054] An existing connection was forcibly closed by the remote host 14:06:22 INFO - TEST-PASS | test_profile_management.py TestLog.test_can_restart_the_browser | took 30570ms 14:06:22 INFO - TEST-START | test_profile_management.py TestLog.test_change_preset 14:06:45 INFO - TEST-PASS | test_profile_management.py TestLog.test_change_preset | took 22465ms 14:06:45 INFO - TEST-START | test_profile_management.py TestLog.test_clean_profile 14:07:07 INFO - TEST-PASS | test_profile_management.py TestLog.test_clean_profile | took 22530ms 14:07:07 INFO - TEST-START | test_profile_management.py TestLog.test_in_app_restart_the_browser 14:08:21 INFO - mozcrash Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win64-debug/1427139628/firefox-39.0a1.en-US.win64.crashreporter-symbols.zip 14:08:29 INFO - mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\f395ad4f-3cc6-4551-aec6-7c87822fa66d.dmp 14:08:29 INFO - mozcrash Saved app info as C:\slave\test\build\blobber_upload_dir\f395ad4f-3cc6-4551-aec6-7c87822fa66d.extra 14:08:29 ERROR - PROCESS-CRASH | test_profile_management.py TestLog.test_in_app_restart_the_browser | application crashed [None] 14:08:29 INFO - Crash dump filename: c:\users\cltbld~1.t-w\appdata\local\temp\tmpbwcgbp.mozrunner\minidumps\f395ad4f-3cc6-4551-aec6-7c87822fa66d.dmp 14:08:30 INFO - Failed to gather test failure debug. 14:08:30 INFO - Traceback (most recent call last): 14:08:30 INFO - File "C:\slave\test\build\tests\marionette\marionette\runner\base.py", line 551, in gather_debug 14:08:30 INFO - with marionette.using_context(marionette.CONTEXT_CHROME): 14:08:30 INFO - File "c:\mozilla-build\python27\Lib\contextlib.py", line 17, in __enter__ 14:08:30 INFO - return self.gen.next() 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1149, in using_context 14:08:30 INFO - scope = self._send_message('getContext', 'value') 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _ 14:08:30 INFO - return func(*args, **kwargs) 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\marionette.py", line 691, in _send_message 14:08:30 INFO - response = self.client.send(message) 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_transport\transport.py", line 87, in send 14:08:30 INFO - self.connect() 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_transport\transport.py", line 69, in connect 14:08:30 INFO - self.sock.connect((self.addr, self.port)) 14:08:30 INFO - File "c:\mozilla-build\python27\Lib\socket.py", line 224, in meth 14:08:30 INFO - return getattr(self._sock,name)(*args) 14:08:30 INFO - error: [Errno 10061] No connection could be made because the target machine actively refused it 14:08:30 ERROR - TEST-UNEXPECTED-FAIL | test_profile_management.py TestLog.test_in_app_restart_the_browser | AssertionError: Timed out waiting for port! 14:08:30 INFO - Traceback (most recent call last): 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette\marionette_test.py", line 296, in run 14:08:30 INFO - testMethod() 14:08:30 INFO - File "C:\slave\test\build\tests\marionette\tests\testing\marionette\client\marionette\tests\unit\test_profile_management.py", line 44, in test_in_app_restart_the_browser 14:08:30 INFO - self.marionette.restart(in_app=True) 14:08:30 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\marionette.py", line 916, in restart 14:08:30 INFO - assert(self.wait_for_port()), "Timed out waiting for port!" 14:08:30 INFO - TEST-INFO took 82168ms 14:08:32 INFO - Failed to gather test failure debug. 14:08:32 INFO - Traceback (most recent call last): 14:08:32 INFO - File "C:\slave\test\build\tests\marionette\marionette\runner\base.py", line 551, in gather_debug 14:08:32 INFO - with marionette.using_context(marionette.CONTEXT_CHROME): 14:08:32 INFO - File "c:\mozilla-build\python27\Lib\contextlib.py", line 17, in __enter__ 14:08:32 INFO - return self.gen.next() 14:08:32 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1149, in using_context 14:08:32 INFO - scope = self._send_message('getContext', 'value') 14:08:32 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _ 14:08:32 INFO - return func(*args, **kwargs) 14:08:32 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_driver\marionette.py", line 691, in _send_message 14:08:32 INFO - response = self.client.send(message) 14:08:32 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_transport\transport.py", line 87, in send 14:08:32 INFO - self.connect() 14:08:32 INFO - File "C:\slave\test\build\venv\lib\site-packages\marionette_transport\transport.py", line 69, in connect 14:08:32 INFO - self.sock.connect((self.addr, self.port)) 14:08:32 INFO - File "c:\mozilla-build\python27\Lib\socket.py", line 224, in meth 14:08:32 INFO - return getattr(self._sock,name)(*args) 14:08:32 INFO - error: [Errno 10061] No connection could be made because the target machine actively refused it 14:08:32 INFO - test_end for test_profile_management.py TestLog.test_in_app_restart_the_browser logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_profile_management.TestLog", "method_name": "test_in_app_restart_the_browser"}, "expected": "PASS", "test": "test_profile_management.py TestLog.test_in_app_restart_the_browser", "message": "error: [Errno 10061] No connection could be made because the target machine actively refused it", "stack": "Traceback (most recent call last):\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette\\marionette_test.py\", line 326, in run\n self.tearDown()\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette\\marionette_test.py\", line 651, in tearDown\n self.marionette.test_name = None\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 951, in test_name\n if self._send_message('setTestName', 'ok', value=test_name):\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 36, in _\n return func(*args, **kwargs)\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 691, in _send_message\n response = self.client.send(message)\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_transport\\transport.py\", line 87, in send\n self.connect()\n File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_transport\\transport.py\", line 69, in connect\n self.sock.connect((self.addr, self.port))\n File \"c:\\mozilla-build\\python27\\Lib\\socket.py\", line 224, in meth\n return getattr(self._sock,name)(*args)\n"} 14:08:34 INFO - SUMMARY 14:08:34 INFO - ------- 14:08:34 INFO - passed: 378 14:08:34 INFO - failed: 2 14:08:34 INFO - todo: 14 (skipped: 3) 14:08:34 INFO - FAILED TESTS 14:08:34 INFO - ------- 14:08:34 INFO - test_profile_management.py test_profile_management.TestLog.test_in_app_restart_the_browser 14:08:34 INFO - test_profile_management.py test_profile_management.TestLog.test_in_app_restart_the_browser 14:08:34 INFO - SUITE-END | took 376s 14:08:34 ERROR - Return code: 10

I'll keep an eye on this and go through the process of attempting to reproduce if it continues to be a problem.

Fixing stackwalking has its benefits :)

We're dying on MOZ_ASSERT(target), intentionally. Somebody is being a naughty caller and trying to schedule new async database commands during shutdown. === storage code: // Dispatch it to the background nsIEventTarget *target = aConnection->getAsyncExecutionTarget(); // If we don't have a valid target, this is a bug somewhere else. In the past, // this assert found cases where a Run method would schedule a new statement // without checking if asyncClose had been called. The caller must prevent // that from happening or, if the work is not critical, just avoid creating // the new statement during shutdown. See bug 718449 for an example. MOZ_ASSERT(target); if (!target) { return NS_ERROR_NOT_AVAILABLE; } === I'm not 100% clear on what's going on with the assert backtrace at the bottom, but it seems like we can probably assume that the code at fault is the code that owns all of the unfinalized statements that mozStorage complained about having to finalize itself. These look like places stuff so I'm turfing to places. (Note that the DataStorage thing in the stack is a red herring, it's just shutting down its worker thread that doesn't run JS and that results in a spun nested event loop. 08:07:40 INFO - [982] WARNING: SQL statement 'WITH RECURSIVE 08:07:40 INFO - ancestors(aid) AS ( 08:07:40 INFO - SELECT id FROM moz_bookmarks WHERE guid = :guid 08:07:40 INFO - UNION ALL 08:07:40 INFO - SELECT parent FROM moz_bookmarks 08:07:40 INFO - JOIN ancestors ON id = aid 08:07:40 INFO - WHERE type = :type 08:07:40 INFO - ) 08:07:40 INFO - UPDATE moz_bookmarks SET lastModified = :time 08:07:40 INFO - WHERE id IN ancestors 08:07:40 INFO - ' (26df7bd0) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - [982] WARNING: SQL statement 'INSERT INTO moz_bookmarks (fk, type, parent, position, title, 08:07:40 INFO - dateAdded, lastModified, guid) 08:07:40 INFO - VALUES ((SELECT id FROM moz_places WHERE url = :url), :type, :parent, 08:07:40 INFO - :index, :title, :date_added, :last_modified, :guid) 08:07:40 INFO - ' (1d8fa240) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - [982] WARNING: SQL statement 'UPDATE moz_bookmarks SET position = position + 1 08:07:40 INFO - WHERE parent = :parent 08:07:40 INFO - AND position >= :index 08:07:40 INFO - ' (25aa3960) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - [982] WARNING: SQL statement 'INSERT OR IGNORE INTO moz_places (url, rev_host, hidden, frecency, guid) 08:07:40 INFO - VALUES (:url, :rev_host, 0, :frecency, GENERATE_GUID()) 08:07:40 INFO - ' (25aa3370) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - [982] WARNING: SQL statement 'SELECT GENERATE_GUID() AS guid' (25aa3110) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - [982] WARNING: SQL statement 'SELECT b.guid, IFNULL(p.guid, "") AS parentGuid, b.position AS 'index', 08:07:40 INFO - b.dateAdded, b.lastModified, b.type, b.title, h.url AS url, 08:07:40 INFO - b.id AS _id, b.parent AS _parentId, 08:07:40 INFO - (SELECT count(*) FROM moz_bookmarks WHERE parent = b.id) AS _childCount, 08:07:40 INFO - p.parent AS _grandParentId 08:07:40 INFO - FROM moz_bookmarks b 08:07:40 INFO - LEFT JOIN moz_bookmarks p ON p.id = b.parent 08:07:40 INFO - LEFT JOIN moz_places h ON h.id = b.fk 08:07:40 INFO - WHERE b.guid = :guid 08:07:40 INFO - ' (25aa22d0) should have been finalized before closing the connection: file /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageConnection.cpp, line 926 08:07:40 INFO - Assertion failure: target, at /builds/slave/try-m64-d-00000000000000000000/build/src/storage/src/mozStorageAsyncStatementExecution.cpp:185

Mak, this is happening pretty frequently. Can you please take a look?

it's very likely bug 1091851.

note bug 1091851 is not fixed yet cause Yoric has a somehow large patch changing Places shutdown to async shutdown and I don't want to bitrot him at this stage. It's almost done though, and we should be able to hook into Places shutdown then.

this might have been fixed by bug 1091851 that just landed, let's see.

Looks like this was indeed fixed by bug 1091851.

Yoric told me on IRC that he's not comfortable with uplifting bug 1091851 to Fx40.