Treeherder Bug Filer Reporter
	Description • 6 years ago
treeherder

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

	Joel Maher ( :jmaher ) (UTC -8)
	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

	Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)
	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)"

	Joel Maher ( :jmaher ) (UTC -8)
	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.

	David Burns :automatedtester 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

	Henrik Skupin [:whimboo][⌚️UTC+2]
	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.

	Henrik Skupin [:whimboo][⌚️UTC+2]
	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.

	David Burns :automatedtester 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

	Henrik Skupin [:whimboo][⌚️UTC+2]
	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.

	Pulsebot
	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

	Bogdan Tara[:bogdan_tara | bogdant]
	Comment 15 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/88d826bf6a68

	BMO Automation
	Comment 17 • 2 years ago

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.