Intermittent Linux Mn testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py TestScreenCaptureChrome.test_formats | AssertionError: u'10a9988c502034662c801565ca05b9c154b933824b2f88849cab0e3e2b492da2' != '92b10dd07e1767c396f6

RESOLVED FIXED in Firefox 69

Status

defect
P1
normal
RESOLVED FIXED
9 months ago
Last month

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

Tracking

({intermittent-failure})

Version 3
mozilla69
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox65 disabled, firefox67 disabled, firefox67.0.1 disabled, firefox68 disabled, firefox69 fixed)

Details

Attachments

(5 attachments)

Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=209411710&repo=try

https://queue.taskcluster.net/v1/task/Ndn7c1ssSUSvu2oo0VFpTQ/runs/0/artifacts/public/logs/live_backing.log

This started on beta simulations, more frequent on late beta:
https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=e336ee10c816dddea2e5fb889718fce0ea33e1fe&selectedJob=209411710 
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=209411710&repo=try&lineNumber=29493

Failed to gather test failure debug: Browsing context has been discarded
[task 2018-11-02T12:11:42.976Z] 12:11:42  WARNING - stacktrace:
[task 2018-11-02T12:11:42.977Z] 12:11:42  WARNING - 	WebDriverError@chrome://marionette/content/error.js:179:5
[task 2018-11-02T12:11:42.977Z] 12:11:42  WARNING - 	NoSuchWindowError@chrome://marionette/content/error.js:411:5
[task 2018-11-02T12:11:42.978Z] 12:11:42  WARNING - 	assert.that/<@chrome://marionette/content/assert.js:401:13
[task 2018-11-02T12:11:42.979Z] 12:11:42  WARNING - 	assert.open@chrome://marionette/content/assert.js:157:10
[task 2018-11-02T12:11:42.981Z] 12:11:42  WARNING - 	GeckoDriver.prototype.getPageSource@chrome://marionette/content/driver.js:1146:15
[task 2018-11-02T12:11:42.982Z] 12:11:42  WARNING - 	despatch@chrome://marionette/content/server.js:291:20
[task 2018-11-02T12:11:42.983Z] 12:11:42  WARNING - 	execute@chrome://marionette/content/server.js:264:11
[task 2018-11-02T12:11:42.984Z] 12:11:42  WARNING - 	onPacket/<@chrome://marionette/content/server.js:237:15
[task 2018-11-02T12:11:42.985Z] 12:11:42  WARNING - 	onPacket@chrome://marionette/content/server.js:236:8
[task 2018-11-02T12:11:42.986Z] 12:11:42  WARNING - 	_onJSONObjectReady/<@chrome://marionette/content/transport.js:490:9
[task 2018-11-02T12:11:42.987Z] 12:11:42  WARNING - 
[task 2018-11-02T12:11:42.988Z] 12:11:42     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py TestScreenCaptureChrome.test_formats | AssertionError: u'10a9988c502034662c801565ca05b9c154b933824b2f88849cab0e3e2b492da2' != '92b10dd07e1767c396f652d93a9720fd8b79b1c2e453b7b7eb2818e4f225cdef'
[task 2018-11-02T12:11:42.989Z] 12:11:42     INFO - Traceback (most recent call last):
[task 2018-11-02T12:11:42.990Z] 12:11:42     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-11-02T12:11:42.990Z] 12:11:42     INFO -     testMethod()
[task 2018-11-02T12:11:42.991Z] 12:11:42     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/decorators.py", line 152, in skip_wrapper
[task 2018-11-02T12:11:42.992Z] 12:11:42     INFO -     return test_item(self, *args, **kwargs)
[task 2018-11-02T12:11:42.993Z] 12:11:42     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py", line 224, in test_formats
[task 2018-11-02T12:11:42.993Z] 12:11:42     INFO -     self.assert_formats()
[task 2018-11-02T12:11:42.994Z] 12:11:42     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py", line 93, in assert_formats
[task 2018-11-02T12:11:42.995Z] 12:11:42     INFO -     self.assertEqual(hash1, hashlib.sha256(screenshot_image).hexdigest())
[task 2018-11-02T12:11:42.996Z] 12:11:42     INFO - TEST-INFO took 243ms
[task 2018-11-02T12:11:42.997Z] 12:11:42     INFO -  1541160702963	Marionette	TRACE	132 -> [0,35,"WebDriver:GetChromeWindowHandles",{}]
[task 2018-11-02T12:11:42.998Z] 12:11:42     INFO -  1541160702964	Marionette	TRACE	132 <- [1,35,null,["3","339"]]
[task 2018-11-02T12:11:42.998Z] 12:11:42     INFO -  1541160702980	Marionette	TRACE	132 -> [0,36,"WebDriver:SwitchToWindow",{"focus":true,"name":"339"}]
[task 2018-11-02T12:11:43.000Z] 12:11:43     INFO -  1541160702982	Marionette	TRACE	132 <- [1,36,null,{"value":null}]
[task 2018-11-02T12:11:43.001Z] 12:11:43     INFO -  1541160702984	Marionette	TRACE	132 -> [0,37,"WebDriver:CloseChromeWindow",{}]
[task 2018-11-02T12:11:43.003Z] 12:11:43     INFO -  1541160702995	Marionette	DEBUG	Received observer notification message-manager-disconnect
[task 2018-11-02T12:11:43.004Z] 12:11:43     INFO -  1541160703000	Marionette	TRACE	132 <- [1,37,null,["3"]]
[task 2018-11-02T12:11:43.005Z] 12:11:43     INFO -  1541160703002	Marionette	TRACE	132 -> [0,38,"WebDriver:SwitchToWindow",{"focus":true,"name":"3"}]
[task 2018-11-02T12:11:43.006Z] 12:11:43     INFO -  1541160703003	Marionette	TRACE	132 <- [1,38,null,{"value":null}]
[task 2018-11-02T12:11:43.018Z] 12:11:43     INFO -  1541160703009	Marionette	TRACE	132 -> [0,39,"WebDriver:GetChromeWindowHandles",{}]
[task 2018-11-02T12:11:43.020Z] 12:11:43     INFO -  1541160703010	Marionette	TRACE	132 <- [1,39,null,["3"]]
[task 2018-11-02T12:11:43.021Z] 12:11:43     INFO -  1541160703011	Marionette	TRACE	132 -> [0,40,"WebDriver:GetWindowHandles",{}]
[task 2018-11-02T12:11:43.021Z] 12:11:43     INFO -  1541160703011	Marionette	TRACE	132 <- [1,40,null,["2147483911"]]
[task 2018-11-02T12:11:43.027Z] 12:11:43     INFO -  1541160703013	Marionette	TRACE	132 -> [0,41,"WebDriver:DeleteSession",{}]
This is for a beta simulation and all failures so far are on Linux opt platforms.
Summary: Intermittent Mn testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py TestScreenCaptureChrome.test_formats | AssertionError: u'10a9988c502034662c801565ca05b9c154b933824b2f88849cab0e3e2b492da2' != '92b10dd07e1767c396f6 → Intermittent Linux Mn testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py TestScreenCaptureChrome.test_formats | AssertionError: u'10a9988c502034662c801565ca05b9c154b933824b2f88849cab0e3e2b492da2' != '92b10dd07e1767c396f6
Is that the first beta simulation? If not did it already fail before? I also see Linux64 opt failing.
Flags: needinfo?(aryx.bugmail)
Did you mean "Linux64 debug"? Yes, had added some retriggers to that.

The issue didn't affect yesterday's simulations: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7f1e42a7de915ec3547461676e7fabe9751d8431&searchStr=linux%2Cmarionette
Flags: needinfo?(aryx.bugmail)
Do you have a list of commits for mozilla-central, which have been landed between those two beta simulations? That would help me a lot. Thanks.
Pushlog: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=3cff4bff1c9d&tochange=a6493a0b53a3

The mozilla-central revisions on which the beta simulations are based can be found in https://docs.google.com/document/d/1826JIk4zfT1fXt115Blvho635bjsGjR7KO0dVq3yBn8/edit# or by clicking at the bottom revision of a beta simulation and then on the parent revision.
As discussed in our WebDriver meeting yesterday it is very hard for me to track down this failure because it only happens for beta simulations. Also by default we truncate the logs, and as such the screenshot data is not fully visible in the logs, which makes it impossible to diagnose what's wrong. 

Sebastian, mind adding the following patch to the next beta simulation? It will give us some more insight into the screenshots for the failing test file.
Assignee: nobody → hskupin
Flags: needinfo?(aryx.bugmail)
Sure, I didn't expect a change in failures. But as I mentioned the logs are more verbose now which should allow us to see what's going on. So lets have a look...
Both attached screenshots should be identical, but in the first one the richlistitem hasn't been selected yet. Note that this entry has the attribute `selected="true"` set and should automatically be selected when the dialog is opened. Here the code:

