1816409 - Firefox does not create MarionetteActivePort file in headless mode on Debian 10

Status: RESOLVED INCOMPLETE

(Firefox :: Headless, defect)

Description

[Lucian Tanase]

Attachment: geckodriver-log-output.txt

Steps to reproduce:

On Debian 10 machine (Bitnami LAMP stack server - PHP 7.4.15) I have installed geckodriver (0.32) and firefox (109.0.1). I am using php-webdriver package to interact with firefox in headless mode for collecting certain information from a public site. The php-webdriver starts the geckodriver, who in turn should spin off a firefox process.
I install firefox from three different sources (firefox-esr form apt repository, downloading the tar file and finally from mozillateam repository) but the problem persisted.

Actual results:

The PHP scripts fails with an error of Failed to read marionette port (if geckodriver level is not set) or a timeout exception (if geckodriver log level is set).
The geckodriver log files shows geckodriver trying to open MarionetteActivePort file from /tmp/rust_mozprofile directory, but such file does not exist. It seems that firefox fail to create such file in the location expected by geckodriver.
The firefox start (as the process may be seen running in the htop listing) but for some reasons does not create the file.

Expected results:

The expected behavior, should be that firefox to run in the headless mode and geckodriver to connect to it in order to allow the webdriver to run the necessary code for scraping the website.
If geckodriver is started manually (running in the backgorund) everything goes as normal and the PHP script execute its task (of collecting info from the website).

Comment 1

[Rares Doghi, Desktop QA]

Im not entirely sure this is the correct component for this issue or maybe its Testing > Geckodriver ? Hopefully one of our devs can take a look and move it to a more suitable component.

Comment 2

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

Please note that the original issue is: https://github.com/mozilla/geckodriver/issues/2082

The log details in comment 0 show two specific lines which most likely are related here:

[GFX1-]: glxtest: Unable to open a connection to the X server
[..]
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt

Based on that the Firefox startup hangs somewhere so that even not the command-line-startup observer notification is sent out which is used by Marionette to start its component. Max, do you have an idea in how to further investigate or even fix this issue? Are there more log types available that maybe could be requested by setting MOZ_LOG?

Comment 3

[Nick Alexander :nalexander [he/him]]

There are many layers of indirection here; let's try to cull some of them. What is the log output from:

mkdir -p /tmp/testprofile
"/usr/lib/firefox/firefox" "--marionette" "-headless" "-no-remote" "-profile" "/tmp/testprofile"

If you can't get that running and waiting for a Marionette connection, all the layers on top won't matter.

Comment 4

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

geckodriver actually creates the profile and adds the default automation preferences that we define to it. So permissions should be there given that otherwise geckodriver itself would bail out early.

Comment 5

[Nick Alexander :nalexander [he/him]]

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

geckodriver actually creates the profile and adds the default automation preferences that we define to it. So permissions should be there given that otherwise geckodriver itself would bail out early.

I think the question still remains for OP: is that actually working, and if it's not, what is the log output from Firefox? ('cuz I don't see that anywhere yet.)

Comment 6

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

Please see https://github.com/mozilla/geckodriver/issues/2082#issuecomment-1425660938 and following comments.

Comment 7

[Lucian Tanase]

(In reply to Nick Alexander :nalexander [he/him] from comment #3)

There are many layers of indirection here; let's try to cull some of them. What is the log output from:

mkdir -p /tmp/testprofile
"/usr/lib/firefox/firefox" "--marionette" "-headless" "-no-remote" "-profile" "/tmp/testprofile"

If you can't get that running and waiting for a Marionette connection, all the layers on top won't matter.

If I run that command in the terminal the following output is generated:
*** You are running in headless mode.
[GFX1-]: glxtest: Unable to open a connection to the X server
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt

Following this command the testprofile directory is filled with files and directories. Among them is MarionetteActivePort file.

Comment 8

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

Lucian, it's interesting to see that the MarionetteActivePort file is present then. Could I ask you for a favor? When you have created the test profile would you mind manually creating a prefs.js file in that folder and filling it with the following data before starting Firefox? It will output more logs during startup so that we can see more details.

user_pref("remote.log.level", "Trace");

If that shows a correct startup of Firefox maybe some other preference that geckodriver sets is causing startup issues.

Comment 9

[Lucian Tanase]

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

Lucian, it's interesting to see that the MarionetteActivePort file is present then. Could I ask you for a favor? When you have created the test profile would you mind manually creating a prefs.js file in that folder and filling it with the following data before starting Firefox? It will output more logs during startup so that we can see more details.

user_pref("remote.log.level", "Trace");

If that shows a correct startup of Firefox maybe some other preference that geckodriver sets is causing startup issues.

Hi Henrik,
The prefs.js was already present. I have added the line mentioned by you, but I do not see any changes in the output of the terminal when I manually run firefox as per command suggested by you in your earlier post. Are there any log file created by firefox? Because I am not able to see it in /var/logs directory or .mozilla folder.

Comment 10

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

There aren't. If you start Firefox as mentioned in comment 7 all the logging output should appear on stdout. The above preference just controls the log details for Marionette and would help me to see where during the startup of Firefox it waits for a certain state to continue.

Comment 11

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

Lucian, do you have an update for us? Otherwise we are not able to further investigate and might have to close this bug.

Comment 12

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

Over on the GitHub issue I asked for a log with MOZ_LOG=Process:5 and that is the output. Important are probably the last lines:

[Parent 18878: Main Thread]: D/Process Starting process allocate on idle
[Parent 18878: Main Thread]: D/Process Trying to start process now
[GFX1-]: Unrecognized feature ACCELERATED_CANVAS2D

While in other cases we see the following extra output it doesn't show up at the very end:

[Parent 18878: Main Thread]: D/Process Starting process allocate on idle
[Parent 18878: Main Thread]: D/Process Trying to start process now
[Parent 18878: Main Thread]: V/Process CreateSubprocess: ContentParent 7faa97760a00 mSubprocess 7faa96ab1200 handle 0
[Parent 18878: Main Thread]: D/Process Preallocated = 3 of 3 processes

Does it mean that we maybe hang in the creation of the ContentParent subprocess somewhere around those lines?

https://searchfox.org/mozilla-central/rev/d630a6aad368dbbae4d90853f8cff5cb7c852407/dom/ipc/PreallocatedProcessManager.cpp#308-321

Jens, do you have an idea?

Comment 13

[Jens Stutte [:jstutte]]

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

Over on the GitHub issue I asked for a log with MOZ_LOG=Process:5 and that is the output.

IIUC the log shows that we created all 3 preallocated processes we wanted to create at max and thus bail out here without dispatching another delayed attempt. Arguably we could avoid printing any log message in that case (or add one to make it clear we are done with allocating preallocated processes).

Does it mean that we maybe hang in the creation of the ContentParent subprocess somewhere around those lines?

I do not think so. Does the log finish right after

[GFX1-]: Unrecognized feature ACCELERATED_CANVAS2D

?

Comment 14

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

(In reply to Jens Stutte [:jstutte] from comment #13)

Does it mean that we maybe hang in the creation of the ContentParent subprocess somewhere around those lines?

I do not think so. Does the log finish right after

[GFX1-]: Unrecognized feature ACCELERATED_CANVAS2D

?

Yes, there is no more output after that line until Firefox gets killed by geckodriver after 60s (default startup timeout).

Comment 15

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

Jens, do you have any idea in how to get this investigated? Note that those are remote systems.

Comment 16

[Jens Stutte [:jstutte]]

Other than improving the output of the PreallocatedProcessManagerImpl::AllocateNow as suggested in comment 13 to confirm that we are not failing anything here around process allocation I have no clue what this could be.

Comment 17

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

I investigated that further and actually found that topic on launchpad:
https://answers.launchpad.net/ubuntu/+question/695824

The problem is that when running with php-webdriver a different user is running geckodriver. Sadly for that www-data user by default no home directory exists, and Firefox fails to start because of that. Creating such a folder should fix the problem.

Lucian, could you please check if that is the case for you as well? Thanks!

Comment 18

[BugBot [:suhaib / :marco/ :calixte]]

A needinfo is requested from the reporter, however, the reporter is inactive on Bugzilla. Closing the bug as incomplete.

For more information, please visit BugBot documentation.