Closed Bug 1475836 Opened 6 years ago Closed 6 years ago

TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_db_enumerator.js, test_nsAbManager3.js, test_nsAbManager2.js, and MozMill

Categories

(MailNews Core :: General, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
Thunderbird 63.0

People

(Reporter: jorgk-bmo, Assigned: kmag)

References

Details

(Keywords: regression, Whiteboard: [Thunderbird-testfailure: XZ all][Thunderbird-disabled-test])

Attachments

(2 files)

TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_db_enumerator.js | xpcshell return code: 1
PROCESS-CRASH | comm/mailnews/addrbook/test/unit/test_db_enumerator.js | application crashed [@ libsystem_platform.dylib + 0x2b17]
TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_nsAbManager3.js | xpcshell return code: 1
PROCESS-CRASH | comm/mailnews/addrbook/test/unit/test_nsAbManager3.js | application crashed [@ libsystem_platform.dylib + 0x2b17]
TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_nsAbManager2.js | xpcshell return code: 1
PROCESS-CRASH | comm/mailnews/addrbook/test/unit/test_nsAbManager2.js | application crashed [@ libsystem_platform.dylib + 0x2b17]

All three tests crash locally now.

M-C last good: 04dd259d71db60341016eccf53ced43742
M-C first bad: 2a8f94a45fd3f898cb63c54b8df662f8ad

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=04dd259d71db60341016eccf53ced43742&tochange=2a8f94a45fd3f898cb63c54b8df662f8ad

Also seems to affect Mozmill:
TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed
PROCESS-CRASH | addrbook | application crashed [@ libsystem_platform.dylib + 0x2b17]
Summary: TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_db_enumerator.js, test_nsAbManager3.js, test_nsAbManager2.js → TEST-UNEXPECTED-FAIL | comm/mailnews/addrbook/test/unit/test_db_enumerator.js, test_nsAbManager3.js, test_nsAbManager2.js, and MozMill
Running the test interactively with
  mach xpcshell-test --interactive comm/mailnews/addrbook/test/unit/test_db_enumerator.js

I get this stack:

xul.dll!pref_Lookup(const char * aPrefName, bool aIncludeTypeNone) Line 1634	C++
xul.dll!mozilla::Preferences::GetInt(const char * aPrefName, int * aResult, mozilla::PrefValueKind aKind) Line 4971	C++
xul.dll!nsPrefBranch::GetIntPref(const char * aPrefName, int * aRetVal) Line 2490	C++
xul.dll!DIR_SetIntPref(const char * prefRoot, const char * prefLeaf, int value, int defaultValue) Line 1375	C++
xul.dll!DIR_SetServerPosition(nsTArray<DIR_Server *> * wholeList, DIR_Server * server, int position) Line 387	C++
xul.dll!DirPrefObserver::Observe(nsISupports * aSubject, const char * aTopic, const char16_t * aData) Line 134	C++
xul.dll!nsPrefBranch::NotifyObserver(const char * aNewPref, void * aData) Line 3040	C++
xul.dll!NotifyCallbacks(const char * aPrefName, const PrefWrapper * aPref) Line 1783	C++
[Inline Frame] xul.dll!NotifyCallbacks(const char *) Line 1537	C++
xul.dll!pref_SetPref(const char * aPrefName, mozilla::PrefType aType, mozilla::PrefValueKind aKind, PrefValue aValue, bool aIsSticky, bool aIsLocked, bool aFromInit) Line 1740	C++
xul.dll!mozilla::Preferences::SetInt(const char * aPrefName, int aValue, mozilla::PrefValueKind aKind) Line 5116	C++
xul.dll!nsPrefBranch::SetIntPref(const char * aPrefName, int aValue) Line 2499	C++
xul.dll!DIR_SetIntPref(const char * prefRoot, const char * prefLeaf, int value, int defaultValue) Line 1384	C++
xul.dll!DIR_SetServerPosition(nsTArray<DIR_Server *> * wholeList, DIR_Server * server, int position) Line 387	C++
xul.dll!DIR_DeleteServerFromList(DIR_Server * server) Line 660	C++
xul.dll!nsAbBSDirectory::DeleteDirectory(nsIAbDirectory * directory) Line 260	C++
xul.dll!nsAbManager::DeleteAddressBook(const nsTSubstring<char> & aURI) Line 369	C++
xul.dll!XPTC__InvokebyIndex() Line 99	Unknown
[Inline Frame] xul.dll!CallMethodHelper::Invoke() Line 1703	C++

That's this line:
if (gCallbackPref && strcmp(aPrefName, gCallbackPref->Name()) == 0) {

aPrefName 0x0000025394b6584c "ldap_2.servers.test5378151.position" const char *

Looks like something went wrong in bug 1471025.

Kris and Nicholas, somehow you broke preferences :-(
Blocks: 1471025
Flags: needinfo?(n.nethercote)
Flags: needinfo?(kmaglione+bmo)
Keywords: regression
Version: 60 → Trunk
You can also see the crash here:
https://taskcluster-artifacts.net/GV9-toz4R2-WCpui4SMI8A/0/public/logs/live_backing.log
Search for "application crashed". The crash is in mozilla::Preferences::GetInt().

I'm happy to admit that we might be doing all sorts of "wrong" things in the test (I haven't looked), but nothing should lead to a crash.
I'll admit, it never occurred to me that a preference observer might delete the preference it was observing.
Flags: needinfo?(n.nethercote)
Flags: needinfo?(kmaglione+bmo)
(In reply to Kris Maglione [:kmag] from comment #3)
> I'll admit, it never occurred to me that a preference observer might delete
> the preference it was observing.
Thanks for looking into it. Wow, from the stack you can work out that the observer is deleting its own pref? Looking at the test, it's deleting address books. Or did you did deeper? Given that it's Sunday, I only gave it a cursory look.

Where from here? Do we need to change our code/test? Even if we're doing something illegal, catching that with a crash is not the most elegant way to deal with it ;-(
Flags: needinfo?(kmaglione+bmo)
(In reply to Jorg K (GMT+2) from comment #4)
> (In reply to Kris Maglione [:kmag] from comment #3)
> > I'll admit, it never occurred to me that a preference observer might delete
> > the preference it was observing.
>
> Thanks for looking into it. Wow, from the stack you can work out that the
> observer is deleting its own pref?

Yes, I can. Even if I couldn't, that's the only way we could crash at that line.

> Where from here? Do we need to change our code/test? Even if we're doing
> something illegal, catching that with a crash is not the most elegant way to
> deal with it ;-(

I'll write a patch to clear the cached pref entry when a pref is deleted. That said, changing preferences from a pref observer sounds like a recipe for disaster to me.
(In reply to Kris Maglione [:kmag] from comment #5)
> Yes, I can. Even if I couldn't, that's the only way we could crash at that
> line.
Can you teach me, please. I guess you saw DirPrefObserver::Observe() and checked DIR_SetServerPosition()?

> I'll write a patch to clear the cached pref entry when a pref is deleted.
> That said, changing preferences from a pref observer sounds like a recipe
> for disaster to me.
Changing or deleting? I guess both.

Looks like the offending code is here. We have DirPrefObserver::Observe() call DIR_SetServerPosition() and that deletes the branch and then sets the pref again:
https://dxr.mozilla.org/comm-central/rev/e5e1510b8d914bfa8439b21ba3f73e4f2e83e957/mailnews/addrbook/src/nsDirPrefs.cpp#383

       pPref->DeleteBranch(server->prefName);

       // mark the server as deleted by setting its position to 0
       DIR_SetIntPref(server->prefName, "position", 0, -1);

I'd have to look at the 20+ y/o logic to see what's going on.
(In reply to Jorg K (GMT+2) from comment #6)
> I guess you saw DirPrefObserver::Observe() and checked DIR_SetServerPosition()?

Yes. Although I didn't need to see the observer to know it was there. gCallbackPref can only be set if we're currently notifying an observer. And the DIR_SetServerPosition line in the stack is immediately after a DeleteBranch call for the preference being observed.

> > I'll write a patch to clear the cached pref entry when a pref is deleted.
> > That said, changing preferences from a pref observer sounds like a recipe
> > for disaster to me.
>
> Changing or deleting? I guess both.

Both seem a bit risky. Changing is probably worse, since deleting currently doesn't notify callbacks, so is less likely to cause an infinite loop. But the fact that it doesn't notify callbacks is also the reason for this issue.

That said, deleting really probably *should* notify callbacks, so I wouldn't be surprised if that changed in the future.
Flags: needinfo?(kmaglione+bmo)
> deleting currently doesn't notify callbacks

This is bug 343600.
(In reply to Kris Maglione [:kmag] from comment #5)
> I'll write a patch to clear the cached pref entry when a pref is deleted.
Could you please do that quickly. For now, I have to switch off the failing tests to allow for efficient sheriffing.
Flags: needinfo?(kmaglione+bmo)
Keywords: leave-open
(In reply to Jorg K (GMT+2) from comment #10)
> (In reply to Kris Maglione [:kmag] from comment #5)
> > I'll write a patch to clear the cached pref entry when a pref is deleted.
> Could you please do that quickly. For now, I have to switch off the failing
> tests to allow for efficient sheriffing.

It's on my todo list for today. As a rule, there's only so much work I'm willing to do on weekends :p
Flags: needinfo?(kmaglione+bmo)
Pushed by mozilla@jorgk.com:
https://hg.mozilla.org/comm-central/rev/2d9d51e1b489
temporarily disable failing tests. rs=bustage-fix
Whiteboard: [Thunderbird-testfailure: XZ all] → [Thunderbird-testfailure: XZ all][Thunderbird-disabled-test]
(In reply to Kris Maglione [:kmag] from comment #11)
> It's on my todo list for today. As a rule, there's only so much work I'm
> willing to do on weekends :p
I know the feeling :-( - Any chance to get to this? It's impacting TB functionality, like deleting an address books will crash.
Flags: needinfo?(kmaglione+bmo)
Thanks Kris, this fixes all our problems.
Flags: needinfo?(kmaglione+bmo)
Comment on attachment 8993772 [details]
Bug 1475836: Clear cached callback pref when deleting branch.

https://reviewboard.mozilla.org/r/258470/#review265594
Attachment #8993772 - Flags: review?(n.nethercote) → review+
Backed out 2 changesets (bug 1477254, bug 1475836) for bustages in builds/worker/workspace/build/src/modules/libpref/Preferences.cpp:4791:1 on a CLOSED TREE

Failure: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&selectedJob=189678167
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=189678157&repo=mozilla-inbound&lineNumber=11432

[task 2018-07-24T00:47:47.237Z] 00:47:47     INFO -  /builds/worker/workspace/build/src/modules/libpref/Preferences.cpp:4791:1: error: unused function 'GetPref' [-Werror,-Wunused-function]
[task 2018-07-24T00:47:47.238Z] 00:47:47     INFO -  GetPref<bool>(const char* aName, bool aDefaultValue)
[task 2018-07-24T00:47:47.239Z] 00:47:47     INFO -  ^
[task 2018-07-24T00:47:47.240Z] 00:47:47     INFO -  /builds/worker/workspace/build/src/modules/libpref/Preferences.cpp:4798:1: error: unused function 'GetPref' [-Werror,-Wunused-function]
[task 2018-07-24T00:47:47.240Z] 00:47:47     INFO -  GetPref<int32_t>(const char* aName, int32_t aDefaultValue)
[task 2018-07-24T00:47:47.241Z] 00:47:47     INFO -  ^
[task 2018-07-24T00:47:47.241Z] 00:47:47     INFO -  /builds/worker/workspace/build/src/modules/libpref/Preferences.cpp:4805:1: error: unused function 'GetPref' [-Werror,-Wunused-function]
[task 2018-07-24T00:47:47.242Z] 00:47:47     INFO -  GetPref<uint32_t>(const char* aName, uint32_t aDefaultValue)
[task 2018-07-24T00:47:47.242Z] 00:47:47     INFO -  ^
[task 2018-07-24T00:47:47.244Z] 00:47:47     INFO -  3 errors generated.
[task 2018-07-24T00:47:47.244Z] 00:47:47     INFO -  /builds/worker/workspace/build/src/config/rules.mk:1052: recipe for target 'Unified_cpp_modules_libpref0.o' failed
[task 2018-07-24T00:47:47.245Z] 00:47:47     INFO -  make[4]: *** [Unified_cpp_modules_libpref0.o] Error 1
[task 2018-07-24T00:47:47.249Z] 00:47:47     INFO -  make[4]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/modules/libpref'
[task 2018-07-24T00:47:47.249Z] 00:47:47     INFO -  /builds/worker/workspace/build/src/config/recurse.mk:74: recipe for target 'modules/libpref/target' failed
[task 2018-07-24T00:47:47.250Z] 00:47:47     INFO -  make[3]: *** [modules/libpref/target] Error 2
[task 2018-07-24T00:47:47.250Z] 00:47:47     INFO -  make[3]: *** Waiting for unfinished jobs....
Flags: needinfo?(jorgk)
Flags: needinfo?(jorgk)
Keywords: leave-open
https://hg.mozilla.org/mozilla-central/rev/37435502b7c0
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 63.0
Pushed by mozilla@jorgk.com:
https://hg.mozilla.org/comm-central/rev/89f2c79f2da9
Backed out changeset 2d9d51e1b489 to re-enable tests. a=backout DONTBUILD
Assignee: nobody → kmaglione+bmo
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: