Closed Bug 1264782 Opened 5 years ago Closed 5 years ago

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

Categories

(Calendar :: General, defect)

Lightning 5.0
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: ssitter, Assigned: aleth)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files, 2 obsolete files)

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.
Attached patch fix test_storage.js crash β€” β€” Splinter Review
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().
Attachment #8741509 - Flags: review?(philipp)
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.
Attachment #8741509 - Flags: review?(philipp) → review+
https://hg.mozilla.org/comm-central/rev/66f5a1abc1d9
Assignee: nobody → ssitter
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
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*)]
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
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?
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?
Blocks: 1258835
Flags: needinfo?(philipp)
Duplicate of this bug: 1265445
Summary: TEST-UNEXPECTED-FAIL | xpcshell-libical.ini:calendar/test/unit/test_storage.js | PROCESS-CRASH | application crashed [@ mozilla::AssertNotAlreadyCached] → TEST-UNEXPECTED-FAIL | xpcshell-libical.ini:calendar/test/unit/test_storage.js | TEST-UNEXPECTED-FAIL | xpcshell-icaljs.ini:calendar/test/unit/test_storage.js
or might you be running into this recent change? https://hg.mozilla.org/mozilla-central/rev/79b6b01de089#l2.12
(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.
Flags: needinfo?(philipp)
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
Flags: needinfo?(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.
Attachment #8743496 - Flags: review?(philipp)
Assignee: ssitter → aleth
Status: REOPENED → ASSIGNED
Flags: needinfo?(ssitter)
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!
Attachment #8743496 - Flags: review?(philipp) → review+
Yes, I'd also like to thank Aleth for his continued effort. He steps in where no one else dares to tread.
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.
Attachment #8743693 - Flags: review?(philipp)
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 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.
Attachment #8743729 - Flags: review+
Attachment #8743496 - Attachment is obsolete: true
Yet another regression from bug 1258835 :-(
Attachment #8743733 - Flags: review?(philipp)
Attachment #8743693 - Attachment is obsolete: true
Attachment #8743693 - Flags: review?(philipp)
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.
Flags: needinfo?(philipp)
https://hg.mozilla.org/comm-central/rev/aaf73ae87441d3361d7656c6bbec41f949b304f7
Bug 1264782 - Ensure xpcshell tests wait for calendar startup to complete. r=Fallen
Summary: 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_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
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("xpcshell@example.com", "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.
Attachment #8743733 - Flags: review?(philipp) → review+
https://hg.mozilla.org/comm-central/rev/a5f12c8dc64f4061f86d1292208bd3a53c6d1c34
Bug 1264782 - Fix calendar xpcshell regression in test_calmgr from bug 1258835. r=Fallen
(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.
Status: ASSIGNED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → 5.0
Flags: needinfo?(philipp)
Blocks: 1266823
You need to log in before you can comment on or make changes to this bug.