Firefox hangs during "Skipping background update check" #1295

cb-salaikumar · 2018-06-12T08:18:35Z

System

Version: geckodriver version :v0.20.0
Platform: Linux / Ubuntu
Firefox: 59.0.1,59.0.2,60
Selenium:3.11, 3.12

Testcase

Create a instance of FirefoxDriver.
Open any url.
Do some navigations.

Points to note:

Firefox will hang whenever it tries to skip the background update check. Please note the issue is random.

I'm not sure of the order in which Firefox invokes its background task. But If "Skipping background update check" happens at any point during QA execution, Firefox hangs 99%.

Minimal Log

[java] 1528782119942 addons.manager INFO Skipping background update check

It is not proceeding after this line.
I tried setting the Log level to TRACE. But no help. There is no extra information regarding this error.

Firefox Driver Configurations

        FirefoxOptions caps = new FirefoxOptions();
        caps.setCapability("marionette", true);       
        caps.setPageLoadStrategy(PageLoadStrategy.NORMAL);
        LoggingPreferences logs = new LoggingPreferences();
        logs.enable(LogType.DRIVER, Level.FINEST); 
        logs.enable(LogType.BROWSER, Level.FINEST);
        logs.enable(LogType.CLIENT, Level.FINEST);
        logs.enable(LogType.SERVER, Level.FINEST);
        caps.setCapability(CapabilityType.LOGGING_PREFS, logs);
        
        caps.setProfile(firefoxProfile);
        caps.setLogLevel(FirefoxDriverLogLevel.INFO);
        caps.addPreference("app.update.enabled", false);
        caps.addPreference("app.update.auto", false);
        caps.addPreference("app.update.staging.enabled", false);
        caps.addPreference("extensions.update.enabled", false);
        caps.addPreference("extensions.update.autoUpdateDefault", false);
        caps.addPreference("media.gmp-provider.enabled", false);
        return new FirefoxDriver(caps);

Stacktrace

NA

Trace-level log

1527680019256	addons.xpi	DEBUG	Updating database with changes to installed add-ons
1527680019256	addons.xpi-utils	DEBUG	Updating add-on states
1527680019264	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/activity-stream@mozilla.org.xpi
1527680019264	addons.xpi	DEBUG	Calling bootstrap method startup on activity-stream@mozilla.org version 2018.02.17.0026-173e2795
1527680019266	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/aushelper@mozilla.org.xpi
1527680019266	addons.xpi	DEBUG	Calling bootstrap method startup on aushelper@mozilla.org version 2.0
1527680019266	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/firefox@getpocket.com.xpi
1527680019268	addons.xpi	DEBUG	Calling bootstrap method startup on firefox@getpocket.com version 1.0.5
1527680019278	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/followonsearch@mozilla.com.xpi
1527680019278	addons.xpi	DEBUG	Calling bootstrap method startup on followonsearch@mozilla.com version 0.9.6
1527680019278	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/formautofill@mozilla.org.xpi
1527680019278	addons.xpi	DEBUG	Calling bootstrap method startup on formautofill@mozilla.org version 1.0
1527680019280	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/onboarding@mozilla.org.xpi
1527680019280	addons.xpi	DEBUG	Calling bootstrap method startup on onboarding@mozilla.org version 1.0
1527680019280	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/screenshots@mozilla.org.xpi
1527680019280	addons.xpi	DEBUG	Calling bootstrap method startup on screenshots@mozilla.org version 25.0.0
1527680019282	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/shield-recipe-client@mozilla.org.xpi
1527680019282	addons.xpi	DEBUG	Calling bootstrap method startup on shield-recipe-client@mozilla.org version 80
1527680019288	addons.xpi	DEBUG	Registering manifest for /usr/lib/firefox/browser/features/webcompat@mozilla.org.xpi
1527680019290	addons.xpi	DEBUG	Calling bootstrap method startup on webcompat@mozilla.org version 1.1
1527680019292	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
1527680019292	addons.manager	DEBUG	Provider finished startup: XPIProvider
1527680019292	addons.manager	DEBUG	Starting provider: LightweightThemeManager
1527680019294	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager
1527680019294	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager
1527680019294	addons.manager	DEBUG	Starting provider: GMPProvider
1527680019296	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider
1527680019296	addons.manager	DEBUG	Provider finished startup: GMPProvider
1527680019296	addons.manager	DEBUG	Starting provider: PluginProvider
1527680019296	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider
1527680019298	addons.manager	DEBUG	Provider finished startup: PluginProvider
1527680019298	addons.manager	DEBUG	Completed startup sequence
1527680019316	Marionette	DEBUG	Received observer notification "profile-after-change"
1527680019347	geckodriver::marionette	TRACE	  connection attempt 7/600
1527680019380	Marionette	DEBUG	Received observer notification "command-line-startup"
1527680019380	Marionette	INFO	Enabled via --marionette

(firefox:3584): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(firefox:3584): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed

(firefox:3584): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(firefox:3584): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed

(firefox:3584): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(firefox:3584): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed
1527680019447	geckodriver::marionette	TRACE	  connection attempt 8/600
1527680019547	geckodriver::marionette	TRACE	  connection attempt 9/600
1527680019580	addons.manager	DEBUG	Starting provider: PreviousExperimentProvider
1527680019580	addons.manager	DEBUG	Registering shutdown blocker for PreviousExperimentProvider
1527680019580	addons.manager	DEBUG	Provider finished startup: PreviousExperimentProvider
1527680019648	geckodriver::marionette	TRACE	  connection attempt 10/600
1527680019748	geckodriver::marionette	TRACE	  connection attempt 11/600
1527680019849	geckodriver::marionette	TRACE	  connection attempt 12/600
1527680019949	geckodriver::marionette	TRACE	  connection attempt 13/600
1527680020050	geckodriver::marionette	TRACE	  connection attempt 14/600
1527680020150	geckodriver::marionette	TRACE	  connection attempt 15/600
1527680020251	geckodriver::marionette	TRACE	  connection attempt 16/600

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_ref: assertion 'object->ref_count > 0' failed

(/usr/lib/firefox/firefox:3632): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed
1527680020351	geckodriver::marionette	TRACE	  connection attempt 17/600
1527680020451	geckodriver::marionette	TRACE	  connection attempt 18/600
1527680020552	geckodriver::marionette	TRACE	  connection attempt 19/600
1527680020652	geckodriver::marionette	TRACE	  connection attempt 20/600
1527680020706	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 24
1527680020753	geckodriver::marionette	TRACE	  connection attempt 21/600
1527680020853	geckodriver::marionette	DEBUG	Connected to Marionette on localhost:46819
1527680021012	Marionette	DEBUG	Received observer notification "sessionstore-windows-restored"
1527680021038	addons.xpi	INFO	Mapping activity-stream@mozilla.org to /usr/lib/firefox/browser/features/activity-stream@mozilla.org.xpi
1527680021038	addons.xpi	INFO	Mapping aushelper@mozilla.org to /usr/lib/firefox/browser/features/aushelper@mozilla.org.xpi
1527680021040	addons.xpi	INFO	Mapping firefox@getpocket.com to /usr/lib/firefox/browser/features/firefox@getpocket.com.xpi
1527680021040	addons.xpi	INFO	Mapping followonsearch@mozilla.com to /usr/lib/firefox/browser/features/followonsearch@mozilla.com.xpi
1527680021040	addons.xpi	INFO	Mapping formautofill@mozilla.org to /usr/lib/firefox/browser/features/formautofill@mozilla.org.xpi
1527680021040	addons.xpi	INFO	Mapping onboarding@mozilla.org to /usr/lib/firefox/browser/features/onboarding@mozilla.org.xpi
1527680021040	addons.xpi	INFO	Mapping screenshots@mozilla.org to /usr/lib/firefox/browser/features/screenshots@mozilla.org.xpi
1527680021040	addons.xpi	INFO	Mapping shield-recipe-client@mozilla.org to /usr/lib/firefox/browser/features/shield-recipe-client@mozilla.org.xpi
1527680021040	addons.xpi	INFO	Mapping webcompat@mozilla.org to /usr/lib/firefox/browser/features/webcompat@mozilla.org.xpi
1527680021040	addons.xpi	DEBUG	Existing add-on activity-stream@mozilla.org in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on aushelper@mozilla.org in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on firefox@getpocket.com in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on followonsearch@mozilla.com in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on formautofill@mozilla.org in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on onboarding@mozilla.org in app-system-defaults
1527680021042	addons.xpi	DEBUG	Existing add-on screenshots@mozilla.org in app-system-defaults
1527680021044	addons.xpi	DEBUG	Existing add-on shield-recipe-client@mozilla.org in app-system-defaults
1527680021044	addons.xpi	DEBUG	Existing add-on webcompat@mozilla.org in app-system-defaults
1527680021044	addons.xpi	INFO	Mapping {972ce4c6-7e08-4474-a285-3208198ce6fd} to /usr/lib/firefox/browser/extensions/{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi
1527680021044	addons.xpi	DEBUG	Existing add-on {972ce4c6-7e08-4474-a285-3208198ce6fd} in app-global
1527680021044	addons.xpi	DEBUG	getInstallState changed: false, state: {}
1527680021268	Marionette	DEBUG	Setting recommended pref browser.newtabpage.introShown to true
1527680021270	Marionette	DEBUG	Setting recommended pref toolkit.cosmeticAnimations.enabled to false
1527680021270	Marionette	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1527680041044	addons.productaddons	INFO	sending request to: https://aus5.mozilla.org/update/3/GMP/59.0.1/20180316021857/Linux_x86_64-gcc3/null/release-cck-ubuntu/Linux%203.13.0-65-generic%20(GTK%203.10.8%2Clibpulse%204.0.0)/canonical/1.0/update.xml
1527680041422	addons.productaddons	INFO	Completed downloading document
1527680041638	addons.productaddons	INFO	downloadXHR File download. status=200
1527680041642	addons.productaddons	INFO	Downloaded file will be saved to /tmp/tmpaddon-2989ec
1527680409392	addons.manager	INFO	Skipping background update check

The text was updated successfully, but these errors were encountered:

andreastt · 2018-06-12T18:46:06Z

I don’t think it’s hanging because the addons manager skips the background update check, but it’s hard to tell what’s going on without a complete trace-level log. Could you pastebin the entire thing?

cb-salaikumar · 2018-06-13T07:50:36Z

@andreastt Sure. Will take a trace level log and update it.

whimboo · 2018-06-18T03:14:58Z

@cb-salaikumar when you create the trace log please use a debug build of Firefox Nightly. It gives way more info about possible hangs in case it appears in Firefox itself. You can download a latest linux64 build from https://queue.taskcluster.net/v1/task/aPs7fAdKTV2f_L7SdMlV9A/runs/0/artifacts/public/build/target.tar.bz2.

cb-salaikumar · 2018-07-24T13:22:15Z

I was able to get the trace level log for the same issue.

In this case, the FF had hanged at the beginning of execution.

whimboo · 2018-07-24T13:33:06Z

@cb-salaikumar are you using this version of Firefox with a different profile too? If yes, I assume it has automatic updates enabled? So did you download an update but haven't applied it to Firefox yet before starting the Selenium test?

cb-salaikumar · 2018-07-24T13:56:22Z

@whimboo I was not able to test it with FF nightly build as mentioned by you. Will try it out. The trace level log was taken using "Mozilla Firefox 59.0.1". And, you had mentioned about disabling SystemAddon update in the issue #1290 . Let me try it out and see if the issue persists.

    FirefoxProfile firefoxProfile = new FirefoxProfile();
    firefoxProfile.setPreference("browser.download.folderList", 2);
    firefoxProfile.setPreference("browser.download.manager.showWhenStarting", false);
    firefoxProfile.setPreference("browser.download.dir", dloadDir.getAbsolutePath());
    firefoxProfile.setPreference("browser.helperApps.neverAsk.saveToDisk", "text/csv,text/html,application/zip");

    FirefoxOptions caps = new FirefoxOptions();
    caps.setCapability("marionette", true);       
    caps.setPageLoadStrategy(PageLoadStrategy.NORMAL);
    caps.setHeadless(true);
    caps.setProfile(firefoxProfile);
    caps.setLogLevel(FirefoxDriverLogLevel.Trace);
    caps.addPreference("app.update.enabled", false);
    caps.addPreference("app.update.auto", false);
    caps.addPreference("app.update.staging.enabled", false);
    caps.addPreference("extensions.update.enabled", false);
    caps.addPreference("extensions.update.autoUpdateDefault", false);
    caps.addPreference("media.gmp-provider.enabled", false);

The above are my settings I use for creating a FF driver. I will add the preference you had mentioned earlier in the issue #1290 . Anything else needs to be disabled?

whimboo · 2018-07-24T17:35:06Z

@cb-salaikumar, not sure why you are referring to issue #1290. This is not related to yours. Please answer my questions from the last comment. Thanks.

cb-salaikumar · 2018-07-25T17:20:12Z

@whimboo , I had added trace level logs from two of our test machines and few notes on it.

Machine 1:
Full_stack_trace_log.txt

After FF launch, it got struck at this point for pretty long time. One observation is I don't see the "Skipping background update check" line at all in the log. But it got hanged at the point mentioned in the log.

Machine 2:
Machine_2_trace_log.txt

But in Machine 2, the following exception had occurred. We usually make multiple attempts in case if such exceptions had occurred. Finally a valid session got created. But again, it got hanged at the same point as in machine 1.

[java] 1532527683293 webdriver::server DEBUG -> GET /session/be67f958-4fac-4d27-853a-b6c7e785f07d/title
[java] 1532527683293 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Tried to run command without establishing a connection","stacktrace":""}}
[java] org.openqa.selenium.SessionNotCreatedException: Tried to run command without establishing a connection
[java] Build info: version: '3.11.0', revision: 'e59cfb3', time: '2018-03-11T20:33:08.638Z'
[java] System info: host: 'ip-172-31-81-34', ip: '172.31.81.34', os.name: 'Linux', os.arch: 'amd64', os.version: '3.13.0-65-generic', java.version: '1.8.0_144'
[java] Driver info: org.openqa.selenium.firefox.FirefoxDriver
[java] Capabilities {acceptInsecureCerts: true, browserName: firefox, browserVersion: 62.0a1, javascriptEnabled: true, moz:accessibilityChecks: false, moz:headless: false, moz:processID: 2426, moz:profile: /tmp/rust_mozprofile.2Ca1TT..., moz:useNonSpecCompliantPointerOrigin: false, moz:webdriverClick: true, pageLoadStrategy: normal, platform: LINUX, platformName: LINUX, platformVersion: 3.13.0-65-generic, rotatable: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}}
[java] Session ID: be67f958-4fac-4d27-853a-b6c7e785f07d
[java] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[java] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
[java] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[java] at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
[java] at org.openqa.selenium.remote.http.W3CHttpResponseCodec.createException(W3CHttpResponseCodec.java:187)
[java] at org.openqa.selenium.remote.http.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:122)
[java] at org.openqa.selenium.remote.http.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:49)
[java] at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:158)
[java] at org.openqa.selenium.remote.service.DriverCommandExecutor.execute(DriverCommandExecutor.java:83)
[java] at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:545)
[java] at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:602)
[java] at org.openqa.selenium.remote.RemoteWebDriver.getTitle(RemoteWebDriver.java:277)
[java] at com.chargebee.qa.core.SeleniumBase.isDriverAlive(SeleniumBase.java:171)
[java] at com.chargebee.qa.core.internal.CBMethodInterceptor.intercept(CBMethodInterceptor.java:33)
[java] at org.testng.TestRunner.createClassBasedParallelWorkers(TestRunner.java:858)
[java] at org.testng.TestRunner.createWorkers(TestRunner.java:824)
[java] at org.testng.TestRunner.privateRun(TestRunner.java:771)
[java] at org.testng.TestRunner.run(TestRunner.java:623)
[java] at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
[java] at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
[java] at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
[java] at org.testng.SuiteRunner.run(SuiteRunner.java:259)
[java] at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
[java] at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
[java] at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
[java] at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
[java] at org.testng.TestNG.run(TestNG.java:1018)

