Closed
Bug 1497094
Opened 6 years ago
Closed 6 years ago
Intermittent Automation Error: Received unexpected exception while running application After AttributeError: 'Marionette' object has no attribute 'is_shutting_down'
Categories
(Testing :: Marionette Client and Harness, defect, P2)
Tracking
(firefox64 fixed)
RESOLVED
FIXED
mozilla64
Tracking | Status | |
---|---|---|
firefox64 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: automatedtester)
References
Details
(Keywords: intermittent-failure)
Filed by: dvarga [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=203940074&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/TRl5IldqQmS2C9lAL6FaGg/runs/3/artifacts/public/logs/live_backing.log 19:24:14 INFO - TEST-START | layout/xul/test/test_splitter.xul 19:24:14 INFO - GECKO(4832) | MEMORY STAT | vsize 1481MB | vsizeMaxContiguous 131741099MB | residentFast 78MB | heapAllocated 14MB 19:24:14 INFO - TEST-OK | layout/xul/test/test_splitter.xul | took 145ms 19:24:14 INFO - TEST-START | Shutdown 19:24:14 INFO - Passed: 61 19:24:14 INFO - Failed: 0 19:24:14 INFO - Todo: 6 19:24:14 INFO - Mode: e10s 19:24:14 INFO - Slowest: 1209ms - /tests/layout/xul/test/test_bug1197913.xul 19:24:14 INFO - SimpleTest FINISHED 19:24:14 INFO - TEST-INFO | Ran 1 Loops 19:24:14 INFO - SimpleTest FINISHED 19:24:14 INFO - GECKO(4832) | [Parent 10740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | [Parent 10740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | [Child 6692, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | [Parent 10740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | [Child 6572, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | [Child 6572, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | 1538940254883 Marionette DEBUG Received observer notification xpcom-will-shutdown 19:24:14 INFO - GECKO(4832) | 1538940254883 Marionette INFO Stopped listening on port 2828 19:24:14 INFO - GECKO(4832) | 1538940254883 Marionette DEBUG Remote service is inactive 19:24:14 INFO - GECKO(4832) | [GPU 10412, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 19:24:14 INFO - GECKO(4832) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost 19:24:15 INFO - TEST-INFO | Main app process: exit 0 19:24:15 INFO - runtests.py | Application ran for: 0:00:07.418000 19:24:15 INFO - zombiecheck | Reading PID log: c:\users\task_1538939328\appdata\local\temp\tmprcxhgopidlog 19:24:15 INFO - ==> process 10740 launched child process 10412 ("Z:\task_1538939328\build\application\firefox\firefox.exe" -contentproc --channel="10740.0.1735769122\271241085" -parentBuildID 20181007171514 -greomni "Z:\task_1538939328\build\application\firefox\omni.ja" -appomni "Z:\task_1538939328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538939328\build\application\firefox\browser" - "C:\Users\task_1538939328\AppData\LocalLow\Mozilla\Temp-{bc6e667b-cd81-463e-8ebf-36393db7ef89}" 10740 "\\.\pipe\gecko-crash-server-pipe.10740" 1436 gpu) 19:24:15 INFO - ==> process 10740 launched child process 6572 ("Z:\task_1538939328\build\application\firefox\firefox.exe" -contentproc --channel="10740.6.1786081138\718318401" -childID 1 -isForBrowser -prefsHandle 2772 -prefMapHandle 2776 -prefsLen 1 -prefMapSize 187890 -schedulerPrefs 0001,2 -parentBuildID 20181007171514 -greomni "Z:\task_1538939328\build\application\firefox\omni.ja" -appomni "Z:\task_1538939328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538939328\build\application\firefox\browser" - 10740 "\\.\pipe\gecko-crash-server-pipe.10740" 2832 tab) 19:24:15 INFO - ==> process 10740 launched child process 3552 ("Z:\task_1538939328\build\application\firefox\firefox.exe" -contentproc --channel="10740.13.1538563721\1793653217" -childID 2 -isForBrowser -prefsHandle 2556 -prefMapHandle 3012 -prefsLen 1 -prefMapSize 187890 -schedulerPrefs 0001,2 -parentBuildID 20181007171514 -greomni "Z:\task_1538939328\build\application\firefox\omni.ja" -appomni "Z:\task_1538939328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538939328\build\application\firefox\browser" - 10740 "\\.\pipe\gecko-crash-server-pipe.10740" 2720 tab) 19:24:15 INFO - ==> process 10740 launched child process 6692 ("Z:\task_1538939328\build\application\firefox\firefox.exe" -contentproc --channel="10740.20.1113638167\1218752604" -childID 3 -isForBrowser -prefsHandle 2708 -prefMapHandle 2764 -prefsLen 41 -prefMapSize 187890 -schedulerPrefs 0001,2 -parentBuildID 20181007171514 -greomni "Z:\task_1538939328\build\application\firefox\omni.ja" -appomni "Z:\task_1538939328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1538939328\build\application\firefox\browser" - 10740 "\\.\pipe\gecko-crash-server-pipe.10740" 3084 tab) 19:24:15 INFO - zombiecheck | Checking for orphan process with PID: 3552 19:24:15 INFO - zombiecheck | Checking for orphan process with PID: 6572 19:24:15 INFO - zombiecheck | Checking for orphan process with PID: 10412 19:24:15 INFO - zombiecheck | Checking for orphan process with PID: 6692 19:24:15 INFO - Stopping web server 19:24:15 INFO - Stopping web socket server 19:24:15 INFO - Stopping ssltunnel 19:24:15 WARNING - leakcheck | refcount logging is off, so leaks can't be detected! 19:24:15 INFO - runtests.py | Running tests: end. 19:24:15 INFO - Buffered messages finished 19:24:15 INFO - Running manifest: modules\libjar\test\mochitest\mochitest.ini 19:24:15 INFO - Z:\task_1538939328\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL 19:24:15 INFO - MochitestServer : launching [u'Z:\\task_1538939328\\build\\tests\\bin\\xpcshell.exe', '-g', 'Z:\\task_1538939328\\build\\application\\firefox', '-f', 'Z:\\task_1538939328\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'c:\\\\users\\\\task_1538939328\\\\appdata\\\\local\\\\temp\\\\tmpdle1zv.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'Z:\\task_1538939328\\build\\tests\\mochitest\\server.js'] 19:24:15 INFO - runtests.py | Server pid: 10732 19:24:15 INFO - runtests.py | Websocket server pid: 6804 19:24:15 INFO - runtests.py | SSL tunnel pid: 10408 19:24:16 INFO - runtests.py | Running with e10s: True 19:24:16 INFO - runtests.py | Running with serviceworker_e10s: False 19:24:16 INFO - runtests.py | Running tests: start. 19:24:16 INFO - 19:24:16 INFO - Application command: Z:\task_1538939328\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile c:\users\task_1538939328\appdata\local\temp\tmpdle1zv.mozrunner 19:24:16 INFO - runtests.py | Application pid: 7712 19:24:16 INFO - TEST-INFO | started process GECKO(7712) 19:24:16 INFO - GECKO(7712) | 1538940256830 Marionette DEBUG Received observer notification profile-after-change 19:24:16 INFO - GECKO(7712) | 1538940256942 Marionette DEBUG Received observer notification toplevel-window-ready 19:24:16 INFO - GECKO(7712) | 1538940256990 Marionette DEBUG Received observer notification command-line-startup 19:24:16 INFO - GECKO(7712) | 1538940256990 Marionette DEBUG Received observer notification nsPref:changed 19:24:16 INFO - GECKO(7712) | 1538940256990 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false) 19:27:16 INFO - Traceback (most recent call last): 19:27:16 INFO - File "Z:\task_1538939328\build\tests\mochitest\runtests.py", line 2818, in doTests 19:27:16 INFO - marionette_args=marionette_args, 19:27:16 INFO - File "Z:\task_1538939328\build\tests\mochitest\runtests.py", line 2256, in runApp 19:27:16 INFO - self.marionette.start_session() 19:27:16 INFO - File "Z:\task_1538939328\build\venv\lib\site-packages\marionette_driver\decorators.py", line 33, in _ 19:27:16 INFO - if m.is_shutting_down: 19:27:16 INFO - AttributeError: 'Marionette' object has no attribute 'is_shutting_down' 19:27:16 ERROR - Automation Error: Received unexpected exception while running application 19:27:16 ERROR - 19:27:16 INFO - Stopping web server
Comment hidden (Intermittent Failures Robot) |
Comment 3•6 years ago
|
||
:aryx, can we look for osx failures that match this and either put them in a specific bug or not? I am looking for issues with OSX where we actually have a similar failure, but end up killing taskcluster worker, the specific error line is: _RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL. that won't be highlighted, but it is nearby the failure: Application command: /Users/cltbld/tasks/task_1539175280/build/application/Firefox Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/p5/tdlp7wrx6pnd3r2h3s1zyh7000000x/T/tmpsdyaOn.mozrunner runtests.py | Application pid: 2065 TEST-INFO | started process GECKO(2065) GECKO(2065) | _RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL. Traceback (most recent call last): File "/Users/cltbld/tasks/task_1539175280/build/tests/mochitest/runtests.py", line 2819, in doTests marionette_args=marionette_args, File "/Users/cltbld/tasks/task_1539175280/build/tests/mochitest/runtests.py", line 2257, in runApp self.marionette.start_session() File "/Users/cltbld/tasks/task_1539175280/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 33, in _ if m.is_shutting_down: AttributeError: 'Marionette' object has no attribute 'is_shutting_down' Automation Error: Received unexpected exception while running application
Flags: needinfo?(aryx.bugmail)
![]() |
||
Comment 4•6 years ago
|
||
Automatically identification with sql.telemetry.mozilla.org is not feasible: The 2 failure lines have either 24k occurrences (is_shutting_down) or ~220k (Automation Error: Received unexpected exception while running application). Can you link such an OSX failure log, please? The OSX failures for this bug don't contain the error message in comment 3. That log will be used for the creation of a bug like "Intermittent OSX AttributeError: 'Marionette' object has no attribute 'is_shutting_down' after _RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL. (check log)"
Flags: needinfo?(aryx.bugmail)
Comment 5•6 years ago
|
||
ok, the logs I am looking at are from BLUE jobs on the tree, so treeherder doesn't have any visibility into the logs or failures.
Assignee | ||
Comment 6•6 years ago
|
||
try push for adding the variable that the decorator is looking for at the time it looks for it. https://treeherder.mozilla.org/#/jobs?repo=try&revision=7ccf96dcb8ffd9996b487378e3f8f3b0f1718c5f This won't solve the underlying issue but hopefully give us a clearer view into the real reason
Comment hidden (Intermittent Failures Robot) |
Comment 9•6 years ago
|
||
(In reply to David Burns :automatedtester from comment #6) > try push for adding the variable that the decorator is looking for at the > time it looks for it. > https://treeherder.mozilla.org/#/ > jobs?repo=try&revision=7ccf96dcb8ffd9996b487378e3f8f3b0f1718c5f > > This won't solve the underlying issue but hopefully give us a clearer view > into the real reason I suggest that we un-dupe bug 1496897 to get the Marionette failure fixed, which I already requested 9 days ago on that other bug. But no action was happening. Once that has been done, we will adjust the summary of this bug if necessary. Note that this might only happen when a command times out! See my comment on bug 1496897 comment 1 from 9 days ago too. When I check the original comment on this bug I can see that there is no `sessionstore-windows-restored` notification received, and as such Marionette doesn't initialize but kills the browser.
Comment 10•6 years ago
|
||
Actually the underlying issue here should resolve to one of the already existent bugs which are dependent on bug 1382162.
Depends on: 1382162
Assignee | ||
Comment 11•6 years ago
|
||
(In reply to Henrik Skupin (:whimboo) from comment #9) > (In reply to David Burns :automatedtester from comment #6) > > Note that this might only happen when a command times out! See my comment on > bug 1496897 comment 1 from 9 days ago too. Since this was not showing up regularly it was low priority. Saying you set a ni? 9 days ago on a seemingly low priority issue adds little value as a comment
Comment 13•6 years ago
|
||
We discussed that topic in our WebDriver meeting, and David will provide a fix soon, so that we can get the regression in Marionette client fixed ASAP.
Comment 14•6 years ago
|
||
Pushed by dburns@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/88d826bf6a68 Add missing attribute is_shutting_down to Marionette python client r=ato
Comment 15•6 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/88d826bf6a68
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Product: Testing → Remote Protocol
Comment 17•2 years ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in
before you can comment on or make changes to this bug.
Description
•