search

mozilla / geckodriver

WebDriver for Firefox
https://firefox-source-docs.mozilla.org/testing/geckodriver/
Mozilla Public License 2.0
7.03k stars 1.51k forks source link

Firefox fails to start-up on Debian 10 in headless mode (Failed to open MarionetteActivePort) #2082

Open ltanase77 opened 1 year ago

ltanase77 commented 1 year ago

System

Testcase

Stacktrace

Facebook\WebDriver\Exception\TimeoutException Failed to read marionette port (Most recent call first) at (unknown method)(/opt/bitnami/sites/Cabinet/vendor/php-webdriver/webdriver/lib/Exception/WebDriverException.php:133) at Facebook\WebDriver\Exception\WebDriverException::throwException(/opt/bitnami/sites/Cabinet/vendor/php-webdriver/webdriver/lib/Remote/HttpCommandExecutor.php:385) at Facebook\WebDriver\Remote\HttpCommandExecutor::execute(/opt/bitnami/sites/Cabinet/vendor/php-webdriver/webdriver/lib/Remote/Service/DriverCommandExecutor.php:42) at Facebook\WebDriver\Remote\Service\DriverCommandExecutor::execute(/opt/bitnami/sites/Cabinet/vendor/php-webdriver/webdriver/lib/Firefox/FirefoxDriver.php:61) at Facebook\WebDriver\Firefox\FirefoxDriver::startUsingDriverService(/opt/bitnami/sites/Cabinet/vendor/php-webdriver/webdriver/lib/Firefox/FirefoxDriver.php:33) at Facebook\WebDriver\Firefox\FirefoxDriver::start(/opt/bitnami/sites/Cabinet/app/Http/Controllers/Maps/CheckLaw.php:60)

Trace-level log

ltanase77 commented 1 year ago

The error appears when WebDriver needs to start the GeckoDriver with this line of code: $driver = Firefox\FirefoxDriver::start($desiredCapabilities); If I start manually firefox and gecko driver and I am using $driver = RemoteWebDriver::create($serverUrl, $desiredCapabilities); everything is fine. But this implies that firefox and geckodriver to run permanently. My full PHP code below:

$desiredCapabilities = DesiredCapabilities::firefox();
$desiredCapabilities->setCapability('acceptSslCerts', false);
 $firefoxOptions = new FirefoxOptions();
$firefoxOptions->addArguments(['-headless', '-vv', '-marionette-port', '0']);
$firefoxOptions->setOption("binary", "/usr/bin/firefox");
$desiredCapabilities->setCapability(FirefoxOptions::CAPABILITY, $firefoxOptions);
$serverUrl = 'http://localhost:4444';
$driver = Firefox\FirefoxDriver::start($desiredCapabilities);
whimboo commented 1 year ago

Could you please attach a trace-level log from geckodriver? Read more about reporting actionable bugs in our contribution guidelines.

ltanase77 commented 1 year ago

Where does geckodriver save his log files? How can I locate them? I saw requirements for providing such trace-level log, but I do not know where to find them or how can I obtain them.

whimboo commented 1 year ago

This depends on the Selenium binding. As you are using the PHP one as I can see you may want to check their support pages. We actually don't have that in our listing because it's not part of the official Selenium repository.

whimboo commented 1 year ago

Alternatively you could try to use geckodriver directly by using eg curl: https://firefox-source-docs.mozilla.org/testing/geckodriver/Usage.html#standalone

ltanase77 commented 1 year ago

Does not have geckodriver a default settings which tell where to place the log files? I tried using it directly with curl but I am not able to pass in the curl data the headless flag.

whimboo commented 1 year ago

You have to specify it similarly to what is described in our documentation.

But I also have just seen that you are using '-marionette-port', '0' in the capabilities. This is not needed and might confuse geckodriver. It's doing that actually already on its own. Probably this might already fix it.

ltanase77 commented 1 year ago

I have tried: $firefoxOptions->setOption("log", ["level" => "trace"]);

The exception is the following:

Facebook\WebDriver\Exception\WebDriverCurlException Curl error thrown for http POST to /session with params: {"capabilities":{"firstMatch":[{"browserName":"firefox","moz:firefoxOptions":{"binary":"/usr/lib/firefox/firefox","log":{"level":"trace"},"args":["-headless"],"prefs":{"reader.parse-on-load.enabled":false,"devtools.jsonview.enabled":false}},"acceptInsecureCerts":false}]}}

Operation timed out after 180001 milliseconds with 0 bytes received

In the curl request seems that log level is set, but there is no sign of a log file. Or at least I do not know where to look.

whimboo commented 1 year ago

geckodriver isn't writing the log to the log file but to stdout. So probably you ignore the output? Maybe start geckodriver manually in a terminal and running the curl command in a different one.

ltanase77 commented 1 year ago

Ok. I raised an issue with php-webdriver team for not being able to output log files. They set a dev-feature/driver-service-logging branch. I used it and set the log level to trace. This is the output of the geckodriver.log file:

1676027182808   geckodriver     INFO    Listening on 127.0.0.1:9515

1676027182828   mozrunner::runner       INFO    Running command: "/usr/lib/firefox/firefox" "--marionette" "-headless" "-no-remote" "-profile" "/tmp/rust_mozprofileLrnVv3"
1676027182828   geckodriver::marionette DEBUG   Waiting 60s to connect to browser on 127.0.0.1
1676027182828   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027182828   geckodriver::marionette TRACE   Retrying in 100ms
[GFX1-]: glxtest: Unable to open a connection to the X server
1676027182928   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027182928   geckodriver::marionette TRACE   Retrying in 100ms
1676027183028   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183028   geckodriver::marionette TRACE   Retrying in 100ms
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
1676027183129   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183129   geckodriver::marionette TRACE   Retrying in 100ms
1676027183229   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183229   geckodriver::marionette TRACE   Retrying in 100ms
1676027183329   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183329   geckodriver::marionette TRACE   Retrying in 100ms
1676027183429   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183429   geckodriver::marionette TRACE   Retrying in 100ms
1676027183529   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183529   geckodriver::marionette TRACE   Retrying in 100ms
1676027183630   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183630   geckodriver::marionette TRACE   Retrying in 100ms
1676027183730   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183730   geckodriver::marionette TRACE   Retrying in 100ms
1676027183830   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183830   geckodriver::marionette TRACE   Retrying in 100ms
1676027183930   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027183930   geckodriver::marionette TRACE   Retrying in 100ms
1676027184030   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184030   geckodriver::marionette TRACE   Retrying in 100ms
1676027184130   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184130   geckodriver::marionette TRACE   Retrying in 100ms
1676027184231   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184231   geckodriver::marionette TRACE   Retrying in 100ms
1676027184331   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184331   geckodriver::marionette TRACE   Retrying in 100ms
1676027184431   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184431   geckodriver::marionette TRACE   Retrying in 100ms
1676027184531   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184531   geckodriver::marionette TRACE   Retrying in 100ms
1676027184631   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184631   geckodriver::marionette TRACE   Retrying in 100ms
1676027184732   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184732   geckodriver::marionette TRACE   Retrying in 100ms
1676027184832   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184832   geckodriver::marionette TRACE   Retrying in 100ms
1676027184932   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027184932   geckodriver::marionette TRACE   Retrying in 100ms
1676027185032   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027185032   geckodriver::marionette TRACE   Retrying in 100ms
1676027185132   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027185132   geckodriver::marionette TRACE   Retrying in 100ms
1676027185232   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027185232   geckodriver::marionette TRACE   Retrying in 100ms
1676027185333   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileLrnVv3/MarionetteActivePort
1676027185333   geckodriver::marionette TRACE   Retrying in 100ms

*** You are running in headless mode.

(firefox:6759): dconf-CRITICAL **: 11:44:01.685: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.685: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.686: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.686: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.687: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.849: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.850: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.850: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:44:01.850: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.687: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.687: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.690: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.690: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.690: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6759): dconf-CRITICAL **: 11:45:01.690: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

1676029561715   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofileFbK2B6/MarionetteActivePort
ltanase77 commented 1 year ago

The stack trace error for this is:

Facebook\WebDriver\Exception\Internal\WebDriverCurlException Curl error thrown for http POST to /session with params: {"capabilities":{"firstMatch":[{"browserName":"firefox","moz:firefoxOptions":{"binary":"/usr/lib/firefox/firefox","log":{"level":"trace"},"args":["-headless"],"prefs":{"reader.parse-on-load.enabled":false,"devtools.jsonview.enabled":false}},"acceptInsecureCerts":false}]}}

Operation timed out after 180001 milliseconds with 0 bytes received

There is no MarionetteActivePort file in the moz profile directory. Just an user.js file. Furthemore there is no .cache directory in the /usr/sbin directory. At least I do not see it.

ltanase77 commented 1 year ago

If i do not set the log level, geckodriver.log file looks like this:

1676028690758   geckodriver     INFO    Listening on 127.0.0.1:9515

1676028690778   mozrunner::runner       INFO    Running command: "/usr/lib/firefox/firefox" "--marionette" "-headless" "-no-remote" "-profile" "/tmp/rust_mozprofilesy2VqH"
[GFX1-]: glxtest: Unable to open a connection to the X server
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt

*** You are running in headless mode.

(firefox:6417): dconf-CRITICAL **: 11:32:30.820: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.820: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.821: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.821: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.822: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.831: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.831: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.831: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:32:30.831: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.822: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.822: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.825: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.825: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.826: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

(firefox:6417): dconf-CRITICAL **: 11:33:30.826: unable to create directory '/usr/sbin/.cache/dconf': Permission denied.  dconf will not work properly.

The stack trace error is : Facebook\WebDriver\Exception\TimeoutException Failed to read marionette port

whimboo commented 1 year ago

So Firefox doesn't correctly startup on this machine and geckodriver tries only 60s to find the marionette port file. Could you please check if headful mode works? Maybe headless mode needs some library which isn't available. To further investigate this issue probably a Firefox bug should be filed on Bugzilla.

ltanase77 commented 1 year ago

Is there any explanation why the problem did not persist if geckodriver is running in the background, permanently and pops only when php-webdriver try to start geckodriver?

ltanase77 commented 1 year ago

I created a .cache directory in the /usr/sbin and grant it relevant permissions and now (firefox:6417): dconf-CRITICAL error has disappeared from the geckodriver.log file. However the issue is not fixed. So I think the problem is connected with the other error mentioning that geckodriver fails to open /tmp/rust_mozprofile3pRsPd/MarionetteActivePort. Is just retrying until is timing out.

ltanase77 commented 1 year ago

The issue seems related with this bug Read Marionette port from MarionetteActivePort file within the Firefox profile directory which was closed one year ago.

ltanase77 commented 1 year ago

Running in headful mode results in this error: Error: no DISPLAY environment variable specified. Manually I can export this DISPLAY variable and firefox starts in headful mode, as I am using Xfvb emulator. But I do not know how to do it when using php-webdriver to start geckodriver.

OndraM commented 1 year ago

But I do not know how to do it when using php-webdriver to start geckodriver.

Hi, php-webdriver maintainer here. Environment variables passed to geckodriver process are (by default) inherited from the parent process (via $_ENV). So you should be able to pass them like this:

  1. make sure ENV values are injected to PHP, run php -i | grep 'variables_order' and if you don't see "E" in the value (like in "EGPCS") but only something like "GPCS", go to your php.ini and change it to variables_order = "EGPCS".
  2. My first guess would be to just try to start the headless mode now, as the environment variables may be the difference causing the issue: 
    php your-script.php
  3. If this doesn't help, try the headful mode or anything else you may need to debug the issue 
    export DISPLAY=...; php your-script.php

Also to add some context, all what php-webdriver does when starting geckodriver binary is just executing command geckodriver -p 9515, nothing else. However, the environment may actually differ from what you get when running the same command manually (what @ltanase77 says its working fine), because PHP may not by exposing any environment variables to the process (however - I just tried this and it works for me in any scenario, I'm unable to reproduce this locally no Arch linux and it also works fine in GH Actions tests).

ltanase77 commented 1 year ago

I changed my php.ini file as suggested by there is no change. I cannot simply php myscript.php because the php code sits in Laravel controller and when I am trying php LaravelController.php I get an error like this: PHP Fatal error: Uncaught Error: Class 'App\Http\Controllers\Controller' not found in path to my controller. Probably I need to make a custom artisan command to run the controller from the terminal. I have found that after each failed attempt there is a firefox process still running. It seems that geckodriver start the firefox : /usr/lib/firefox/firefox --marionette -headless -no-remote -profile /tmp/rust_mozprofileetc. Then it tries to reach a certain file in this rust_mozprofile directories, repsectively: MarionetteActivePort. I do not know if geckodriver is creating such directories or firefox, but somehow it seems geckodriver expect firefox to write a certain file in this directories which firefox does not, for some unknown reasons.

whimboo commented 1 year ago

Yes, geckodriver waits for such a file that is created by Marionette after Firefox has started up. If the file doesn't appear then there is a problem with the startup. As said please file a bug for Firefox and tell us the bug number here. I'm happy to continue helping once I'm back and in case no-one did on the bug until then. Thanks.

ltanase77 commented 1 year ago

New Firefox bug created: https://bugzilla.mozilla.org/show_bug.cgi?id=1816409

murkl commented 1 year ago

Same issue here. Unfortunately when i run the docker container with user permissions (in docker compose: user: "${UID:-1000}:${GID:-1000}") i got the same error. When deleted this flag, it works :)

whimboo commented 1 year ago

@murkl this is a very interesting information! When you have this flag set, can you start Firefox manually in headless mode? You could try to use the --screenshot argument which uses headless by default and will exit Firefox once the screenshot has been created.

whimboo commented 1 year ago

Changing the permissions didn't help for another user. So it might not be the right solution.

Anyone who can see this could you please run the test with the environment variable MOZ_LOG="Process:5"set? I would like to know if there might be something interesting in the trace log of geckodriver.

whimboo commented 1 year ago

@ltanase77 or @murkl would you mind trying out what I suggested in my last comment? I would appreciate any feedback so that we can get it investigated. Thanks!

ltanase77 commented 1 year ago

This is an log output if a set environment variable MOZ_LOG="Process:5" *** You are running in headless mode. [GFX1-]: glxtest: Unable to open a connection to the X server [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type privilegedabout [Parent 18878: Main Thread]: D/Process Launching new process immediately for type privilegedabout [Parent 18878: Main Thread]: V/Process CreateSubprocess: ContentParent 7faaa2c07f00 mSubprocess 7faaa3250c80 handle 0 [Parent 18878: Main Thread]: D/Process AddBlocker: privilegedabout 7faaa2c07f00 (sNumBlockers=0) [Parent 18878: Main Thread]: D/Process Enabling preallocation: 3 [Parent 18878: Main Thread]: D/Process Starting delayed process start, delay=1000 [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess: new immediate process 7faaa2c07f00 [Parent 18878: Main Thread]: D/Process ContentParent::InitInternal: 7faaa2c07f00 [Child 18921: Main Thread]: D/Process Changed name of process 18921 to Web Content [Child 18921: Main Thread]: D/Process Setting remoteType of process 18921 to privilegedabout [Child 18921: Main Thread]: D/Process Changed name of process 18921 to Privileged Content [Parent 18878: Main Thread]: V/Process RecvFirstIdle 7faaa2c07f00: Removing Blocker for privilegedabout [Parent 18878: Main Thread]: D/Process RemoveBlocker: privilegedabout 7faaa2c07f00 (sNumBlockers=1) [Parent 18878: Main Thread]: D/Process Blocked preallocation for 162.704997ms [Parent 18878: Main Thread]: D/Process Starting delayed process start, delay=1000 [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type extension [Parent 18878: Main Thread]: D/Process Launching new process immediately for type extension [Parent 18878: Main Thread]: V/Process CreateSubprocess: ContentParent 7faa9a646100 mSubprocess 7faa9a882740 handle 0 [Parent 18878: Main Thread]: D/Process AddBlocker: extension 7faa9a646100 (sNumBlockers=0) [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess: new immediate process 7faa9a646100 [Parent 18878: Main Thread]: D/Process ContentParent::InitInternal: 7faa9a646100 [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type extension [Parent 18878: Main Thread]: D/Process GetUsedProcess: Reused process 7faa9a646100 (2) for extension [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type extension [Parent 18878: Main Thread]: D/Process GetUsedProcess: Reused process 7faa9a646100 (2) for extension [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type extension [Parent 18878: Main Thread]: D/Process GetUsedProcess: Reused process 7faa9a646100 (2) for extension [Parent 18878: Main Thread]: D/Process GetNewOrUsedProcess for type extension [Parent 18878: Main Thread]: D/Process GetUsedProcess: Reused process 7faa9a646100 (2) for extension [Child 18969: Main Thread]: D/Process Changed name of process 18969 to Web Content [Child 18969: Main Thread]: D/Process Setting remoteType of process 18969 to extension [Child 18969: Main Thread]: D/Process Changed name of process 18969 to WebExtensions [Parent 18878: Main Thread]: D/Process Starting process allocate on idle [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]: D/Process Starting delayed process start, delay=1000 [Parent 18878: Main Thread]: D/Process Trying to start process now [Parent 18878: Main Thread]: D/Process Starting delayed process start, delay=1000 [Parent 18878: Main Thread]: V/Process RecvFirstIdle 7faa9a646100: Removing Blocker for extension [Parent 18878: Main Thread]: D/Process RemoveBlocker: extension 7faa9a646100 (sNumBlockers=1) [Parent 18878: Main Thread]: D/Process Blocked preallocation for 838.870148ms [Parent 18878: Main Thread]: D/Process Starting delayed process start, delay=1000 [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 7faa97764100 mSubprocess 7faa99f9cac0 handle 0 [Parent 18878: Main Thread]: D/Process Preallocated = 1 of 3 processes [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 7faa97762d00 mSubprocess 7faa96ab1740 handle 0 [Parent 18878: Main Thread]: D/Process Preallocated = 2 of 3 processes [Parent 18878: Main Thread]: D/Process ContentParent::InitInternal: 7faa97764100 [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 [Parent 18878: Main Thread]: D/Process ContentParent::InitInternal: 7faa97762d00 [Parent 18878: Main Thread]: D/Process ContentParent::InitInternal: 7faa97760a00 [Child 19007: Main Thread]: D/Process Changed name of process 19007 to Web Content [Child 19006: Main Thread]: D/Process Changed name of process 19006 to Web Content [Child 19009: Main Thread]: D/Process Changed name of process 19009 to Web Content [Child 19006: Main Thread]: D/Process Setting remoteType of process 19006 to prealloc [Child 19006: Main Thread]: D/Process Changed name of process 19006 to Web Content [Child 19007: Main Thread]: D/Process Setting remoteType of process 19007 to prealloc [Child 19009: Main Thread]: D/Process Setting remoteType of process 19009 to prealloc [Child 19009: Main Thread]: D/Process Changed name of process 19009 to Web Content [Child 19007: Main Thread]: D/Process Changed name of process 19007 to Web Content [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

whimboo commented 1 year ago

Thanks a lot! I copied this info over to the Bugzilla bug and will continue over there. Lets see if the found details might be helpful.

cinnamon17 commented 1 year ago

I'm having the same issue, any update about how to fix it?

Distributor ID: Debian Description: Debian GNU/Linux 11 (bullseye) Release: 11 Codename: bullseye

[critical] Uncaught PHP Exception Facebook\WebDriver\Exception\TimeoutException: "Failed to read marionette port" at /vendor/php-webdriver/webdriver/lib/Exception/WebDriverException.php line 136

It appears to be failing only on Debian, as I have tested it on Ubuntu 22.04.2 LTS and it works fine.

ssada1975 commented 1 year ago

did anyone solved this issue? myself same problem. Ok if I run geckodriver manually, no way to make it work from phpwebdriver. I'm using Debian 11

whimboo commented 1 year ago

did anyone solved this issue? myself same problem. Ok if I run geckodriver manually, no way to make it work from phpwebdriver. I'm using Debian 11

Interesting. Could you provide trace logs from geckodriver for both cases? I would like to see the difference in how the browser gets started. It sounds like an issue with phpwebdriver then.

ssada1975 commented 1 year ago

@whimboo here below the log of the manual run from bash. NO idea on how to do the log on automatic run :-(

In php I have

$usr_dir = "/tmp/firefox/profile/"; $host = 'http://localhost:4444'; putenv('WEBDRIVER_FIREFOX_DRIVER=/usr/local/bin/geckodriver'); $firefoxOptions = new FirefoxOptions(); $firefoxOptions->addArguments(['-headless']); $firefoxOptions->addArguments(["-profile", "$usr_dir"]); $firefoxOptions->setOption("binary", '/opt/firefox/./firefox'); $firefoxOptions->setOption("log", ["level" => "trace"]); // Create $capabilities and add configuration from ChromeOptions $capabilities = DesiredCapabilities::firefox(); $capabilities->setCapability(FirefoxOptions::CAPABILITY, $firefoxOptions ); $capabilities->setPlatform(WebDriverPlatform::LINUX);

$driver = RemoteWebDriver::create($host, $capabilities); $driver->get('https://www.google.it'); $driver->close();

geckodriver trace log 1688151883746 geckodriver INFO Listening on 127.0.0.1:4444 1688151886902 geckodriver::browser DEBUG Backing up prefs to "/tmp/firefox/profile/user.geckodriver_backup" 1688151886910 mozrunner::runner INFO Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/opt/firefox/./firefox" "--marionette" "-headless" "-profile" "/tmp/firefox/profile/" "-no-remote" 1688151886915 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1 1688151886916 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688151886916 geckodriver::marionette TRACE Retrying in 100ms *** You are running in headless mode. 1688151887016 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688151887017 geckodriver::marionette TRACE Retrying in 100ms console.warn: services.settings: Ignoring preference override of remote settings server console.warn: services.settings: Allow by setting MOZ_REMOTE_SETTINGS_DEVTOOLS=1 in the environment 1688151887119 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688151887120 geckodriver::marionette TRACE Retrying in 100ms [GFX1-]: glxtest: Unable to open a connection to the X server 1688151887171 Marionette INFO Marionette enabled 1688151887172 RemoteAgent DEBUG Setting recommended pref apz.content_response_timeout to 60000 1688151887173 RemoteAgent DEBUG Setting recommended pref browser.contentblocking.introCount to 99 1688151887173 RemoteAgent DEBUG Setting recommended pref browser.download.panel.shown to true 1688151887174 RemoteAgent DEBUG Setting recommended pref browser.newtabpage.enabled to false 1688151887174 RemoteAgent DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true 1688151887174 RemoteAgent DEBUG Setting recommended pref browser.search.update to false 1688151887175 RemoteAgent DEBUG Setting recommended pref browser.startup.couldRestoreSession.count to -1 1688151887175 RemoteAgent DEBUG Setting recommended pref browser.tabs.closeWindowWithLastTab to false 1688151887175 RemoteAgent DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false 1688151887176 RemoteAgent DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false 1688151887176 RemoteAgent DEBUG Setting recommended pref browser.tabs.warnOnClose to false 1688151887176 RemoteAgent DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false 1688151887177 RemoteAgent DEBUG Setting recommended pref browser.tabs.warnOnOpen to false 1688151887177 RemoteAgent DEBUG Setting recommended pref browser.toolbars.bookmarks.visibility to never 1688151887177 RemoteAgent DEBUG Setting recommended pref browser.topsites.contile.enabled to false 1688151887178 RemoteAgent DEBUG Setting recommended pref browser.usedOnWindows10.introURL to 1688151887178 RemoteAgent DEBUG Setting recommended pref browser.urlbar.merino.endpointURL to 1688151887178 RemoteAgent DEBUG Setting recommended pref browser.urlbar.suggest.searches to false 1688151887179 RemoteAgent DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false 1688151887179 RemoteAgent DEBUG Setting recommended pref dom.disable_open_during_load to false 1688151887179 RemoteAgent DEBUG Setting recommended pref dom.event.wheel-event-groups.enabled to false 1688151887180 RemoteAgent DEBUG Setting recommended pref dom.file.createInChild to true 1688151887180 RemoteAgent DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0 1688151887180 RemoteAgent DEBUG Setting recommended pref dom.max_script_run_time to 0 1688151887181 RemoteAgent DEBUG Setting recommended pref dom.navigation.locationChangeRateLimit.count to 0 1688151887181 RemoteAgent DEBUG Setting recommended pref dom.push.connection.enabled to false 1688151887182 RemoteAgent DEBUG Setting recommended pref dom.screenorientation.allow-lock to true 1688151887182 RemoteAgent DEBUG Setting recommended pref dom.successive_dialog_time_limit to 0 1688151887182 RemoteAgent DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false 1688151887182 RemoteAgent DEBUG Setting recommended pref extensions.getAddons.discovery.api_url to data:, 1688151887183 RemoteAgent DEBUG Setting recommended pref network.http.phishy-userpass-length to 255 1688151887183 RemoteAgent DEBUG Setting recommended pref network.http.prompt-temp-redirect to false 1688151887183 RemoteAgent DEBUG Setting recommended pref privacy.trackingprotection.enabled to false 1688151887183 RemoteAgent DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false 1688151887184 RemoteAgent DEBUG Setting recommended pref security.notification_enable_delay to 0 1688151887184 RemoteAgent DEBUG Setting recommended pref signon.autofillForms to false 1688151887184 RemoteAgent DEBUG Setting recommended pref signon.rememberSignons to false 1688151887185 RemoteAgent DEBUG Setting recommended pref widget.windows.window_occlusion_tracking.enabled to false 1688151887185 RemoteAgent DEBUG Setting recommended pref dom.disable_beforeunload to true 1688151887186 Marionette TRACE Received observer notification final-ui-startup 1688151887186 Marionette INFO Listening on port 39907 1688151887187 Marionette DEBUG Marionette is listening Read port: 39907 1688151887257 Marionette DEBUG Accepted connection 0 from 127.0.0.1:47606 1688151887266 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:39907. 1688151887276 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"browserName":"firefox","platformName":"linux"}] 1688151887281 Marionette DEBUG Waiting for initial application window [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt console.error: ({}) 1688151888829 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished 1688151888852 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=200 waitForExplicitStart=false 1688151888854 RemoteAgent TRACE [3] ProgressListener Setting unload timer (200ms) 1688151888855 RemoteAgent TRACE [3] Document already finished loading: about:blank 1688151888855 RemoteAgent TRACE [3] ProgressListener Stop: has error=false 1688151888896 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"78d4b271-a87d-4517-81ae-bb0830d113b8","capabilities":{"browserName":"firefox","browserVersion":"114.0.2","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":"20230619081400","moz:headless":true,"moz:platformVersion":"5.10.177.1-1.cm1","moz:processID":7112,"moz:profile":"/tmp/firefox/profile","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}] 1688151888915 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"78d4b271-a87d-4517-81ae-bb0830d113b8","capabilities":{"acceptInsecureCerts":false,"browserNa ... ctability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}} 1688151888932 webdriver::server DEBUG -> POST /session/78d4b271-a87d-4517-81ae-bb0830d113b8/url {"url":"https:\/\/www.google.it"} 1688151888933 Marionette DEBUG 0 -> [0,2,"WebDriver:Navigate",{"url":"https://www.google.it"}] 1688151888963 Marionette TRACE [3] Received event beforeunload for about:blank 1688151889283 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 11 1688151889304 Marionette TRACE [11] Received event beforeunload for about:blank 1688151889314 Marionette TRACE [11] Received event pagehide for about:blank 1688151889647 Marionette TRACE [11] Received event DOMContentLoaded for https://www.google.it/ 1688151889951 Marionette TRACE [11] Received event pageshow for https://www.google.it/ 1688151889956 Marionette DEBUG 0 <- [1,2,null,{"value":null}] 1688151889977 webdriver::server DEBUG <- 200 OK {"value":null} 1688151889979 webdriver::server DEBUG -> GET /session/78d4b271-a87d-4517-81ae-bb0830d113b8/source 1688151890014 Marionette DEBUG 0 -> [0,3,"WebDriver:GetPageSource",{}] 1688151890018 RemoteAgent TRACE WebDriverProcessData actor created for PID 7389 1688151890024 Marionette TRACE [11] MarionetteCommands actor created for window id 8589934593 1688151890043 Marionette DEBUG 0 <- [1,3,null,{"value":""}] 1688151890095 webdriver::server DEBUG <- 200 OK {"value":""} 1688151890100 webdriver::server DEBUG -> DELETE /session/78d4b271-a87d-4517-81ae-bb0830d113b8/window 1688151890117 Marionette DEBUG 0 -> [0,4,"WebDriver:CloseWindow",{}] 1688151890118 Marionette DEBUG 0 <- [1,4,null,[]] 1688151890119 webdriver::server DEBUG Last window was closed, deleting session 1688151890119 webdriver::server DEBUG Teardown session 1688151890119 Marionette DEBUG 0 -> [0,5,"Marionette:Quit",{"flags":["eForceQuit"]}] 1688151890122 Marionette INFO Stopped listening on port 39907 1688151890124 Marionette TRACE [11] MarionetteCommands actor destroyed for window id 8589934593 1688151890393 Marionette TRACE Received observer notification quit-application 1688151890406 Marionette TRACE Received observer notification quit-application 1688151890412 Marionette DEBUG Marionette stopped listening 1688151890413 RemoteAgent DEBUG Resetting recommended pref apz.content_response_timeout 1688151890419 RemoteAgent DEBUG Resetting recommended pref browser.contentblocking.introCount 1688151890426 RemoteAgent DEBUG Resetting recommended pref browser.download.panel.shown 1688151890428 RemoteAgent DEBUG Resetting recommended pref browser.newtabpage.enabled 1688151890442 RemoteAgent DEBUG Resetting recommended pref browser.pagethumbnails.capturing_disabled 1688151890443 RemoteAgent DEBUG Resetting recommended pref browser.search.update 1688151890445 RemoteAgent DEBUG Resetting recommended pref browser.startup.couldRestoreSession.count 1688151890447 RemoteAgent DEBUG Resetting recommended pref browser.tabs.closeWindowWithLastTab 1688151890448 RemoteAgent DEBUG Resetting recommended pref browser.tabs.disableBackgroundZombification 1688151890449 RemoteAgent DEBUG Resetting recommended pref browser.tabs.unloadOnLowMemory 1688151890449 RemoteAgent DEBUG Resetting recommended pref browser.tabs.warnOnClose 1688151890450 RemoteAgent DEBUG Resetting recommended pref browser.tabs.warnOnCloseOtherTabs 1688151890450 RemoteAgent DEBUG Resetting recommended pref browser.tabs.warnOnOpen 1688151890451 RemoteAgent DEBUG Resetting recommended pref browser.toolbars.bookmarks.visibility 1688151890452 RemoteAgent DEBUG Resetting recommended pref browser.topsites.contile.enabled 1688151890453 RemoteAgent DEBUG Resetting recommended pref browser.usedOnWindows10.introURL 1688151890454 RemoteAgent DEBUG Resetting recommended pref browser.urlbar.merino.endpointURL 1688151890457 RemoteAgent DEBUG Resetting recommended pref browser.urlbar.suggest.searches 1688151890459 RemoteAgent DEBUG Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted 1688151890459 RemoteAgent DEBUG Resetting recommended pref dom.disable_open_during_load 1688151890460 RemoteAgent DEBUG Resetting recommended pref dom.event.wheel-event-groups.enabled 1688151890461 RemoteAgent DEBUG Resetting recommended pref dom.file.createInChild 1688151890462 RemoteAgent DEBUG Resetting recommended pref dom.max_chrome_script_run_time 1688151890463 RemoteAgent DEBUG Resetting recommended pref dom.max_script_run_time 1688151890465 RemoteAgent DEBUG Resetting recommended pref dom.navigation.locationChangeRateLimit.count 1688151890465 RemoteAgent DEBUG Resetting recommended pref dom.push.connection.enabled 1688151890466 RemoteAgent DEBUG Resetting recommended pref dom.screenorientation.allow-lock 1688151890467 RemoteAgent DEBUG Resetting recommended pref dom.successive_dialog_time_limit 1688151890468 RemoteAgent DEBUG Resetting recommended pref extensions.getAddons.cache.enabled 1688151890469 RemoteAgent DEBUG Resetting recommended pref extensions.getAddons.discovery.api_url 1688151890470 RemoteAgent DEBUG Resetting recommended pref network.http.phishy-userpass-length 1688151890471 RemoteAgent DEBUG Resetting recommended pref network.http.prompt-temp-redirect 1688151890472 RemoteAgent DEBUG Resetting recommended pref privacy.trackingprotection.enabled 1688151890472 RemoteAgent DEBUG Resetting recommended pref security.fileuri.strict_origin_policy 1688151890472 RemoteAgent DEBUG Resetting recommended pref security.notification_enable_delay 1688151890480 RemoteAgent DEBUG Resetting recommended pref signon.autofillForms 1688151890485 RemoteAgent DEBUG Resetting recommended pref signon.rememberSignons 1688151890487 RemoteAgent DEBUG Resetting recommended pref widget.windows.window_occlusion_tracking.enabled 1688151890488 RemoteAgent DEBUG Resetting recommended pref dom.disable_beforeunload 1688151890490 Marionette DEBUG 0 <- [1,5,null,{"cause":"shutdown","forced":false,"in_app":true}] 1688151890548 Marionette DEBUG Closed connection 0 1688151890837 geckodriver::browser DEBUG Browser process stopped: exit status: 0 1688151890838 webdriver::server DEBUG <- 200 OK {"value":[]} 1688151890838 webdriver::server DEBUG -> POST /session/78d4b271-a87d-4517-81ae-bb0830d113b8/url {"url":"https:\/\/www.sephora.fr"} 1688151890839 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":""}}
ssada1975 commented 1 year ago

@whimboo here is instead the log when I start from PHP. The issue is always the same Failed to open /tmp/firefox/profile/MarionetteActivePort

geckodriver trace logs with php root@c47e50293a23:/tmp/firefox/profile# cat geckodriver.log 1688152971927 geckodriver INFO Listening on 127.0.0.1:9515 1688152971956 mozrunner::runner INFO Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/opt/firefox/./firefox" "--marionette" "-headless" "-profile" "/tmp/firefox/profile/" "-no-remote" 1688152971958 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1 1688152971958 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688152971958 geckodriver::marionette TRACE Retrying in 100ms 1688152972058 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688152972058 geckodriver::marionette TRACE Retrying in 100ms 1688152972158 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688152972159 geckodriver::marionette TRACE Retrying in 100ms [GFX1-]: glxtest: Unable to open a connection to the X server 1688152972260 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort [..] 1688153011556 geckodriver::marionette TRACE Retrying in 100ms 1688153011656 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688153011656 geckodriver::marionette TRACE Retrying in 100ms *** You are running in headless mode. (firefox:6182): dconf-CRITICAL **: 19:23:52.120: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.121: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.121: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.121: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.123: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.156: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.156: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.157: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:23:52.157: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.123: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.123: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.126: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.126: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.127: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. (firefox:6182): dconf-CRITICAL **: 19:24:52.127: unable to create directory '/var/www/.cache/dconf': Permission denied. dconf will not work properly. 1688153011757 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort
whimboo commented 1 year ago

@ssada1975 when you run the script via PHP do you have another Firefox instance open at the same time on the same machine? If yes, can you please close it and check if that makes a difference? When you start it manually is there another Firefox instance as well or not?

ssada1975 commented 1 year ago

After restarting completely the server, same issue with auto start Also killing all firefox instances, same issue with auto start.

whimboo commented 1 year ago

Oh, @ssada1975 when running geckodriver via PHP I assume the user is different as when you run it yourself. Would you mind checking if manually starting geckodriver by using that other user (something like www-data) produces the same error? Maybe some permissions aren't set or are explicitly set to prevent launching specific apps.

ssada1975 commented 1 year ago

@whimboo how can I run geckodriver as another user?

whimboo commented 1 year ago

You can use the su command under Linux.

ssada1975 commented 1 year ago

@whimboo confirm that if i run manually geckodriver as www-data, "su -pc geckodriver www-data", it doesn't work likewise if I run automatically

root@714e8dfc4dd1:~# su -pc geckodriver www-data bash: /root/.bashrc: Permission denied 1688589263837 geckodriver INFO Listening on 127.0.0.1:4444 1688589266837 geckodriver::browser DEBUG Backing up prefs to "/tmp/firefox/profile/user.geckodriver_backup_1" 1688589266846 mozrunner::runner INFO Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/opt/firefox/./firefox" "--marionette" "-headless" "-vv" "-profile" "/tmp/firefox/profile/" "--shm-size 2g" "-no-remote" 1688589266848 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1 1688589266849 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589266849 geckodriver::marionette TRACE Retrying in 100ms *** You are running in headless mode. 1688589266951 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589266952 geckodriver::marionette TRACE Retrying in 100ms [GFX1-]: glxtest: Unable to open a connection to the X server 1688589267052 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267055 geckodriver::marionette TRACE Retrying in 100ms 1688589267156 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267159 geckodriver::marionette TRACE Retrying in 100ms [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt 1688589267259 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267260 geckodriver::marionette TRACE Retrying in 100ms 1688589267360 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267360 geckodriver::marionette TRACE Retrying in 100ms 1688589267460 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267460 geckodriver::marionette TRACE Retrying in 100ms 1688589267561 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267561 geckodriver::marionette TRACE Retrying in 100ms 1688589267661 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267661 geckodriver::marionette TRACE Retrying in 100ms 1688589267761 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267761 geckodriver::marionette TRACE Retrying in 100ms 1688589267861 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267862 geckodriver::marionette TRACE Retrying in 100ms 1688589267962 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589267962 geckodriver::marionette TRACE Retrying in 100ms 1688589268062 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268062 geckodriver::marionette TRACE Retrying in 100ms 1688589268163 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268163 geckodriver::marionette TRACE Retrying in 100ms 1688589268263 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268263 geckodriver::marionette TRACE Retrying in 100ms 1688589268363 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268363 geckodriver::marionette TRACE Retrying in 100ms 1688589268464 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268464 geckodriver::marionette TRACE Retrying in 100ms 1688589268564 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268564 geckodriver::marionette TRACE Retrying in 100ms 1688589268664 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268664 geckodriver::marionette TRACE Retrying in 100ms 1688589268764 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268764 geckodriver::marionette TRACE Retrying in 100ms 1688589268865 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268865 geckodriver::marionette TRACE Retrying in 100ms 1688589268965 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589268965 geckodriver::marionette TRACE Retrying in 100ms 1688589269065 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269065 geckodriver::marionette TRACE Retrying in 100ms 1688589269165 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269165 geckodriver::marionette TRACE Retrying in 100ms 1688589269266 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269266 geckodriver::marionette TRACE Retrying in 100ms 1688589269366 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269366 geckodriver::marionette TRACE Retrying in 100ms 1688589269466 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269466 geckodriver::marionette TRACE Retrying in 100ms 1688589269566 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269566 geckodriver::marionette TRACE Retrying in 100ms 1688589269667 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269667 geckodriver::marionette TRACE Retrying in 100ms 1688589269767 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269767 geckodriver::marionette TRACE Retrying in 100ms 1688589269867 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269867 geckodriver::marionette TRACE Retrying in 100ms 1688589269967 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589269967 geckodriver::marionette TRACE Retrying in 100ms 1688589270068 geckodriver::browser TRACE Failed to open /tmp/firefox/profile/MarionetteActivePort 1688589270068 geckodriver::marionette TRACE Retrying in 100ms

(firefox:6288): dconf-CRITICAL **: 20:34:30.157: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

(firefox:6288): dconf-CRITICAL **: 20:34:30.157: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

(firefox:6288): dconf-CRITICAL **: 20:34:30.162: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

(firefox:6288): dconf-CRITICAL **: 20:34:30.163: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

(firefox:6288): dconf-CRITICAL **: 20:34:30.163: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

(firefox:6288): dconf-CRITICAL **: 20:34:30.163: unable to create directory '/root/.cache/dconf': Permission denied. dconf will not work properly.

whimboo commented 1 year ago

@ssada1975 thanks a lot! So could you now try to start Firefox by using the www-data user? I would assume that it doesn't start as well. If that is the case it would be best to get a bug filed for Firefox directly. Let me know and I can guide you.

whimboo commented 1 year ago

Oh, I actually found https://answers.launchpad.net/ubuntu/+question/695824. As it looks like www-data doesn't have a home directory by default and as such Firefox fails to store the profile. Comment 5 on this bug tracker issue should help you. Please let us know.

ltanase77 commented 1 year ago

Hi whimboo! So, in the home directory should I create a www-data folder with the same write access as the other user, where firefox will create the .mozilla folder when run by www-data user?

whimboo commented 1 year ago

@ltanase77 please have a look at https://linuxhandbook.com/create-home-directory-existing-user/. That should do it.

ltanase77 commented 1 year ago

sudo mkhomedir_helper www-data does not create a home directory for www-data user.

ltanase77 commented 1 year ago

The home directory for www-data user seems to be /var/www where a .profile, .bashrc and bash_logout file exists

ssada1975 commented 1 year ago

no way to make it works, even creating /var/www/.cache or .mozilla and giving rights to www-data

ltanase77 commented 1 year ago

In my case the www-data is set as nologin user and probably that's why I cannot create a home directory.

ssada1975 commented 1 year ago

@ltanase77 in the world we are just you and me not being able to run geckodriver automatically from Php? 😭 It sounds crazy there is no solution

ltanase77 commented 1 year ago

I have somehow bypass the problem, by running geckodriver as background process with nohup geckodriver and then instead of $driver = Firefox\FirefoxDriver::start($desiredCapabilities); I am using $driver = RemoteWebDriver::create($serverUrl, $desiredCapabilities); In this way I was able to schedule a Laravel job that is running automatically daily at certain hours, using the php-webdriver for scraping info from a certain website.

whimboo commented 1 year ago

@ltanase77 thanks for checking. So there is indeed a problem in starting Firefox with the www-data user, and some missing permissions. Could you maybe check if that really only applies to headless? I assume that headful will also be affected the same way.

Do you actually see where geckodriver tries to create the temporary Firefox profile? Is it also under /tmp/firefox/...? I assume www-data doesn't have access to? Also you could start geckodriver with the --profile-root argument (which is new since version 0.32.0) and specify the /var/www/ folder. Does that work then?

ltanase77 commented 1 year ago

I am using aws lightsail bitnami lamp stack, which according with their docs runs apache and php under daemon user and group. Starting geckodriver manually with --profile-root /var/www-data returns this errorgeckodriver: error: Unable to write to temporary directory; consider --profile-root with a writeable directory Geckodriver is creating temporary firefox profile in directly in /tmp by creating a folder rust_mozprofile{uid}. Some of such folders are created by the daemon user, some by the ssh user under which I log in the machine. I assume that when php-webdriver is trying to start geckodriver is using the daemon user under which php is running.