1452399 - |mach mochitest (or reftest) <dir> --app=org.mozilla.geckoview.test| does not complete

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, enhancement, P1)

Description

[Geoff Brown [:gbrown]]

I can run mochitests (or reftests) in geckoview_example in an emulator with:

mach mochitest testing/mochitest/tests/Harness_sanity --app=org.mozilla.geckoview_example

mach reftest layout/reftests/reftest-sanity --app=org.mozilla.geckoview_example

Everything works great until the tests complete -- then geckoview_example does not quit and the harness hangs.


Do we need changes to the harness? Changes to geckoview_example?

Comment 1

[Bob Clary [:bc] (inactive)]

Can you attach the log and logcat from an example run?

Comment 2

[Geoff Brown [:gbrown]]

See also https://bugzilla.mozilla.org/show_bug.cgi?id=1448188#c10 -- maybe this isn't the right way to run mochi/reftests  in geckoview.

Comment 3

[Bob Clary [:bc] (inactive)]

Perhaps we need to uplift something like Autophone's stop_application: https://github.com/mozilla/autophone/blob/master/phonetest.py#L749

Comment 4

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #2)
> See also https://bugzilla.mozilla.org/show_bug.cgi?id=1448188#c10 -- maybe
> this isn't the right way to run mochi/reftests  in geckoview.

Let's concentrate then on running in TestRunnerActivity, with updates from bug 1452694.

Unfortunately, the problem persists.

Comment 5

[Geoff Brown [:gbrown]]

