900954 - 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"

Reporter

Description

•

12 years ago

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

Comment hidden (Legacy TBPL/Treeherder Robot)

:Felipe Gomes (needinfo for replies!)

Comment 25

•

12 years ago

Attached patch test-addonrepository-cache (obsolete) — Details — 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)

Blair McBride [:Unfocused] (UNAVAILABLE)

Updated

•

12 years ago

Attachment #808929 - Flags: review?(bmcbride) → review+

:Felipe Gomes (needinfo for replies!)

Comment 26

•

12 years ago

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]

Ed Morley [:emorley]

Comment 27

•

12 years ago

https://hg.mozilla.org/mozilla-central/rev/24c2574041dd

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 56

•

12 years ago

Guess not :(

Assignee: nobody → felipc

Flags: needinfo?

Comment hidden (Legacy TBPL/Treeherder Robot)

:Felipe Gomes (needinfo for replies!)

Comment 66

•

12 years ago

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?

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 128

•

11 years ago

Any new ideas here? This is an ongoing failure across nearly every supported branch.

Flags: needinfo?(robert.bugzilla)

Flags: needinfo?(felipc)

Robert Strong (they/them - no direct email)

Comment 129

•

11 years ago

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)

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 130

•

11 years ago

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)

Comment hidden (Legacy TBPL/Treeherder Robot)

Dave Townsend [:mossop]

Comment 133

•

11 years ago

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)

Comment hidden (Legacy TBPL/Treeherder Robot)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 162

•

11 years ago

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)

:Irving Reid (No longer working on Firefox)

Assignee

Updated

•

11 years ago

Assignee: felipc → irving

Status: NEW → ASSIGNED

Comment hidden (Legacy TBPL/Treeherder Robot)

Roberto Agostino Vitillo (:rvitillo)

Updated

•

11 years ago

Blocks: 988292

Comment hidden (Legacy TBPL/Treeherder Robot)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 172

•

11 years ago

Attached patch Add flush() to the AddonRepository api and use it in tests (obsolete) — Details — Splinter Review

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)

Comment hidden (Legacy TBPL/Treeherder Robot)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 174

•

11 years ago

Clean try run on Windows, Linux, Mac, Android: https://tbpl.mozilla.org/?tree=Try&rev=49638026cd2d

Comment hidden (Legacy TBPL/Treeherder Robot)

:Felipe Gomes (needinfo for replies!)

Updated

•

11 years ago

Attachment #8407275 - Flags: review?(felipc) → review+

Comment hidden (Legacy TBPL/Treeherder Robot)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 185

•

11 years ago

Attached patch Add flush() to the AddonRepository api and use it in tests (as landed) — Details — Splinter 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+

:Irving Reid (No longer working on Firefox)

Assignee

Updated

•

11 years ago

Whiteboard: [leave open]

Comment hidden (Legacy TBPL/Treeherder Robot)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 187

•

11 years ago

https://hg.mozilla.org/integration/fx-team/rev/16ad8026a23a

Flags: in-testsuite+

Whiteboard: [fixed-in-fx-team]

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 188

•

11 years ago

https://hg.mozilla.org/mozilla-central/rev/16ad8026a23a

Status: ASSIGNED → RESOLVED

Closed: 11 years ago

Resolution: --- → FIXED

Whiteboard: [fixed-in-fx-team]

Target Milestone: --- → mozilla32

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 190

•

11 years ago

Thanks for fixing this, Irving! Please request Aurora and Beta approval on this when you're reasonably comfortable doing so :)

status-b2g-v1.2: --- → wontfix

status-b2g-v1.3: --- → wontfix

status-b2g-v2.0: --- → fixed

status-firefox30: --- → affected

status-firefox31: --- → affected

status-firefox32: --- → fixed

status-firefox-esr24: --- → unaffected

Flags: needinfo?(irving)

:Irving Reid (No longer working on Firefox)

Assignee

Comment 191

•

11 years ago

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)

Sylvestre Ledru [:Sylvestre]

Updated

•

11 years ago

Attachment #8414482 - Flags: approval-mozilla-beta?

Attachment #8414482 - Flags: approval-mozilla-beta+

Attachment #8414482 - Flags: approval-mozilla-aurora?

Attachment #8414482 - Flags: approval-mozilla-aurora+

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 192

•

11 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/7be99e603884 https://hg.mozilla.org/releases/mozilla-beta/rev/1c5aa2062579

status-b2g-v1.4: --- → affected

status-firefox30: affected → fixed

status-firefox31: affected → fixed

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 193

•

11 years ago

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/1c5aa2062579

Ryan VanderMeulen [:RyanVM]

Reporter

Updated

•

11 years ago

status-b2g-v1.4: affected → fixed

test-addonrepository-cache 12 years ago :Felipe Gomes (needinfo for replies!) 4.00 KB, patch	Unfocused : review+	Details \| Diff \| Splinter Review
Add flush() to the AddonRepository api and use it in tests 11 years ago :Irving Reid (No longer working on Firefox) 29.41 KB, patch	Felipe : review+	Details \| Diff \| Splinter Review
Add flush() to the AddonRepository api and use it in tests (as landed) 11 years ago :Irving Reid (No longer working on Firefox) 26.79 KB, patch	Irving : review+ Sylvestre : approval-mozilla-aurora+ Sylvestre : approval-mozilla-beta+	Details \| Diff \| Splinter Review