Last Comment Bug 790590 - Repeating events are not always synchronized if offline cache is enabled [Error syncing items: TypeError: oid.parent is not a function]
: Repeating events are not always synchronized if offline cache is enabled [Err...
Status: RESOLVED FIXED
:
Product: Calendar
Classification: Client Software
Component: Provider: GData (show other bugs)
: Lightning 1.7
: All All
: -- normal (vote)
: 1.8
Assigned To: Philipp Kewisch [:Fallen]
:
:
Mentors:
: 794894 (view as bug list)
Depends on:
Blocks: calcache
  Show dependency treegraph
 
Reported: 2012-09-12 05:19 PDT by heXler81
Modified: 2012-10-03 18:04 PDT (History)
5 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---


Attachments
Fix - v1 (2.47 KB, patch)
2012-10-02 05:58 PDT, Philipp Kewisch [:Fallen]
matthew.mecca: review+
Details | Diff | Splinter Review

Description heXler81 2012-09-12 05:19:29 PDT
User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0
Build ID: 20120824154833

Steps to reproduce:

I have a repeating event in my google calendar that I've created using the webinterface. Later I've deleted my google calender from lightning and added it anew.


Actual results:

As expected, after creating the event it showed up in Lightning as well. However, after deleting my google calender from lightning and adding it anew, the repeating event was not added to Lightning. A newly created repeating event is again displayed correctly, though.


Expected results:

The repeating event should always be displayed in Lightning.
Comment 1 Lewis Rosenthal 2012-09-12 06:02:12 PDT
What Ligtning & GData builds are you using?
I can't confirm this behavior. If I am reading your report correctly, you are saying that you can create a repeating event via GData, confirm that it is indeed created in the Google calendar, delete the calendar *just* from Lightning, add it back, and the recurring event is lost.

If you create the repeating event from the Google web interface instead, does it appear (and behave properly) in Lightning, and if you subsequently remove the calendar from Lightning and add it back, does that same event show up?
Comment 2 heXler81 2012-09-12 07:48:56 PDT
I'm using Lightning 1.7 and Google Calender Provider 0.16.
Almost right ;-)
1. I had my google calender in Lightning. 
2. Than I created a repeating event using the web interface.
3. The event showed up correctly in Lightning as well.
4. I've removed my google calender from Lightning only (i.e. the google calender was still available in the web interface).
5. I've added the calender again to Lightning.
6. "Normal" events were imported. Repeating events were missing in Lightning (but still present in the web interfacte).
Comment 3 Lewis Rosenthal 2012-09-12 08:45:31 PDT
Do you have caching enabled for the calendar in Lightning?

So, by re-reading your steps, it appears that:

1. Repeating events created in the web interface for Google Calendar while the GData Provider is configured to access that same calendar in Lightning *do* appear in Lightning.

2. Repeating events created in the web interface for Google Calendar while *no* corresponding GData-accessed calendar exists in Lightning do not appear *when* the calendar is created in Lightning.

This is still difficult to follow, logistically. Can you try creating the calendar not using GData, but instead using CalDAV, and see what you get? I'll try to recreate this situation in the interim.

Do you have any other devices/applications which access your Google calendar, and if so, are they impacted in any way? I'm trying to understand whether there is some "extra" data being introduced into these events (even when created in the web interface) which would cause them to *not* display/sync in Lightning.
Comment 4 heXler81 2012-09-13 00:13:39 PDT
Yes, this sound like what I did.

I use no other devices to access the calender. Only the webinterface and Lightning.
Caching was enabled in Lightning. After disabling the Cache, however, the repeating events are corretly displayed! But after re-enabling the cache, the repeating events are again missing.
Comment 5 heXler81 2012-09-13 07:03:34 PDT
I tried switching the caching on and off and noticed that other events are affected as well, i.e., some other events disappear as well with caching enabled. Currently it seems to me that only events in the past (i.e. before today) are affected.
Comment 6 Lewis Rosenthal 2012-09-13 07:31:33 PDT
Now we're getting to it.

