platform: linux1804

try push: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=3c36bd183199b979328fa600902e48587b296727
logs: https://firefoxci.taskcluster-artifacts.net/AvtvYxLDTVG90FLpqkYyZw/0/public/logs/live_backing.log

log excerpt:

[setup 2020-03-16T21:33:02.346Z] MOZ_FETCHES_DIR is /builds/worker/fetches
[fetches 2020-03-16T21:33:02.346Z] fetching artifacts
[fetches 2020-03-16T21:33:02.346Z] executing ['/usr/bin/python3', '-u', '/builds/worker/bin/fetch-content', 'task-artifacts']
[fetches 2020-03-16T21:33:02.438Z] attempt 1/5
[fetches 2020-03-16T21:33:02.438Z] attempt 1/5
[fetches 2020-03-16T21:33:02.438Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KA0m3hM2QEGBujHcAOhMLA/artifacts/public/build/target.tar.bz2 to /builds/worker/fetches/target.tar.bz2
[fetches 2020-03-16T21:33:02.438Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GF2KiI6OSGWCF5OkeHjVcA/artifacts/public/build/node.tar.xz to /builds/worker/fetches/node.tar.xz
[fetches 2020-03-16T21:33:02.438Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KA0m3hM2QEGBujHcAOhMLA/artifacts/public/build/target.tar.bz2
[fetches 2020-03-16T21:33:02.438Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GF2KiI6OSGWCF5OkeHjVcA/artifacts/public/build/node.tar.xz
[fetches 2020-03-16T21:33:02.897Z] https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GF2KiI6OSGWCF5OkeHjVcA/artifacts/public/build/node.tar.xz resolved to 14160640 bytes with sha256 ff58a62c8eadbde6be3006a9e3633555af28881c94c1e0baab32fce649511c5e in 0.458s
[fetches 2020-03-16T21:33:02.897Z] Extracting /builds/worker/fetches/node.tar.xz to /builds/worker/fetches
[fetches 2020-03-16T21:33:04.117Z] https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KA0m3hM2QEGBujHcAOhMLA/artifacts/public/build/target.tar.bz2 resolved to 72730231 bytes with sha256 9d0fd99902618b17841d2e5b62687d667e31cdb370f2d6389d4a7a206dc715fd in 1.678s
[fetches 2020-03-16T21:33:04.117Z] Extracting /builds/worker/fetches/target.tar.bz2 to /builds/worker/fetches
[fetches 2020-03-16T21:33:04.875Z] /builds/worker/fetches/node.tar.xz extracted in 1.978s
[fetches 2020-03-16T21:33:04.875Z] Removing /builds/worker/fetches/node.tar.xz
[fetches 2020-03-16T21:33:13.943Z] /builds/worker/fetches/target.tar.bz2 extracted in 9.826s
[fetches 2020-03-16T21:33:13.944Z] Removing /builds/worker/fetches/target.tar.bz2
[fetches 2020-03-16T21:33:13.955Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "fetch_content", "value": 11.517984468999998, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[fetches 2020-03-16T21:33:13.969Z] finished fetching artifacts
[task 2020-03-16T21:33:13.969Z] executing ['bash', '-cx', 'cd $GECKO_PATH/ && ./mach puppeteer-test -vv --binary $MOZ_FETCHES_DIR/firefox/firefox --headless --write-results /builds/worker/results.json --log-tbpl - --log-errorsummary /builds/worker/pup_errorsummary.json --log-raw /builds/worker/pup_raw.log\n']
[task 2020-03-16T21:33:13.971Z] + cd /builds/worker/checkouts/gecko/
[task 2020-03-16T21:33:13.971Z] + ./mach puppeteer-test -vv --binary /builds/worker/fetches/firefox/firefox --headless --write-results /builds/worker/results.json --log-tbpl - --log-errorsummary /builds/worker/pup_errorsummary.json --log-raw /builds/worker/pup_raw.log
[task 2020-03-16T21:33:21.335Z] 
[task 2020-03-16T21:33:21.335Z] > puppeteer@2.0.0-post install /builds/worker/checkouts/gecko/remote/test/puppeteer
[task 2020-03-16T21:33:21.335Z] > node install.js
[task 2020-03-16T21:33:21.335Z] 
[task 2020-03-16T21:33:21.411Z] **INFO** Skipping Chromium download. "PUPPETEER_SKIP_CHROMIUM_DOWNLOAD" environment variable was found.
[task 2020-03-16T21:33:21.708Z] npm notice created a lockfile as package-lock.json. You should commit this file.
[task 2020-03-16T21:33:21.709Z] added 164 packages from 156 contributors and audited 269 packages in 6.286s
[task 2020-03-16T21:33:21.792Z] 
[task 2020-03-16T21:33:21.792Z] 1 package is looking for funding
[task 2020-03-16T21:33:21.792Z]   run `npm fund` for details
[task 2020-03-16T21:33:21.792Z] 
[task 2020-03-16T21:33:21.792Z] found 0 vulnerabilities
[task 2020-03-16T21:33:21.792Z] 
[task 2020-03-16T21:33:22.060Z] SUITE-START | Running 0 tests
[task 2020-03-16T21:33:22.349Z] PID 105 | 
[task 2020-03-16T21:33:22.349Z] PID 105 | > puppeteer@2.0.0-post funit /builds/worker/checkouts/gecko/remote/test/puppeteer
[task 2020-03-16T21:33:22.349Z] PID 105 | > PUPPETEER_PRODUCT=firefox node test/test.js "--verbose"
[task 2020-03-16T21:33:22.349Z] PID 105 | 
[task 2020-03-16T21:33:22.486Z] PID 105 | Testing on Node v10.19.0
[task 2020-03-16T21:33:22.550Z] PID 105 | WARN: running Firefox tests with /builds/worker/fetches/firefox/firefox
[task 2020-03-16T21:33:22.631Z] PID 105 | Running all 638 tests on 1 worker(s):
[task 2020-03-16T21:33:22.631Z] PID 105 | 
[task 2020-03-16T21:33:22.675Z] PID 105 | *** You are running in headless mode.
[task 2020-03-16T21:33:23.436Z] PID 105 | 1584394403431	addons.webextension.doh-rollout@mozilla.org	WARN	Loading extension 'doh-rollout@mozilla.org': Reading manifest: Invalid extension permission: networkStatus
[task 2020-03-16T21:33:24.282Z] PID 105 | 1584394404282	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-03-16T21:33:24.283Z] PID 105 | 1584394404282	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2020-03-16T21:33:24.283Z] PID 105 | 1584394404282	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-03-16T21:33:24.283Z] PID 105 | 1584394404282	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2020-03-16T21:33:37.660Z] PID 105 | 
[task 2020-03-16T21:33:37.660Z] PID 105 | 
[task 2020-03-16T21:33:37.660Z] PID 105 | 
[task 2020-03-16T21:33:37.660Z] PID 105 | Ran 0  of 638 test(s)
[task 2020-03-16T21:33:37.661Z] PID 105 | Finished in 15.029 seconds
[task 2020-03-16T21:33:37.661Z] PID 105 | ## CRASHED ##
[task 2020-03-16T21:33:37.661Z] PID 105 | Message:
[task 2020-03-16T21:33:37.661Z] PID 105 |   puppeteer.spec.js:84:5 - Timeout Exceeded 15000ms while running "beforeAll" in suite "Firefox Browser"
[task 2020-03-16T21:33:37.661Z] PID 105 | WORKERS STATE
[task 2020-03-16T21:33:45.782Z] PID 105 | DevTools listening on ws://localhost:35577/devtools/browser/2502aad9-6fb7-4f73-9936-fe6dd99092c0
[task 2020-03-16T21:33:45.866Z] PID 105 | 1584394425865	RemoteAgent	TRACE	(connection {89d6c75b-2517-400d-8ba1-2df190218554})-> {"method":"Target.setDiscoverTargets","params":{"discover":true},"id":1}
[task 2020-03-16T21:33:45.869Z] PID 105 | 1584394425868	RemoteAgent	TRACE	<-(connection {89d6c75b-2517-400d-8ba1-2df190218554}) {"method":"Target.targetCreated","params":{"targetInfo":{"browserContextId":null,"targetId":9,"type":"page","url":"about:blank"}}}
[task 2020-03-16T21:33:45.873Z] PID 105 | 1584394425868	RemoteAgent	TRACE	<-(connection {89d6c75b-2517-400d-8ba1-2df190218554}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"2502aad9-6fb7-4f73-9936-fe6dd99092c0","type":"browser"}}}
[task 2020-03-16T21:33:45.873Z] PID 105 | 1584394425869	RemoteAgent	TRACE	<-(connection {89d6c75b-2517-400d-8ba1-2df190218554}) {"id":1}
[task 2020-03-16T21:34:04.961Z] PID 105 | console.error: BroadcastService:
[task 2020-03-16T21:34:04.962Z] PID 105 |   receivedBroadcastMessage: handler for
[task 2020-03-16T21:34:04.962Z] PID 105 |   remote-settings/monitor_changes
[task 2020-03-16T21:34:04.962Z] PID 105 |   threw error:
[task 2020-03-16T21:34:04.962Z] PID 105 |   Message: Error: Polling for changes failed: NetworkError when attempting to fetch resource..
[task 2020-03-16T21:34:04.962Z] PID 105 |   Stack:
[task 2020-03-16T21:34:04.962Z] PID 105 |     remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:255:13
[task 2020-03-16T21:34:04.962Z] PID 105 | async*receivedBroadcastMessage@resource://services-settings/remote-settings.js:470:27
[task 2020-03-16T21:34:04.963Z] PID 105 | receivedBroadcastMessage@resource://gre/modules/PushBroadcastService.jsm:263:23
[task 2020-03-16T21:34:04.963Z] PID 105 | async*receivedBroadcastMessage@resource://gre/modules/PushService.jsm:843:8
[task 2020-03-16T21:34:04.963Z] PID 105 | _handleBroadcastReply@resource://gre/modules/PushServiceWebSocket.jsm:845:27
[task 2020-03-16T21:34:04.963Z] PID 105 | _wsOnMessageAvailable@resource://gre/modules/PushServiceWebSocket.jsm:1167:18
[task 2020-03-16T21:34:04.963Z] PID 105 | onMessageAvailable@resource://gre/modules/PushServiceWebSocket.jsm:111:23
[task 2020-03-16T21:34:04.963Z] PID 105 | 
[task 2020-03-16T21:36:44.927Z] PID 105 | *** PurgeTrackerService: returning early, etpActive: false, purgeEnabled: false

[taskcluster:error] Task timeout after 3600 seconds. Force killing container.
[taskcluster 2020-03-16 22:30:08.338Z] === Task Finished ===
[taskcluster 2020-03-16 22:30:08.338Z] Unsuccessful task run with exit code: -1 completed in 3826.885 seconds

Filed bug as requested on https://phabricator.services.mozilla.com/D66348#2027574.

With the ubuntu1804-test image used (instead of desktop1604-test, puppeteer attempts to launch Firefox but times out waiting for it.

Edwin, do the normal browser chrome tests for remote under /remote/tests/browser/ work on that distribution, or do you see the same problem?

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #2)

Edwin, do the normal browser chrome tests for remote under /remote/tests/browser/ work on that distribution, or do you see the same problem?

I checked through the manifests ran in mochitest-browser-chrome on this mozilla-central push but was not able to find any instance of remote/tests/browser being run.

Those are called remote mochitest and can be seen here:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&tier=1%2C2%2C3&searchStr=linux1804%2Cremote%2Cmochi&revision=5100681103a8c27f67a1acc7f657422b6b79e23b

So it's really only an issue with Puppeteer. I can see that the websocket is listening, the client connects, and two targets (a browser and a page) are created. So I wonder why we are timing out waiting for the page target here:

https://searchfox.org/mozilla-central/rev/d6f957415cf009995ecb539ef1425316d82164a9/remote/test/puppeteer/lib/Launcher.js#425-426

Simon, I assume this patch was not targeted for this bug? Or is it?

Comment on attachment 9142361 [details]
Bug 1623128 - Use mozilla::Variant for ResultHelper.

Revision D71936 was moved to bug 1632128. Setting attachment 9142361 [details] to obsolete.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #6)

Simon, I assume this patch was not targeted for this bug? Or is it?

Oops, sorry, two digits were flipped in the bug number.

Edwin, which patch would i need to get the puppeteer test running on Ubuntu 18.04? I would like to check the next days why we are hanging. Thanks.

:whimboo - if you apply the following patch, it will switch over to using ubuntu1804 for the test:

# HG changeset patch
# User Edwin Takahashi <egao@mozilla.com>
# Date 1583276481 28800
# Node ID c620dce29c9b8861c954fc9a16f013a3baa42bd5
# Parent  bf8af9af80475880154922cf2465dc0b0ecd27fd
ubuntu1804 - source-test-remote

diff --git a/taskcluster/ci/source-test/remote.yml b/taskcluster/ci/source-test/remote.yml
--- a/taskcluster/ci/source-test/remote.yml
+++ b/taskcluster/ci/source-test/remote.yml
@@ -13,17 +13,17 @@ job-defaults:
             - target.tar.bz2
         toolchain:
             - linux64-node
     treeherder:
         kind: test
         tier: 3
     worker-type: t-linux-xlarge
     worker:
-        docker-image: {in-tree: desktop1604-test}
+        docker-image: {in-tree: ubuntu1804-test}
         max-run-time: 1800
 
 puppeteer:
     description: Puppeteer tests against Firefox CDP-based remote protocol
     run-on-projects: ["mozilla-central", "try"]
     treeherder:
         symbol: remote(pup)
     run:

I tried several things, which didn't give any detail what's wrong, but finally i noticed that we run the test in headless mode. That's not how we run tests by default in CI. So we clearly have to run the tests in normal mode. Making this change brought us a step forward:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3f985425b06bb0f28a6f7c67b3bf3a2563bca684&selectedJob=299298264

It's running now but crashing because Firefox fails to start:

Error: cannot open display: :0

As it looks like I have to add 'NEED_WINDOW_MANAGER: 'true'` to the taskcluster config. So lets try again:

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

That still doesn't work because the source tree tests do not actually call test-linux.sh, which is responsible for bringing up the window manager. So which options do we have now? If source tree jobs should never use a window manager, we may have to move the pup job to an ordinary test job?

So once bug 1633101 has been fixed we will be able to get the pup job running on Ubuntu 18.04:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=93666667f3ae627c01a79e3c723bdbb186567575&selectedJob=299379279

We can even try non-headless by using NEED_WINDOW_MANAGER: 'true' and:

https://searchfox.org/mozilla-central/source/taskcluster/ci/source-test/python.yml#104-105

source /builds/worker/scripts/xvfb.sh &&
start_xvfb '1600x1200x24' 0 &&

Unassigning myself until the blocker has been fixed.

With the fontconfig dependency fixed for ubuntu18.04 we should be able to get the tests enabled now. Here a try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8a7de18b8c0e83c86b0efec05329988fd24f540d

I will file a new bug for also running the Puppeteer unit tests in non-headless mode.

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