1529597 - Mozharness Fennec screenshots always show first-run screen (pgo)

Status: RESOLVED WORKSFORME

(Firefox for Android Graveyard :: Testing, defect, P3)

Description

[Michael Shal [:mshal]]

Attachment: screenshot-120s-G5KWbs.png

While trying to debug Android PGO profile generation, I enabled screenshot_times in the mozharness config to take periodic snapshots. Unfortunately the captured screen only ever shows the "Thanks for choosing Nightly" welcome page instead of the actual test page. There are several "firstrun" prefs that are disabled, but they don't seem to have an effect on this welcome page:

user_pref("browser.firstrun.show.localepicker", false);
user_pref("browser.firstrun.show.uidiscovery", false);
user_pref("browser.snippets.firstrunHomepage.enabled", false);

I see the same behavior on other Android test suites (eg: opt-marionette-1), so it's possible this regressed at some point.

Comment 1

[Michael Shal [:mshal]]

:gbrown, can you provide some guidance here? I'm not sure what I'm missing.

Comment 2

[Geoff Brown [:gbrown]]

I tried my own experiment with screenshot_times:

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

I found exactly one first-run screen, for one of the 3 marionette runs there. In that case:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=229670321&repo=try&lineNumber=1468-1472

[task 2019-02-21T16:26:58.139Z] 16:26:58 INFO - adb launch_application: am start -W -n org.mozilla.fennec_aurora/org.mozilla.gecko.BrowserApp -a android.intent.action.VIEW --es env8 R_LOG_LEVEL=6 --es args "-no-remote -profile /sdcard/tests/profile -marionette" --es env3 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4,MediaPipelineFactory:4 --es env2 MOZ_HIDE_RESULTS_TABLE=1 --es env1 R_LOG_VERBOSE=1 --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_PROCESS_LOG=/tmp/tmpKptVSXpidlog --es env6 MOZ_CRASHREPORTER_NO_REPORT=1 --es env5 R_LOG_DESTINATION=stderr --es env4 MOZ_CRASHREPORTER_here'SHUTDOWN=1
[task 2019-02-21T16:27:48.460Z] 16:27:48 INFO - timed (60s) screenshot complete
[task 2019-02-21T16:28:48.510Z] 16:28:48 INFO - timed (120s) screenshot complete
[task 2019-02-21T16:29:48.488Z] 16:29:48 INFO - timed (180s) screenshot complete
[task 2019-02-21T16:29:58.096Z] 16:29:58 INFO - Profile path is /tmp/tmpHSkJLm.mozrunner

it looks like the screenshots were taken after fennec was started but before tests started. I don't know much about marionette tests; I wonder what the harness was doing/waiting for. Also curious is that the 60s screenshot does not show the first-run screen, but the 120s and 180s screenshots do show "Thanks for choosing Nightly". At 240s, the welcome screen is gone and we are running tests.

I don't see any first-run screens in the robocop, mochitest, or reftest tasks. Have you seen any?

The prefs you mentioned are my best guess at which prefs are involved in first-run suppression, but I'm not sure.

Comment 3

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

The startup of Fennec is kinda slow. See those times here from the android adb logcat:

02-21 08:27:53.881 797 821 I Gecko : 1550766473885 Marionette TRACE Received observer notification profile-after-change
[..]
02-21 08:27:58.811 797 821 I Gecko : 1550766478816 Marionette TRACE Received observer notification command-line-startup
02-21 08:27:58.821 797 821 I Gecko : 1550766478822 Marionette TRACE Received observer notification nsPref:changed
02-21 08:27:58.831 797 821 I Gecko : 1550766478830 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
[..]
02-21 08:28:04.602 797 821 I Gecko : 1550766484604 Marionette TRACE Received observer notification toplevel-window-ready
[..]
02-21 08:28:38.271 797 821 I Gecko : 1550766518279 Marionette TRACE Received observer notification sessionstore-windows-restored
02-21 08:28:38.301 797 821 I Gecko : 1550766518300 Marionette TRACE Received observer notification marionette-startup-requested
02-21 08:28:38.341 797 821 I Gecko : 1550766518344 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[..]
02-21 08:29:44.121 797 821 I Gecko : 1550766584129 Marionette TRACE All scripts recorded.
02-21 08:29:53.542 797 821 I Gecko : 1550766593548 Marionette INFO Listening on port 2828
02-21 08:29:53.761 797 821 I Gecko : 1550766593763 Marionette DEBUG Remote service is active

These are 105s between the profile-after-change and marionette-startup-requested notifications, with additional 15s until Marionette enabled its port and is active.

So there is no wonder why the tab doesn't change its initial page, and tests are getting started with such a delay.

Comment 4

[Jan Henning [:JanH]]

(In reply to Michael Shal [:mshal] from comment #0)

user_pref("browser.firstrun.show.localepicker", false);
user_pref("browser.firstrun.show.uidiscovery", false);
user_pref("browser.snippets.firstrunHomepage.enabled", false);

All those prefs are unused (bug 1529863).

As far as I can tell after a quick look, first run on Android is controlled solely by native Android app SharedPrefs, but as of bug 1432598, it should also turn itself off if it detects being run in automation.

Comment 5

[Michael Shal [:mshal]]

(In reply to Geoff Brown [:gbrown] from comment #2)

it looks like the screenshots were taken after fennec was started but before tests started. I don't know much about marionette tests; I wonder what the harness was doing/waiting for. Also curious is that the 60s screenshot does not show the first-run screen, but the 120s and 180s screenshots do show "Thanks for choosing Nightly". At 240s, the welcome screen is gone and we are running tests.

I don't see any first-run screens in the robocop, mochitest, or reftest tasks. Have you seen any?

Hmm, it looks like it was just marionette, but I saw them on every run:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3800cf8807eba9f3aae21a88d079bcaac88faa3&selectedJob=228669869

Ultimately I'm trying to get screenshots to see the activity of running the profile server. Here's an example try push:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=cad851f680246f4a0e4b147043730c833cc2dff3&selectedJob=228655154

The screenshots all have the first run screen after about a minute, and stay for the duration (or at least through the 995s for the last screenshot). I'm not sure why in your push, the marionette test shows a first run screen that then goes away, but mine seem to persist.

Comment 6

[Michael Shal [:mshal]]

(In reply to Jan Henning [:JanH] from comment #4)

As far as I can tell after a quick look, first run on Android is controlled solely by native Android app SharedPrefs, but as of bug 1432598, it should also turn itself off if it detects being run in automation.

Ahh thanks for the tip, looks like I'm missing MOZ_IN_AUTOMATION in the environment. I'll give that a try.

Comment 7

[Michael Shal [:mshal]]

Setting MOZ_IN_AUTOMATION=1 in the FennecEmulatorRunner environment did the trick. Thanks for the help!