Closed Bug 1496759 Opened 1 year ago Closed 1 year ago

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

Categories

(Firefox :: Session Restore, defect, P1)

defect

Tracking

()

VERIFIED FIXED
Firefox 64
Tracking Status
firefox-esr60 --- unaffected
firefox62 --- unaffected
firefox63 --- unaffected
firefox64 + verified

People

(Reporter: CosminS, Assigned: whimboo)

References

(Depends on 1 open bug)

Details

(Keywords: regression)

Attachments

(1 file)

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?
Flags: needinfo?(ckerschb)
See Also: → 1497116
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?
Flags: needinfo?(ckerschb) → needinfo?(csabou)
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?
Flags: needinfo?(csabou) → needinfo?(hskupin)
Summary: Perma beta marionette test_restore_windows_after_restart_and_quit en-US failures when Gecko 64 merges to Beta on 2018-10-15 → Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit en-US failures when Gecko 64 merges to Beta on 2018-10-15
Probably we can/should this one also out of dom:security eventually.
Component: DOM: Security → Session Restore
Product: Core → Firefox
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.
I don't understand what is going wrong. Backout might be tricky due to dependencies. Skip that test until Henrik returns?
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.
Flags: needinfo?(hskupin)
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!
Flags: needinfo?(aryx.bugmail)
QA Contact: ckerschb
Summary: Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit en-US failures when Gecko 64 merges to Beta on 2018-10-15 → Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit.py, test_refresh_firefox.py en-US failures when Gecko 64 merges to Beta on 2018-10-15
(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!?
Summary: Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit.py, test_refresh_firefox.py en-US failures when Gecko 64 merges to Beta on 2018-10-15 → Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit.py, test_refresh_firefox.py en-US failures when Gecko 64 merges to Beta on 2018-10-05
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.
Assignee: nobody → hskupin
No longer blocks: 1433873, 1433905
Status: NEW → RESOLVED
Closed: 1 year ago
Depends on: 1433873, 1433905
Flags: needinfo?(aryx.bugmail)
Keywords: leave-openregression
Resolution: --- → FIXED
Summary: Perma beta Windows opt marionette test_restore_windows_after_restart_and_quit.py, test_refresh_firefox.py en-US failures when Gecko 64 merges to Beta on 2018-10-05 → 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-05
Target Milestone: --- → Firefox 64
Actually beta simulation is not beta merge as Sebastian cleared it up on the other bug. So restoring the summary of the bug.
Summary: 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-05 → 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
(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
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.
Status: RESOLVED → REOPENED
Depends on: 1400780
Priority: -- → P1
Resolution: FIXED → ---
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?
Flags: needinfo?(agashlin)
I don't know of anything. I'm not sure what test failure this bug is about now.
Flags: needinfo?(agashlin)
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.
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.
The patch on bug 1493796 backed out the failing code, so with the next uplift to beta this will be fixed.
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.