1496759 - Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit.py en-US failures when Gecko 64 merges to Beta on 2018-10-15

Status: VERIFIED FIXED

(Firefox :: Session Restore, defect, P1)

Description

[Cosmin Sabou [:CosminS]]

central as beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed,busted,exception,retry,usercancel,runnable&revision=abe33ef03345af2ff608ac1d8503bbbe153221e4&selectedJob=203662192

failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=203662192&repo=try&lineNumber=48303

14:59:16     INFO -  1538751556649	Marionette	TRACE	2 -> [0,1329,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"Z:\\task_1538750764\\build\\v ... ancelQuit, \"quit-application-requested\", null);\n                return cancelQuit.data;","sandbox":"default","line":1062}]
14:59:16     INFO -  1538751556653	Marionette	TRACE	2 <- [1,1329,null,{"value":false}]
14:59:16     INFO -  1538751556658	Marionette	TRACE	2 -> [0,1330,"Marionette:SetContext",{"value":"chrome"}]
14:59:16     INFO -  1538751556658	Marionette	TRACE	2 <- [1,1330,null,{"value":null}]
14:59:16     INFO -  1538751556659	Marionette	TRACE	2 -> [0,1331,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
14:59:16     INFO -  1538751556660	Marionette	INFO	Stopped listening on port 2828
14:59:16     INFO -  1538751556747	Marionette	TRACE	2 <- [1,1331,null,{"cause":"restart"}]
14:59:16     INFO -  [Parent 5632, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 5852, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 5852, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 256: TypeError: browser.frameLoader is null
14:59:16     INFO -  [Parent 5632, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
14:59:16     INFO -  1538751556821	Marionette	DEBUG	Closed connection 2
14:59:16     INFO -  [Parent 5632, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Parent 5632, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 4216, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 4216, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 5228, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 5228, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 256: TypeError: browser.frameLoader is null
14:59:16     INFO -  [Parent 5632, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 4940, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  [Child 4940, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:59:16     INFO -  JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 256: TypeError: browser.frameLoader is null
14:59:17     INFO -  1538751557085	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
14:59:17     INFO -  1538751557085	Marionette	DEBUG	Remote service is inactive
14:59:18     INFO - TEST-UNEXPECTED-ERROR | testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | IOError: Process has been unexpectedly closed (Exit code: 0) (Reason: Requested restart of the application was aborted)
14:59:18     INFO - Traceback (most recent call last):
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
14:59:18     INFO -     testMethod()
14:59:18     INFO -   File "Z:\task_1538750764\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py", line 76, in test_restore_with_restart
14:59:18     INFO -     self.restart()
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\firefox_puppeteer\mixins.py", line 74, in restart
14:59:18     INFO -     self.marionette.restart(*args, **kwargs)
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\decorators.py", line 31, in _
14:59:18     INFO -     m._handle_socket_failure()
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\marionette.py", line 839, in _handle_socket_failure
14:59:18     INFO -     reraise(IOError, message.format(returncode=returncode, reason=val), tb)
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
14:59:18     INFO -     return func(*args, **kwargs)
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1172, in restart
14:59:18     INFO -     reraise(exc, "Requested restart of the application was aborted", tb)
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1167, in restart
14:59:18     INFO -     self.raise_for_port(timeout=timeout)
14:59:18     INFO -   File "Z:\task_1538750764\build\venv\lib\site-packages\marionette_driver\marionette.py", line 730, in raise_for_port
14:59:18     INFO -     self.host, self.port))
14:59:18     INFO - TEST-INFO took 7378ms
14:59:18    ERROR - test_end for testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_restore_windows_after_restart_and_quit.TestSessionStoreDisabled", "method_name": "test_restore_with_restart"}, "expected": "PASS", "test": "testing\\firefox-ui\\tests\\functional\\sessionstore\\test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n  File \"Z:\\task_1538750764\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 190, in run\n    self.tearDown()\n  File \"Z:\\task_1538750764\\build\\tests\\firefox-ui\\tests\\testing\\firefox-ui\\tests\\functional\\sessionstore\\session_store_test_case.py\", line 65, in tearDown\n    super(SessionStoreTestCase, self).tearDown()\n  File \"Z:\\task_1538750764\\build\\venv\\lib\\site-packages\\firefox_puppeteer\\mixins.py\", line 97, in tearDown\n    self.marionette.set_context('chrome')\n  File \"Z:\\task_1538750764\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1432, in set_context\n    {\"value\": context})\n  File \"Z:\\task_1538750764\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 26, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_1538750764\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 748, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n"}

This looks to be a regression from https://hg.mozilla.org/mozilla-central/rev/37fcdbb6756c#l5.15 
Christoph, could you take a look?

Comment 1

[Christoph Kerschbaumer [:ckerschb]]

It's possible it's a regression from Bug 1495983 but it seems I can't reproduce locally. Is this test run in the test suite all the time? I mean what's different in terms of testing when we merge into beta?
I tried running the test using:
> ./mach test testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py

Is there anything I can try differently which would allow me to reproduce the problem?

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Saturday's beta simulation had the patch backed out and the failures were still around: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed,busted,exception,usercancel,runnable&revision=fe899aa0ca1d613a0faf9d2b62328cb355c5e494&selectedJob=203857446

So it's not from your patch.

For completeness:
Apply the "base config" and "trunk as early" beta patches from here if you want beta builds: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e3ab3609cac6d71540c707fd82aea3f24a39baad

Checked central, there the test runs. They fail in the beta simulation on Windows opt-ish builds

Henrik, hi, any pointers what broke those tests on beta?

Comment 3

[Intermittent Failures Robot]

1 failures in 2708 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 1

Platform breakdown:
* windows7-32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1496759&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 4

[Christoph Kerschbaumer [:ckerschb]]

Probably we can/should this one also out of dom:security eventually.

Comment 7

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

This looks like fallout from bug 1433905 and bug 1433873. It's also the explanation why the error message changed.

Current state of it in beta simulations: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed,busted,exception,retry,runnable&revision=3410b8781c8ea426e6892a231aeb51208cea8fb5&selectedJob=204815736 (en-US is also failing)

The first merge from central to beta is on Monday (2018-10-15) and will cause perma failures.

Geoff, Henrik is on PTO at least this week. Do you have recommendations how to resolve this? Thank you.

Comment 8

[Geoff Brown [:gbrown]]

I don't understand what is going wrong. Backout might be tricky due to dependencies. Skip that test until Henrik returns?

Comment 9

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: phabricator request

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I will have a look at the bug now, but also CC'ing Adam because he did most of the work on those tests lately.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so from the patch as provided it looks like it is not only a sessionstore test whichh is failing but also test_refresh_firefox.py. And that all on Windows.

Here my investigation for the initial comment:

> 14:59:16     INFO -  1538751556659	Marionette	TRACE	2 -> [0,1331,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
> 14:59:16     INFO -  1538751556660	Marionette	INFO	Stopped listening on port 2828
> 14:59:16     INFO -  1538751556747	Marionette	TRACE	2 <- [1,1331,null,{"cause":"restart"}]

Marionette clearly triggers a restart of Firefox, and then 2s later we hit:

> 14:59:17     INFO -  1538751557085	Marionette	DEBUG	Remote service is inactive
> 14:59:18     INFO - TEST-UNEXPECTED-ERROR | testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | IOError: Process has been unexpectedly closed (Exit code: 0) (Reason: Requested restart of the application was aborted)

Please note the reason `Requested restart of the application was aborted`. This is clearly the code before my patch on bug 1433873 landed on central, which was Fri, 05 Oct 2018 16:43:18.

So what was the base revision for the central to beta merge on 2018-10-15? That is not clear to me. There is a difference of 10 days!

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #2)
> Saturday's beta simulation had the patch backed out and the failures were
> still around:
> https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed,
> busted,exception,usercancel,
> runnable&revision=fe899aa0ca1d613a0faf9d2b62328cb355c5e494&selectedJob=203857
> 446

Note that those builds actually fail differently with `TestFirefoxRefresh.testReset | AssertionError: Reset profile path should contain profile name to remove`. And I don't see the failure for the sessionstore test anymore.

Also the initial comment was not for Oct 15th but Oct 5th! Which would explain it. My assumption is that the patch on bug 1433905 caused a regression, and which was then fixed by my patch on bug 1433873. Note that it was hard to fix those issues because both patches depend on each other.

My question now would be do we see the firefox refresh failure only on beta merges, or also on central? I'm not aware of a filed bug yet. All of those instances were marked as expected fail!?

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually there is bug 1497062 which has been marked as duplicate of this bug, which is wrong. I will reopen the other bug to track this correctly. The problem as mentioned here are fixed by bug 1433873.

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually beta simulation is not beta merge as Sebastian cleared it up on the other bug. So restoring the summary of the bug.

Comment 15

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

(In reply to Henrik Skupin (:whimboo) from comment #11)
> So what was the base revision for the central to beta merge on 2018-10-15?
Base revisions:
2018-10-04: https://hg.mozilla.org/mozilla-central/rev/f87eeba88f1cf3f4d41095f7a58cb518a59f844c 
2018-10-05: https://hg.mozilla.org/mozilla-central/rev/863c5a0642a84831b8ff3cac737c8657c70b05f1 
2018-10-06: https://hg.mozilla.org/mozilla-central/rev/6f233fd06aace5fdbad3ffa1692329c508b16b2b

(In reply to Henrik Skupin (:whimboo) from comment #12)
> My question now would be do we see the firefox refresh failure only on beta
> merges, or also on central? I'm not aware of a filed bug yet. All of those
> instances were marked as expected fail!?
Only aware of them for beta simulations as Windows permafails. And permafails get set to "expected fail" to avoid orangefactor bot from commenting daily. If it stops failing, the bug gets closed.

Today's early beta simulation based on https://hg.mozilla.org/mozilla-central/rev/9079bbe837184ed183b133a374753865b6768bc4  :

https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=retry,testfailed,busted,exception,runnable&revision=20ff6a370c03e1f22cc9fe559ed521f3a20b6035&selectedJob=205795361

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so this seems to be still present then but with a different failure now. And it can also be seen on mozilla-beta itself:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta&searchStr=fxfn&selectedJob=205649410

The underlying problem here seems to be bug 1400780.

Comment 17

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Adam, do you know if there were some sessionstore changes for Windows only within the last 2 weeks, which could have caused this? Or is a feature only enabled in Nightly but not releases?

Comment 18

[Adam Gashlin (he/him) [:agashlin] (ex-moco)]

I don't know of anything. I'm not sure what test failure this bug is about now.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yeah, it's nothing which has been changed on your side, but it's one of my patches for mozprocess which caused this problem. See bug 1400780 for more details.

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I have just pushed a try build for bug 1493796, which is actually the underlying problem here. It will temporarily backout the change as made in https://hg.mozilla.org/integration/autoland/rev/8793e332890e, and skip the appropriate mozprocess unit test on Windows only.

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The patch on bug 1493796 backed out the failing code, so with the next uplift to beta this will be fixed.

Comment 22

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Verified fixed with today's beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception%2Crunnable&revision=f7ac7e6ce3518f18d06ad07ee080d219dc16cf33&selectedJob=206668654