Closed Bug 1713030 Opened 3 years ago Closed 2 years ago

High frequency TEST-UNEXPECTED-TIMEOUT | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state (launcher.spec.ts) | expected PASS

Categories

(Remote Protocol :: CDP, defect, P5)

defect

Tracking

(firefox96 fixed)

RESOLVED FIXED
96 Branch
Tracking Status
firefox96 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure)

Attachments

(5 files)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=340895650&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YYix59AwSAGWgkgOrc5cMw/runs/0/artifacts/public/logs/live_backing.log


[task 2021-05-26T22:59:08.907Z] TEST-PASS | Launcher specs Puppeteer Puppeteer.launch userDataDir argument (launcher.spec.ts) | took 2111ms
[task 2021-05-26T22:59:08.907Z] PID 357 | ["pass",{"title":"userDataDir argument","fullTitle":"Launcher specs Puppeteer Puppeteer.launch userDataDir argument","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts","duration":2110,"currentRetry":0}]
[task 2021-05-26T22:59:08.907Z] TEST-START | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state (launcher.spec.ts)
[task 2021-05-26T22:59:08.907Z] PID 357 | ["test-start",{"title":"userDataDir option should restore state","fullTitle":"Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts","currentRetry":0}]
[task 2021-05-26T22:59:08.936Z] PID 357 | *** You are running in headless mode.
[task 2021-05-26T22:59:09.143Z] PID 357 | [GFX1-]: glxtest: libEGL initialize failed
[task 2021-05-26T22:59:09.143Z] PID 357 | [GFX1-]: glxtest: Unable to open a connection to the X server
[task 2021-05-26T22:59:09.144Z] PID 357 | [GFX1-]: glxtest: libEGL initialize failed
[task 2021-05-26T22:59:10.539Z] PID 357 | DevTools listening on ws://localhost:33543/devtools/browser/9dbb35d6-77b6-4235-90aa-e70f0a4e54c2
[task 2021-05-26T22:59:11.480Z] PID 357 | *** You are running in headless mode.
[task 2021-05-26T22:59:11.542Z] PID 357 | [GFX1-]: glxtest: libEGL initialize failed
[task 2021-05-26T22:59:11.543Z] PID 357 | [GFX1-]: glxtest: Unable to open a connection to the X server
[task 2021-05-26T22:59:11.543Z] PID 357 | [GFX1-]: glxtest: libEGL initialize failed
[task 2021-05-26T22:59:12.236Z] PID 357 | DevTools listening on ws://localhost:40138/devtools/browser/400fa2a0-0b7a-498d-894c-47f447f4d534
[task 2021-05-26T22:59:28.917Z] TEST-UNEXPECTED-TIMEOUT | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state (launcher.spec.ts) | expected PASS
[task 2021-05-26T22:59:28.918Z] TEST-INFO took 20010ms
[task 2021-05-26T22:59:28.918Z] PID 357 | ["fail",{"title":"userDataDir option should restore state","fullTitle":"Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts","duration":20010,"currentRetry":0,"err":"Timeout of 20000ms exceeded. For async tests and hooks, ensure \"done()\" is called; if returning a Promise, ensure it resolves. (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts)","stack":"Error: Timeout of 20000ms exceeded. For async tests and hooks, ensure \"done()\" is called; if returning a Promise, ensure it resolves. (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts)\n    at createTimeoutError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/errors.js:491:15)\n    at Test.Runnable._timeoutError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:431:10)\n    at Timeout.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:246:24)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}]
[task 2021-05-26T22:59:28.918Z] TEST-START | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore cookies (launcher.spec.ts)
[task 2021-05-26T22:59:28.918Z] TEST-SKIP | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore cookies (launcher.spec.ts) | took 0ms
[task 2021-05-26T22:59:28.918Z] PID 357 | ["pending",{"title":"userDataDir option should restore cookies","fullTitle":"Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore cookies","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts","currentRetry":0}]
[task 2021-05-26T22:59:28.918Z] TEST-START | Launcher specs Puppeteer Puppeteer.launch should return the default arguments (launcher.spec.ts)
[task 2021-05-26T22:59:28.918Z] PID 357 | ["test-start",{"title":"should return the default arguments","fullTitle":"Launcher specs Puppeteer Puppeteer.launch should return the default arguments","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/launcher.spec.ts","currentRetry":0}]
[task 2021-05-26T22:59:28.919Z] TEST-PASS | Launcher specs Puppeteer Puppeteer.launch should return the default arguments (launcher.spec.ts) | took 1ms

Maybe this is related to the Unable to open a connection to the X server failure that we are seeing here. Lets see how often this happens.

Part of today's failures are retriggers, please disregard the small spike.

Maybe some of the launcher tests are failing because we do not have a valid X server setup:

[task 2021-09-26T22:36:56.650Z] PID 403 | Unable to init server: Could not connect: Connection refused
[task 2021-09-26T22:36:56.650Z] PID 403 | Error: cannot open display: :0

With bug 1669435 fixed, we might get more passing tests, and maybe this one fixed.

Depends on: 1669435

My last comment might not apply given that there are also the same kind of failures in the Puppeteer CI:
https://github.com/puppeteer/puppeteer/issues/7615

The startup of Firefox is pretty quick and protocols are listening. But then there is this long hang without any CDP connection being made:
https://treeherder.mozilla.org/logviewer?job_id=353187684&repo=mozilla-central&lineNumber=25202-25208

[task 2021-09-30T05:27:04.291Z] PID 406 | *** You are running in headless mode.
[task 2021-09-30T05:27:04.356Z] PID 406 | [GFX1-]: glxtest: Unable to open a connection to the X server
[task 2021-09-30T05:27:04.356Z] PID 406 | [GFX1-]: glxtest: libEGL initialize failed
[task 2021-09-30T05:27:04.665Z] PID 406 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2021-09-30T05:27:05.155Z] PID 406 | DevTools listening on ws://localhost:34334/devtools/browser/fe8fd5bc-33fb-4b98-9b42-a00149113802
[task 2021-09-30T05:27:05.155Z] PID 406 | WebDriver BiDi listening on ws://localhost:34334
No longer depends on: 1669435

It's interesting that I can replicate the hang locally all the time when running with an artifact build. But that's mostly bug 1701596. Using a Nightly build instead the hang doesn't occur at least on MacOS.

See Also: → 1701596
Depends on: 1734208

So the problem here seems to be the following... These specific launcher tests that use a manually created temporary directory as profile directory do NOT have the appropriate Firefox preferences set. As such the profile as used is not actually prepared to be run with Puppeteer.

I would have to check which kind of refactoring in Puppeteer is necessary to actually apply all the required preferences before Puppeteer starts Firefox.

Blocks: 1701596
See Also: 1701596

The upstream PR can be found here:
https://github.com/puppeteer/puppeteer/pull/7684

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Blocks: 1734354

I checked mozilla-central and this failure turns out to be nearly a perma failure. We should try to get this fixed sooner than later.

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state (launcher.spec.ts) | expected PASS → High frequency TEST-UNEXPECTED-TIMEOUT | Launcher specs Puppeteer Puppeteer.launch userDataDir option should restore state (launcher.spec.ts) | expected PASS

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

The upstream PR can be found here:
https://github.com/puppeteer/puppeteer/pull/7684

And this PR has finally been merged. That means I'm going to use the given changes and backport that to Puppeteer 9.0.0, which is what we have in mozilla-central. If try is happy I'm going to update the existing patches.

Attachment #9245875 - Attachment description: Bug 1713030 - [puppeteer] Prepare temporary folder with Firefox preferences. → Bug 1713030 - [puppeteer] Support for custom user data (profile) directory for Firefox.
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9670993c90dd
[puppeteer] "--foreground" argument for Firefox is only supported on MacOS. r=webdriver-reviewers,jdescottes
https://hg.mozilla.org/integration/autoland/rev/ecd431bf8b40
[puppeteer] Extract default preferences for Firefox from profile creation. r=webdriver-reviewers,jdescottes
https://hg.mozilla.org/integration/autoland/rev/12f64d368932
[puppeteer] Extract creation of Firefox preferences files from profile creation. r=webdriver-reviewers,jdescottes
https://hg.mozilla.org/integration/autoland/rev/31302975681c
[puppeteer] Support for custom user data (profile) directory for Firefox. r=webdriver-reviewers,jdescottes
https://hg.mozilla.org/integration/autoland/rev/1ac20e7f3d1a
[puppeteer] Update puppeteer expectation data and launcher tests. r=webdriver-reviewers,jdescottes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: