Closed Bug 1821983 Opened 2 years ago Closed 1 year ago

[wdspec] Tests with missing capabilities (binary) inappropriately launch the default installation of the browser

Categories

(Remote Protocol :: Marionette, defect, P1)

Product:
Remote Protocol
Component:
Marionette
Type:
defect
Points:
2

Tracking

(firefox115 fixed)

Status:
RESOLVED FIXED
Milestone:
115 Branch
Tracking Flags:
Tracking Status
firefox115 --- fixed

People

(Reporter: whimboo, Assigned: jgraham)

References

Details

(Whiteboard: [webdriver:m7][webdriver:external], [wptsync upstream])

Attachments

(1 file)

Bug 1821983 - Pass Firefox binary in to geckodriver as a command line argument,
48 bytes, text/x-phabricator-request
Details | Review

Seen in the following WebDriver test for a Firefox TSAN build:

https://treeherder.mozilla.org/logviewer?job_id=408649751&repo=try&lineNumber=8792-8860

[task 2023-03-12T11:45:45.446Z] 11:45:45     INFO - PID 1832 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-12T11:45:45.447Z] 11:45:45     INFO - PID 1832 |           Blocker:  Waiting for ping task
[task 2023-03-12T11:45:45.448Z] 11:45:45     INFO - PID 1832 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-03-12T11:45:45.449Z] 11:45:45     INFO - PID 1832 |           State: (none)
[task 2023-03-12T11:45:45.449Z] 11:45:45     INFO - PID 1832 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.450Z] 11:45:45     INFO - PID 1832 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-12T11:45:45.451Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-12T11:45:45.451Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-12T11:45:45.452Z] 11:45:45     INFO - PID 1832 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-12T11:45:45.453Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-12T11:45:45.453Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-12T11:45:45.454Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-12T11:45:45.454Z] 11:45:45     INFO - PID 1832 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-12T11:45:45.455Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-12T11:45:45.455Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-12T11:45:45.456Z] 11:45:45     INFO - PID 1832 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-12T11:45:45.457Z] 11:45:45     INFO - PID 1832 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-12T11:45:45.474Z] 11:45:45     INFO - PID 1832 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[..]
[task 2023-03-12T11:45:45.589Z] 11:45:45     INFO - PID 1832 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-12T11:45:45.592Z] 11:45:45     INFO - PID 1832 |           Blocker:  TelemetryController: shutting down
[task 2023-03-12T11:45:45.592Z] 11:45:45     INFO - PID 1832 |           Phase: profile-before-change-telemetry
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 |           State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-12T11:45:45.593Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-12T11:45:45.594Z] 11:45:45     INFO - PID 1832 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-12T11:45:45.594Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-12T11:45:45.595Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-12T11:45:45.596Z] 11:45:45     INFO - PID 1832 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-12T11:45:45.596Z] 11:45:45     INFO - PID 1832 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-12T11:45:45.599Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-12T11:45:45.600Z] 11:45:45     INFO - PID 1832 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-12T11:45:45.605Z] 11:45:45     INFO - PID 1832 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.606Z] 11:45:45     INFO - PID 1832 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.607Z] 11:45:45     INFO - PID 1832 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.608Z] 11:45:45     INFO - PID 1832 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-12T11:45:45.609Z] 11:45:45     INFO - PID 1832 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"

Maybe this needs a fix for bug 1802551 or would there be more work required?

Flags: needinfo?(brennie)
Severity: -- → S4
Priority: -- → P3

This would likely be fixed by bug 1802551, which is mostly complete but has a timing out test on try that I cannot reproduce locally. I've unfortunately been able to work on it due to other higher priority work coming up

Depends on: 1802551
Flags: needinfo?(brennie)

Hm, so OSFile has been completely removed from Telemetry? When I have a look at various Wd jobs on mozilla-central I can still see a lot of instances of this particular problem:

https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wd%2Ctsan&selectedTaskRun=cy5PaNRBTmWUkrXE7P0zKw.0

[task 2023-05-09T16:01:17.054Z] 16:01:17     INFO - PID 8712 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-05-09T16:01:17.055Z] 16:01:17     INFO - PID 8712 |           Blocker:  Waiting for ping task
[task 2023-05-09T16:01:17.055Z] 16:01:17     INFO - PID 8712 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-05-09T16:01:17.056Z] 16:01:17     INFO - PID 8712 |           State: (none)
[task 2023-05-09T16:01:17.057Z] 16:01:17     INFO - PID 8712 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-05-09T16:01:17.057Z] 16:01:17     INFO - PID 8712 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-05-09T16:01:17.058Z] 16:01:17     INFO - PID 8712 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-05-09T16:01:17.058Z] 16:01:17     INFO - PID 8712 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-05-09T16:01:17.059Z] 16:01:17     INFO - PID 8712 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-05-09T16:01:17.059Z] 16:01:17     INFO - PID 8712 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-05-09T16:01:17.060Z] 16:01:17     INFO - PID 8712 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-05-09T16:01:17.062Z] 16:01:17     INFO - PID 8712 | console.error: "TelemetryScheduler.shutdown - Already shut down"