https://searchfox.org/mozilla-central/source/testing/marionette/chrome/test_dialog.xul

Given that nothing changed on our side lately, I wonder if this might be a regression in Firefox caused by some XBL/XUL removal work?

Sebastian, could someone from SV may do a bisect for the integration branch merges by backfilling the merge commits from the pushlog in comment 5? I would kind appreciate this help. Thanks!
Flags: needinfo?(aryx.bugmail)
Bisecting shows this starts after bug 1362774 landed.
Blocks: 1362774
Flags: needinfo?(aryx.bugmail)
You should wait with comparing things until the window has been activated / received focus.
Comment on attachment 9022903 [details] [diff] [review]
patch_no_truncation.diff

Review of attachment 9022903 [details] [diff] [review]:
-----------------------------------------------------------------

I think it will be good to have this enabled by default for the screenshot tests, so that we can identify problems way easier and not have to request special pushes with this patch being applied.
Attachment #9022903 - Flags: review?(ato)
(In reply to :Gijs (he/him) from comment #14)
> You should wait with comparing things until the window has been activated /
> received focus.

That's what I did with my patch on bug 1507803 and which landed on central on Nov 23rd. But there are still problems with beta sims as it looks like.

I will have a look again once the patch as attached got landed, and I can more easily investigate those failures.
Also how is bug 1362774 related here, which is marked to be the reason of the regression? It sounds only to be related to initial browsers. But the test failing here is using a XUL window/dialog without any browsers attached:

https://searchfox.org/mozilla-central/source/testing/marionette/chrome/test_dialog.xul
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Henrik Skupin (:whimboo) from comment #20)
> Also how is bug 1362774 related here, which is marked to be the reason of
> the regression?

I don't know the exact details, but you can refer to the discussion in bug 1492480.

> It sounds only to be related to initial browsers. But the
> test failing here is using a XUL window/dialog without any browsers attached:
> 
> https://searchfox.org/mozilla-central/source/testing/marionette/chrome/
> test_dialog.xul

But there's a main browser window open, and your test opens the dialog repeatedly. I bet focus is not returning to the original browser window between you closing 1 dialog and opening the next, and as a result the focus event happens once the new window is open, meaning it loses focus.
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to :Gijs (he/him) from comment #21)
> as a result the focus event happens once the new window is open, meaning it loses focus.

So, to be clear, what you expect is:

1) browser window focuses
2) open dialog
3) dialog gains focus
4) dialog closed
5) browser window focused
6) you open another dialog
7) next dialog gets focused.


Instead, (5) happens after (6) and you end up with an unfocused dialog.

This can be fixed by waiting for focus/activate on the parent browser window when closing the dialog.

Also note that https://searchfox.org/mozilla-central/source/testing/marionette/client/marionette_driver/marionette.py#1498 only sends a message and doesn't wait for that message to have been acted upon.
Attachment #9022903 - Flags: review?(ato) → review+
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/74b45418136b
"Intermittent Linux Mn testing/marionette/harness/marionette_harness/tests/unit/test_screenshot.py TestScreenCaptureChrome.test_formats | AssertionError: u'10a9988c502034662c801565ca05b9c154b933824b2f88849cab0e3e2b492da2' != '92b10dd07e1767c396f6" r=ato
Keywords: checkin-needed
Thanks Gijs! I will have a look at it tomorrow. Now that it is not related to opening a new window, it looks like to be related to the `WebDriver:switchToWindow` command. So it might have to wait for bug 1335085.
Keywords: leave-open
Given that I will still need a bit to fix the underlying bugs, I propose that we just skip this test on both integration branches and beta for now.

I will make sure to have this fixed as soon as possible.
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/75b067260e38
[marionette] Temporarily skip TestScreenCaptureChrome.test_formats on Linux. r=whimboo
Sebastian, when the next merge simulation works fine and this failure is gone, can we please uplift the skip patch to mozilla-beta?
Flags: needinfo?(aryx.bugmail)
Flags: needinfo?(aryx.bugmail)
Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended]
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/59b4cb737397
[marionette] Re-enable test TestScreenCaptureChrome.test_formats. r=webdriver-reviewers,ato
Status: NEW → ASSIGNED
Keywords: leave-open
Priority: P5 → P1
Status: ASSIGNED → RESOLVED
Closed: 2 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla69

Please uplift this test-only patch to beta. Thanks.

Whiteboard: [checkin-needed-beta]
Whiteboard: [checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.