Try this:

 1. Turn of caching for all calendars.
 2. Close Thunderbird/SeaMonkey/Firefox (whatever app is running Lightning).
 3. Locate your profile directory in the filesystem.
 4. Navigate to the calendar-data directory under your profile directory.
 5. Rename the cache.sqlite file to cache.sqlite.old.
 6. Start the application.
 7. Ensure that the repeating events are visible in the calendar, per your previous comment.
 8. Enable caching for the Google calendar, and allow it to build the cache.
 9. Close & re-open the application.
10. Verify that the cached data is indeed still displaying the recurring events.

I think this is specifically a cache problem where the cache isn't getting cleared out when the calendar is removed, and for some reason, when a calendar of the same name is recreated, and we "re-use" the old cached data, these previously-cached recurring events are being ignored instead of getting refreshed from the live data.

Right now, I'd just like to narrow down what's happening, and then let Philipp deal with the actual coding fix, as I think it's well beyond my capabilities.
Comment 7 heXler81 2012-09-13 22:27:27 PDT
I followed your instruction without success.
After deleting the cache.sqlite file and re-enabling the cache, the recurring events were again missing.
Comment 8 Lewis Rosenthal 2012-09-14 07:35:14 PDT
(In reply to heXler81 from comment #7)
> I followed your instruction without success.
> After deleting the cache.sqlite file and re-enabling the cache, the
> recurring events were again missing.

That is indeed odd that recurring events are still missing. Please enable calendar.debug.log and calendar.debug.log.verbose in the advanced config editor, and let's see what we can capture when building a new cache file, perhaps.

Is there anything special about the Google calendar? Is it shared? Is it a secondary calendar?
Comment 9 heXler81 2012-09-16 23:40:46 PDT
There is nothing special about my calendar. It is not shared and it is my primary calender.

When Lightning tries to sync the missing event I see the following messages in the log:

[calGoogleCalendar] Logging calIEvent:
	id:s82fth8oebl7q7j02h40dsjluk
	editurl:[private data]
	created:2012/08/15 06:51:16 Europe/Berlin isDate=0 nativeTime=1345006276000000
	updated:2012/08/15 06:51:16 Europe/Berlin isDate=0 nativeTime=1345006276000000
	title:[private data]
	content:null
	transparency:TRANSPARENT
	status:CONFIRMED
	startTime:2012/10/01 08:00:00 Europe/Berlin isDate=0 nativeTime=1349071200000000
	endTime:2012/10/01 13:00:00 Europe/Berlin isDate=0 nativeTime=1349089200000000
	location:null
	privacy:DEFAULT
	sequence:0
	alarmLastAck:null
	snoozeTime:null
	isOccurrence: false
	Organizer: 
		ID: mailto:[private data]
			Name: [private data]
			Rsvp: FALSE
			Is Organizer: yes
			Role: null
			Status: null
	Attendees: 
	recurrence: no
	alarms: no

[calGoogleCalendar] Parsing entry:
[object Element]

[calGoogleCalendar] Error syncing items:
TypeError: oid.parent is not a function

[calCachedCalendar] replayChangesOn finished.

[calCachedCalendar] sync queue empty.

Hopefully this helps the find the bug.

P.S.: I replaced anything private in the log by [private data].
Comment 10 Lewis Rosenthal 2012-09-18 06:42:42 PDT
Thanks for this.

It looks like the errant code is in js/calGoogleCalendar.js, starting at line 1250:

                if (aIsFullSync && item.recurrenceInfo) {
                    // On a full synchronization, we can go ahead and pre-parse
                    // all exceptions and then add the item at once. This way we
                    // make sure
                    for each (let oid in gdataXPath(xml, 'atom:feed/atom:entry[gd:originalEvent/@id="' + item.id + '"]')) {
                        // Get specific fields so we can speed up the parsing process
                        let status = gdataXPathFirst(oid, 'atom:entry/gd:eventStatus/@value').substring(39);

                        if (status == "canceled") {
                            let rId = gdataXPathFirst(oid, 'atom:entry/gd:when/@startTime');
                            let rDate = cal.fromRFC3339(rId, timezone);
                            item.recurrenceInfo.removeOccurrenceAt(rDate);
                            cal.LOG("[calGoogleCalendar] Negative exception " + rId + "/" + rDate);
                        } else {
                            // Parse the exception and modify the current item
                            let excItem = XMLEntryToItem(oid.parent(),
                                                         timezone,
                                                         this);
                            if (excItem) {
                                // Google uses the status field to reflect negative
                                // exceptions.
                                excItem.calendar = this;
                                item.recurrenceInfo.modifyException(excItem, true);
                            }
                        }
                    }
                }

Perhaps something changed in the Google API, but for some reason, it doesn't seem to like oid.parent(). I'm hoping that Philipp can comment further, as I simply don't know enough about this code to debug. It *does* look like a bug, though (or a mismatch between what Google wants and how we're making the request).

