1384303 - Firefox 54 shutdown hang on MacOS not resolved by force quit

Status: RESOLVED WORKSFORME

(Firefox :: Untriaged, defect)

Description

[Liz Henry (:lizzard)]

(Filing this for sancarlosastro - lizzard.) On 7/23, I noticed that firefox was responding very slowly, and in the past killing the process through force quit was required.  To recap, I've noticed Firefox using a lot more RAM than I would expect, like more than 5 GB.  A normal quit under those conditions would not succeed, evidenced by these four things after a normal quit attempt:

    The Firefox icon in the OSX dock still had an indicator "light" under it.  Long clicking on the Firefox icon in the dock would bring up the Quit/Hide/Show-All-Windows contextual menu, and instead of "quit" the option changed to "force quit."  Selecting "force quit" had no effect.
    Clicking on Apple/force-quit" gave no error but had no impact.  The Firefox process remained on the list of processes that could be forced to quit.
    Firefox was no longer visible on the OSX Activity Monitor, and could not be seen using the CLI utility "top" and "sudo ps Ax | grep fox" (or any other reasonable search string as in firefox, Fire, etc.).
    Attempts to start Firefox failed because the "profile was in use."

When the above happens, the only way to get things working is a reboot of my Mac.

On the 23rd, I collected a lot of data and it is attached to this email.  Several of the attachments are screen shots that show information that's not readily available anywhere else.  Notably, a few of the screen captures show that Firefox had a recent hang count of 3.  When Firefox becomes impossible to quit/force-quit, I've seen the recent hang count to be at least 17 and increasing.

I suspect that Firefox thinks the profile is in use after a force-quit because of some lockfile that is left behind.  The Activity Monitor will show all of the processes open files, but in a scrollable region that refuses to be "selected" long enough for even a quick Select-All and an immediate Copy.  So I used the Mac OSX CLI to list relevant open files with this command: "lsof | grep firefox > lsof-grep-firefox-20170723.txt" and I've included that info as an attachment to this message.

Finally, I used the "Sample" feature to collect info on every stat which that feature can collect.  I saved that to a file which is attached and is titled "lsof-grep-firefox-20170723.txt"

On the 23rd, Firefox did "force quit" and it did complain about Firefox Shockwave Flash Plugin Quit Unexpectedly, and I'm willing to disable that plugin to see if it is any help.  It may be part of the cause of the problem, but I have no way to rule out that the plugin quit simply because I Force-Quit Firefox.

Two weeks ago, I build Firefox Nightly 54.01 (and later 54.02) hoping that a locally built copy might behave better, but it exhibited exactly the same problem.  For performance reasons, those were not debug builds but my nextt step will be to create a debug build of the production 54.01 to see if I can collect a crash dump.

Even though I got Firefox to force quit, no report was generated and the often seen error message asking me to report the crash to Mozilla, and my "crash history" on the Firefox Health Report web page (about:healthreport) does not show any of these crashes.

Any guidance would be appreciated.  My plan is to do a local debug build of 54.01 and see if it yields something useful.

Thanks for your help!

Comment 1

[:Gijs (he/him)]

Liz, can you attach the files mentioned in comment #0?

Comment 2

[Liz Henry (:lizzard)]

I emailed them to you rather than attach so much info to the bug (Not sure if the logs have any personal info).

Comment 3

[Ron Sidell]

Finally, Firefox crashed and generated a crash report.  It can be found at:
https://crash-stats.mozilla.com/report/index/bp-7925099b-c2fb-40da-a304-f7f5c0170727

Comment 4

[Ron Sidell]

Ah, forgot to mention, I am [e-mail]
Thanks everyone for your help on this.
Ron

Comment 5

[Kohei Yoshino [:kohei]]

Apparently your have many extensions installed. Please troubleshoot with Safe Mode with extensions disabled: https://support.mozilla.org/kb/troubleshoot-firefox-issues-using-safe-mode

Comment 6

[:Gijs (he/him)]

Attachment: Sample of Firefox.txt

This is the sample from activity monitor that Liz forwarded for Ron. It only contains stack traces from Firefox (much like the crash report) sampled at 1ms intervals, no personal information, so I think I'm OK attaching this. Unfortunately, some of the stack traces lack symbols (ie readable method names etc.) so I don't really know what to make of these. I already added the [qf] whiteboard tag earlier, so hopefully folks who *can* make sense of the sample will be along sometime in the next week or two with more questions/suggestions/solutions.

Ron: in the lsof file (which I'm not attaching because it does have information that might be considered private), Firefox still has lots of files open. I'm a little confused as to whether you're saying firefox is no longer listed in `top` at this point? What about `plugin-container`, do you see any processes matching that? In any case it's kind of weird because lsof clearly shows a 'firefox' process holding all these files and connections...

Rather than rebooting your mac, if you look in the lsof list you'll see a file called .parentlock. This is the file that causes the 'profile in use' warning, so once firefox is conclusively not running on the machine, removing that file should allow you to start it up again.


Of course, none of that really helps in establishing why the hang is happening in the first place, though I do agree with comment #5 in that the add-ons might have something to do with it. We're already working on better isolation of add-ons so that they don't interfere with Firefox in the same way (coming in 57), but in the meantime it might be worth trying to see if disabling some of them helps with narrowing down the cause to be correlated to one or more of those add-ons.

Comment 7

[Andrew Overholt [:overholt]]

Is this the same as bug 1384197 (which was duped to bug 1383742)?

Ehsan can probably take a look at the info here to see if this is indeed a [qf]-like bug, but for now the Quantum Flow triage consensus was qf-. Obviously that can change :)

Comment 8

[(no longer active)]

As Gijs mentioned, attachment 8890769 [details] is lacking symbols so unfortunately it's impossible to say anything about what was happening from it.

(In reply to Andrew Overholt [:overholt] from comment #7)
> Is this the same as bug 1384197 (which was duped to bug 1383742)?

All shutdown hangs have very similar symptoms but can have vastly different causes.  Bug 1383742 is a recent Nightly regression so I very much doubt this is related to it.

Ron, if possible, can you please go to about:crashes in Firefox and see if there is any recent submitted crash reports listed there?  If yes, I'd appreciate if you can click on them and paste the links here.  Thanks!

Comment 9

[Ron Sidell]

There are no new crashes since the one I linked to a few days ago, at: https://crash-stats.mozilla.com/report/index/bp-7925099b-c2fb-40da-a304-f7f5c0170727

Report ID 	                                        Date Submitted
bp-7925099b-c2fb-40da-a304-f7f5c0170727          	7/26/17	5:45 PM

I've been running the release version of 54.01, and I'll do the following:
1. turn off all plugins that are not required for my normal use, including flash
2. I'll build a debug version of firefox-release and use it for further testing
3. I can launch Firefox from a terminal window, sometime that reveals some error info not shown elsewhere, I think (please correct me if I'm wrong about this).

Comment 10

[(no longer active)]

(In reply to Ron Sidell from comment #9)
> There are no new crashes since the one I linked to a few days ago, at:
> https://crash-stats.mozilla.com/report/index/bp-7925099b-c2fb-40da-a304-
> f7f5c0170727

That seems to be the signature of bug 1251615.

> Report ID 	                                        Date Submitted
> bp-7925099b-c2fb-40da-a304-f7f5c0170727          	7/26/17	5:45 PM
> 
> I've been running the release version of 54.01, and I'll do the following:
> 1. turn off all plugins that are not required for my normal use, including
> flash
> 2. I'll build a debug version of firefox-release and use it for further
> testing
> 3. I can launch Firefox from a terminal window, sometime that reveals some
> error info not shown elsewhere, I think (please correct me if I'm wrong
> about this).

Is this a problem that you can reproduce?  If yes then if you can do the the above steps that would be really helpful.  Another helpful thing to do would be to use http://mozilla.github.io/mozregression/ to find a regression range for when this problem started occurring.  For example if this started to happen in 54 but 53 was unaffected, sometimes using that tool allows you to narrow this issue down to the exact code change that introduced the issue for the first time, and the mozregression tool does the hard work of downloading the builds and running them for you (of course this only works if you have a relatively easy way to reproduce the issue.)

Comment 11

[Ron Sidell]

No, I cannot cause this problem to happen on demand, I am sorry to say.  But I have experienced another crash. The crash can be found at:
Submitted Crash Reports
Report ID 	                                   Date Submitted
bp-d14075b4-c196-44b8-8051-c76f00170801            8/1/17	12:20 PM
 
More info:
1. I turned off every plugin that I could "live without" but that still leaves a handful of plugins that might be causing the problem.  If needed, I could turn off a few more, or even all of them.  Though if I turn them all off, it will limit how much use I can get out of Firefox.

2. Then I used mercurial to download source using: hg clone https://hg.mozilla.org/releases/mozilla-release mozilla-release

3. Next, I created a minimal .mozconfig that enabled the debug flag:  ac_add_options --enable-debug

>>>>>Note, in the info below, I have typed $FFPATH in place of the path prefix, to save space on the screen and to simplify the output. <<<<<<

4. Then I built Firefox using: ./mach build
   This built Nightly 54.0.2, though I expected the release repo to build the current release, 54.0.1 by default.  If this turns out to be a problem please let me know (I could use a hint as to which hg command to use to select 54.0.1 :p )

5. Finally, I started the new debug build from the Mac CLI using: $FFPATH/mozilla-release/obj-ff-dbg/dist/NightlyDebug.app/Contents/MacOS/firefox-bin -p &

6. After it crashed, I copied the output from the terminal window to a file, which is 497KB in size.  I'll upload it here if that would be helpful.  There are a huge number of lines in that file that look just like these:
[1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
[1345] WARNING: Fix the caller!: file $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
[1345] WARNING: Fix the caller!: file $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
[1345] WARNING: Fix the caller!: file $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
[1345] WARNING: Fix the caller!: file $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
[1345] WARNING: Fix the caller!: file $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673

7.  The last few lines of output (in the same terminal window mentioned above) leading up to the crash are:
[1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
[1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch), at $FFPATH/mozilla-release/toolkit/components/autocomplete/nsAutoCompleteController.cpp:860
#01: non-virtual thunk to nsAutoCompleteController::OnSearchResult(nsIAutoCompleteSearch*, nsIAutoCompleteResult*)[$FFPATH/mozilla-release/obj-ff-dbg/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3e10dcd]
#02: non-virtual thunk to nsFormFillController::OnSearchCompletion(nsIAutoCompleteResult*)[$FFPATH/mozilla-release/obj-ff-dbg/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3e1cd17]

Since I can't yet trigger the crash, it seems that running http://mozilla.github.io/mozregression/ won't be very helpful.  But I'm willing to do that if asked.

One of my hobbies, and possibly a strength of mine, is in troubleshooting intermittent, hard to reproduce failure modes for both software and  hardware. This latest crash happened sooner than I expected, and I had several things going on on my computer that I suspect are triggering the crash.  I'll keep trying to narrow it down so that I can cause the crash "on demand."  My feeling is that the problem happens when my computer is low on free RAM, and possibly when I have a tab open to a page that has poorly behaving Javascript code.  When memory is low, it's because I'm running multiple VMWare VMs alongside Firefox (and Thunderbird) and a collection of apps that help me get things done.  Any suggestions on how to trigger the problem will be gratefully accepted.

Comment 12

[:Gijs (he/him)]

(In reply to Ron Sidell from comment #11)
> No, I cannot cause this problem to happen on demand, I am sorry to say.  But
> I have experienced another crash. The crash can be found at:
> Submitted Crash Reports
> Report ID 	                                   Date Submitted
> bp-d14075b4-c196-44b8-8051-c76f00170801            8/1/17	12:20 PM
>  
> More info:
> 1. I turned off every plugin that I could "live without" but that still
> leaves a handful of plugins that might be causing the problem.  If needed, I
> could turn off a few more, or even all of them.  Though if I turn them all
> off, it will limit how much use I can get out of Firefox.
> 
> 2. Then I used mercurial to download source using: hg clone
> https://hg.mozilla.org/releases/mozilla-release mozilla-release
> 
> 3. Next, I created a minimal .mozconfig that enabled the debug flag: 
> ac_add_options --enable-debug
> 
> >>>>>Note, in the info below, I have typed $FFPATH in place of the path prefix, to save space on the screen and to simplify the output. <<<<<<
> 
> 4. Then I built Firefox using: ./mach build
>    This built Nightly 54.0.2, though I expected the release repo to build
> the current release, 54.0.1 by default.  If this turns out to be a problem
> please let me know (I could use a hint as to which hg command to use to
> select 54.0.1 :p )
> 
> 5. Finally, I started the new debug build from the Mac CLI using:
> $FFPATH/mozilla-release/obj-ff-dbg/dist/NightlyDebug.app/Contents/MacOS/
> firefox-bin -p &
> 
> 6. After it crashed, I copied the output from the terminal window to a file,
> which is 497KB in size.  I'll upload it here if that would be helpful. 
> There are a huge number of lines in that file that look just like these:
> [1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005:
> file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
> [1345] WARNING: Fix the caller!: file
> $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
> [1345] WARNING: Fix the caller!: file
> $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
> [1345] WARNING: Fix the caller!: file
> $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
> [1345] WARNING: Fix the caller!: file
> $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
> [1345] WARNING: Fix the caller!: file
> $FFPATH/mozilla-release/dom/events/EventDispatcher.cpp, line 673
> 
> 7.  The last few lines of output (in the same terminal window mentioned
> above) leading up to the crash are:
> [1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005:
> file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
> [1345] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005:
> file $FFPATH/mozilla-release/chrome/nsChromeRegistry.cpp, line 212
> Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch), at
> $FFPATH/mozilla-release/toolkit/components/autocomplete/
> nsAutoCompleteController.cpp:860
> #01: non-virtual thunk to
> nsAutoCompleteController::OnSearchResult(nsIAutoCompleteSearch*,
> nsIAutoCompleteResult*)[$FFPATH/mozilla-release/obj-ff-dbg/dist/NightlyDebug.
> app/Contents/MacOS/XUL +0x3e10dcd]
> #02: non-virtual thunk to
> nsFormFillController::OnSearchCompletion(nsIAutoCompleteResult*)[$FFPATH/
> mozilla-release/obj-ff-dbg/dist/NightlyDebug.app/Contents/MacOS/XUL
> +0x3e1cd17]

This looks like a fatal assertion, which happens because it's a debug build. You could just build an opt build. You should still get decent stacktraces when you crash, but Firefox will be a lot more usable that way...

In the meantime, we've also released Firefox 55. Are things any better with that version?

Comment 13

[:Gijs (he/him)]

Alternatively, you could replace everything but line 450 in this block: https://dxr.mozilla.org/mozilla-release/rev/710711a481286f27b81df2e4b082d48829510633/mfbt/Assertions.h#447-451 , and then rebuild.

(In reply to Ron Sidell from comment #11)
> No, I cannot cause this problem to happen on demand, I am sorry to say.  But
> I have experienced another crash. The crash can be found at:
> Submitted Crash Reports
> Report ID 	                                   Date Submitted
> bp-d14075b4-c196-44b8-8051-c76f00170801            8/1/17	12:20 PM

FWIW, this looks like a content process being killed by the parent process, not a crash of the parent process. :-(

Comment 14

[Ron Sidell]

Firefox 55 seems to work without any problem. I am slowly re-enabling my add-ons (extensions) one by one, but so far so good.

In the future, I'll use opt builds to get useful crash info, thanks for the suggestion.

Comment 15

[:Gijs (he/him)]

OK, so I will tentatively resolve as "works for me" per comment #14. We can reopen if the problem reoccurs on current versions of Firefox and/or more information comes to light.