Closed Bug 1152372 Opened 9 years ago Closed 2 years ago

Intermittent Windows OSError: IO Completion Port failed to signal process shutdown after "ABORT: Aborting on channel error.: file ipc\glue\MessageChannel.cpp, line 1610"

Categories

(Testing :: Mozbase, defect)

Product:
Testing
Component:
Mozbase
Platform:
x86_64
Windows 8.1
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(e10s-, firefox40 wontfix)

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
e10s - ---
firefox40 --- wontfix

People

(Reporter: RyanVM, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: crash, intermittent-failure, regression) 

21:45:48 INFO - 165 INFO TEST-START | layout/base/tests/test_remote_frame.html
21:45:48 INFO - ++DOMWINDOW == 140 (000000EF06EF8000) [pid = 1260] [serial = 591] [outer = 000000EF0398AC00]
21:45:48 INFO - [Parent 1260] WARNING: Performance Entry buffer size maximum reached!: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\dom\base\nsPerformance.cpp, line 593
21:45:50 INFO - [NPAPI 1628] ###!!! ABORT: Aborting on channel error.: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\ipc\glue\MessageChannel.cpp, line 1610
21:48:55 INFO - Parent process 1260 exited with children alive:
21:48:55 INFO - PIDS: 3900
21:48:55 INFO - Attempting to kill them...
21:50:22 INFO - [1528] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\toolkit\components\places\Database.cpp, line 453
21:50:22 INFO - [1528] WARNING: NS_ENSURE_TRUE(mDB) failed: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\toolkit\components\places\nsNavHistory.cpp, line 293
21:50:22 INFO - JavaScript error: resource://gre/modules/FormHistory.jsm, line 377: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
21:50:22 INFO - [1528] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\toolkit\components\places\Database.cpp, line 453
21:50:22 INFO - [1528] WARNING: NS_ENSURE_TRUE(mDB) failed: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\toolkit\components\places\nsNavHistory.cpp, line 293
21:50:22 INFO - JavaScript error: resource://gre/modules/PlacesUtils.jsm, line 1872: NS_ERROR_XPC_GS_RETURNED_FAILURE: Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]
21:52:25 INFO - Exception in thread Thread-17:
21:52:25 INFO - Traceback (most recent call last):
21:52:25 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 551, in __bootstrap_inner
21:52:25 INFO - self.run()
21:52:25 INFO - File "c:\mozilla-build\python27\Lib\threading.py", line 504, in run
21:52:25 INFO - self.__target(*self.__args, **self.__kwargs)
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 350, in _procmgr
21:52:25 INFO - self._poll_iocompletion_port()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 385, in _poll_iocompletion_port
21:52:25 INFO - self.kill()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 158, in kill
21:52:25 INFO - self.returncode = self.wait()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 179, in wait
21:52:25 INFO - self.returncode = self._wait()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 492, in _wait
21:52:25 INFO - raise OSError(err)
21:52:25 INFO - OSError: IO Completion Port failed to signal process shutdown
21:52:25 INFO - Traceback (most recent call last):
21:52:25 INFO - File "C:\slave\test\build\tests\mochitest\runtests.py", line 2252, in doTests
21:52:25 INFO - quiet=options.quiet
21:52:25 INFO - File "C:\slave\test\build\tests\mochitest\runtests.py", line 1793, in runApp
21:52:25 INFO - status = proc.wait()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 807, in wait
21:52:25 INFO - self.returncode = self.proc.wait()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 179, in wait
21:52:25 INFO - self.returncode = self._wait()
21:52:25 INFO - File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 492, in _wait
21:52:25 INFO - raise OSError(err)
21:52:25 INFO - OSError: IO Completion Port failed to signal process shutdown
21:52:25 INFO - 166 ERROR Automation Error: Received unexpected exception while running application
21:52:25 INFO - Stopping web server
21:52:25 INFO - Stopping web socket server
21:52:25 INFO - Stopping ssltunnel
21:52:25 INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
21:52:25 INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
21:52:25 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 25000 bytes
21:52:25 INFO - TEST-INFO | leakcheck | geckomediaplugin process: leak threshold set at 20000 bytes
21:52:25 WARNING - TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
21:52:25 INFO - TEST-INFO | leakcheck | missing output line from log file c:\users\cltbld~1.t-w\appdata\local\temp\tmpsonjc8.mozrunner\runtests_leaks.log
21:52:25 WARNING - TEST-UNEXPECTED-FAIL | leakcheck | plugin process: missing output line for total leaks!
21:52:25 INFO - TEST-INFO | leakcheck | missing output line from log file c:\users\cltbld~1.t-w\appdata\local\temp\tmpsonjc8.mozrunner\runtests_leaks_plugin_pid1628.log
21:52:25 INFO - TEST-INFO | leakcheck | tab process: ignoring missing output line for total leaks
21:52:25 INFO - runtests.py | Running tests: end.
21:52:26 INFO - 167 INFO TEST-PASS | layout/base/tests/test_remote_frame.html | A valid string reason is expected
21:52:26 INFO - 168 INFO TEST-PASS | layout/base/tests/test_remote_frame.html | Reason cannot be empty
21:52:26 INFO - SUITE-END | took 490s
21:52:26 ERROR - Return code: 1
21:52:26 ERROR - No tests run or test summary not found
This is python blowing up...
Component: IPC → Mozbase
Product: Core → Testing
(In reply to Ben Turner [:bent] (use the needinfo flag!) from comment #2)
> This is python blowing up...

Actually I think the python problem is just a side effect, the chrome process aborts - 

21:45:48 INFO - 165 INFO TEST-START | layout/base/tests/test_remote_frame.html
21:45:48 INFO - ++DOMWINDOW == 140 (000000EF06EF8000) [pid = 1260] [serial = 591] [outer = 000000EF0398AC00]
21:45:48 INFO - [Parent 1260] WARNING: Performance Entry buffer size maximum reached!: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\dom\base\nsPerformance.cpp, line 593
21:45:50 INFO - [NPAPI 1628] ###!!! ABORT: Aborting on channel error.: file c:\builds\moz2_slave\m-in-w64-d-0000000000000000000\build\src\ipc\glue\MessageChannel.cpp, line 1610

21:48:55 INFO - Parent process 1260 exited with children alive:
21:48:55 INFO - PIDS: 3900
21:48:55 INFO - Attempting to kill them... 

and then python blows up trying to clean up.

Very very rare crash, and is test only based on the data in bug 1051567.
See Also: → 1274584
I believe I have a fix for the python OSError in bug 1274584. But Jim is right in comment 3. The OSError is a failure while mozprocess is trying to cleanup and force-kill the leftover child processes. But there is still some kind of underlying issue that is causing the child processes to not get terminated properly in the first place.

So after bug 1274584, OSError will no longer be raised and (I think) the jobs will no longer turn orange.
No updates in the last 2 years. Going to mark as WFM.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WORKSFORME
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=179895553&repo=autoland&lineNumber=2990394

21:54:13     INFO -  MemoryError
21:56:57     INFO -  JavaScript error: jar:file:///Z:/task_1527109412/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 805: TypeError: this._db is undefined
21:57:43     INFO -  Traceback (most recent call last):
21:57:43     INFO -    File "Z:\task_1527109412\build\venv\lib\site-packages\mozprocess\processhandler.py", line 521, in _wait
21:57:43     INFO -      self.MAX_PROCESS_KILL_DELAY)
21:57:43     INFO -    File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get
21:57:43     INFO -      raise Empty
21:57:43     INFO -  Empty
21:57:43     INFO -  IO Completion Port unexpectedly closed
21:57:43     INFO -  Traceback (most recent call last):
21:57:43     INFO -    File "Z:\task_1527109412\build\tests\mochitest\runtests.py", line 2802, in doTests
21:57:43     INFO -      marionette_args=marionette_args,
21:57:43     INFO -    File "Z:\task_1527109412\build\tests\mochitest\runtests.py", line 2289, in runApp
21:57:43     INFO -      status = proc.wait()
21:57:43     INFO -    File "Z:\task_1527109412\build\venv\lib\site-packages\mozprocess\processhandler.py", line 863, in wait
21:57:43     INFO -      self.returncode = self.proc.wait()
21:57:43     INFO -    File "Z:\task_1527109412\build\venv\lib\site-packages\mozprocess\processhandler.py", line 221, in wait
21:57:43     INFO -      self.returncode = self._wait()
21:57:43     INFO -    File "Z:\task_1527109412\build\venv\lib\site-packages\mozprocess\processhandler.py", line 527, in _wait
21:57:43     INFO -      raise OSError("IO Completion Port failed to signal process shutdown")
21:57:43     INFO -  OSError: IO Completion Port failed to signal process shutdown
21:57:43     INFO -  832 ERROR Automation Error: Received unexpected exception while running application
21:57:43     INFO -  Stopping web server
21:57:43     INFO -  Stopping web socket server
21:57:43     INFO -  Stopping ssltunnel
21:57:43     INFO -  TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
21:57:43     INFO -  TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
21:57:43     INFO -  TEST-INFO | leakcheck | tab process: leak threshold set at 1000 bytes
21:57:43     INFO -  TEST-INFO | leakcheck | geckomediaplugin process: leak threshold set at 20000 bytes
21:57:43     INFO -  TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
21:57:43    ERROR -  833 ERROR TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks.log
21:57:43    ERROR -  834 ERROR TEST-UNEXPECTED-FAIL | leakcheck | plugin process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_plugin_pid3344.log
21:57:43    ERROR -  835 ERROR TEST-UNEXPECTED-FAIL | leakcheck | plugin process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_plugin_pid3972.log
21:57:43    ERROR -  836 ERROR TEST-UNEXPECTED-FAIL | leakcheck | tab process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_tab_pid1964.log
21:57:43    ERROR -  837 ERROR TEST-UNEXPECTED-FAIL | leakcheck | tab process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_tab_pid3480.log
21:57:43    ERROR -  838 ERROR TEST-UNEXPECTED-FAIL | leakcheck | tab process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_tab_pid3904.log
21:57:43    ERROR -  839 ERROR TEST-UNEXPECTED-FAIL | leakcheck | tab process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_tab_pid5800.log
21:57:43    ERROR -  840 ERROR TEST-UNEXPECTED-FAIL | leakcheck | tab process: missing output line for total leaks!
21:57:43     INFO -  TEST-INFO | leakcheck | missing output line from log file c:\users\task_1527109412\appdata\local\temp\tmpnthpd0.mozrunner\runtests_leaks_tab_pid6016.log
21:57:43     INFO -  runtests.py | Running tests: end.
21:57:43     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:44     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:45     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:46     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:48     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:51     INFO -  Exception WindowsError: WindowsError(5, 'Access is denied') in <bound method Profile.__del__ of <mozprofile.profile.Profile object at 0x025C8690>> ignored
21:57:51     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:51     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:52     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:54     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:56     INFO -  remove() failed for "(u'c:\\users\\task_1527109412\\appdata\\local\\temp\\tmpnthpd0.mozrunner\\extensions\\workerbootstrap-test@mozilla.org.xpi',)". Reason: Access is denied (13). Retrying...
21:57:58     INFO -  Exception WindowsError: WindowsError(5, 'Access is denied') in <bound method AddonManager.__del__ of <mozprofile.addons.AddonManager object at 0x02A4E6F0>> ignored
21:57:58     INFO -  Buffered messages logged at 21:25:43
21:57:58     INFO -  841 INFO Entering test bound contentscript_connect_and_move_tabs
21:57:58     INFO -  842 INFO Extension loaded
21:57:58     INFO -  843 INFO Console message: Warning: attempting to write 5424 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
21:57:58     INFO -  Buffered messages logged at 21:25:44
21:57:58     INFO -  844 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
21:57:58     INFO -  Buffered messages logged at 21:25:46
21:57:58     INFO -  845 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping -
21:57:58     INFO -  846 INFO Console message: [JavaScript Error: "Promise rejected after context unloaded: Message manager disconnected
21:57:58     INFO -  " {file: "moz-extension://57e2d3e2-dd3e-4972-9358-7e6a057ea125/script.js" line: 8}]
21:57:58     INFO -  @moz-extension://57e2d3e2-dd3e-4972-9358-7e6a057ea125/script.js:8:13
21:57:58     INFO -  847 INFO Leaving test bound contentscript_connect_and_move_tabs
21:57:58     INFO -  848 INFO Entering test bound extension_tab_connect_and_move_tabs
21:57:58     INFO -  849 INFO Extension loaded
21:57:58     INFO -  850 INFO Console message: Warning: attempting to write 5504 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
21:57:58     INFO -  851 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: open_extension_tab, Actual: open_extension_tab -
21:57:58     INFO -  852 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
21:57:58     INFO -  Buffered messages finished
21:57:58     INFO -  Running manifest: browser\extensions\webcompat-reporter\test\browser\browser.ini
21:57:58     INFO -  The following extra prefs will be set:
21:57:58     INFO -    dom.animations-api.core.enabled=true
21:57:59     INFO -  Z:\task_1527109412\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL
21:57:59     INFO -  Increasing default timeout to 90 seconds
21:57:59     INFO -  MochitestServer : launching [u'Z:\\task_1527109412\\build\\tests\\bin\\xpcshell.exe', '-g', 'Z:\\task_1527109412\\build\\application\\firefox', '-f', 'Z:\\task_1527109412\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'c:\\\\users\\\\task_1527109412\\\\appdata\\\\local\\\\temp\\\\tmp7dncyp.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'Z:\\task_1527109412\\build\\tests\\mochitest\\server.js']
21:57:59     INFO -  runtests.py | Server pid: 6024
21:57:59     INFO -  runtests.py | Websocket server pid: 5296
21:57:59     INFO -  runtests.py | SSL tunnel pid: 4596
21:57:59     INFO -  Couldn't convert chrome URL: chrome://branding/locale/brand.properties
21:57:59     INFO -  [6024, Main Thread] WARNING: Failed to get directory to cache.: file z:/build/build/src/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp, line 83
21:57:59     INFO -  [6024, Main Thread] WARNING: Failed to get directory to cache.: file z:/build/build/src/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp, line 83
21:57:59     INFO -  [6024, Main Thread] WARNING: Failed to get directory to cache.: file z:/build/build/src/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp, line 83
21:57:59     INFO -  [6024, Main Thread] WARNING: Failed to get directory to cache.: file z:/build/build/src/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp, line 83
21:57:59     INFO -  [6024, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file z:/build/build/src/dom/media/CubebUtils.cpp, line 351
21:57:59     INFO -  runtests.py | Running with e10s: True
21:57:59     INFO -  runtests.py | Running tests: start.
21:57:59     INFO -  Found 'firefox' running before starting test browser!
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
The above happens due to the following assertion which repeats and fills up the log until a memory error is reported:

> 21:54:11     INFO -  GECKO(2920) | [Parent 2920, Compositor] ###!!! ASSERTION: Child has wrong manager: 'Error', file z:/build/build/src/gfx/layers/Layers.cpp, line 966
> 21:54:11     INFO -  GECKO(2920) | #01: mozilla::layers::ContainerLayer::RemoveChild(mozilla::layers::Layer *) [gfx/layers/Layers.cpp:966]
> 21:54:11     INFO -  GECKO(2920) | #02: mozilla::layers::ContainerLayerComposite::~ContainerLayerComposite() [gfx/layers/composite/ContainerLayerComposite.cpp:653]
> 21:54:11     INFO -  GECKO(2920) | #03: mozilla::layers::Layer::Release() [gfx/layers/Layers.h:782]

So this is bug 1346126.

Bugbug thinks this bug is a regression, but please revert this change in case of error.

Keywords: regression
Status: REOPENED → RESOLVED
Closed: 6 years ago → 2 years ago
status-firefox40: affected → wontfix
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.