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

No reply from Marionette:Register #1838

Closed
mrhili opened this issue Feb 2, 2021 · 20 comments
Closed

No reply from Marionette:Register #1838

mrhili opened this issue Feb 2, 2021 · 20 comments
Assignees

Comments

@mrhili
Copy link

mrhili commented Feb 2, 2021

System

  • Version:
  • 0.25
  • Platform:
  • windows 10 latest
  • Firefox:
    85.0 64bit
  • Selenium:
    selenium==3.141.0

/after some initialization code I want to get/
driver.get('http://google.com/')

Trace-level log

1612266596021 geckodriver INFO Listening on 127.0.0.1:59832
1612266598992 mozrunner::runner INFO Running command: "C:\Program Files\Mozilla Firefox\firefox.exe" "--marionette" "-foreground" "-no-remote" "-profile" "C:\Users\HP\AppData\Local\Temp\rust_mozprofiletlW72N"
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
1612266605070 Marionette INFO Listening on port 59841
1612266605617 Marionette WARN TLS certificate errors will be ignored for this session
1612266605637 Marionette ERROR [15] No reply from Marionette:Register
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
1612266648442 Marionette INFO Stopped listening on port 59841

@whimboo
Copy link
Collaborator

whimboo commented Feb 2, 2021

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

Does that also happen with Firefox 84?

@mrhili
Copy link
Author

mrhili commented Feb 2, 2021

Does that also happen with Firefox 84?: YES
I run the code without any options and it works:

my options was:

            options = FirefoxOptions()
            options = options.page_load_strategy = 'normal'
            #headless files did not work properly
            #i keepit as a ref
            #options.headless = True
            self.driver = webdriver.Firefox(executable_path=str(self.driver_path),service_log_path="drivers/driver_logs/geckodriver.logs", options=options)

@mrhili
Copy link
Author

mrhili commented Feb 2, 2021

