Closed Bug 1689562 Opened 4 years ago Closed 4 years ago

thunderbird perma fail after bug 1667276 | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js, toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_policies.js, test_crash_backgroundtask_moz_crash.js

Categories

(Thunderbird :: Upstream Synchronization, defect, P5)

Tracking

(thunderbird_esr78 unaffected)

RESOLVED FIXED
87 Branch
Tracking Status
thunderbird_esr78 --- unaffected

People

(Reporter: intermittent-bug-filer, Assigned: mkmelin)

References

(Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell fixed:patch])

Attachments

(2 files)

Summary: thunderbird perma fail after bug 1667276 | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js | test_backgroundtask_specific_pref - [test_backgroundtask_specific_pref : 19] 79 == 2 → thunderbird perma fail after bug 1667276 | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js and toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_policies.js

toolkit/crashreporter/test/unit/test_crash_backgroundtask_moz_crash.js is also from bug 1667276 (which added that)

Summary: thunderbird perma fail after bug 1667276 | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js and toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_policies.js → thunderbird perma fail after bug 1667276 | toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js, toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_policies.js, test_crash_backgroundtask_moz_crash.js

https://searchfox.org/mozilla-central/search?q=MOZ_BACKGROUNDTASKS&path=browser&case=false&regexp=false would probably need to be ported.
Arguably the tests should bail out if AppConstants.MOZ_BACKGROUNDTASKS isn't on though.

Rebuilt. AppConstants.MOZ_BACKGROUNDTASKS is true...

For some reason ChromUtils.import("resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm") will fail while the others work

This should be done. Doesn't help with the test failure.

Keywords: leave-open
Pushed by mkmelin@iki.fi: https://hg.mozilla.org/comm-central/rev/056822744fc3 port bug 1667276 to THunderbird - Add a Gecko background task mode and `--backgroundtask` flag to allow running short-lived processes that perform maintenance. rs=me

Nick, any ideas why this would fail for Thunderbird?

Flags: needinfo?(nalexander)

(In reply to Magnus Melin [:mkmelin] from comment #2)

https://searchfox.org/mozilla-central/search?q=MOZ_BACKGROUNDTASKS&path=browser&case=false&regexp=false would probably need to be ported.
Arguably the tests should bail out if AppConstants.MOZ_BACKGROUNDTASKS isn't on though.

Yes, we should. I tried to ensure this but clearly missed some; patches appreciated.

(In reply to Magnus Melin [:mkmelin] from comment #8)

Nick, any ideas why this would fail for Thunderbird?

Not immediately. The logs report error 2, which isn't supposed to happen: it means the relevant promise hasn't resolved but that we're exiting for some reason. I think that must mean the event loop has processed all events.

Now, I fetched this macOS Thunderbird Daily and with that I find (after removing some log cruft):

~/Mozilla/gecko $ /Volumes/Thunderbird\ Daily/Thunderbird\ DailyDebug.app/Contents/MacOS/thunderbird --backgroundtask success
*** You are running in background task mode. ***
*** You are running in headless mode.
~/Mozilla/gecko $ echo $?
0
~/Mozilla/gecko $ /Volumes/Thunderbird\ Daily/Thunderbird\ DailyDebug.app/Contents/MacOS/thunderbird --backgroundtask failure
*** You are running in background task mode. ***
*** You are running in headless mode.
~/Mozilla/gecko $ echo $?
1
~/Mozilla/gecko $ /Volumes/Thunderbird\ Daily/Thunderbird\ DailyDebug.app/Contents/MacOS/thunderbird --backgroundtask exception
*** You are running in background task mode. ***
*** You are running in headless mode.
console.error: BackgroundTasksManager: 
  Backgroundtask named 'exception' threw exception
  Message: Error: test
  Stack:
    runBackgroundTask@resource:///modules/backgroundtasks/BackgroundTask_exception.jsm:11:9
runBackgroundTaskNamed@resource://gre/modules/BackgroundTasksManager.jsm:117:26
~/Mozilla/gecko $ echo $?
3

That's all correct, so the actual --backgroundtask stuff is working, it's "just" something to do with the test harnesses. That strongly suggests that the mangling to load test-only background tasks isn't quite working for Thunderbird. The way this works is that the launching harness takes its own modules directory (i.e., it's own resources://testing-common URI) and puts it in the XPCSHELL_TESTING_MODULES_URI environment variable for the launched --backgroundtask process to find and search for task modules.

So the next thing would be to bump the background task logging pref toolkit.backgroundtasks.loglevel to debug, either by modifying the source here or with a try push that sets the preference. I haven't time to do that locally, sorry.

Alternately, you can default this to off in Thunderbird. I think this probably makes the most sense. See https://searchfox.org/mozilla-central/rev/fd853f4aea89186efdb368e759a71b7a90c2b89c/toolkit/moz.configure#2505.

Flags: needinfo?(nalexander)

The problem is it doesn't find the resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm module -> exception in the outer try-catch.

success, failure and exception works. It's the specific_pref one that doesn't

Is this supposed to be working?

obj-x86_64-pc-linux-gnu/dist/bin/thunderbird --backgroundtask specific_pref
*** You are running in background task mode. ***
*** You are running in headless mode.
console.info: BackgroundTasksManager: Running background task named 'specific_pref' (with 0 arguments)
console.debug: BackgroundTasksManager:
Looking for background task at URI: resource:///modules/backgroundtasks/BackgroundTask_specific_pref.jsm
console.debug: BackgroundTasksManager:
Looking for background task at URI: resource://gre/modules/backgroundtasks/BackgroundTask_specific_pref.jsm
console.info: BackgroundTasksManager: Invoking Services.startup.quit(..., 2)
JavaScript error: resource://gre/modules/BackgroundTasksManager.jsm, line 82: NS_ERROR_UNEXPECTED

Flags: needinfo?(nalexander)

Oh that doesn't work on Firefox nightly either. I guess test only...

The jsm does get put at ./obj-x86_64-pc-linux-gnu/_tests/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm

(In reply to Magnus Melin [:mkmelin] from comment #13)

Oh that doesn't work on Firefox nightly either. I guess test only...

The jsm does get put at ./obj-x86_64-pc-linux-gnu/_tests/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm

Can you run the test with the logging pref? You should see 3 Looking for background task ... lines, the third being the resource://testing-common/... search path, which is test-only. (The test should also be chatty about the resource://testing-common substitution.)

You can run the test with ./mach test toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js, possibly with the path updated for Thunderbird's directory structure. Thanks for tracking this down with me!

Flags: needinfo?(nalexander) → needinfo?(mkmelin+mozilla)

Thanks for looking! Hope the logging is useful, but it doesn't give me much clues. Like I wrote the issue seems to be that esource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm is not found. (So it doesn't get to the third "looking for")

./mach test toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js

pid:296038 > *** You are running in background task mode. ***
0:08.29 pid:296038 > *** You are running in headless mode.
0:08.35 pid:296038 > console.info: BackgroundTasksManager: Running background task named 'backgroundtask_specific_pref' (with 1 arguments)
0:08.35 pid:296038 > console.error: BackgroundTasksManager:
0:08.35 pid:296038 > Substitution set: resource://testing-common aliases file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/_tests/modules/
0:08.35 pid:296038 > console.debug: BackgroundTasksManager:
0:08.35 pid:296038 > Looking for background task at URI: resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
0:08.35 pid:296038 > console.debug: BackgroundTasksManager:
0:08.35 pid:296038 > Looking for background task at URI: resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
0:08.36 pid:296038 > console.info: BackgroundTasksManager: Invoking Services.startup.quit(..., 2)
0:08.36 pid:296038 > JavaScript error: resource://gre/modules/BackgroundTasksManager.jsm, line 82: NS_ERROR_UNEXPECTED
0:08.38 FAIL test_backgroundtask_specific_pref - [test_backgroundtask_specific_pref : 19] 79 == 2
/home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js:test_backgroundtask_specific_pref:19
/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:_do_main:239
/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:_execute_test:567
-e:null:1
0:08.38 INFO exiting test
0:08.38 ERROR Unexpected exception NS_ERROR_ABORT:
_abort_failed_test@/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:827:20
do_report_result@/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:928:5
Assert<@/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:73:21
proto.report@resource://testing-common/Assert.jsm:233:10
equal@resource://testing-common/Assert.jsm:275:8
test_backgroundtask_specific_pref@/home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/_tests/xpcshell/toolkit/components/backgroundtasks/tests/xpcshell/test_backgroundtask_specific_pref.js:19:10
_do_main@/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:239:6
_execute_test@/home/magnus/Code/tb/mozilla/testing/xpcshell/head.js:567:5
@-e:1:1

Flags: needinfo?(mkmelin+mozilla)

This is fascinating. So, based on

 Substitution set: resource://testing-common aliases file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/_tests/modules/

I can see that the test harness is configuring the environment correctly. However, what's happening is that the ChromeUtils.import(...) is throwing NS_ERROR_UNEXPECTED for resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm when the code expects only NS_ERROR_FILE_NOT_FOUND.

Can you bump the catch here to be more general (catch both, or catch anything) and see if that addresses the issue? Then we could try to understand why the code path in MozJSComponentLoader.cpp diverges. If you can attach a debugger and see where this NS_ERROR_UNEXPECTED arises that would be grand. If it's from the only obvious place that suggests a subtle bug in the module loader when trying to load a module from multiple locations.

Thanks!

Flags: needinfo?(mkmelin+mozilla)

If I catch anything (the NS_ERROR_UNEXPECTED really) and just dump it, then the test passes.

0:02.33 pid:306978 > Looking for background task at URI: resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
0:02.33 pid:306978 > xxxmagnus ex=[Exception... "File error: Not found" nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)" location: "JS frame :: resource://gre/modules/BackgroundTasksManager.jsm :: findRunBackgroundTask :: line 82" data: no]console.debug: BackgroundTasksManager:
0:02.33 pid:306978 > Looking for background task at URI: resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
0:02.33 pid:306978 > xxxmagnus ex=[Exception... "Unexpected error" nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: resource://gre/modules/BackgroundTasksManager.jsm :: findRunBackgroundTask :: line 82" data: no]console.debug: BackgroundTasksManager:

The failure is returned from here: https://searchfox.org/mozilla-central/rev/927e525f481a93a8f63d27a78ae6201e42b1b1fb/js/xpconnect/loader/mozJSComponentLoader.cpp#1238 - NS_ERROR_UNEXPECTED for
newEntry->resolvedURL=file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/dist/bin/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
existingPath=resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm
info.Key()=resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm

Flags: needinfo?(mkmelin+mozilla) → needinfo?(nalexander)

mccr8: can you explain what is supposed to happen in this case? In BackgroundTasksManager.jsm I iterate through possible module locations and use ChromeUtils.import(...) to try to import them. On Firefox, this appears to work fine, and modules that are not found return NS_ERROR_FILE_NOT_FOUND as I expect. However, on Thunderbird, we get an NS_ERROR_UNEXPECTED (see link above) for at least some modules that are not found, which suggests that the import code is modifying some data structure even though the load fails. Is there a bug here, or is my expectation for this API not correct?

Flags: needinfo?(nalexander) → needinfo?(continuation)

Sorry for the delay. I'm not super familiar with this code so it took me a bit to get my head around what you were asking. :)

It looks like mozJSComponentLoader::Import() does mLocations.Put(), which adds the entry that gets looked up later. However, it looks like it can fail for many different reasons, but we don't remove the entry from mLocations if it does fail, so the second check will then fail at the earlier point as noted in comment 17. So I guess I'm not sure why it works in Firefox. Maybe in Firefox it always succeed the first time around the loop?

Flags: needinfo?(continuation)

I guess we just been lazy tagging it. It's still 100% happening.

Some debugging (at https://searchfox.org/mozilla-central/rev/1b7ed77360ed02de111cf2098b2b48648c382fa1/js/xpconnect/loader/mozJSComponentLoader.cpp#1314)

For Thunderbird:
mLocations.Put(file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/dist/bin/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm, resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm)

... and next call throws NS_ERROR_UNEXPECTED since it has the same key but the value is changing from
resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm to
resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm

For Firefox:
mLocations.Put(file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/dist/bin/browser/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm, resource:///modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm)
-> File not found (ok)

mLocations.Put(file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/dist/bin/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm, resource://gre/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm)
-> File not found (ok)

mLocations.Put(file:///home/magnus/Code/tb/mozilla/obj-x86_64-pc-linux-gnu/_tests/modules/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm, resource://testing-common/backgroundtasks/BackgroundTask_backgroundtask_specific_pref.jsm)


Note the firefox dist/bin/browser/modules vs the thunderbird dist/bin/modules.
The NS_ERROR_UNEXPECTED doesn't happen for firefox because the mLocations key is different for all the calls.
I don't know if a dist/bin/browser location is expected or not.

Clear the key from mLocations if it runs in into an error maybe?

Excellent debugging, Magnus -- I see the difference between browser/ and comm/ now. The expedient fix is to recognize that the app-specific path is the same as the toolkit path, and only check one. (Or just skip one of the checks on Thunderbird.) The deeper fix is to ensure we don't get into the bad state at all, by only filling mLocations on success, or clearing it on error, or whatever.

Can you investigate one of the simple fixes, which I will happily review and help land, and we'll file a ticket for the real issue separately?

Flags: needinfo?(mkmelin+mozilla)

Thanks, seems easiest to just do the real fix right away.

Flags: needinfo?(mkmelin+mozilla)
Assignee: nobody → mkmelin+mozilla
Status: NEW → ASSIGNED
Attachment #9200374 - Attachment description: bug1689562_backgroundtasks.patch → [checked in] packaging/build changes - bug1689562_backgroundtasks.patch
Pushed by mkmelin@iki.fi: https://hg.mozilla.org/integration/autoland/rev/620e3ca4f901 mozJSComponentLoader::Import should not store locations that failed to resolve. r=kmag
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:patch]

Hi Magnus, should this be closed since there are no failures any longer?

Flags: needinfo?(mkmelin+mozilla)

Yes indeed!

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Flags: needinfo?(mkmelin+mozilla)
Resolution: --- → FIXED
Target Milestone: --- → 87 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: