Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PHP-Webdriver does not spin a new geckodriver/firefox process and does not create a log file #1048

Closed
ltanase77 opened this issue Feb 8, 2023 · 11 comments
Labels
bug Something isn't working waiting for reaction Further information/reaction is requested

Comments

@ltanase77
Copy link

ltanase77 commented Feb 8, 2023

Bug description

PHP-WebDriver does not succeed in making geckodriver to connect to marionette port, when using FirefoxDriver::start($desiredCapabilities); in headless mode. Furthermore, although an option is passed for setting the log level no geckodriver.log file is created and thus there is very little info available for determining what is going on.

How could the issue be reproduced

$desiredCapabilities = DesiredCapabilities::firefox();
 $desiredCapabilities->setCapability('acceptSslCerts', false);
 $firefoxOptions = new FirefoxOptions();
 $firefoxOptions->addArguments(['-headless']);
 $firefoxOptions->setOption("binary", "/usr/lib/firefox/firefox");
 $firefoxOptions->setOption("log", ["level" => "trace"]);
 $desiredCapabilities->setCapability(FirefoxOptions::CAPABILITY, $firefoxOptions);
 $serverUrl = 'http://localhost:4444';
 //$driver = RemoteWebDriver::create($serverUrl, $desiredCapabilities);
 $driver = FirefoxDriver::start($desiredCapabilities);
 $driver->get('https://example.com');

Expected behavior

As per documentation, the script should start geckodriver directly, which in turn spin of firefox and get the content of the targeted web page.

Php-webdriver version

1.13

PHP version

7.4.15

How do you start the browser driver or Selenium server

N/A

Selenium server / Selenium Docker image version

No response

Browser driver (chromedriver/geckodriver...) version

0.32

Browser name and version

Firefox 109.0.1 (headless)

Operating system

Debian 10

Additional context

Starting manually geckodriver and using RemoteWebDriver::create($serverUrl, $desiredCapabilities); make the script work, but this implies running geckodriver on a permament basis. I want to use the script as Laravel Job which to run once per day, and therefore it is unnecessary to have geckodriver running permanently.

This is the exception returned by PHP-Webdriver when the log level is set:

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

When I am not setting the log level it returns the following error message:
Facebook\WebDriver\Exception\TimeoutException Failed to read marionette port

@ltanase77 ltanase77 added the bug Something isn't working label Feb 8, 2023
@OndraM
Copy link
Collaborator

OndraM commented Feb 9, 2023

Hi,
true is, the support for starting local geckodriver process in php-webdriver is basic, and may be missing some features, like the mentioned possibility of setting the log file (or chaning the default port on which geckodriver listens, which is currently hardcoded to 9515).

Nevertheless, we have a test covering exactly this scenario (starting Geckodriver in headless mode) and it works fine. Also if I try exactly the script you provide, it also works without an issue on my machine, so I cannot reproduce this. It seems there may be something specific related to your setup.

If you try spinning up geckodriver process manually, you can see what is the issue. If you run this command, you will mimic exactly what php-webdriver does.

geckodriver -p=9515

and you can see the output right in the terminal. You can add --log=trace to increase the error level.

To connect to this instance, use it as remote server on localhost:9515.

$capabilities = DesiredCapabilities::firefox();
$firefoxOptions = new FirefoxOptions();
$firefoxOptions->addArguments(['-headless']);
$capabilities->setCapability(FirefoxOptions::CAPABILITY, $firefoxOptions);

$serverUrl = 'http://localhost:9515';
$driver = RemoteWebDriver::create($serverUrl, $capabilities);
$driver->get('https://example.com');

echo $driver->getTitle();
$driver->quit();

Let us know what is the result or if you find anything in the error log.

@OndraM OndraM added the waiting for reaction Further information/reaction is requested label Feb 9, 2023
@ltanase77
Copy link
Author

Hi, as I mentioned in the additional context section, starting geckodriver manually and using $driver = RemoteWebDriver::create($serverUrl, $capabilities); works as intended.
The issue arise only when I am trying to start geckodriver with PHP-Webriver using start() method.
I will try your example and post the output of the log.

@github-actions github-actions bot removed the waiting for reaction Further information/reaction is requested label Feb 9, 2023
@OndraM
Copy link
Collaborator

OndraM commented Feb 9, 2023

Oh, sorry, I missed that. Then its even more weird, because php-webdriver should not be doing anything different than starting the geckodriver on port 9515. If you are doing it manually, are you using the same port 9515? There could be something occupying this port, for example.

@ltanase77
Copy link
Author

ltanase77 commented Feb 9, 2023

In the past when I started geckodriver manually I did not specify a port. This is the output in the terminal of your example:

1675951542919   geckodriver     INFO    Listening on 127.0.0.1:9515
1675951677533   mozrunner::runner       INFO    Running command: "/usr/lib/firefox/firefox" "--marionette" "-headless" "-no-remote" "-profile" "/tmp/rust_mozprofilengD39b"
1675951677535   geckodriver::marionette DEBUG   Waiting 60s to connect to browser on 127.0.0.1
1675951677535   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951677535   geckodriver::marionette TRACE   Retrying in 100ms
1675951677635   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951677635   geckodriver::marionette TRACE   Retrying in 100ms
*** You are running in headless mode.
1675951677735   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951677735   geckodriver::marionette TRACE   Retrying in 100ms
1675951677836   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951677836   geckodriver::marionette TRACE   Retrying in 100ms
1675951677936   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951677936   geckodriver::marionette TRACE   Retrying in 100ms
1675951678036   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678036   geckodriver::marionette TRACE   Retrying in 100ms
1675951678136   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678136   geckodriver::marionette TRACE   Retrying in 100ms
1675951678236   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678236   geckodriver::marionette TRACE   Retrying in 100ms
1675951678336   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678336   geckodriver::marionette TRACE   Retrying in 100ms
[GFX1-]: glxtest: Unable to open a connection to the X server
1675951678437   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678437   geckodriver::marionette TRACE   Retrying in 100ms
1675951678518   Marionette      INFO    Marionette enabled
1675951678524   RemoteAgent     DEBUG   Setting recommended pref apz.content_response_timeout to 60000
1675951678525   RemoteAgent     DEBUG   Setting recommended pref browser.contentblocking.introCount to 99
1675951678525   RemoteAgent     DEBUG   Setting recommended pref browser.download.panel.shown to true
1675951678525   RemoteAgent     DEBUG   Setting recommended pref browser.newtabpage.enabled to false
1675951678526   RemoteAgent     DEBUG   Setting recommended pref browser.pagethumbnails.capturing_disabled to true
1675951678526   RemoteAgent     DEBUG   Setting recommended pref browser.search.update to false
1675951678526   RemoteAgent     DEBUG   Setting recommended pref browser.startup.couldRestoreSession.count to -1
1675951678527   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.closeWindowWithLastTab to false
1675951678527   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.disableBackgroundZombification to false
1675951678528   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.unloadOnLowMemory to false
1675951678528   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.warnOnClose to false
1675951678528   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
1675951678529   RemoteAgent     DEBUG   Setting recommended pref browser.tabs.warnOnOpen to false
1675951678529   RemoteAgent     DEBUG   Setting recommended pref browser.toolbars.bookmarks.visibility to never
1675951678529   RemoteAgent     DEBUG   Setting recommended pref browser.topsites.contile.enabled to false
1675951678532   RemoteAgent     DEBUG   Setting recommended pref browser.usedOnWindows10.introURL to
1675951678534   RemoteAgent     DEBUG   Setting recommended pref browser.urlbar.merino.endpointURL to
1675951678535   RemoteAgent     DEBUG   Setting recommended pref browser.urlbar.suggest.searches to false
1675951678535   RemoteAgent     DEBUG   Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1675951678536   RemoteAgent     DEBUG   Setting recommended pref dom.disable_open_during_load to false
1675951678536   RemoteAgent     DEBUG   Setting recommended pref dom.file.createInChild to true
1675951678536   RemoteAgent     DEBUG   Setting recommended pref dom.max_chrome_script_run_time to 0
1675951678537   RemoteAgent     DEBUG   Setting recommended pref dom.max_script_run_time to 0
1675951678537   geckodriver::browser    TRACE   Failed to open /tmp/rust_mozprofilengD39b/MarionetteActivePort
1675951678537   geckodriver::marionette TRACE   Retrying in 100ms
1675951678537   RemoteAgent     DEBUG   Setting recommended pref dom.navigation.locationChangeRateLimit.count to 0
1675951678537   RemoteAgent     DEBUG   Setting recommended pref dom.push.connection.enabled to false
1675951678538   RemoteAgent     DEBUG   Setting recommended pref dom.successive_dialog_time_limit to 0
1675951678538   RemoteAgent     DEBUG   Setting recommended pref extensions.getAddons.cache.enabled to false
1675951678538   RemoteAgent     DEBUG   Setting recommended pref extensions.getAddons.discovery.api_url to data:,
1675951678538   RemoteAgent     DEBUG   Setting recommended pref network.http.phishy-userpass-length to 255
1675951678539   RemoteAgent     DEBUG   Setting recommended pref network.http.prompt-temp-redirect to false
1675951678539   RemoteAgent     DEBUG   Setting recommended pref privacy.trackingprotection.enabled to false
1675951678539   RemoteAgent     DEBUG   Setting recommended pref security.fileuri.strict_origin_policy to false
1675951678540   RemoteAgent     DEBUG   Setting recommended pref security.notification_enable_delay to 0
1675951678540   RemoteAgent     DEBUG   Setting recommended pref signon.autofillForms to false
1675951678540   RemoteAgent     DEBUG   Setting recommended pref signon.rememberSignons to false
1675951678540   RemoteAgent     DEBUG   Setting recommended pref widget.windows.window_occlusion_tracking.enabled to false
1675951678541   RemoteAgent     DEBUG   Setting recommended pref dom.disable_beforeunload to true
1675951678543   Marionette      TRACE   Received observer notification final-ui-startup
1675951678545   Marionette      INFO    Listening on port 33657
1675951678546   Marionette      DEBUG   Marionette is listening
Read port: 33657
1675951678773   Marionette      DEBUG   Accepted connection 0 from 127.0.0.1:38252
1675951678780   geckodriver::marionette DEBUG   Connection to Marionette established on 127.0.0.1:33657.
1675951678874   Marionette      DEBUG   0 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":false,"browserName":"firefox"}]
1675951678888   Marionette      DEBUG   Waiting for initial application window
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/rust_mozprofilengD39b/search.json.mozlz4", (void 0)))
1675951683738   Marionette      TRACE   Received observer notification browser-idle-startup-tasks-finished
1675951683767   RemoteAgent     TRACE   [8] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=200 waitForExplicitStart=false
1675951683771   RemoteAgent     TRACE   [8] ProgressListener Setting unload timer (200ms)
1675951683773   RemoteAgent     TRACE   [8] Document already finished loading: about:blank
1675951683774   RemoteAgent     TRACE   [8] ProgressListener Stop: has error=false
1675951683879   Marionette      DEBUG   0 <- [1,1,null,{"sessionId":"4402e4f6-6149-48fb-9281-e7efe8b261d0","capabilities":{"browserName":"firefox","browserVersion":"109.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":"20230127170202","moz:headless":true,"moz:platformVersion":"4.19.0-14-cloud-amd64","moz:processID":16359,"moz:profile":"/tmp/rust_mozprofilengD39b","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
1675951683954   webdriver::server       DEBUG   <- 200 OK {"value":{"sessionId":"4402e4f6-6149-48fb-9281-e7efe8b261d0","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"109.0.1","moz:accessibilityChecks":false,"moz:buildID":"20230127170202","moz:geckodriverVersion":"0.32.0","moz:headless":true,"moz:platformVersion":"4.19.0-14-cloud-amd64","moz:processID":16359,"moz:profile":"/tmp/rust_mozprofilengD39b","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"normal","platformName":"linux","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
1675951683986   webdriver::server       DEBUG   -> POST /session/4402e4f6-6149-48fb-9281-e7efe8b261d0/url {"url":"https:\/\/github.com"}
1675951684011   Marionette      DEBUG   0 -> [0,2,"WebDriver:Navigate",{"url":"https://github.com"}]
1675951684033   Marionette      TRACE   [8] Received event beforeunload for about:blank
1675951684147   Marionette      TRACE   Remoteness change detected. Set new top-level browsing context to 11
1675951684171   Marionette      TRACE   [11] Received event beforeunload for about:blank
1675951684187   Marionette      TRACE   [11] Received event pagehide for about:blank
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: WebGL warning: <Create>: WebglAllowWindowsNativeGl:false restricts context creation on this system.
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: Failed to create WebGL context: WebGL creation failed:
* WebglAllowWindowsNativeGl:false restricts context creation on this system. ()
* Exhausted GL driver options. (FEATURE_FAILURE_WEBGL_EXHAUSTED_DRIVERS)
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: WebGL warning: <Create>: AllowWebgl2:false restricts context creation on this system.
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: Failed to create WebGL context: WebGL creation failed:
* AllowWebgl2:false restricts context creation on this system. ()
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: WebGL warning: <Create>: WebglAllowWindowsNativeGl:false restricts context creation on this system.
JavaScript warning: https://github.githubassets.com/assets/vendors-node_modules_github_webgl-globe_dist_js_main_js-c61608acc916.js, line 16: Failed to create WebGL context: WebGL creation failed:
* WebglAllowWindowsNativeGl:false restricts context creation on this system. ()
* Exhausted GL driver options. (FEATURE_FAILURE_WEBGL_EXHAUSTED_DRIVERS)
1675951688939   Marionette      TRACE   [11] Received event DOMContentLoaded for https://github.com/
1675951691329   Marionette      TRACE   [11] Received event pageshow for https://github.com/
1675951691329   Marionette      DEBUG   0 <- [1,2,null,{"value":null}]
1675951692384   webdriver::server       DEBUG   <- 200 OK {"value":null}
1675951692408   webdriver::server       DEBUG   -> GET /session/4402e4f6-6149-48fb-9281-e7efe8b261d0/title
1675951692945   Marionette      DEBUG   0 -> [0,3,"WebDriver:GetTitle",{}]
1675951693186   Marionette      DEBUG   0 <- [1,3,null,{"value":"GitHub: Let’s build from here · GitHub"}]
1675951693517   webdriver::server       DEBUG   <- 200 OK {"value":"GitHub: Let’s build from here · GitHub"}
1675951693557   webdriver::server       DEBUG   -> DELETE /session/4402e4f6-6149-48fb-9281-e7efe8b261d0
1675951693895   Marionette      DEBUG   0 -> [0,4,"Marionette:Quit",{"flags":["eForceQuit"]}]
1675951693899   Marionette      INFO    Stopped listening on port 33657
1675951699320   Marionette      TRACE   Received observer notification quit-application
1675951699323   Marionette      TRACE   Received observer notification quit-application
1675951699324   Marionette      DEBUG   Marionette stopped listening
1675951699325   RemoteAgent     DEBUG   Resetting recommended pref apz.content_response_timeout
1675951699326   RemoteAgent     DEBUG   Resetting recommended pref browser.contentblocking.introCount
1675951699327   RemoteAgent     DEBUG   Resetting recommended pref browser.download.panel.shown
1675951699328   RemoteAgent     DEBUG   Resetting recommended pref browser.newtabpage.enabled
1675951699333   RemoteAgent     DEBUG   Resetting recommended pref browser.pagethumbnails.capturing_disabled
1675951699334   RemoteAgent     DEBUG   Resetting recommended pref browser.search.update
1675951699335   RemoteAgent     DEBUG   Resetting recommended pref browser.startup.couldRestoreSession.count
1675951699337   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.closeWindowWithLastTab
1675951699338   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.disableBackgroundZombification
1675951699339   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.unloadOnLowMemory
1675951699339   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.warnOnClose
1675951699339   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
1675951699340   RemoteAgent     DEBUG   Resetting recommended pref browser.tabs.warnOnOpen
1675951699341   RemoteAgent     DEBUG   Resetting recommended pref browser.toolbars.bookmarks.visibility
1675951699342   RemoteAgent     DEBUG   Resetting recommended pref browser.topsites.contile.enabled
1675951699344   RemoteAgent     DEBUG   Resetting recommended pref browser.usedOnWindows10.introURL
1675951699345   RemoteAgent     DEBUG   Resetting recommended pref browser.urlbar.merino.endpointURL
1675951699354   RemoteAgent     DEBUG   Resetting recommended pref browser.urlbar.suggest.searches
1675951699356   RemoteAgent     DEBUG   Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
1675951699358   RemoteAgent     DEBUG   Resetting recommended pref dom.disable_open_during_load
1675951699359   RemoteAgent     DEBUG   Resetting recommended pref dom.file.createInChild
1675951699360   RemoteAgent     DEBUG   Resetting recommended pref dom.max_chrome_script_run_time
1675951699360   RemoteAgent     DEBUG   Resetting recommended pref dom.max_script_run_time
1675951699362   RemoteAgent     DEBUG   Resetting recommended pref dom.navigation.locationChangeRateLimit.count
1675951699363   RemoteAgent     DEBUG   Resetting recommended pref dom.push.connection.enabled
1675951699364   RemoteAgent     DEBUG   Resetting recommended pref dom.successive_dialog_time_limit
1675951699371   RemoteAgent     DEBUG   Resetting recommended pref extensions.getAddons.cache.enabled
1675951699372   RemoteAgent     DEBUG   Resetting recommended pref extensions.getAddons.discovery.api_url
1675951699373   RemoteAgent     DEBUG   Resetting recommended pref network.http.phishy-userpass-length
1675951699375   RemoteAgent     DEBUG   Resetting recommended pref network.http.prompt-temp-redirect
1675951699375   RemoteAgent     DEBUG   Resetting recommended pref privacy.trackingprotection.enabled
1675951699376   RemoteAgent     DEBUG   Resetting recommended pref security.fileuri.strict_origin_policy
1675951699378   RemoteAgent     DEBUG   Resetting recommended pref security.notification_enable_delay
1675951699387   RemoteAgent     DEBUG   Resetting recommended pref signon.autofillForms
1675951699391   RemoteAgent     DEBUG   Resetting recommended pref signon.rememberSignons
1675951699394   RemoteAgent     DEBUG   Resetting recommended pref widget.windows.window_occlusion_tracking.enabled
1675951699395   RemoteAgent     DEBUG   Resetting recommended pref dom.disable_beforeunload
1675951699400   Marionette      DEBUG   0 <- [1,4,null,{"cause":"shutdown","forced":false,"in_app":true}]
1675951699555   webdriver::server       DEBUG   Teardown session
1675951699569   Marionette      DEBUG   Closed connection 0
WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:718:15
addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.jsm:19:28
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
_submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
sendPing@resource://gre/modules/EventPing.jsm:51:30
_submitPing@resource://gre/modules/EventPing.jsm:229:12
shutdown@resource://gre/modules/EventPing.jsm:112:10
_cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:940:31
shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1010:24
observe@resource://gre/modules/AsyncShutdown.jsm:572:16

WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:718:15
addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.jsm:19:28
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
_submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
_cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:959:35
observe@resource://gre/modules/AsyncShutdown.jsm:572:16

WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:718:15
addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.jsm:19:28
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
_submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:1014:36
shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
_cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:959:35
observe@resource://gre/modules/AsyncShutdown.jsm:572:16

WARNING: A blocker encountered an error while we were waiting.
          Blocker:  TelemetryController: shutting down
          Phase: profile-before-change-telemetry
          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.jsm:718:15
addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.jsm:19:28
getShutdownState@resource://gre/modules/TelemetrySend.jsm:1692:7
getShutdownState@resource://gre/modules/TelemetrySend.jsm:374:30
_getState@resource://gre/modules/TelemetryControllerParent.jsm:1058:38
setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:917:18
safeGetState@resource://gre/modules/AsyncShutdown.jsm:254:17
Barrier/_internalAddBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:773:20
observe@resource://gre/modules/AsyncShutdown.jsm:572:16

WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:718:15
addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.jsm:19:28
removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:721:5
removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
observe@resource://gre/modules/AsyncShutdown.jsm:572:16

JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"

JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 718: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
1675951700058   geckodriver::browser    DEBUG   Browser process stopped: exit status: 0
1675951700087   webdriver::server       DEBUG   <- 200 OK {"value":null}

@OndraM
Copy link
Collaborator

OndraM commented Feb 9, 2023

Thanks, so this is the output when running the process manually, right? Because there is no error, according to the log it createw new session, responds, and then visit a new URL.

@OndraM
Copy link
Collaborator

OndraM commented Feb 9, 2023

@ltanase77 Ok, so to make it easier to debug, I implemented a prototype feature which enables storing output of the geckodriver process to a file.

  • Use branch feature/driver-service-logging (ie. use version dev-feature/driver-service-logging in composer.json)
  • Setup it like this:
$desiredCapabilities = DesiredCapabilities::firefox();
$firefoxOptions = new FirefoxOptions();
$firefoxOptions->addArguments(['-headless']);
$firefoxOptions->setOption('log', ['level' => 'trace']);
$desiredCapabilities->setCapability(FirefoxOptions::CAPABILITY, $firefoxOptions);

$service = FirefoxDriverService::createDefaultService('/tmp/geckodriver.log'); // or use different file name
$driver = FirefoxDriver::startUsingDriverService($service, $desiredCapabilities);
$driver->get('https://example.com');

echo $driver->getTitle();
$driver->quit();

And check how it behaves, if the error is still present, provide the full output of the geckodriver.log.

@ltanase77
Copy link
Author

Yes, the output is when I start manually the geckodriver and I got echoed in the browser the title of github.com website. So, in my composer.json instead of
"php-webdriver/webdriver": "^1.13",
I will require:
"php-webdriver/webdriver": "dev-feature/driver-service-logging",
An then, I assume that I need to run composer update command.

@ltanase77
Copy link
Author

ltanase77 commented Feb 10, 2023

This is the output of the geckodriver.log:

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
Copy link
Author

ltanase77 commented Feb 10, 2023

There is no MarionetteActivePort file in that profile directory (just an user.js file), so of course it fails to open it.
The Stack Trace error is the following:

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

@OndraM
Copy link
Collaborator

OndraM commented Feb 11, 2023

This may be issue of geckodriver, lets wait if mozilla/geckodriver#2082 gives any hints.

@OndraM OndraM added the waiting for reaction Further information/reaction is requested label Feb 11, 2023
@github-actions
Copy link

This issue has been automatically closed because there has been no response to our request for more information from the original author. With only the information that is currently in the issue, we don't have enough information to take action.
If the original issue author adds comment with more information, this issue will be automatically reopened and we can investigate further.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working waiting for reaction Further information/reaction is requested
Projects
None yet
Development

No branches or pull requests

2 participants