1612275246090 geckodriver INFO Listening on 127.0.0.1:61004
1612275248897 mozrunner::runner INFO Running command: "C:\Program Files\Mozilla Firefox\firefox.exe" "--marionette" "-foreground" "-no-remote" "-profile" "C:\Users\HP\AppData\Local\Temp\rust_mozprofileYtQdGu"
1612275248906 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:61013
1612275255534 Marionette TRACE Marionette enabled
1612275256130 Marionette TRACE Received observer notification toplevel-window-ready
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
console.error: Region.jsm: "Error fetching region" (new Error("TIMEOUT", "resource://gre/modules/Region.jsm", 775))
console.error: Region.jsm: "Failed to fetch region" (new Error("TIMEOUT", "resource://gre/modules/Region.jsm", 422))
1612275267050 Marionette TRACE Received observer notification marionette-startup-requested
1612275267050 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
1612275267170 Marionette TRACE All scripts recorded.
1612275267170 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
1612275267171 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
1612275267171 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
1612275267171 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
1612275267173 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
1612275267173 Marionette DEBUG Setting recommended pref browser.search.update to false
1612275267173 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
1612275267173 Marionette DEBUG Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
1612275267174 Marionette DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false
1612275267174 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
1612275267174 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
1612275267174 Marionette DEBUG Setting recommended pref browser.toolbars.bookmarks.visibility to never
1612275267174 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
1612275267174 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
1612275267176 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1612275267176 Marionette DEBUG Setting recommended pref dom.disable_beforeunload to true
1612275267176 Marionette DEBUG Setting recommended pref dom.disable_open_during_load to false
1612275267176 Marionette DEBUG Setting recommended pref dom.file.createInChild to true
1612275267176 Marionette DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0
1612275267176 Marionette DEBUG Setting recommended pref dom.max_script_run_time to 0
1612275267178 Marionette DEBUG Setting recommended pref dom.push.connection.enabled to false
1612275267178 Marionette DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false
1612275267178 Marionette DEBUG Setting recommended pref extensions.getAddons.discovery.api_url to data:,
1612275267178 Marionette DEBUG Setting recommended pref network.http.prompt-temp-redirect to false
1612275267178 Marionette DEBUG Setting recommended pref privacy.trackingprotection.enabled to false
1612275267178 Marionette DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false
1612275267179 Marionette DEBUG Setting recommended pref security.notification_enable_delay to 0
1612275267179 Marionette DEBUG Setting recommended pref signon.autofillForms to false
1612275267180 Marionette DEBUG Setting recommended pref signon.rememberSignons to false
1612275267207 Marionette INFO Listening on port 61013
1612275267207 Marionette DEBUG Marionette is listening
1612275267686 Marionette DEBUG Remote agent not available for this build and platform
1612275267688 Marionette DEBUG Accepted connection 0 from 127.0.0.1:61034
1612275267691 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:61013.
1612275267727 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":true,"browserName":"firefox"}]
1612275267728 Marionette WARN TLS certificate errors will be ignored for this session
1612275267737 Marionette TRACE [15] Frame script loaded
1612275267747 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"c639dc9a-28bf-4748-89ee-b16613e31531","capabilities":{"browserName":"firefox","browserVersion":"85.0" ... \rust_mozprofileYtQdGu","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
1612275267751 Marionette ERROR [15] No reply from Marionette:Register
1612275267751 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"c639dc9a-28bf-4748-89ee-b16613e31531","capabilities":{"acceptInsecureCerts":true,"browserName":"firefox","browserVersion":"85.0","moz:accessibilityChecks":false,"moz:buildID":"20210118153634","moz:geckodriverVersion":"0.29.0","moz:headless":false,"moz:processID":12696,"moz:profile":"C:\Users\HP\AppData\Local\Temp\rust_mozprofileYtQdGu","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
1612275268058 Marionette DEBUG Closed connection 0

@mrhili
Copy link
Author

mrhili commented Feb 2, 2021

the last log i run it wit that code:

start = Start(config)

class Start:

    

    BASE_DIR = Path(__file__).resolve().parent.parent

    
    driver_motor = None
    driver_path = None
    page_load_time_out = None
    wait_until_sec = None
    #Driver options
    driver_wait = None
    action_chains = None

    def __init__(self, config):

        #initialization of the most required parameters

        self.config = config


        #initialization of browser parameters
        self.driver_motor = self.config('DRYVER_TYPE')
        self.page_load_time_out = self.config('PAGE_LOAD_TIME_OUT')
        self.wait_until_sec = self.config('WAIT_UNTIL_SEC')

        #like CHROMEDRIVER_PATH=drivers/chromedriver.exe
        DRIVER_PATH='{}DRIVER_PATH'.format(self.driver_motor)
        DRIVER_PATH_INIT = self.config(DRIVER_PATH)


        #then get the relative path
        self.driver_path = Path( os.path.join( self.BASE_DIR, str(DRIVER_PATH_INIT) ) )




        if( self.driver_motor == 'FIREFOX'):
            options = FirefoxOptions()
            options = self.fill_standart_options(options)

            self.driver = webdriver.Firefox(executable_path=str(self.driver_path),service_log_path="drivers/driver_logs/geckodriver.logs", options=options)


 



    # fill standart repeated options
    def fill_standart_options(self, options):
        options.page_load_strategy = 'normal'
        options.log.level = "trace"
        return options

    def lunch(self):
        self.driver.get('http://google.com/')

    def close(self):
        self.driver.quit()

@whimboo
Copy link
Collaborator

whimboo commented Feb 2, 2021

What does run without any options and it works mean? Was it about headless only? I have to ask because I still see that you are setting page_load_strategy. Do older releases of Firefox also fail? When does this problem actually start to happen?

@mrhili
Copy link
Author

mrhili commented Feb 2, 2021

I will give you a code and a trace


import time
from selenium import webdriver
from selenium.webdriver.common.by import By
from selenium.webdriver.common.keys import Keys
from selenium.webdriver.support.ui import WebDriverWait
from selenium.webdriver.support.expected_conditions import presence_of_element_located

with webdriver.Firefox() as driver:
    wait = WebDriverWait(driver, 10)
    driver.get("https://google.com/")
    driver.options.log.level = "trace"
    time.sleep(15)

and the trace is:

1612294458620 geckodriver INFO Listening on 127.0.0.1:52022
1612294461947 mozrunner::runner INFO Running command: "C:\Program Files\Mozilla Firefox\firefox.exe" "--marionette" "-foreground" "-no-remote" "-profile" "C:\Users\HP\AppData\Local\Temp\rust_mozprofileXrnMbf"
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
1612294469853 Marionette INFO Listening on port 52030
console.error: Region.jsm: "Error fetching region" (new Error("TIMEOUT", "resource://gre/modules/Region.jsm", 775))
console.error: Region.jsm: "Failed to fetch region" (new Error("TIMEOUT", "resource://gre/modules/Region.jsm", 422))
1612294470313 Marionette WARN TLS certificate errors will be ignored for this session
1612294470338 Marionette ERROR [18] No reply from Marionette:Register
1612294495945 Marionette INFO Stopped listening on port 52030
JavaScript error: resource://activity-stream/lib/ASRouter.jsm, line 987: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]

###!!! [Child][MessageChannel] Error: (msgtype=0x6B0027,name=PNecko::Msg_RemoveRequestContext) Channel closing: too late to send/recv, messages will be lost

###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

@whimboo
Copy link
Collaborator

whimboo commented Feb 2, 2021

Note, there is no self.options for the driver instance. As such the trace option has to be set before creating the driver, and passing options into webdriver.Firefox(). As such the log above is not a trace log.

@mrhili
Copy link
Author

mrhili commented Feb 7, 2021

THank you i will see what i can do

@remorhaz
Copy link

I'm exeperiencing similar problem:

1613545358116	geckodriver	INFO	Listening on 127.0.0.1:15183
1613545358132	mozrunner::runner	INFO	Running command: "/usr/bin/firefox" "--marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofileOAlNDd"
[GFX1-]: glxtest: libpci missing
[GFX1-]: glxtest: libEGL missing
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
1613545360788	Marionette	INFO	Listening on port 37798
1613545360878	Marionette	ERROR	[15] No reply from Marionette:Register
07:02:40.879 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
07:02:40.881 INFO [Distributor.newSession] - Session created by the distributor. Id: 696f4c68-cfcc-4982-983b-b9121dec9527, Caps: Capabilities {acceptInsecureCerts: false, browserName: firefox, browserVersion: 85.0.2, moz:accessibilityChecks: false, moz:buildID: 20210208133944, moz:geckodriverVersion: 0.29.0, moz:headless: false, moz:processID: 8425, moz:profile: /tmp/rust_mozprofileOAlNDd, moz:shutdownTimeout: 60000, moz:useNonSpecCompliantPointerOrigin: false, moz:webdriverClick: true, pageLoadStrategy: normal, platformName: linux, platformVersion: 4.4.0-142-generic, rotatable: false, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify}
1613545367296	Marionette	INFO	Stopped listening on port 37798

@whimboo
Copy link
Collaborator

whimboo commented Feb 17, 2021

@remorhaz which version of Firefox are you using? Can you please try to run your tests with Firefox preference marionette.actors.enabled set to true?

@remorhaz
Copy link

@whimboo All the versions are mentioned in the log (as a part of session creation), I'll put them here for convenience:

  • Firefox 85.0.2 build 20210208133944
  • GeckoDriver 0.29.0

The problem occured under low resources on CI agent and has (probably temporarily) gone after purging old containers. I will try to reproduce it under stress. I will also try to enable actors and see what happens.

@whimboo
Copy link
Collaborator

whimboo commented Feb 17, 2021

Thanks. Make sure to also set marionette.log.level to Trace so we get the maximum available logging output. Thanks.

@remorhaz
Copy link

I've got some problems while trying to enabling actors (will investigate that later), but for now - here's the piece of log with debug level:

19:44:08.412 INFO [Distributor.newSession] - Session request received by the distributor: 
{
  "desiredCapabilities": {
    "moz:firefoxOptions": {
      "log": {
        "level": "debug"
      },
      "prefs": {
        "general.useragent.override": "Mozilla\u002f5.0 (Android 4.4; Mobile; rv:41.0) Gecko\u002f41.0 Firefox\u002f41.0"
      }
    },
    "browserName": "firefox"
  },
  "capabilities": {
    "firstMatch": [
      {
        "browserName": "firefox",
        "moz:firefoxOptions": {
          "log": {
            "level": "debug"
          },
          "prefs": {
            "general.useragent.override": "Mozilla\u002f5.0 (Android 4.4; Mobile; rv:41.0) Gecko\u002f41.0 Firefox\u002f41.0"
          }
        }
      }
    ]
  }
}
1613591048418	geckodriver	INFO	Listening on 127.0.0.1:22676
1613591048428	mozrunner::runner	INFO	Running command: "/usr/bin/firefox" "--marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofileLLnSBR"
1613591048428	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:35051
[GFX1-]: glxtest: libpci missing
[GFX1-]: glxtest: libEGL missing
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
1613591049930	Marionette	DEBUG	Setting recommended pref apz.content_response_timeout to 60000
1613591049930	Marionette	DEBUG	Setting recommended pref browser.contentblocking.introCount to 99
1613591049930	Marionette	DEBUG	Setting recommended pref browser.download.panel.shown to true
1613591049930	Marionette	DEBUG	Setting recommended pref browser.newtabpage.enabled to false
1613591049931	Marionette	DEBUG	Setting recommended pref browser.pagethumbnails.capturing_disabled to true
1613591049931	Marionette	DEBUG	Setting recommended pref browser.search.update to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.tabs.disableBackgroundZombification to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.tabs.unloadOnLowMemory to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.tabs.warnOnOpen to false
1613591049932	Marionette	DEBUG	Setting recommended pref browser.toolbars.bookmarks.visibility to never
1613591049932	Marionette	DEBUG	Setting recommended pref browser.usedOnWindows10.introURL to 
1613591049932	Marionette	DEBUG	Setting recommended pref browser.urlbar.suggest.searches to false
1613591049933	Marionette	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1613591049933	Marionette	DEBUG	Setting recommended pref dom.disable_beforeunload to true
1613591049933	Marionette	DEBUG	Setting recommended pref dom.disable_open_during_load to false
1613591049933	Marionette	DEBUG	Setting recommended pref dom.file.createInChild to true
1613591049933	Marionette	DEBUG	Setting recommended pref dom.max_chrome_script_run_time to 0
1613591049933	Marionette	DEBUG	Setting recommended pref dom.max_script_run_time to 0
1613591049934	Marionette	DEBUG	Setting recommended pref dom.push.connection.enabled to false
1613591049934	Marionette	DEBUG	Setting recommended pref extensions.getAddons.cache.enabled to false
1613591049934	Marionette	DEBUG	Setting recommended pref extensions.getAddons.discovery.api_url to data:, 
1613591049935	Marionette	DEBUG	Setting recommended pref network.http.prompt-temp-redirect to false
1613591049935	Marionette	DEBUG	Setting recommended pref privacy.trackingprotection.enabled to false
1613591049935	Marionette	DEBUG	Setting recommended pref security.fileuri.strict_origin_policy to false
1613591049935	Marionette	DEBUG	Setting recommended pref security.notification_enable_delay to 0
1613591049935	Marionette	DEBUG	Setting recommended pref signon.autofillForms to false
1613591049936	Marionette	DEBUG	Setting recommended pref signon.rememberSignons to false
1613591049938	Marionette	INFO	Listening on port 35051
1613591049938	Marionette	DEBUG	Marionette is listening
1613591050043	Marionette	DEBUG	Remote agent not available for this build and platform
1613591050044	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:55946
1613591050045	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:35051.
1613591050049	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"browserName":"firefox"}]
1613591050058	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"b1722bec-39fd-4739-915e-eaf67844fa8f","capabilities":{"browserName":"firefox","browserVersion":"85.0. ... /rust_mozprofileLLnSBR","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
1613591050059	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"b1722bec-39fd-4739-915e-eaf67844fa8f","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"85.0.2","moz:accessibilityChecks":false,"moz:buildID":"20210208133944","moz:geckodriverVersion":"0.29.0","moz:headless":false,"moz:processID":71073,"moz:profile":"/tmp/rust_mozprofileLLnSBR","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"4.4.0-142-generic","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
1613591050059	Marionette	ERROR	[15] No reply from Marionette:Register

I don't see anything wierd there, though. And was wrong when I thought that the error depends from resources - it seems to occur always.

And that would be awesome if you'll add some mode to replace screenshot dumps in the log with just placeholders like [...tons of base64 skipped...]: I think, in most cases we don't need to dig through them.

@remorhaz
Copy link

By the way, how do I set marionette.log.level and marionette.actors.enable? With log level the following doesn't work:

{"moz:firefoxOptions": {"prefs": {"marionette.log.level": "debug"}}}

But the following works:

{"moz:firefoxOptions": {"log": {"level": "debug"}}}

So, how exactly should I set marionette.actors.enable?

@remorhaz
Copy link

I've also found marionette.log.truncate that should obviously help me with cutting screenshot dumps, but I still don't know, how to pass it to Marionette. I use Selenium, so the full chain is Selenium -> GeckoDriver -> Marionette, I guess.

@whimboo
Copy link
Collaborator

whimboo commented Feb 19, 2021

You have to pass it via the prefs like you pasted above:

{"moz:firefoxOptions": {"prefs": {"marionette.log.truncate": "true"}}}

This would also apply to the actors preference.

@remorhaz
Copy link

Aah, I see:

1613736149526	Marionette	DEBUG	0 <- [1,32,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABVAAAAODCAYAAABaBCrzAAAgAElEQVR4nOy9148j2X7nOe/3QfdFWA2ws4I0D3paPehhB/oLBEiCVsCO ... q8EHOqCi0HPcnMUoKxZqcpQVR6FvNAKzk0iq4t0mdwdquMHpAglb6XfpfHM8xLfo2eXw4VOz30LrfoU96p1VIOVKX7of8Hklbw0onp2ZYAAAAASUVORK5CYII="}]
1613736149539	webdriver::server	DEBUG	<- 200 OK {"value":"<here goes non-truncated dump>

Marionette truncates it's dump, but webdriver::server (probably it's GeckoDriver) doesn't, that's why I missed it. Is there a way to truncate GeckoDriver's dumps, too?

@whimboo
Copy link
Collaborator

whimboo commented Feb 19, 2021

Hm, the above preference or log setting should only affect Marionette but not geckodriver. Do you maybe pass -vv or --log TRACE to geckodriver itself?

@remorhaz
Copy link

Probably that's Selenium overriding the settings; I'll investigate that later. Anyway, I've succeeded to start my tests with marionette.actors.enable, it will take some time to get the logs.

@whimboo
Copy link
Collaborator

whimboo commented Mar 11, 2021

With Firefox 88 Nightly and Firefox 87 beta the code around Marionette:Register is no longer present. As such I'm going to close this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants