1453895 - reftest.jsm hangs before reading tests if browser cannot be brought into focus

Status: RESOLVED FIXED

(Testing :: Reftest, enhancement)

Description

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

(In reply to Henrik Skupin (:whimboo) from bug 1436237 comment #30)
> Oh, you are right. I totally missed that. Sorry. Also with your patch we
> have kinda huge logs ~17MB per test job due to debug level logging. I think
> that we are fine and don't need anything extra.
> 
> So I have taken another look at the logs and noticed the following. For a
> successful build the following reftest extension log is seen right after:
> 
> https://taskcluster-artifacts.net/SjXrJ914SDmH3bXODrKvzg/0/public/logs/
> log_info.log
> 
> > 02:49:53     INFO -  REFTEST INFO | Reading manifest file://C:\Users\task_1523587360\build\tests\reftest\tests\layout\reftests\reftest.list
> > 02:49:53     INFO -  REFTEST INFO | Dumping JSON representation of sandbox
> 
> Note that this is NOT happening in case of hangs! So it feels to me that the
> reftest extension might fail early during initialization/startup. Maybe
> something similar to what I fixed yesterday on bug 1452913.
> 
> Here where it is called:
> https://dxr.mozilla.org/mozilla-central/rev/
> 325ef357e5b73d63794e47c02c7f8e7cf58ccb48/layout/tools/reftest/reftest.jsm#391
> 
> The code lives in `ReadTests` which gets called at:
> 
> https://dxr.mozilla.org/mozilla-central/rev/
> 325ef357e5b73d63794e47c02c7f8e7cf58ccb48/layout/tools/reftest/reftest.
> jsm#306-312
> 
> Interesting is the check for `FOCUS_FILTER_NON_NEEDS_FOCUS_TESTS`. If
> `focusFilterMode` is different we register a listener for focus, which calls
> `ReadTests`. Please note that we would never reach `ReadTests` if the
> browser doesn't emit this event.
> 
> The `focusFilterMode` is set via the preference `reftest.focusFilterMode` in
> the reftest harness which directly comes from the command line options:
> 
> https://dxr.mozilla.org/mozilla-central/rev/
> 325ef357e5b73d63794e47c02c7f8e7cf58ccb48/layout/tools/reftest/runreftest.
> py#304
> 
> And we don't set this option in mozharness:
> 
> https://dxr.mozilla.org/mozilla-central/rev/
> 325ef357e5b73d63794e47c02c7f8e7cf58ccb48/testing/mozharness/configs/
> unittests/win_taskcluster_unittest.py#121-135
> 
> As such it is None and I'm fairly sure that we hang due to the above
> described scenario. Firefox does not have focus.
> 
> Geoff, I would suggest that we add another `logger.info()` call which
> explains that we wait for focus. I will file a new bug and provide a patch.

(In reply to Henrik Skupin (:whimboo) from comment #31)
> Btw the mochitest harness seems to log some more helpful messages in case
> the focus cannot be set:
> 
> > 0:39.87 INFO Error: Unable to restore focus, expect failures and timeouts.
> [..]
> > 0:39.93 INFO must wait for load
> > 0:39.93 INFO must wait for focus
> 
> Geoff, it looks like we might want to do some more work, which I don't have
> the time for. Maybe you could pick this up?

Comment 1

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

Two things we should fix:

1) Better handling of failing to set the focus in reftest.jsm which this bug is for.

2) Figuring out why Firefox isn't in focus intermittently. For this we would have to create screenshots, which we aren't doing yet.

Comment 2

[Geoff Brown [:gbrown]]

Regarding the focusFilterMode, note that there is also this code:

https://dxr.mozilla.org/mozilla-central/rev/325ef357e5b73d63794e47c02c7f8e7cf58ccb48/layout/tools/reftest/runreftest.py#569-573

        # First job is only needs-focus tests.  Remaining jobs are
        # non-needs-focus and chunked.
        perProcessArgs[0].insert(-1, "--focus-filter-mode=needs-focus")
        for (chunkNumber, jobArgs) in enumerate(perProcessArgs[1:], start=1):
            jobArgs[-1:-1] = ["--focus-filter-mode=non-needs-focus",

I don't know this code. :jmaher or :ahal might be able to comment / might be interested??


At my current backlog level, I don't think I can look at this in Q2.

Comment 3

[Geoff Brown [:gbrown]]

This is causing significant trouble in bug 1436237 again.

Comment 4

[Geoff Brown [:gbrown]]

From that bug:

This failure is easily reproduced on try, at least on windows-10/debug.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=31bb93611267c85883d29a0740cbfb75fe5cd32a

Debug logging in that try push shows that this code is run for both success and failure cases:

https://dxr.mozilla.org/mozilla-central/rev/c291143e24019097d087f9307e59b49facaf90cb/layout/tools/reftest/reftest.jsm#308-309

but ReadTests() is never called in the failure cases: reftests do not start because the focus event is never received.

Comment 5

[Geoff Brown [:gbrown]]

Is that because g.browser sometimes already has focus? I'm seeing some evidence of that. Let's see:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=198291df616a048daea297963f93e83c35ba1cfc

Comment 6

[Andreea Pavel [:apavel]]

Henrik could you take a look at the above?

Comment 7

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

Looks like the last try still have failures. Geoff, maybe best to also log various states from the focus manager, like focusedWindow, activeWindow. Maybe Firefox is not the front-most application and as such it fails to call focus.

I wonder if the focusmanager test mode would make a difference for reftests.

Comment 8

[Geoff Brown [:gbrown]]

(In reply to Henrik Skupin (:whimboo) from comment #7)
> I wonder if the focusmanager test mode would make a difference for reftests.

What is that?

Comment 9

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

The testmode simulates that Firefox is the top-most application when `window.focus()` has been called for the chrome window. Even if Firefox then moves into the background due to some other applications stealing the focus, Firefox internally will think it is still the front-most. 

For tests with Selenium + geckodriver it allows us to run multiple Firefox processes in parallel, and each of those having the focus. 

But yes, not sure if reftests would benefit from that.

Comment 10

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=fddc989a2e7115785b7ef803f00b93f7fb2b3af3

In the normal, successful case, before the focus() call, focusmanager's focusedWindow == activeWindow == reftest.jsm's g.containWindow == reftest.xul and focusedElement == null; after the focus() call, the focus event is observed, focusedWindow and activeWindow stay the same (reftest.xul) and focusedElement == xul:browser.

In the intermittent failure case, before the focus() call, focusmanager's focusedWindow == activeWindow == about:blank and focusedElement = null; after the focus(), nothing changes.

Perhaps reftest.xul has not yet loaded?

Comment 11

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #10)
> Perhaps reftest.xul has not yet loaded?

That seems unlikely: https://dxr.mozilla.org/mozilla-central/rev/c291143e24019097d087f9307e59b49facaf90cb/layout/tools/reftest/reftest.xul#12

Comment 12

[Geoff Brown [:gbrown]]

I'm finally making progress:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=fd1a5cee02830a1e61bd4d9241a0ffca994c2adf

Comment 13

[Geoff Brown [:gbrown]]

Attachment: focus g.containingWindow if needed

See observations in comment 10 and try results in comment 12. Also, here's a "does no harm" run for reftest on all platforms:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a33fc70f72ca29b9ca5d13f0aea821ad0e098e3d

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 9023055 [details] [diff] [review]
focus g.containingWindow if needed

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

this seems harmless and hopefully productive.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fec6ab4ed627
Avoid reftest startup hang waiting for focus; r=jmaher

Comment 16

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/fec6ab4ed627

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/afe2dac07dff

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr60/rev/6b64af95c34f