Good job with the log!
Comment 11 Lewis Rosenthal 2012-09-30 22:13:25 PDT
Confirmed with GData 0.19pre (2012-09-25 nightly). Turning cache off properly renders repeating events; turning it back on makes them disappear. It does not appear to be stale cache data, either; I've rebuilt the cache several times.

I'm also seeing:

Warning: Use of getAttributeNodeNS() is deprecated. Use getAttributeNS() instead.
Source file: moz-nullprincipal:{151cda4c-830d-47a2-b1b2-95bbe05bd208}

in the error log, though this may be unrelated (I am seeing an issue where selecting a calendar via RMB *after* the first time appears to open the context menu on that item but then selecting properties brings up the properties for the next calendar *below* the currently-selected one. I think the above has to do with that and not the calendar cache - unless someone else is seeing this entry, as well).

And:

Warning: Use of attributes' ownerDocument attribute is deprecated.
Source file: moz-nullprincipal:{151cda4c-830d-47a2-b1b2-95bbe05bd208}

which is documented (reported) in:

bug 771417 - Warning: Use of attributes' ownerDocument attribute is deprecated. 
bug 791491 - Lightning w/GDATA Provider, hangs Thunderbird 15
http://blog.mozilla.org/calendar/2012/07/please-test-print-support-in-lightning-1-7b2/

so not sure if directly related to this issue.

Also, I am not seeing problems with read-only (public) calendars with repeating events (holidays), but these events may not be repeating and instead may actually be individual entries.
Comment 12 Stefan Sitter 2012-10-01 10:20:41 PDT
*** Bug 794894 has been marked as a duplicate of this bug. ***
Comment 13 Stefan Sitter 2012-10-01 10:25:44 PDT
Confirming based on the various reports. Please ignore the deprecated warnings mentioned in previous comment, they are not related.

If using GData provider without cache is not an option for you just switch to using the built-in CalDAV provider instead. Instruction can be found on https://support.google.com/calendar/bin/answer.py?hl=en&answer=99358#sunbird
Comment 14 Stefan Sitter 2012-10-01 11:21:44 PDT
From a quick test the error seems to happen only for repeatings events with an EXDATE property (e.g. a single occurrence of the event was deleted) - but only if the occurrence was deleted using the Google Calendar web interface. If it was deleted from within Lightning it will not trigger the error.
Comment 15 Philipp Kewisch [:Fallen] 2012-10-02 05:58:48 PDT
Created attachment 666956 [details] [diff] [review]
Fix - v1

I'm going to push this since I'd like to do a release with it, but I'd still appreciate a review.
Comment 16 Philipp Kewisch [:Fallen] 2012-10-02 06:01:09 PDT
Pushed to comm-central changeset bef79afa4bf4
Comment 17 Philipp Kewisch [:Fallen] 2012-10-02 06:01:30 PDT
Backported to releases/comm-aurora changeset 927063d5643d
Comment 18 Philipp Kewisch [:Fallen] 2012-10-02 06:01:49 PDT
Backported to releases/comm-beta changeset 57c3eb20deb1
Comment 19 Lewis Rosenthal 2012-10-02 19:08:47 PDT
Thanks Philipp!