Why is osfile.jsm still be used in TelemetryStorage? Strangely I'm not able to see the usage in the code:

https://searchfox.org/mozilla-central/rev/445a5ab684b73eb56d807d0f3b2fabcc85a7c3dd/toolkit/components/telemetry/app/TelemetryStorage.sys.mjs#797-805

Also we seem to run the correct build:

[task 2023-05-09T15:40:18.990Z] 15:40:18     INFO - mozversion application_buildid: 20230509151822
[task 2023-05-09T15:40:18.991Z] 15:40:18     INFO - mozversion application_changeset: a5468e74965354b636bbe3a68b367756baa81ef6
[task 2023-05-09T15:40:18.991Z] 15:40:18     INFO - mozversion application_display_name: Nightly
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion application_name: Firefox
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion application_remotingname: firefox-default
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion application_vendor: Mozilla
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion application_version: 115.0a1
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion platform_buildid: 20230509151822
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion platform_changeset: a5468e74965354b636bbe3a68b367756baa81ef6
[task 2023-05-09T15:40:18.993Z] 15:40:18     INFO - mozversion platform_version: 115.0a1

Barret, can you please check?

Flags: needinfo?(brennie)

It is still used until the patch in bug 1776480 lands.

Depends on: 1776480

I'm investigating how this is being imported but I must admit I'm quite confused: that stack doesn't make any sense.

I did find two imports of ospath_unix.jsm from extensions code, but they don't import anything else. Hopefully bug 1776480 can land right after bug 1832344.

Flags: needinfo?(brennie)

Re the above stack:

resource://gre/modules/TelemetryStorage.sys.mjs:10:28

That line used to import os.file: https://hg.mozilla.org/mozilla-central/file/e221ddc823c0e35cf78f0a15f9ecec8bae088da2/toolkit/components/telemetry/app/TelemetryStorage.sys.mjs#l10

Should this be closed now that osfile is gone, or is this still happening?

This is still present in [Wd1 jobs](https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wd1 from this morning for mozilla-central builds: https://treeherder.mozilla.org/logviewer?job_id=416062535&repo=mozilla-central&lineNumber=26238-26256

So how builds can still refer to osfile.jsm if this file is no longer present? Now it really looks that something weird is going on for the workers and that we may build on outdated cached sources?

The mozinfo output for this particular build is:

[task 2023-05-17T04:18:29.381Z] 04:18:29     INFO - mozversion application_buildid: 20230517033250
[task 2023-05-17T04:18:29.382Z] 04:18:29     INFO - mozversion application_changeset: 08207806be4c7c13165c07ab2cf6dd811da2e198
[task 2023-05-17T04:18:29.383Z] 04:18:29     INFO - mozversion application_display_name: Nightly
[task 2023-05-17T04:18:29.384Z] 04:18:29     INFO - mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
[task 2023-05-17T04:18:29.386Z] 04:18:29     INFO - mozversion application_name: Firefox
[task 2023-05-17T04:18:29.386Z] 04:18:29     INFO - mozversion application_remotingname: firefox-default
[task 2023-05-17T04:18:29.387Z] 04:18:29     INFO - mozversion application_vendor: Mozilla
[task 2023-05-17T04:18:29.387Z] 04:18:29     INFO - mozversion application_version: 115.0a1
[task 2023-05-17T04:18:29.387Z] 04:18:29     INFO - mozversion platform_buildid: 20230517033250
[task 2023-05-17T04:18:29.388Z] 04:18:29     INFO - mozversion platform_changeset: 08207806be4c7c13165c07ab2cf6dd811da2e198
[task 2023-05-17T04:18:29.389Z] 04:18:29     INFO - mozversion platform_version: 115.0a1

That's a changeset on mozilla-central from Wed, 17 May 2023 03:32:50.

Builds affected so far are TSAN and CCOV on Linux. I wasn't able to find other platforms or build types that are showing this failure as well. Maybe for those the shutdown is faster and as such do not enter this specific code path?

Needinfo'ing Marco and Christian in case they have an idea as well.

Flags: needinfo?(mcastelluccio)
Flags: needinfo?(choller)

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

This is still present in [Wd1 jobs](https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wd1 from this morning for mozilla-central builds: https://treeherder.mozilla.org/logviewer?job_id=416062535&repo=mozilla-central&lineNumber=26238-26256

So how builds can still refer to osfile.jsm if this file is no longer present? Now it really looks that something weird is going on for the workers and that we may build on outdated cached sources?

I have no idea why that might be happening, it is pretty strange. Maybe some AsyncShutdown expert can tell us who might be registering that "OS.File: flush I/O queued before profileBeforeChange" condition? Is it possible it's some kind of extension that we install during tests and is outside the tree?
Though I don't see how osfile.jsm is still imported now, given line 10 of TelemetryStorage.sys.mjs is no longer importing it.

Builds affected so far are TSAN and CCOV on Linux. I wasn't able to find other platforms or build types that are showing this failure as well. Maybe for those the shutdown is faster and as such do not enter this specific code path?

CCOV builds' shutdown is slower than other builds.

Flags: needinfo?(mcastelluccio)

(In reply to Marco Castelluccio [:marco] from comment #10)

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

This is still present in [Wd1 jobs](https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wd1 from this morning for mozilla-central builds: https://treeherder.mozilla.org/logviewer?job_id=416062535&repo=mozilla-central&lineNumber=26238-26256

So how builds can still refer to osfile.jsm if this file is no longer present? Now it really looks that something weird is going on for the workers and that we may build on outdated cached sources?

I have no idea why that might be happening, it is pretty strange. Maybe some AsyncShutdown expert can tell us who might be registering that "OS.File: flush I/O queued before profileBeforeChange" condition? Is it possible it's some kind of extension that we install during tests and is outside the tree?
Though I don't see how osfile.jsm is still imported now, given line 10 of TelemetryStorage.sys.mjs is no longer importing it.

Right, the stacks are what are very confusing here, as they're composed of lines and files that should not exist anymore.

Is this 100% reproducible, and if so, can we get a pernosco trace of what's happening? (ni whimboo for this)

I had a look but AFAICT the infra for fetching and using the build is pretty similar to most of our jobs, and so I don't see why this would be using old binaries just for this job.

One thing I did notice is that we're using the same Firefox profile for each run, whereas e.g. mochitest will have a new profile for each manifest being run. The practical consequence of this may be that if we're reusing the profile also across jobs, there's a fastload / XUL cache file that still has the old files cached? But that should be invalidated at least whenever the version number changes, and I think also when the build ID changes. Checking that bit with Dave...

Flags: needinfo?(hskupin)
Flags: needinfo?(dtownsend)

(In reply to :Gijs (he/him) from comment #11)

One thing I did notice is that we're using the same Firefox profile for each run, whereas e.g. mochitest will have a new profile for each manifest being run. The practical consequence of this may be that if we're reusing the profile also across jobs, there's a fastload / XUL cache file that still has the old files cached? But that should be invalidated at least whenever the version number changes, and I think also when the build ID changes. Checking that bit with Dave...

Yes, we invalidate the caches if any of the version, build ID, OS, ABI or install directory change.

Flags: needinfo?(dtownsend)

It looks like as well as the Firefox version we're interested in testing we are also sometimes launching the system installed Firefox which is version 113.0.1. It is this version which is throwing the errors as understandably it still has OS.File in there.

I don't know enough about these tests to guess why this is happening. If it isn't intentional I would guess that somewhere we're not passing the install directory of the browser we actually want to run and so mozrunner is falling back to the OS default.

Potentially we're running tests against the wrong browser version here which seems bad.

test_no_capabilities is not passing any capabilities.

From a previous test in the log file, the capabilities appear to be:

INFO - PID 8709 | 1684298625221 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpf5z0__0b.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}}}}

For test_no_capabilities, it is:

INFO - PID 8709 | 1684298629449 webdriver::server DEBUG -> POST /session {}

Hence, it doesn't know where the binary is and tries to discover what it can.

Also, since this is re-using the same profile, I would guess that we might be putting up the "can't downgrade profile dialog", which is probably also upsetting things as well.

(In reply to Mark Banner (:standard8) from comment #14)

Also, since this is re-using the same profile, I would guess that we might be putting up the "can't downgrade profile dialog", which is probably also upsetting things as well.

Is it reusing the same profile? The launch line says:

[task 2023-05-17T04:43:52.456Z] 04:43:52     INFO - PID 8709 | 1684298632454	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"38f1e0c8-c7a6-486b-914e-87f6c2764806","capabilities":{"browserName":"firefox","browserVersion":"113.0.1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":false,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230511191846","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":23081,"moz:profile":"/tmp/rust_mozprofileajhiZT","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]

which has "moz:profile":"/tmp/rust_mozprofileajhiZT", so I think it might be using a different profile. Still, this is clearly what is wrong here. Thanks for figuring this out Dave! I'll clear Christian's needinfo as I think this needs Henrik to look into why the test is doing this.

Flags: needinfo?(choller)

(In reply to Dave Townsend [:mossop] from comment #13)

It looks like as well as the Firefox version we're interested in testing we are also sometimes launching the system installed Firefox which is version 113.0.1. It is this version which is throwing the errors as understandably it still has OS.File in there.

Oh wow. This is a very good find and that explains it perfectly.

I don't know enough about these tests to guess why this is happening. If it isn't intentional I would guess that somewhere we're not passing the install directory of the browser we actually want to run and so mozrunner is falling back to the OS default.

Given that for these particular tests we do not send any capabilities to the driver it doesn't know that it has to use a specific installation of the browser. As such it tries to find the default installation and picks its binary as we can see here.

For geckodriver we could find a way to use the --binary argument and set the custom firefox binary, but at least chromedriver doesn't support that. As such I'm not sure how to get this scenario handled in an official wdspec test.

It might be best to discuss that in our next triage meeting in how to get this working for the binary and at least using different profiles for these tests to prevent a potential downgrade dialog to appear.

Severity: S4 → --
Component: Telemetry → Marionette
Flags: needinfo?(hskupin)
Priority: P3 → --
Product: Toolkit → Remote Protocol
Summary: "Blocker: Waiting for ping task" is delaying shutdown of Firefox → [wdspec] Tests with missing capabilities (binary) inappropriately launch the default installation of the browser
Whiteboard: [webdriver:triage]

As we discussed we would have to find a way to set the default binary for geckodriver. Given that we support the --binary argument it should be possible. Once we get it working we should check if Chrome and Safari as affected as well, and if that's the case both Google and Apple need to be informed about that issue so that they can work on a similar fix for Chromedriver and Safaridriver.

James could have a look if that's easily doable for Firefox / geckodriver.

Flags: needinfo?(james)
Whiteboard: [webdriver:triage]

This ensures that for wdspec tests we get the correct binary even if
we don't provide any capabilities, which happens for some of the
restart tests.

Assignee: nobody → james
Status: NEW → ASSIGNED

While this is not an issue on Windows (installing the custom Firefox will update the registry which we use as alternative), it also fails on MacOS but differently given that there is no system-wide installed Firefox available:

[task 2023-05-23T22:27:53.872Z] 22:27:53     INFO - PID 2672 | 1684880873869	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"session not created","message":"Expected browser binary location, but unable  ... t location, no 'moz:firefoxOptions.binary' capability provided, and no binary flag set on the command line","stacktrace":""}}
[task 2023-05-23T22:27:53.968Z] 22:27:53     INFO - STDOUT: FAILED

Once the following try builds have been finished I will take another look:
https://treeherder.mozilla.org/jobs?repo=try&revision=a1ce21f9070b619ec9e95ae7b3f106b358086c5b&searchStr=wd3

Flags: needinfo?(james)
Severity: -- → S3
Points: --- → 2
Priority: -- → P1
Whiteboard: [webdriver:m7][webdriver:external]
Pushed by james@hoppipolla.co.uk: https://hg.mozilla.org/integration/autoland/rev/f7e0e57e2bf1 Pass Firefox binary in to geckodriver as a command line argument, r=webdriver-reviewers,whimboo
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/40251 for changes under testing/web-platform/tests
Whiteboard: [webdriver:m7][webdriver:external] → [webdriver:m7][webdriver:external], [wptsync upstream]

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

Status: ASSIGNED → RESOLVED
Closed: 1 year ago
status-firefox115: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 115 Branch

The upstream PR cannot be merged because of the following failure:

./wptrunner/wptrunner/browsers/firefox.py:143:16: E713 test for membership should be 'not in'

James, can you please have a look? Thanks.

Flags: needinfo?(james)
Upstream PR merged by moz-wptsync-bot
Flags: needinfo?(james)
Pushed by wptsync@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/b4cec82609dc [wpt PR 40251] - [Gecko Bug 1821983] Pass Firefox binary in to geckodriver as a command line argument, a=testonly
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: