Closed Bug 900954 Opened 11 years ago Closed 10 years ago

Intermittent test_AddonRepository_cache.js | test failed (with xpcshell return code: 0) | head_addons.js | "XPI Add-on 1 - Creator" == "Repo Add-on 1 - Creator"

Categories

(Toolkit :: Add-ons Manager, defect)

x86
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla32
Tracking Status
firefox30 --- fixed
firefox31 --- fixed
firefox32 --- fixed
firefox-esr24 --- unaffected
b2g-v1.2 --- wontfix
b2g-v1.3 --- wontfix
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: RyanVM, Assigned: Irving)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 2 obsolete files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=26070823&tree=Fx-Team

Ubuntu VM 12.04 x64 fx-team debug test xpcshell on 2013-08-02 04:37:24 PDT for push fa4afb7214ae
slave: tst-linux64-ec2-050

05:28:14     INFO -  TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | running test ...
05:28:20  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | test failed (with xpcshell return code: 0), see following log:
05:28:20     INFO -  >>>>>>>
05:28:20     INFO -  ### XPCOM_MEM_LEAK_LOG defined -- logging leaks to /tmp/tmpclQUPi/runxpcshelltests_leaks.log
05:28:20     INFO -  System JS : WARNING /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:1017
05:28:20     INFO -                       function check_test_completed does not always return a value
05:28:20     INFO -  System JS : WARNING /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:1144
05:28:20     INFO -                       in strict mode code, functions may be declared only at top level or immediately within another function
05:28:20     INFO -  System JS : WARNING /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:1185
05:28:20     INFO -                       anonymous function does not always return a value
05:28:20     INFO -  System JS : WARNING /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:1294
05:28:20     INFO -                       test for equality (==) mistyped as assignment (=)?
05:28:20     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
05:28:20     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
05:28:20     INFO -  *** LOG addons.manager: Application has been upgraded
05:28:20     INFO -  *** LOG addons.xpi: startup
05:28:20     INFO -  *** LOG addons.xpi: checkForChanges
05:28:20     INFO -  *** LOG addons.xpi: No changes found

yadda yadda yadda...

05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 456] false == false
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 460] false == false
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 456] false == false
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 460] false == false
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 456] false == false
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js | [check_results/< : 460] false == false
05:28:21     INFO -  TEST-INFO | (xpcshell/head.js) | test run_test_15 pending (2)
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Save changes
05:28:21     INFO -  TEST-INFO | (xpcshell/head.js) | test run_test_15 finished (2)
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Starting timer
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
05:28:21     INFO -  System JS : ERROR /builds/slave/test/build/tests/xpcshell/head.js:436
05:28:21     INFO -                       TypeError: callback is undefined
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Starting write
05:28:21     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (2)
05:28:21     INFO -  *** LOG addons.repository: Requesting http://localhost:4444/data/test_AddonRepository_cache.xml
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Write succeeded
05:28:21     INFO -  *** LOG addons.repository: Compatibility override of unsupported type found.
05:28:21     INFO -  *** LOG addons.repository: Compatibility override is missing a valid application range.
05:28:21     INFO -  *** WARN addons.repository: Unknown type id when parsing addon: 9999
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Save changes
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Starting timer
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | [do_check_addons : 206] [object Object],[object Object],[object Object] != null
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | [do_check_addons : 207] 3 == 3
05:28:21     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | [do_check_addon : 223] [object Object] != null
05:28:21  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | "XPI Add-on 1 - Creator" == "Repo Add-on 1 - Creator" - See following stack:
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js :: do_check_author :: line 299
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js :: do_check_addon/< :: line 247
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js :: do_check_addon :: line 225
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js :: do_check_addons :: line 209
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js :: check_results :: line 450
05:28:21     INFO -  JS frame :: /builds/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js :: run_test_15/</< :: line 745
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: safeCall :: line 83
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: getAddonsByIDs_noMoreObjects :: line 1769
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 178
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: getAddonsByIDs_getAddonByID :: line 1764
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: safeCall :: line 83
05:28:21     INFO -  JS frame :: resource://gre/modules/AddonManager.jsm :: getAddonByID_safeCall :: line 1683
05:28:21     INFO -  JS frame :: resource://gre/modules/XPIProvider.jsm :: getAddonByID_getVisibleAddonForID :: line 3416
05:28:21     INFO -  JS frame :: resource://gre/modules/XPIProvider.jsm -> resource://gre/modules/XPIProviderUtils.js :: getVisibleAddonForID_executeAsync :: line 1391
05:28:21     INFO -  JS frame :: resource://gre/modules/XPIProvider.jsm -> resource://gre/modules/XPIProviderUtils.js :: AsyncAddonListCallback_handleCompletion :: line 173
05:28:21     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
05:28:21     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
05:28:21     INFO -  *** WARN addons.manager: Exception calling callback: NS_ERROR_ABORT
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** LOG addons.updates: Requesting http://127.0.0.1/updateBackgroundURL
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  *** WARN addons.updates: Request failed: http://127.0.0.1/updateBackgroundURL - 404: Not Found
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Starting write
05:28:21     INFO -  *** LOG DeferredSave/addons.json: Write succeeded
05:28:21     INFO -  *** LOG addons.manager: shutdown
05:28:21     INFO -  *** LOG addons.xpi: shutdown
05:28:21     INFO -  *** LOG addons.xpi-utils: shutdown
05:28:21     INFO -  *** LOG addons.xpi-utils: Database closed
Attached patch test-addonrepository-cache (obsolete) — Splinter Review
I don't know if this will fix the intermittent failure, but I think it has a good chance.

When the trigger_background_update callback is called, everything was already updated in memory, but it's possible that the file hasn't finished writing to disk yet. So an operation that re-reads from disk like run_test_15 does needs to wait. The good news is that the test doesn't need to care about the addons-background-update-complete notification anymore, because waitForFlushedData will already cover that.

Only run_test_13 still needs it because it's deleting the database and in that case waitForFlushedData will not receive addon-repository-data-written.

Sent to try: https://tbpl.mozilla.org/?tree=Try&rev=6b1ca61553d9
Attachment #808929 - Flags: review?(bmcbride)
Attachment #808929 - Flags: review?(bmcbride) → review+
https://hg.mozilla.org/integration/fx-team/rev/24c2574041dd

leave open because we don't know if this will fix the orange yet. It will need a few days to verify
Whiteboard: [leave open]
Guess not :(
Assignee: nobody → felipc
Flags: needinfo?
The test seems to be happening more often now, so I've backed out the patch that I landed.
https://hg.mozilla.org/integration/mozilla-inbound/rev/bc0cd43eff34

Though I think the higher frequency might be related to more changes that have been going on in AddonManager land instead of this particular patch, but we'll know for sure now.
Flags: needinfo?
Any new ideas here? This is an ongoing failure across nearly every supported branch.
Flags: needinfo?(robert.bugzilla)
Flags: needinfo?(felipc)
Looking at the logs for that test

http://hg.mozilla.org/mozilla-central/filelog/d05c721ea1b0/toolkit/mozapps/extensions/test/xpcshell/test_AddonRepository_cache.js

I would suggest either asking Blair or Dave instead of myself.
Flags: needinfo?(robert.bugzilla)
Dammit sorry, I keep mentally mixing up Application Update and Add-ons Manager for some reason I can't figure out :(.
Flags: needinfo?(dtownsend+bugmail)
Flags: needinfo?(bmcbride)
I took a look at this last week and didn't really get anywhere (not helped by build config brokenness). Looks like this is tied up in the new async stuff that I don't have a lot of knowledge on though
Flags: needinfo?(dtownsend+bugmail)
I think I've figured out what's going on here - if I'm right, it's a race condition between when we think the addons.json file has been written vs. when we think the background update check has completed - we may be getting the "addons.json written" signal from the delayed write of a previous change rather than the current one.
Flags: needinfo?(felipc)
Flags: needinfo?(bmcbride)
Assignee: felipc → irving
Status: NEW → ASSIGNED
The existing test was sometimes waiting for the wrong write to complete - the next phase of the test would trigger off the delayed addons.json write from the previous test instead of the current one.

While debugging this, I also noticed some cases where a new background update check was started before the previous one completed, so I made that throw an error.

I also converted the test to task.jsm style, to make it clearer what we are waiting for at each stage in the test, and added some more promise APIs to the test harness.
Attachment #8407275 - Flags: review?(felipc)
Clean try run on Windows, Linux, Mac, Android: https://tbpl.mozilla.org/?tree=Try&rev=49638026cd2d
Attachment #8407275 - Flags: review?(felipc) → review+
Carrying forward felipe's r+

The added check in AddonManager.jsm to throw an error if a background update is requested while another is still in progress caused the browser_hotfix.js test to fail on Try, so I'm moving that code to my WIP patch on bug 1000695; rs=felipe on IRC.
Attachment #808929 - Attachment is obsolete: true
Attachment #8407275 - Attachment is obsolete: true
Attachment #8414482 - Flags: review+
Whiteboard: [leave open]
https://hg.mozilla.org/integration/fx-team/rev/16ad8026a23a
Flags: in-testsuite+
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/16ad8026a23a
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla32
Thanks for fixing this, Irving! Please request Aurora and Beta approval on this when you're reasonably comfortable doing so :)
Comment on attachment 8414482 [details] [diff] [review]
Add flush() to the AddonRepository api and use it in tests (as landed)

[Approval Request Comment]
Bug caused by (feature/regressing bug #):
User impact if declined: None (Sheriffs need to keep starring oranges)
Testing completed (on m-c, etc.): Fix has been on M-C for a week with no issues
Risk to taking this patch (and alternatives if risky): 
Low risk, the changes to shipped Toolkit code are minimal. 
String or IDL/UUID changes made by this patch: A test-only Observer notification has been removed.
Attachment #8414482 - Flags: approval-mozilla-beta?
Attachment #8414482 - Flags: approval-mozilla-aurora?
Flags: needinfo?(irving)
Attachment #8414482 - Flags: approval-mozilla-beta?
Attachment #8414482 - Flags: approval-mozilla-beta+
Attachment #8414482 - Flags: approval-mozilla-aurora?
Attachment #8414482 - Flags: approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.