1653908 - Crash in [@ PLDHashTable::Add | nsBaseHashtable<T>::Put | Parser::Parse]

Status: RESOLVED WORKSFORME

(Core :: Preferences: Backend, defect, P1)

Description

[Gabriele Svelto [:gsvelto]]

This bug is for crash report bp-14041536-565e-4a1c-80c6-2af2e0200718.

Top 10 frames of crashing thread:

0 xul.dll PLDHashTable::Add xpcom/ds/PLDHashTable.cpp:509
1 xul.dll nsBaseHashtable<nsCStringHashKey, TelemetryLoadData, TelemetryLoadData, nsDefaultConverter<TelemetryLoadData, TelemetryLoadData> >::Put xpcom/ds/nsBaseHashtable.h:177
2 xul.dll Parser::Parse modules/libpref/Preferences.cpp:1773
3 xul.dll mozilla::openPrefFile modules/libpref/Preferences.cpp:4191
4 xul.dll mozilla::Preferences::ReadSavedPrefs modules/libpref/Preferences.cpp:4003
5 xul.dll static mozilla::Preferences::InitializeUserPrefs modules/libpref/Preferences.cpp:3678
6 xul.dll nsXREDirProvider::InitializeUserPrefs toolkit/xre/nsXREDirProvider.cpp:878
7 xul.dll XREMain::XRE_mainRun toolkit/xre/nsAppRunner.cpp:4486
8 xul.dll XREMain::XRE_main toolkit/xre/nsAppRunner.cpp:4868
9 xul.dll XRE_main toolkit/xre/nsAppRunner.cpp:4922

This is an odd crash, and not a new one, we have reports going back six months. If I'm reading the stack correctly gTelemetryLoadData is NULL here. The crashing address is always 0x4 or 0x8 depending on the build which is the offset of the mEntry field of PLDHashTable.

However gTelemetryLoadData should be initialized when the prefs service is instanced, so how is it possible that it's still NULL at this point?

Comment 1

[Gabriele Svelto [:gsvelto]]

Also my bad, the crashes don't go back six months but a little less. This seems to have started in the beta channel with buildid 20200210140608. It does not seem to happen on desktop nightly at all but we have a few nightly crashes from Fenix. Maybe we hit an assertion on nightly desktop before getting to this point? Or maybe the volume is just too low.

Comment 2

[BugBot [:suhaib / :marco]]

The severity field is not set for this bug.
:njn, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 3

[Julien Cristau [:jcristau] (back August 18)]

There's quite a few of those startup crashes in 80.0 beta.

Comment 4

[Sylvestre Ledru [:Sylvestre]]

Nick is off. 302 then
David, Gabriele, is there anything we can do here? thanks

Comment 5

[Gabriele Svelto [:gsvelto]]

Oh wow, this got a lot worse than when I filed it. I'll dig a bit further.

Comment 6

[Gabriele Svelto [:gsvelto]]

I cracked open a minidump and I can confirm that the crash is caused by gTelemetryLoadData being NULL. This means it's most likely a startup race; not the first one I saw caused by components assuming that the initialization of an XPCOM service has already happened. I'll dig further after lunch.

Comment 7

[(Away)]

Yeah, I agree with comment 6.

Comment 8

[Gabriele Svelto [:gsvelto]]

I've captured a stack trace of when the pref service gets instanced first and it happens implicitly via a bunch of other services that get instanced in turn. From the looks of it this should happen before the point where we crash and I couldn't find any place in the code where it seems like it might deviate from this and not instance the pref service.

That being said, right before reaching the line where we crash, the code invokes Preferences::InitStaticMembers() which does instance the service on its own unless we're shutting down. So in theory the pref service should always have been instanced at that point since all the crashes are happening at startup.

It's all very confusing, maybe we created the pref service and then it got destroyed, is that even possible? Like if nobody holds a reference to it? I don't think it's possible to commence shut down before initialization has completed so I'm not considering that possibility.

Comment 9

[BugBot [:suhaib / :marco]]

The severity field is not set for this bug.
:njn, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 10

[Gabriele Svelto [:gsvelto]]

Kris, as we discussed yesterday do you think that my hypothesis that the service is instanced and then destroyed during startup is valid? I don't remember when XPCOM services get killed but my idea is that we might run this code and then when prefService goes out of scope we destroy the service which would reset gTelemetryLoadData to null.

This would all happen here so by the time we reach ReadSavedPrefs() here the service is gone and we hit the NULL pointer.

Comment 11

[Kris Wright :KrisWright]

(In reply to Gabriele Svelto [:gsvelto] from comment #10)

Kris, as we discussed yesterday do you think that my hypothesis that the service is instanced and then destroyed during startup is valid? I don't remember when XPCOM services get killed but my idea is that we might run this code and then when prefService goes out of scope we destroy the service which would reset gTelemetryLoadData to null.

This would all happen here so by the time we reach ReadSavedPrefs() here the service is gone and we hit the NULL pointer.

I would think that the only way this would happen would be 1) the preferences service was never created or 2) we have, for some reason, tried to shut down preferences and then access ReadSavedPrefs(). From your comments it seems the possibility of 1 is ruled out (we are at a point in startup where the preferences service has been created). If we haven't destroyed XPCOM's static members, there should still be an existing reference to preferences and it should not be destroyed.

If that's the case, we need some check that ensures we don't try to make accesses into preferences after the service has been destroyed. Alternatively, we can check to see if the preferences service exists before attempting to read from it. Or if this is a startup race, which is always still possible, we need to ensure preferences doesn't attempt access until it's been fully initialized. Either way I feel like it's better practice to make sure ReadSavedPrefs() can't attempt accesses into the service when it doesn't exist. I'll look into this further to try to work out exactly when this is happening.

Comment 12

[Gabriele Svelto [:gsvelto]]

Thanks Kris. Note this are all startup crashes, most of them with just a couple of seconds of uptime so I'd rule out that the service has been shut down. I think it's some kind of startup race but I really can't see how it's happening given that the service should have already been created (once) at that point.

Comment 13

[Julien Cristau [:jcristau] (back August 18)]

Do we have any further leads here? I'm worried about shipping 80 with these startup crashes, and we're now in RC week.

Comment 14

[Gabriele Svelto [:gsvelto]]

Attachment: Bug 1653908 - Start the prefs service very early during startup to work around a startup crash potentially caused by a race

Comment 15

[Gabriele Svelto [:gsvelto]]

Comment on attachment 9170486 [details]
Bug 1653908 - Start the prefs service very early during startup to work around a startup crash potentially caused by a race

This is a bit clunky but it should prevent the crash. WDYT?

Comment 16

[Julien Cristau [:jcristau] (back August 18)]

We'd like to respin a 80 RC today, any chance we can get that in?

Comment 17

[Kris Wright :KrisWright]

Comment on attachment 9170486 [details]
Bug 1653908 - Start the prefs service very early during startup to work around a startup crash potentially caused by a race

See comments in phabricator. I haven't worked out yet which calls to the prefs service are going out of scope, so the best thing we can probably do is make sure it exists and stays alive while we're using it.

Comment 18

[Nathan Froyd [:froydnj]]

This smells a little like initialization of the prefs service (i.e. the initial get of the first instance) failing and then later things just falling over, similar to bug 1276488.

Comment 19

[Gabriele Svelto [:gsvelto]]

After more time poring over the code I tend to agree with Nathan's assessment in comment 18. The component manager should retain a strong reference of the service, so there should be no way for it to go out of scope, even w/o my patch. If we're failing before reaching that point though we have two problems:

• We're doing so silently, so it's going to be really hard finding where and why it's happening
• Even if we don't crash where we're crashing we would probably still fail to instance the service, which means we'd crash somewhere else anyway :-(

Comment 20

[Kris Wright :KrisWright]

Comment on attachment 9170486 [details]
Bug 1653908 - Start the prefs service very early during startup to work around a startup crash potentially caused by a race

Beta/Release Uplift Approval Request

• User impact if declined: Startup crash due to unavailable preferences service at ReadSavedPrefs, probably caused by a startup race
• Is this code covered by automated tests?: Unknown
• Has the fix been verified in Nightly?: No
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): The preferences service usually inits itself later anyway, but this patch ensures the preferences service is created before any other threads can try to access it.
• String changes made/needed:

Comment 21

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9170486 [details]
Bug 1653908 - Start the prefs service very early during startup to work around a startup crash potentially caused by a race

Per Slack discussion with Nathan and Kris, let's take this for RC2 now so we know where we stand ASAP with respect to this bug. Approved for 80.0rc2.

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/bd5d1f49975d

Comment 23

[Ryan VanderMeulen [:RyanVM]]

No reports from 80.0rc2, so either this patch or the one from bug 1656261 or the combination of the two appears to have been effective. We'll still need to figure out what to do for 81+, however.

Comment 25

[Julien Cristau [:jcristau] (back August 18)]

As with bug 1656261 this is still an issue in 81.

Comment 26

[Julien Cristau [:jcristau] (back August 18)]

Fixed by backout in 81.0b6

Comment 27

[Gabriele Svelto [:gsvelto]]

We still need to identify the root cause, fix it and then revert the workaround I landed in this bug.

Comment 28

[Ryan VanderMeulen [:RyanVM]]

This is still showing up high in the Fenix and Focus topcrashes for releases shipping GV80/GV81.

Comment 29

[Gabriele Svelto [:gsvelto]]

I'll have a look ASAP, sorry for the delay.

Comment 30

[Kris Wright :KrisWright]

This crash is still happening, but with the removal of gTelemetryLoadData in bug 1660946 the signature will probably change. The prefs service is still getting stuck/silently failing somewhere.

Comment 31

[Kris Wright :KrisWright]

I've looked at this some more and I've got a few conclusions about what's not going wrong. I haven't been able to replicate it, which is frustrating.

• Could not find any problems with the services getting prefs service during startup
• Could not find any instances where preferences init should be capable of racing

I feel like this is silently failing for some other reason, and given the fact that a lot of services that call prefs in startup don't care about failures of the prefs service, it wouldn't crash until later when something else can't access preferences. I want to add some diagnostic asserts that deal with places where the prefs service could fail early, so that we get more specific crash data for these kind of crashes.

Comment 32

[BugBot [:suhaib / :marco]]

Closing because no crashes reported for 12 weeks.