Closed Bug 1453895 Opened 2 years ago Closed Last year

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

Categories

(Testing :: Reftest, enhancement)

enhancement
Not set

Tracking

(firefox-esr60 fixed, firefox64 fixed, firefox65 fixed)

RESOLVED FIXED
mozilla65
Tracking Status
firefox-esr60 --- fixed
firefox64 --- fixed
firefox65 --- fixed

People

(Reporter: whimboo, Assigned: gbrown)

References

Details

Attachments

(1 file)

(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?
Flags: needinfo?(gbrown)
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.
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.
Flags: needinfo?(gbrown)
This is causing significant trouble in bug 1436237 again.
Assignee: nobody → 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.
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
Henrik could you take a look at the above?
Flags: needinfo?(hskupin)
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.
Flags: needinfo?(hskupin)
(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?
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.
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?
(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
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
Attachment #9023055 - Flags: review?(jmaher)
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.
Attachment #9023055 - Flags: review?(jmaher) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fec6ab4ed627
Avoid reftest startup hang waiting for focus; r=jmaher
https://hg.mozilla.org/mozilla-central/rev/fec6ab4ed627
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.