Applied the patch, and then had to turn off all Google calendars (4 read-only; 1 read/write) and re-enable one at a time, giving each time to rebuild the cache (my SeaMonkey crashed a couple times before I decided to turn off all calendars).

CPU load was as expected (approximately 50%), with considerable disk activity (not thrashing, however). I monitored the size of cache.sqlite, which likely had not been updating properly for some time, as it is now more than double the size it was when it started (now 14MB), and compacting makes little difference. The database *does* validate, and cached entries in the past as well as the future appear to have come down from the remote calendars.

Nice work!
Comment 20 Lewis Rosenthal 2012-10-02 20:26:26 PDT
Tested Fix v1 on two systems, and I'm finding that with cache enabled, I am unable to save new (or edit and save existing) events. Clicking Save and Close does nothing. Disabling cache allows the event to save and close.
Comment 21 Philipp Kewisch [:Fallen] 2012-10-03 00:51:18 PDT
Lewis, do you get any errors when clicking save and close? Does clicking save only work? I've tested this on my system and it seems to work without trouble.

Thanks for testing this!
Comment 22 Lewis Rosenthal 2012-10-03 06:42:41 PDT
I'll get a log snippet later this morning, Philipp. What I found in a few more minutes of testing earlier was that I *could* create a new event and save it, but *already cached* events would not save (either save or save & close) upon editing. Apologies for not posting the log with comment 20. More, when I get back to the office.
Comment 23 Lewis Rosenthal 2012-10-03 08:34:10 PDT
I applied the patch to 0.19pre running (on this particular system) under Lightning 1.8b1. Perhaps it was my mistake. Here's the log entry:

Timestamp: 10/03/2012 11:27:18 AM
Error: [Exception... "'JavaScript component does not have a method named: "modifyItemOrUseCache"' when calling method: [calIChangeLog::modifyItemOrUseCache]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: resource://calendar/modules/calUtils.jsm -> file:///home/lewis/.thunderbird/3p1xi1te.default/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calCachedCalendar.js :: <TOP_LEVEL> :: line 768"  data: no]
Source File: resource://calendar/modules/calUtils.jsm -> file:///home/lewis/.thunderbird/3p1xi1te.default/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calCachedCalendar.js
Line: 768

If this was my mistake, Philipp, I sincerely apologize for jumping the gun. The above cropped up when trying to dismiss an alarm (same symptom as editing a cached event).
Comment 24 Stefan Sitter 2012-10-03 09:08:32 PDT
Lewis, you mixed incompatible builds from different branches and therefore caused the problem yourself. If testing on comm-beta use a corresponding builds of Lightning 1.8 + GData Provider 0.17pre. Builds from different branches won't work here.
Comment 25 Philipp Kewisch [:Fallen] 2012-10-03 09:10:53 PDT
Oh I hope this is not another problem like in bug 788004. Lewis, could you apply the patch for aurora there (the one with wrapInstance) and check if the problem goes away?

I don't think 0.19 should be a problem in this specific case since gdata provider is js only, but you could try the gdata-provider from here: http://ftp.mozilla.org/pub/mozilla.org/calendar/lightning/candidates/1.8-candidates/build1/
Comment 26 Lewis Rosenthal 2012-10-03 09:15:19 PDT
Will do, Philipp.
Comment 27 Stefan Sitter 2012-10-03 09:17:35 PDT
GData provider 0.19pre or 0.18pre won't work with Lightning 1.8 because the interface for cached calendars did change in Lightning 1.9 with Bug 756052.
Comment 28 Lewis Rosenthal 2012-10-03 09:30:48 PDT
Confirmed that this was *my* error. Applying the patch to build 1 as suggested and re-testing works fine. Apologies again for the false alarm, and thanks (again) for the fix to this cache thing!
Comment 29 Matthew Mecca [:mmecca] 2012-10-03 18:04:15 PDT
Comment on attachment 666956 [details] [diff] [review]
Fix - v1

r=mmecca

Note You need to log in before you can comment on or make changes to this bug.