1264782 - TEST-UNEXPECTED-FAIL | xpcshell-libical.ini:calendar/test/unit/test_storage.js | TEST-UNEXPECTED-FAIL | xpcshell-icaljs.ini:calendar/test/unit/test_storage.js | TEST-UNEXPECTED-FAIL | xpcshell-libical.ini:calendar/test/unit/test_calmgr.js

Status: RESOLVED FIXED

(Calendar :: General, defect)

Description

[Stefan Sitter [:ssitter]]

Following crash is reported since this checkin:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=69b4c4164312c107137efa4fae17c63608fa30d1

> 12:49:29     INFO -  xpcshell-libical.ini:calendar/test/unit/test_storage.js | Starting testAttachRoundtrip

> 12:49:29     INFO -  (xpcshell/head.js) | test testAttachRoundtrip pending (2)

> 12:49:29     INFO -  PROCESS | 6740 | Attempt to add a uint pref cache for preference 'browser.cache.use_new_backend' at address '66B16AF4'was made. However, a pref was already cached at this address.

> 12:49:29     INFO -  PROCESS | 6740 | Assertion failure: false (Should not have an existing pref cache for this address), at c:/builds/moz2_slave/tb-c-cen-w32-d-000000000000000/build/mozilla/modules/libpref/Preferences.cpp:217

> 12:49:42 WARNING - PROCESS-CRASH | xpcshell-libical.ini:calendar/test/unit/test_storage.js | application crashed [@ mozilla::AssertNotAlreadyCached]

Both bug 1258835 and bug 1115667 touched test_storage.js.

Comment 1

[Stefan Sitter [:ssitter]]

Attachment: fix test_storage.js crash

This fixes the test_storage.js crash for me. I just applied the same pattern that is used in the other test files. do_calendar_startup() just calls another function without add_test().

Comment 2

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Comment on attachment 8741509 [details] [diff] [review]
fix test_storage.js crash

Review of attachment 8741509 [details] [diff] [review]:
-----------------------------------------------------------------

Great, lets try it! Thanks for looking into this so quickly.

Comment 3

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

https://hg.mozilla.org/comm-central/rev/66f5a1abc1d9

Comment 4

[Stefan Sitter [:ssitter]]

Hmm, the test past for me locally. But on the build servers it now triggers a different assertion in mozStorageConnection.cpp leading to new crash:

> 02:01:43 INFO -  PROCESS | 5468 | [5468] WARNING: SQL statement 'SELECT DISTINCT(zone) FROM (SELECT recurrence_id_tz AS zone FROM cal_attendees...
> 
> 02:01:43 INFO -  PROCESS | 5468 | [5468] WARNING: SQL statement 'SELECT version FROM cal_tz_version LIMIT 1' (1fc41370) should have been finalized before closing the connection: 
>          file /builds/slave/tb-c-cen-m64-d-000000000000000/build/mozilla/storage/mozStorageConnection.cpp, line 963
> 
> 02:01:43 INFO -  PROCESS | 5468 | \x07[5468] ###!!! ASSERTION: Invalid state to get the params object - all calls will fail!: 'state == mozIStorageStatement::MOZ_STORAGE_STATEMENT_READY', 
>          file /builds/slave/tb-c-cen-m64-d-000000000000000/build/mozilla/storage/mozStorageStatementJSHelper.cpp, line 138
>
> 02:01:59 WARNING - PROCESS-CRASH | xpcshell-libical.ini:calendar/test/unit/test_storage.js | application crashed [@ mozalloc_abort(char const*)]

Comment 5

[Stefan Sitter [:ssitter]]

On the Windows builders the crash is gone. They fail with

> 09:49:54  INFO -  PROCESS | 7920 | Error: [calStorageCalendar] Message: prepareStatement exception
> 
> 09:49:54  INFO -  PROCESS | 7920 | Exception: [Exception... "Cannot modify properties of a WrappedNative"  nsresult: "0x80570034 (NS_ERROR_XPC_CANT_MODIFY_PROP_ON_WN)"  
>           location: "JS frame :: file:///C:/slave/test/build/application/thunderbird/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/components/calStorageCalendar.js :: cSC_prepareStatement :: line 378"  data: no]
> 
> 09:49:54  INFO -  PROCESS | 7920 | Error: [calStorageCalendar] Message: Error selecting item by id attachItem!
> 
> 09:49:54  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-libical.ini:calendar/test/unit/test_storage.js |  
>           - NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [mozIStorageStatement.reset]

Any idea?

Comment 6

[Stefan Sitter [:ssitter]]

On my Windows debug build the test pass but only after multiple retries:
2:56.28 LOG: MainThread INFO Retrying tests that failed when run in parallel.
2:56.59 TEST_START: Thread-197 xpcshell-icaljs.ini:calendar/test/unit/test_storage.js

The failed test run show the same assertion as in Comment 4. 
When run with --sequential I get no message about retries.

Philipp, does your patch from Bug 1258835 supports running tests in parallel? 
Maybe you can try and run tests sequential?

Comment 8

[aleth [:aleth]]

or might you be running into this recent change? https://hg.mozilla.org/mozilla-central/rev/79b6b01de089#l2.12

Comment 9

[aleth [:aleth]]

(In reply to aleth [:aleth] from comment #8)
> or might you be running into this recent change?
> https://hg.mozilla.org/mozilla-central/rev/79b6b01de089#l2.12

Looks like support-files is already present: https://dxr.mozilla.org/comm-central/source/calendar/test/unit/xpcshell-libical.ini#6

(In reply to Stefan Sitter from comment #6)
> Philipp, does your patch from Bug 1258835 supports running tests in
> parallel? 
> Maybe you can try and run tests sequential?

On OSX the test fails with and without --sequential.

It would be good to debug this soon as this failure breaks xpcshell log parsing and I am concerned new unrelated failures might go unnoticed.

Comment 10

[aleth [:aleth]]

There is something wrong with both the before and after of https://hg.mozilla.org/comm-central/rev/66f5a1abc1d9#l1.9.
do_calendar_startup is async, and there is nothing here to stop the test from exiting too early.

And indeed, adding a do_test_pending() at the end of run_test() and a matching do_test_finished() at the end of testAttachRoundtrip() makes the test pass.

But if this pattern is repeated in other calendar tests, it would be best to fix this properly.

Here's some documentation on async tests: https://developer.mozilla.org/en-US/docs/Mozilla/QA/Writing_xpcshell-based_unit_tests#Async_tests

Comment 11

[Stefan Sitter [:ssitter]]

I don't know how to fix this and I don't know why a failing test should cause parsing errors.
My fix was just an attempt to make it look like other tests in this folder.
I hope that someone who is familiar with the tests will take a look.

Comment 12

[aleth [:aleth]]

Attachment: Ensure xpcshell tests wait for calendar startup to complete

Comment 13

[aleth [:aleth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=cea5083ab672

Comment 14

[aleth [:aleth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=77512d3c358d

Comment 15

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Comment on attachment 8743496 [details] [diff] [review]
Ensure xpcshell tests wait for calendar startup to complete

Review of attachment 8743496 [details] [diff] [review]:
-----------------------------------------------------------------

You could move the do_test_pending() into the else-case, this way you don't need to do_test_finished() for the sync case where ss.started == true. Thank you for taking care of this fix, much appreciated!

Comment 16

[Jorg K (CEST = GMT+2)]

Yes, I'd also like to thank Aleth for his continued effort. He steps in where no one else dares to tread.

Comment 17

[aleth [:aleth]]

Attachment: Fix calendar xpcshell regressions from bug 1258835

Based on the try run, it looks like fixing the above uncovered some regressions. I don't know this code, so please check this patch doesn't undo too much of the intended changes.

Comment 18

[aleth [:aleth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6a7316ecd84b

Comment 19

[aleth [:aleth]]

Comment on attachment 8743693 [details] [diff] [review]
Fix calendar xpcshell regressions from bug 1258835

Review of attachment 8743693 [details] [diff] [review]:
-----------------------------------------------------------------

Note in test_calmgr there are no changes, just a reordering (matching the previous test running order) to ensure that calendarCount is zero at the beginning of test_registration.

Comment 20

[aleth [:aleth]]

Attachment: Ensure xpcshell tests wait for calendar startup to complete

Comment 21

[aleth [:aleth]]

Comment on attachment 8743729 [details] [diff] [review]
Ensure xpcshell tests wait for calendar startup to complete

Review of attachment 8743729 [details] [diff] [review]:
-----------------------------------------------------------------

r+ carried forward.

Comment 22

[aleth [:aleth]]

Attachment: Fix calendar xpcshell regressions from bug 1258835

Yet another regression from bug 1258835 :-(

Comment 23

[aleth [:aleth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=481c2dcd1e7b

Comment 24

[aleth [:aleth]]

Looks like there are still intermittent failures in test_gdata_provider.js. 

I'm not the right person to debug those, as even when those tests pass locally, I see errors in the output (e.g. "Cannot modify properties of a WrappedNative") and am not sure if they are intentional/harmless or not.

Comment 25

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/aaf73ae87441d3361d7656c6bbec41f949b304f7
Bug 1264782 - Ensure xpcshell tests wait for calendar startup to complete. r=Fallen

Comment 26

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Comment on attachment 8743733 [details] [diff] [review]
Fix calendar xpcshell regressions from bug 1258835

Review of attachment 8743733 [details] [diff] [review]:
-----------------------------------------------------------------

I'm ok taking this patch if it would fix it short term, but I have questions:

::: calendar/test/unit/test_deleted_items.js
@@ +9,5 @@
> +    // Initialize the floating timezone without actually starting the service.
> +    cal.getTimezoneService().floating;
> +    let delmgr = Components.classes["@mozilla.org/calendar/deleted-items-manager;1"]
> +                           .getService(Components.interfaces.calIDeletedItems);
> +    delmgr.observe(null, "profile-after-change", null);

profile-after-change should be notified by do_calendar_startup, so not sure why this needs to be reverted.

::: calendar/test/unit/test_gdata_provider.js
@@ +451,5 @@
>      gServer = new GDataServer("[e-mail]", "tasksId");
>      gServer.start();
> +    do_calendar_startup(() => {
> +        do_test_pending();
> +        cal.getTimezoneService().startup({onResult: function() {

Can you explain why this is needed? The point of do_calendar_startup is to not have to spin up any services.

Comment 27

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/a5f12c8dc64f4061f86d1292208bd3a53c6d1c34
Bug 1264782 - Fix calendar xpcshell regression in test_calmgr from bug 1258835. r=Fallen

Comment 28

[aleth [:aleth]]

(In reply to Philipp Kewisch [:Fallen] from comment #26)
> I'm ok taking this patch if it would fix it short term, but I have questions:

The only part of the patch I am confident about is the test_calmgr fix, which I have just pushed.

As per comment 24, I don't think the other two "fixes" are correct. They at first appeared to fix the test failure (for reasons I didn't investigate, as they just backed out recent changes), which is why they were in the patch, but further try and local testing reveals the failure is actually intermittent and so there must be some other race condition somewhere which is causing the actual problem.

> ::: calendar/test/unit/test_deleted_items.js
> profile-after-change should be notified by do_calendar_startup, so not sure
> why this needs to be reverted.

I currently can't reproduce the failure in test_deleted_items any more. Let's see if it shows up again on c-c.

> ::: calendar/test/unit/test_gdata_provider.js

This one is weird. Locally, this test sometimes passes, and sometimes fails. But it doesn't always fail in the same place. See comment 24.
Let's close this bug and deal with that (probably unrelated) problem in a separate bug.

Comment 29

[Intermittent Failures Robot]

16 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* comm-central: 16

Platform breakdown:
* osx-10-6: 5
* osx-10-10: 5
* windowsxp: 3
* windows7-32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1264782&startday=2016-04-18&endday=2016-04-24&tree=all