whimboo · 2018-07-27T07:43:59Z

Can you still please answer my questions from 3 days ago as those can be found here: #1295 (comment) ? Those are related to any outside of automation interaction with Firefox. Thanks.

cb-salaikumar · 2018-07-27T13:03:28Z

Are you using this version of Firefox with a different profile too? If yes, I assume it has automatic updates enabled?
--> We just create a profile during automation and use the same for testing. Other than Selenium tests, we don't launch firefox for any reason in the test machines. And the machines are headless,used only for testing.

So did you download an update but haven't
applied it to Firefox yet before starting the Selenium test?

--> I'm not sure on this part. We run our qa in headless servers using Xvfb as mentioned. I assume you're talking about FireFox auto updates on its launch if check for updates is enabled. I can't surely say if there is an update downloaded and not installed.

After firefox installed , we will just do a firefox -v to see the version installed. Other than that, we don't launch firefox. Probably as background using "firefox &" to check if is running properly.

Could you please point me in right directions to check these?

I would like to know Why are you looking into such areas? Is there anything wrong in the log? Given that, I would be able to give more information.

One additional information would be, Firefox doesn't hang in all machines. But it occurs whenever "Skipping background update check" happens during the launch of Firefox. If it happens during test cases execution, it is will not have an issue. And when I see logs on machines in which Firefox launched properly, I don't see "Skipping background update check" during the launch of Firefox.