(In reply to Bob Clary [:bc:] from comment #1)
> Can you attach the log and logcat from an example run?

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

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

[task 2018-04-09T19:03:23.179Z] 19:03:23     INFO -  14 INFO TEST-OK | caps/tests/mochitest/test_extensionURL.html | took 7505ms
[task 2018-04-09T19:03:23.179Z] 19:03:23     INFO -  15 INFO TEST-START | Shutdown
[task 2018-04-09T19:03:23.181Z] 19:03:23     INFO -  16 INFO Passed:  70
[task 2018-04-09T19:03:23.181Z] 19:03:23     INFO -  17 INFO Failed:  0
[task 2018-04-09T19:03:23.182Z] 19:03:23     INFO -  18 INFO Todo:    0
[task 2018-04-09T19:03:23.182Z] 19:03:23     INFO -  19 INFO Mode:    non-e10s
[task 2018-04-09T19:03:23.182Z] 19:03:23     INFO -  20 INFO Slowest: 7505ms - /tests/caps/tests/mochitest/test_extensionURL.html
[task 2018-04-09T19:03:23.182Z] 19:03:23     INFO -  21 INFO SimpleTest FINISHED
[task 2018-04-09T19:17:22.391Z] 19:17:22     INFO -  Browser unexpectedly found running. Killing...
[task 2018-04-09T19:17:22.391Z] 19:17:22     INFO -  TEST-INFO | started process screentopng
[task 2018-04-09T19:17:22.747Z] 19:17:22     INFO -  TEST-INFO | screentopng: exit 0
[task 2018-04-09T19:17:37.404Z] 19:17:37  WARNING -  TEST-UNEXPECTED-FAIL | caps/tests/mochitest/test_extensionURL.html | application timed out after 370 seconds with no output

Unfortunately, we lost the logcat here, but the reftests look better...

Comment 6

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?job_id=172720821&repo=try&lineNumber=4632-4645

[task 2018-04-09T19:46:23.030Z] 19:46:23     INFO -  REFTEST TEST-PASS | http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-13.html == http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-8-ref.html | image comparison, max difference: 0, number of differing pixels: 0
[task 2018-04-09T19:46:23.030Z] 19:46:23     INFO -  REFTEST TEST-END | http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-13.html == http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-8-ref.html
[task 2018-04-09T19:46:23.030Z] 19:46:23     INFO -  REFTEST INFO | Result summary:
[task 2018-04-09T19:46:23.030Z] 19:46:23     INFO -  REFTEST INFO | Successful: 499 (483 pass, 16 load only)
[task 2018-04-09T19:46:23.030Z] 19:46:23     INFO -  REFTEST INFO | Unexpected: 0 (0 unexpected fail, 0 unexpected pass, 0 unexpected asserts, 0 failed load, 0 exception)
[task 2018-04-09T19:46:23.031Z] 19:46:23     INFO -  REFTEST INFO | Known problems: 46 (16 known fail, 0 known asserts, 6 random, 24 skipped, 0 slow)
[task 2018-04-09T19:46:23.031Z] 19:46:23     INFO -  REFTEST SUITE-END | Shutdown
[task 2018-04-09T19:46:23.031Z] 19:46:23     INFO -  REFTEST INFO | Slowest test took 14951ms (http://10.0.2.2:8888/tests/image/test/reftest/downscaling/huge-1.html?32768x100.gif,32768,100)
[task 2018-04-09T19:46:23.032Z] 19:46:23     INFO -  REFTEST INFO | Total canvas count = 2
[task 2018-04-09T19:53:36.540Z] 19:53:36     INFO -  Browser unexpectedly found running. Killing...
[task 2018-04-09T19:53:36.541Z] 19:53:36     INFO -  REFTEST TEST-INFO | started process screentopng
[task 2018-04-09T19:53:36.871Z] 19:53:36     INFO -  REFTEST TEST-INFO | screentopng: exit 0
[task 2018-04-09T19:53:50.914Z] 19:53:50  WARNING -  TEST-UNEXPECTED-FAIL | http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-13.html == http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-8-ref.html | application timed out after 370 seconds with no output
[task 2018-04-09T19:53:50.915Z] 19:53:50     INFO -  INFO | automation.py | Application ran for: 0:49:58.001658


https://taskcluster-artifacts.net/YTX643jtRgCf0LmQMdbwaw/0/public/test_info//logcat-emulator-5554.log

04-09 12:46:17.984   771   784 I Gecko   : {"action":"test_status","time":1523303177990,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-13.html == http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-8-ref.html","subtest":"image comparison, max difference: 0, number of differing pixels: 0","status":"PASS","extra":{"status_msg":"Pass"}}
04-09 12:46:17.984   771   784 I Gecko   : 
04-09 12:46:17.984   771   784 I Gecko   : {"action":"test_end","time":1523303177993,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-13.html == http://10.0.2.2:8888/tests/layout/reftests/w3c-css/submitted/css21/pagination/moz-css21-block-page-break-inside-avoid-8-ref.html","status":"OK"}
04-09 12:46:17.994   771   784 I Gecko   : 
04-09 12:46:17.994   771   784 I Gecko   : {"action":"log","time":1523303177996,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Loading a blank page"}
04-09 12:46:18.175   771   771 D GeckoNetworkManager: Incoming event disableNotifications for state OffWithListeners -> OffNoListeners
04-09 12:46:18.245   771   784 I Gecko   : 
04-09 12:46:18.245   771   784 I Gecko   : {"action":"suite_end","time":1523303178252,"thread":null,"pid":null,"source":"reftest","extra":{"results":{"Pass":483,"LoadOnly":16,"Exception":0,"FailedLoad":0,"UnexpectedFail":0,"UnexpectedPass":0,"AssertionUnexpected":0,"AssertionUnexpectedFixed":0,"KnownFail":16,"AssertionKnown":0,"Random":6,"Skip":24,"Slow":0}}}
04-09 12:46:18.255   771   784 I Gecko   : 
04-09 12:46:18.255   771   784 I Gecko   : {"action":"log","time":1523303178261,"thread":null,"pid":null,"source":"reftest","level":"INFO","message":"Slowest test took 14951ms (http://10.0.2.2:8888/tests/image/test/reftest/downscaling/huge-1.html?32768x100.gif,32768,100)"}
04-09 12:46:18.255   771   784 I Gecko   : 
04-09 12:46:18.255   771   784 I Gecko   : {"action":"log","time":1523303178262,"thread":null,"pid":null,"source":"reftest","level":"INFO","message":"Total canvas count = 2"}
04-09 12:46:56.205   277   279 D dalvikvm: GC_CONCURRENT freed 643K, 15% free 5474K/6368K, paused 5ms+24ms, total 111ms
04-09 12:47:30.515   277   279 D dalvikvm: GC_CONCURRENT freed 674K, 15% free 5472K/6368K, paused 5ms+31ms, total 122ms
04-09 12:48:04.904   277   279 D dalvikvm: GC_CONCURRENT freed 682K, 15% free 5462K/6368K, paused 5ms+7ms, total 123ms
04-09 12:48:39.175   277   279 D dalvikvm: GC_CONCURRENT freed 649K, 15% free 5450K/6368K, paused 5ms+4ms, total 95ms
04-09 12:49:13.335   277   279 D dalvikvm: GC_CONCURRENT freed 652K, 15% free 5452K/6368K, paused 5ms+5ms, total 109ms
04-09 12:49:47.604   277   279 D dalvikvm: GC_CONCURRENT freed 641K, 15% free 5450K/6368K, paused 5ms+5ms, total 97ms
04-09 12:50:21.865   277   279 D dalvikvm: GC_CONCURRENT freed 645K, 15% free 5455K/6368K, paused 5ms+19ms, total 105ms
04-09 12:50:56.185   277   279 D dalvikvm: GC_CONCURRENT freed 649K, 15% free 5456K/6368K, paused 5ms+19ms, total 107ms
04-09 12:51:30.424   277   279 D dalvikvm: GC_CONCURRENT freed 652K, 15% free 5451K/6368K, paused 5ms+4ms, total 101ms
04-09 12:52:04.504   277   279 D dalvikvm: GC_CONCURRENT freed 647K, 15% free 5452K/6368K, paused 5ms+5ms, total 104ms
04-09 12:52:38.775   277   279 D dalvikvm: GC_CONCURRENT freed 642K, 15% free 5451K/6368K, paused 6ms+6ms, total 98ms
04-09 12:53:13.026   277   279 D dalvikvm: GC_CONCURRENT freed 652K, 15% free 5452K/6368K, paused 6ms+5ms, total 109ms
04-09 12:53:37.354   771   776 I dalvikvm: threadid=3: reacting to signal 3
04-09 12:53:37.444   771   776 I dalvikvm: Wrote stack traces to '/data/anr/traces.txt'

Comment 7

[Geoff Brown [:gbrown]]

(In reply to Bob Clary [:bc:] from comment #3)
> Perhaps we need to uplift something like Autophone's stop_application:
> https://github.com/mozilla/autophone/blob/master/phonetest.py#L749

Cool stuff there, but I don't know that it will help here. The harnesses are waiting for the app to finish tests and quit, or at least go to background. In Fennec, that normally happens when we hit code like:

https://dxr.mozilla.org/mozilla-central/rev/30d72755b1749953d438199456f1524ce84ab5e5/layout/tools/reftest/reftest.jsm#767-768

        let appStartup = Cc["@mozilla.org/toolkit/app-startup;1"].getService(Ci.nsIAppStartup);
        appStartup.quit(Ci.nsIAppStartup.eForceQuit);


:snorp -- How would you expect TestRunnerActivity to react to this sort of quit() call? Can you have a look?

Comment 8

[James Willcox (:snorp) ([e-mail]) (he/him)]

Yeah, for some reason shutdown isn't working as expected. Investigating.

Comment 9

[James Willcox (:snorp) ([e-mail]) (he/him)]

Attachment: Bug 1452399 - Add GeckoRuntime.Delegate

This lets us notify apps when Gecko exits and maybe other interesting
things in the future.

Review commit: https://reviewboard.mozilla.org/r/235384/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/235384/

Comment 10

[James Willcox (:snorp) ([e-mail]) (he/him)]

Attachment: Bug 1452399 - Shut down TestRunnerActivity when Gecko exits

Review commit: https://reviewboard.mozilla.org/r/235386/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/235386/

Comment 11

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8966686 [details]
Bug 1452399 - Add GeckoRuntime.Delegate

https://reviewboard.mozilla.org/r/235384/#review241096

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:56
(Diff revision 1)
>  
>          return sDefaultRuntime;
>      }
>  
>      private GeckoRuntimeSettings mSettings;
> +    private Delegate mDelegate;

/* package */

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:73
(Diff revision 1)
>          if (!appContext.equals(GeckoAppShell.getApplicationContext())) {
>              GeckoAppShell.setApplicationContext(appContext);
>          }
>      }
>  
> +    private BundleEventListener mEventListener = new BundleEventListener() {

final

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:75
(Diff revision 1)
>          }
>      }
>  
> +    private BundleEventListener mEventListener = new BundleEventListener() {
> +        @Override
> +        public void handleMessage(String event, GeckoBundle message, EventCallback callback) {

final args

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:78
(Diff revision 1)
> +    private BundleEventListener mEventListener = new BundleEventListener() {
> +        @Override
> +        public void handleMessage(String event, GeckoBundle message, EventCallback callback) {
> +            if ("Gecko:Exited".equals(event) && mDelegate != null) {
> +                mDelegate.onExit();
> +                EventDispatcher.getInstance().unregisterUiThreadListener(mEventListener, "Gecko:Exited", null);

Don't need null at the end.

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:101
(Diff revision 1)
>                  return false;
>              }
>              mSettings = settings;
> +
> +            // Bug 1453062 -- the EventDispatcher should really live here (or in GeckoThread)
> +            EventDispatcher.getInstance().registerUiThreadListener(mEventListener, "Gecko:Exited", null);

Don't need null at the end.

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:167
(Diff revision 1)
>  
> +    /**
> +     * Set a delegate for receiving callbacks relevant to to this GeckoRuntime
> +     * @param delegate an implementation of {@link GeckoRuntime.Delegate}
> +     */
> +    public void setDelegate(Delegate delegate) {

final

Comment 12

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8966687 [details]
Bug 1452399 - Shut down TestRunnerActivity when Gecko exits

https://reviewboard.mozilla.org/r/235386/#review241098

::: mobile/android/geckoview/src/androidTest/java/org/mozilla/geckoview/test/TestRunnerActivity.java:26
(Diff revision 1)
>  
>      static GeckoRuntime sRuntime;
>  
> -    GeckoSession mSession;
> -    GeckoView mView;
> +    private GeckoSession mSession;
> +    private GeckoView mView;
> +    private boolean mKillProcessOnDestroy;

/* package */

::: mobile/android/modules/geckoview/GeckoViewNavigation.jsm:251
(Diff revision 1)
>    }
>  
>    // nsIBrowserDOMWindow.
>    canClose() {
>      debug("canClose");
> -    return false;
> +    return BrowserUtils.canCloseWindow(this.window);

Do we need this? `GeckoRuntime.shutdown` should still close the window even if this returns false here.

Comment 13

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 8966686 [details]
Bug 1452399 - Add GeckoRuntime.Delegate

https://reviewboard.mozilla.org/r/235384/#review241096

> /* package */

Why?

Comment 14

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 8966687 [details]
Bug 1452399 - Shut down TestRunnerActivity when Gecko exits

https://reviewboard.mozilla.org/r/235386/#review241122

::: mobile/android/geckoview/src/androidTest/java/org/mozilla/geckoview/test/TestRunnerActivity.java:26
(Diff revision 1)
>  
>      static GeckoRuntime sRuntime;
>  
> -    GeckoSession mSession;
> -    GeckoView mView;
> +    private GeckoSession mSession;
> +    private GeckoView mView;
> +    private boolean mKillProcessOnDestroy;

Why?

::: mobile/android/modules/geckoview/GeckoViewNavigation.jsm:251
(Diff revision 1)
>    }
>  
>    // nsIBrowserDOMWindow.
>    canClose() {
>      debug("canClose");
> -    return false;
> +    return BrowserUtils.canCloseWindow(this.window);

The BrowserUtils thing will run 'beforeunload' handlers which could block the window close and therefore the shutdown. It seems like we'd want that in most cases where you care closing a session, but no the shutdown case. I can change this to 'true' for now and file a followup for the 'beforeunload' case.

Comment 15

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 8966686 [details]
Bug 1452399 - Add GeckoRuntime.Delegate

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/235384/diff/1-2/

Comment 16

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 8966687 [details]
Bug 1452399 - Shut down TestRunnerActivity when Gecko exits

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/235386/diff/1-2/

Comment 17

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8966686 [details]
Bug 1452399 - Add GeckoRuntime.Delegate

https://reviewboard.mozilla.org/r/235384/#review241096

> Why?

It's used by the `mEventListener` inner class.

Comment 18

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8966687 [details]
Bug 1452399 - Shut down TestRunnerActivity when Gecko exits

https://reviewboard.mozilla.org/r/235386/#review241122

> The BrowserUtils thing will run 'beforeunload' handlers which could block the window close and therefore the shutdown. It seems like we'd want that in most cases where you care closing a session, but no the shutdown case. I can change this to 'true' for now and file a followup for the 'beforeunload' case.

I would return `true` for now. I think `GeckoRuntime.shutdown` implies a forced shutdown where we close everything?

Comment 19

[Eugen Sawin [:esawin]]

Comment on attachment 8966686 [details]
Bug 1452399 - Add GeckoRuntime.Delegate

https://reviewboard.mozilla.org/r/235384/#review241376

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:160
(Diff revision 2)
>  
>          GeckoThread.forceQuit();
>      }
>  
> +    /**
> +     * Set a delegate for receiving callbacks relevant to to this GeckoRuntime

.

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:161
(Diff revision 2)
>          GeckoThread.forceQuit();
>      }
>  
> +    /**
> +     * Set a delegate for receiving callbacks relevant to to this GeckoRuntime
> +     * @param delegate an implementation of {@link GeckoRuntime.Delegate}

Add empty line and period.

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:170
(Diff revision 2)
> +    }
> +
> +    /**
> +     * Returns the current delegate, if any.
> +     *
> +     * @return an instance of {@link GeckoRuntime.Delegate} or null if no delegate has been set

.

::: mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoRuntime.java:206
(Diff revision 2)
>          public GeckoRuntime[] newArray(final int size) {
>              return new GeckoRuntime[size];
>          }
>      };
> +
> +    public interface Delegate {

Please move the interface either to top of the class definition or close to the setter, this is Parcelable territory.

Comment 20

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Jim Chen [:jchen] [:darchons] from comment #17)
> Comment on attachment 8966686 [details]
> Bug 1452399 - Add GeckoRuntime.Delegate
> 
> https://reviewboard.mozilla.org/r/235384/#review241096
> 
> > Why?
> 
> It's used by the `mEventListener` inner class.

Sure, but inner classes are allowed to access private members of their container.

Comment 21

[(inactive) Jim Chen [:jchen] [:darchons]]

(In reply to James Willcox (:snorp) ([e-mail]) from comment #20)
> (In reply to Jim Chen [:jchen] [:darchons] from comment #17)
> 
> > It's used by the `mEventListener` inner class.
> 
> Sure, but inner classes are allowed to access private members of their
> container.

Through synthetic accessor methods. That's why we use /* package */ for these cases to avoid the synthetic methods adding to our dex count.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1a959252a818
Add GeckoRuntime.Delegate r=esawin
https://hg.mozilla.org/integration/mozilla-inbound/rev/73ba53cdcc2b
Shut down TestRunnerActivity when Gecko exits r=jchen

Comment 23

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/1a959252a818
https://hg.mozilla.org/mozilla-central/rev/73ba53cdcc2b

Comment 24

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/1a959252a818
https://hg.mozilla.org/mozilla-central/rev/73ba53cdcc2b