429521 - [Trunk] database schema upgrade 6/7/8/9 -> 10 fails [An error was encountered preparing the calendar located at moz-profile-calendar:// for use.]

Status: RESOLVED FIXED

(Toolkit :: Storage, defect)

Description

[Stefan Sitter [:ssitter]]

[Trunk] database schema upgrade 6/7 -> 8 fails

Loading a profile that was created with a nightly build before 2008-02-18 in a nightly build after 2008-02-18 will result in a popup error message: "An error was encountered preparing the calendar located at moz-profile-calendar:// for use. It will not be available.". Error Console shows additional messages, see below.

Regression range:
  WORKS in Sunbird 0.6a1 (2008-02-18-18) trunk
  FAILS in Sunbird 0.6a1 (2008-02-19-21) trunk

  WORKS in Lightning 0.6a1 (2008-02-17-21) + Tb 3.0a1pre (2008041703)
  FAILS in Lightning 0.6a1 (2008-02-18-20) + Tb 3.0a1pre (2008041703)

Checkins during regression range: http://tinyurl.com/4vus7s --> Only Bug 410931

The error happens only if there exists at least one event in the database. From the console output it seems that in the error case the schema upgrade 6/7 -> 8 is started twice. The database itself is still schema 7 afterwards but console shows no dumps for failure case.

--------------------------------------------------------------------

Console output if no event exists (success case):
    **** Upgrading schema from 6/7 -> 8
    [calAlarmService] starting...

--------------------------------------------------------------------

Console output if event exists (failure case):
    **** Upgrading schema from 6/7 -> 8
    **** Upgrading schema from 6/7 -> 8

Error Console output:

Error: Assert failed: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [calICalendar.uri]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///[...]/sunbird/js/calCalendarManager.js :: anonymous :: line 459"  data: no]
1: [file:///[...]/sunbird/js/calUtils.js:1369] ASSERT
2: [file:///[...]/sunbird/js/calCalendarManager.js:462] anonymous
3: [file:///[...]/sunbird/js/calCalendarManager.js:602] cmgr_assureCache
4: [file:///[...]/sunbird/js/calCalendarManager.js:579] cmgr_getCalendars
5: [null:0] null
Source File: file:///[...]/sunbird/js/calUtils.js Line: 1373

--------------------------------------------------------------------

Error: Can't create calendar for 1 (storage, moz-profile-calendar://): TypeError: cal is null
Source File: file:///[...]/sunbird/js/calCalendarManager.js Line: 709

--------------------------------------------------------------------

Error: Assert failed: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [calICalendar.uri]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///[...]/sunbird/js/calCalendarManager.js :: anonymous :: line 459"  data: no]
1: [file:///[...]/sunbird/js/calUtils.js:1369] ASSERT
2: [file:///[...]/sunbird/js/calCalendarManager.js:462] anonymous
3: [null:0] null
4: [chrome://calendar/content/calendar-management.js:104] loadCalendarManager
5: [chrome://calendar/content/calendar.js:89] calendarInit
Source File: file:///[...]/sunbird/js/calUtils.js Line: 1373

--------------------------------------------------------------------

Error: calendar is null
Source File: file:///[...]/sunbird/js/calCalendarManager.js Line: 563

--------------------------------------------------------------------

Error: uncaught exception: [Exception... "'[JavaScript Error: "calendar is null" {file: "file:///[...]/sunbird/js/calCalendarManager.js" line: 563}]' when calling method: [calICalendarManager::registerCalendar]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: chrome://calendar/content/calendar-management.js :: loadCalendarManager :: line 106"  data: yes]

--------------------------------------------------------------------

Comment 3

[Stefan Sitter [:ssitter]]

Possible workaround:
1. Open with the old working Sunbird/Lightning build
2. Export each calendar to iCalendar format and save the .ics file 
   Note the URLs for remote calendars
3. Close Sunbird/Thunderbird
4. Delete the database file "storage.sdb" from profile
5. Start Sunbird/Thunderbird to create a new database file "storage.sdb"
6. Create new calendars and import the .ics files
   Resubscribe to remote calendars

Comment 4

[Stefan Sitter [:ssitter]]

Additional information:

By adding dump() statements to the source code I can follow the upgrade procedure to the following line:

    tzId = getTzIds.row.zone;

http://bonsai.mozilla.org/cvsblame.cgi?file=/mozilla/calendar/providers/storage/calStorageCalendar.js&rev=1.136&mark=1171#1152

I don't see any dump() output directly added after that statement. Seems the execution hangs/waits or has been aborted silently.

Anyone knows why the statement mentioned above works on MOZILLA_1_8_BRANCH but not on Trunk?

Comment 5

[Simon Paquet [:sipaq]]

This should definitely be fixed, but trunk bugs cannot become wanted/blocking0.9 by definition as it will be released from the branch.

Comment 6

[Stefan Sitter [:ssitter]]

Using the same Lightning builds as mentioned in Comment #0 but different Thunderbird builds I get the additional regression range:

    Works in Thunderbird 3.0a1pre (2008-01-10-03)
    Fails in Thunderbird 3.0a1pre (2008-01-11-03)

Checkins during that range: http://tinyurl.com/45w8zt

From a first glance I'd say Bug 406087 (update to sqlite 3.5.4) might be related.

Comment 7

[Stefan Sitter [:ssitter]]

Shawn, do you know if the SQLite update (Bug 406087) might be responsible for the mozStorage statement failure/hang mentioned in Comment #4 above?

Comment 8

[Shawn Wilsher :sdwilsh]

There's *a lot* different from trunk to branch in storage.  SQLite shouldn't have had an behavior change there.  Can I see a stack trace of the hang (including JS stack please)?

Comment 9

[Stefan Sitter [:ssitter]]

See also regression range mentioned in Comment #6. The very same calendar code works on Trunk up to the 2008-01-10-03 nightly build but fails in the next nightly Trunk build.

How do I create the requested JS stack? Currently all the code runs during application startup and I was only able to add some dump() statements in the code for debugging.

Comment 10

[Shawn Wilsher :sdwilsh]

When you get the hang, attach gdb, then do the following two things:
call DumpJSStack()
bt

The js stack will dump out to the console window you opened the application with, and the backtrace will dump out into gdb's terminal.

I don't know how to do that on windows though...

Comment 11

[Stefan Sitter [:ssitter]]

When trying with a debug build the information I get is:

0[a94eb0]: BEGIN TRANSACTION

0[a94eb0]: WARNING: Unsafe use of LIKE detected!  Please ensure that you are using mozIStorageConnection::escapeStringForLIKE and that you are binding that result to the statement to prevent SQL injection attacks.: file e:/dev/sb-trunk/mozilla/storage/src/mozStorageStatement.cpp, line 176

0[a94eb0]: SELECT DISTINCT(zone) FROM (SELECT recurrence_id_tz AS zone FROM cal_attendees  WHERE recurrence_id_tz LIKE '/mozilla.org%' UNION SELECT recurrence_id_tz AS zone FROM cal_events     WHERE recurrence_id_tz LIKE '/mozilla.org%' UNION SELECT event_start_tz   AS zone FROM cal_events     WHERE event_start_tz   LIKE '/mozilla.org%' UNION SELECT event_end_tz     AS zone FROM cal_events     WHERE event_end_tz     LIKE '/mozilla.org%' UNION SELECT alarm_time_tz    AS zone FROM cal_events     WHERE alarm_time_tz    LIKE '/mozilla.org%' UNION SELECT recurrence_id_tz AS zone FROM cal_properties WHERE recurrence_id_tz LIKE '/mozilla.org%' UNION SELECT recurrence_id_tz AS zone FROM cal_todos      WHERE recurrence_id_tz LIKE '/mozilla.org%' UNION SELECT todo_entry_tz    AS zone FROM cal_todos      WHERE todo_entry_tz    LIKE '/mozilla.org%' UNION SELECT todo_due_tz      AS zone FROM cal_todos      WHERE todo_due_tz      LIKE '/mozilla.org%' UNION SELECT alarm_time_tz    AS zone FROM cal_todos      WHERE alarm_time_tz    LIKE '/mozilla.org%');

Comment 12

[Stefan Sitter [:ssitter]]

Attachment: xpcshell testcase

xpcshell testcase that shows the same behavior as observed above in calStorageCalendar.js by doing the same basic steps.

Basically the code creates and initializes a mozIStorageStatementWrapper object and calls step() on it (line 64). When trying to read the row member of the wrapper object (line 69) the execution stops immediately. There is no sign for a hang.

I hope someone can use it to debug the issue.

Comment 13

[Shawn Wilsher :sdwilsh]

It'll be a lot easier if you make this test run in |make check| like the rest of the storage tests (and a lot of your functions are needed either since they are provided by head_storage.js).  It will certainly increase the likelihood of me looking at this sooner rather than later.

Comment 15

[Stefan Sitter [:ssitter]]

Attachment: xpcshell testcase, v2

testcase can be run by copying it to mozilla/storage/test/unit and executing |make check|. The execution stops immediately at the line |var tzId = wrapper.row.zone;|

Comment 16

[Shawn Wilsher :sdwilsh]

(In reply to comment #15)
> Created an attachment (id=323585) [details]
> xpcshell testcase, v2
> 
> testcase can be run by copying it to mozilla/storage/test/unit and executing
> |make check|. The execution stops immediately at the line |var tzId =
> wrapper.row.zone;|
Awesome!  I was actually going to do that myself today.  This bug is next on my todo list.

Comment 17

[Shawn Wilsher :sdwilsh]

I can reproduce - not sure what's up though...

Stepping through with gdb doesn't find it, but printing out the strings, I see they are equal.  Looking for some JS folks to chime in.

Comment 18

[Stefan Sitter [:ssitter]]

Same failure using Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2pre) Gecko/2008070219 Calendar/0.6a1.

Is there an possible workaround for the error, e.g. by changing the SQL query?

Comment 19

[Shawn Wilsher :sdwilsh]

The error is in the wrapper code (but I'm not sure why).  The workaround would be to use the mozIStorageStatement API's directly.  I need someone more familiar with the JS engine to help me out with this since it's not clear why it's hanging.

Comment 20

[Blake Kaplan (:mrbkap) (inactive)]

Attachment: Possible fix

The reason for the problem here is that the code returns false from a JS hook without reporting an error.

A minimized testcase would be either someMozStorageStatementRow[3] or someMozStorageStatementRow.foopy (where foopy isn't a column name).

Also, if you set *_retval, you don't really want to return NS_ERROR_* because that'll override the exception that the JS engine threw.

Comment 21

[Shawn Wilsher :sdwilsh]

Note - the issue with this test case is that the name isn't defined.  You need to use "AS zone" in the SQL.

Comment 22

[Shawn Wilsher :sdwilsh]

Comment on attachment 331647 [details] [diff] [review]
Possible fix

r=sdwilsh

Comment 23

[Samuel Sidler (old account; do not CC)]

Comment on attachment 331647 [details] [diff] [review]
Possible fix

Please re-request approval after this lands and bakes on mozilla-central.

Comment 24

[Blake Kaplan (:mrbkap) (inactive)]

Fix pushed as http://hg.mozilla.org/index.cgi/mozilla-central/rev/f01bfd359595