Adding a log in which Firefox launch doesn't had any issues to see the difference in the log.

Working FF Log
Working_FF_Log.txt

Usually after this "WARN TLS certificate errors will be ignored for this session" part, "Skipping background update check" will happen and FF will hang.

whimboo · 2018-08-02T11:58:03Z

We just create a profile during automation and use the same for testing

So it means you create a profile with Selenium, and pass that over to geckodriver? If yes, can you please remove that code, and check if Firefox gets correctly started on those affected machines if geckodriver itself creates the profile?

whimboo · 2018-09-03T07:56:35Z

No reply from reporter. Closing issue.

lock · 2019-08-16T17:54:47Z

This issue has been automatically locked since there has not been any recent activity after it was closed. If you have run into an issue you think is related, please open a new issue.

andreastt added the awaiting reporter feedback label Jun 13, 2018

whimboo mentioned this issue Jun 18, 2018

Connection refused error because the GFX sanity window of Firefox isn't closing #1290

Closed

This comment has been minimized.

Sign in to view

whimboo closed this as completed Sep 3, 2018

lock bot locked and limited conversation to collaborators Aug 16, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Firefox hangs during "Skipping background update check" #1295

Firefox hangs during "Skipping background update check" #1295

cb-salaikumar commented Jun 12, 2018 •

edited by AutomatedTester

Loading

andreastt commented Jun 12, 2018

cb-salaikumar commented Jun 13, 2018

whimboo commented Jun 18, 2018

cb-salaikumar commented Jul 24, 2018

whimboo commented Jul 24, 2018

cb-salaikumar commented Jul 24, 2018

whimboo commented Jul 24, 2018

cb-salaikumar commented Jul 25, 2018

whimboo commented Jul 27, 2018

cb-salaikumar commented Jul 27, 2018

This comment has been minimized.

whimboo commented Aug 2, 2018

whimboo commented Sep 3, 2018

lock bot commented Aug 16, 2019

Firefox hangs during "Skipping background update check" #1295

Firefox hangs during "Skipping background update check" #1295

Comments

cb-salaikumar commented Jun 12, 2018 • edited by AutomatedTester Loading

System

Testcase

Points to note:

Minimal Log

Firefox Driver Configurations

Stacktrace

Trace-level log

andreastt commented Jun 12, 2018

cb-salaikumar commented Jun 13, 2018

whimboo commented Jun 18, 2018

cb-salaikumar commented Jul 24, 2018

whimboo commented Jul 24, 2018

cb-salaikumar commented Jul 24, 2018

whimboo commented Jul 24, 2018

cb-salaikumar commented Jul 25, 2018

whimboo commented Jul 27, 2018

cb-salaikumar commented Jul 27, 2018

This comment has been minimized.

whimboo commented Aug 2, 2018

whimboo commented Sep 3, 2018

lock bot commented Aug 16, 2019

cb-salaikumar commented Jun 12, 2018 •

edited by AutomatedTester

Loading