Closed
Bug 700637
Opened 13 years ago
Closed 13 years ago
this.mItemInfoCache[aNewItem.id] is null using caldav cached calendar
Categories
(Calendar :: Provider: CalDAV, defect)
Calendar
Provider: CalDAV
Tracking
(Not tracked)
RESOLVED
FIXED
1.2
People
(Reporter: Fallen, Assigned: Fallen)
Details
Attachments
(1 file)
(deleted),
patch
|
redDragon
:
review+
|
Details | Diff | Splinter Review |
I haven't been able to reproduce this correctly, but it happens randomly once in a while:
Modifying an item (in my case, dismissing an alarm) no longer works and fails with the error in the summary, line 691. Debugging into it, the mItemInfoCache is indeed filled with information, just not on the item being changed.
A workaround would be to catch all cases where the item info cache doesn't contain the item, but this means the location path might not be correct and the etag is not sent.
It would be splendid if we could find out why this happens in the first place.
Assignee | ||
Comment 1•13 years ago
|
||
Also, its impossible to make this go away since the ctag matches and when updating items nothing is done. The only way to do so is to disable/re-enable the cache or delete cache.sqlite.
Comment 2•13 years ago
|
||
According to https://trac.calendarserver.org/browser/CalendarServer/trunk/doc/Extensions/caldav-ctag.txt
It seems like the ctag only changes when there is a change to the "calendar collection" at the server side.
But the offline modification, does not change the ctag, and somehow if modified items are not played back, then I think in my view this problem might be reproduced, i have tried to reproduce it by shutting down SOGo Calendar server, but no luck yet. Some weird combination of playback, offline modify must be breaking this.
Assignee | ||
Comment 3•13 years ago
|
||
An offline modification doesn't have to change the ctag, but pushing the items back to the server should. I'm not sure if its actually the ctag being the same, but this at least explains why we never get an updated copy of the item and the problem won't go away when it shows up.
I'll have to make this show up again until I can definitely say that changing the ctag server side makes it go away though. In any case, this would relieve the problem, but its not the core issue.
Comment 4•13 years ago
|
||
I run into this issue every now and then with TB8 and Lightning 1.0.
I get the impressiton that it could be related to
1. Quiting TB8 on PC 1
2. Editing calendars on PC 2
3. Starting TB8 on PC 1
Workaround: Deactivate and re-activate cache
Comment 5•13 years ago
|
||
(In reply to Michael Duelli from comment #4)
> I run into this issue every now and then with TB8 and Lightning 1.0.
>
> I get the impressiton that it could be related to
> 1. Quiting TB8 on PC 1
> 2. Editing calendars on PC 2
> 3. Starting TB8 on PC 1
>
> Workaround: Deactivate and re-activate cache
Awesome! so u r able to reproduce the issue, most of the time using the steps above?
Comment 6•13 years ago
|
||
Currently, it is more a suspicion than knowledge since it only occurred twice.
But I will test and report tomorrow!
Comment 7•13 years ago
|
||
So far, my tests were not able to reproduce the problem. I will try to figure this out when the problem occurs the next time.
Comment 8•13 years ago
|
||
Here is how I reproduce it:
1) create a daily recurring event starting 10 minutes from now, with a reminder 5 minutes before the beginning of the event
2) dismiss the alarm a first time
3) close Thunderbird
4) reopen it only when the next alarm will popup
5) try to dismiss it again
I understand that this is not a really scalable way to debug the issue but that is the only scenario I have found so far.
Also, it is not really explicit from the original bug description but once the issue has started to show up, there is nothing one can do with that event anymore, not even delete it.
Comment 9•13 years ago
|
||
(In reply to Arnaud Quillaud from comment #8)
> Here is how I reproduce it:
> 1) create a daily recurring event starting 10 minutes from now, with a
> reminder 5 minutes before the beginning of the event
> 2) dismiss the alarm a first time
> 3) close Thunderbird
> 4) reopen it only when the next alarm will popup
> 5) try to dismiss it again
>
> I understand that this is not a really scalable way to debug the issue but
> that is the only scenario I have found so far.
>
YES this scenario reproduces the bug, I can confirm, I did wait one or two days for the alarm to pop up again, and I received 3 error messages in the console, now the next thing is to reproduce it at a constant basis and then find the cause.
> Also, it is not really explicit from the original bug description but once
> the issue has started to show up, there is nothing one can do with that
> event anymore, not even delete it.
Comment 10•13 years ago
|
||
I got there too. I cannot save any new events to the calendar. I was adding participants to an event and moving it in time. However, I was online all the time ...
Assignee | ||
Comment 11•13 years ago
|
||
Glad this is now reproducable!
You could possibly use a different client that allows more fine-grained recurrence rules, or maybe even use a command line utility like curl to change the event so that it uses FREQ=HOURLY (i.e recurrs every 1 hour), I think there was also MINUTELY. Please check the rfc to make sure.
Comment 12•13 years ago
|
||
I tried debugging this further. Here's what I get :-
This is the sequence of actions performed when an event is dismissed the second time (right before the aNewItem.id is null gets raised)
2: [resource://calendar/modules/calUtils.jsm -> file:///Users/msk/Desktop/gem/comm-central/obj-x86_64-apple-darwin10.8.0/mozilla/dist/Daily.app/Contents/MacOS/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calCachedCalendar.js:779] null
3: [resource://calendar/modules/calUtils.jsm -> file:///Users/msk/Desktop/gem/comm-central/obj-x86_64-apple-darwin10.8.0/mozilla/dist/Daily.app/Contents/MacOS/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calAlarmService.js:243] cAS_dismissAlarm
4: [chrome://calendar/content/calendar-alarm-dialog.js:77] onDismissAlarm
5: [chrome://calendar/content/widgets/calendar-alarm-widget.xml:221] dismissAlarm
6: [chrome://calendar/content/calendar-alarm-dialog.xul:1] oncommand
7: [null:0] null
and following the code from the moment the dismiss_Alarm is called: http://mxr.mozilla.org/comm-central/source/calendar/base/src/calAlarmService.js
the aNewItem is essentially a clone of the aOldItem.parent, as such the meta information, about the old item is not within the mItemInfoCache, at the time the alarm gets dismissed.
Now why is this so? Stuck at this.... I am using a google caldav calendar btw.
(In reply to Philipp Kewisch [:Fallen] from comment #11)
> Glad this is now reproducable!
>
> You could possibly use a different client that allows more fine-grained
> recurrence rules, or maybe even use a command line utility like curl to
> change the event so that it uses FREQ=HOURLY (i.e recurrs every 1 hour), I
> think there was also MINUTELY. Please check the rfc to make sure.
I changed the recurrence rule directly in the sqlite DB to HOURLY and then MINUTELY (According to the RFC they are valid FREQ) , but it did not work out. Does Lightning process hourly or minutely recurrences?
Also, a comment at http://mxr.mozilla.org/comm-central/source/calendar/base/src/calAlarmService.js
232 // We want the parent item, otherwise we're going to accidentally create an
233 // exception. We've relnoted (for 0.1) the slightly odd behavior this can
234 // cause if you move an event after dismissing an alarm
Is Felix's behavior (reported in comment#10) is related to the above comment?
Comment 13•13 years ago
|
||
(In reply to Mohit Kanwal [:redDragon] from comment #12)
> and following the code from the moment the dismiss_Alarm is called:
> http://mxr.mozilla.org/comm-central/source/calendar/base/src/calAlarmService.
> js
> the aNewItem is essentially a clone of the aOldItem.parent, as such the meta
> information, about the old item is not within the mItemInfoCache, at the
> time the alarm gets dismissed.
>
> Now why is this so? Stuck at this.... I am using a google caldav calendar
> btw.
I'm not sure if this answers your question, but aNewItem starts as a clone of aOldItem.parent because the alarm service only modifies the parent item when an alarm is updated for an occurrence, rather than creating an exception. I don't know how that affects mItemInfoCache though.
Comment 14•13 years ago
|
||
(In reply to Matthew Mecca [:mmecca] from comment #13)
Yes, the mItemInfoCache stores meta objects according to the id, and aNewItem and aOldItem have the same ids in this case, however the meta information was missing when essentially it should be present, as the id is the same, and the assumption is that meta info about aOldItem already exists..(being downloaded from a previous transaction)
What's intriguing is that, the info is missing for that particular id from mItemInfoCache. aOldItem and aNewItem have the same id (in the case of dismissal of reminders). They share the same meta info. I believe there is a deletion of old meta data happening in the workflow somewhere, which is raising the error.
Assignee | ||
Comment 15•13 years ago
|
||
I've had this happen in other cases where no dismiss was involved. Since you are keying the mItemInfoCache with the "id" getter, that shouldn't be a problem since (item.id == item.parentItem.id) is true.
I don't know how/if Lightning process HOURLY/MINUTELY occurrences, I just assumed it would work since this should be part of libical. I've never tried, so it might not work for some other reason.
Could you maybe add warn messages everywhere that the metadata is removed from mItemInfoCache, with a stack? This way you could see in which cases its being removed and why. Or have you already done that?
Comment 16•13 years ago
|
||
(In reply to Philipp Kewisch [:Fallen] from comment #15)
> I've had this happen in other cases where no dismiss was involved. Since you
> are keying the mItemInfoCache with the "id" getter, that shouldn't be a
> problem since (item.id == item.parentItem.id) is true.
>
> I don't know how/if Lightning process HOURLY/MINUTELY occurrences, I just
> assumed it would work since this should be part of libical. I've never
> tried, so it might not work for some other reason.
nope was not able to make it work. I edited the sqlite file directly using a sqlite viewer. is that the correct way?
>
> Could you maybe add warn messages everywhere that the metadata is removed
> from mItemInfoCache, with a stack? This way you could see in which cases its
> being removed and why. Or have you already done that?
Nope haven't done it, I am going to grep mCachedItemInfo and add debug or WARN messages everywhere..
Wolfgang was mentioning in the IRC that caldav calendars start a request before they have finished one, and the offline code had something to do with it. Do you know which part was he talking about? I feel it might have something to do with this behavior as it was not happening before.
Assignee | ||
Comment 17•13 years ago
|
||
(In reply to Mohit Kanwal [:redDragon] from comment #16)
> (In reply to Philipp Kewisch [:Fallen] from comment #15)
> > I've had this happen in other cases where no dismiss was involved. Since you
> > are keying the mItemInfoCache with the "id" getter, that shouldn't be a
> > problem since (item.id == item.parentItem.id) is true.
> >
> > I don't know how/if Lightning process HOURLY/MINUTELY occurrences, I just
> > assumed it would work since this should be part of libical. I've never
> > tried, so it might not work for some other reason.
> nope was not able to make it work. I edited the sqlite file directly using a
> sqlite viewer. is that the correct way?
Yeah that should be correct. Maybe you can instead try importing or subscribing to an .ics file that has been modified beforehand.
> >
> > Could you maybe add warn messages everywhere that the metadata is removed
> > from mItemInfoCache, with a stack? This way you could see in which cases its
> > being removed and why. Or have you already done that?
> Nope haven't done it, I am going to grep mCachedItemInfo and add debug or
> WARN messages everywhere..
Great!
>
> Wolfgang was mentioning in the IRC that caldav calendars start a request
> before they have finished one, and the offline code had something to do with
> it. Do you know which part was he talking about? I feel it might have
> something to do with this behavior as it was not happening before.
I don't quite remember, I think this has to do with the fact that we do all requests from the different areas of calendar at once. Therefore its possible that multiple getItems() requests are done before all properties are collected. Maybe you can ask Wolfgang about this, he would know best.
Assignee | ||
Comment 18•13 years ago
|
||
I successfully modified an item to be a MINUTELY event, here are the steps:
1. Install ICS Inspector extension from addons.mozilla.org (please tell me if the uploaded version doesn't work, my local one does)
2. Right click on daily recurring event, select "Evaluate Javascript..."
3. Check "Target Master Item"
4. Insert the following code:
var f = target.clone();
var ri = f.recurrenceInfo.getRecurrenceItemAt(0)
.QueryInterface(Components.interfaces.calIRecurrenceRule);
ri.type = "MINUTELY";
ri.count = 20;
f.recurrenceInfo.setRecurrenceItems(1, [ri]);
target.calendar.modifyItem(f, target, null);
5. You now have a MINUTELY recurring event. Have fun!
On the downside, I was not able to reproduce the steps from comment 8. I haven't tried a DAILY recurrence item yet.
Assignee | ||
Comment 19•13 years ago
|
||
BUT, I found another reliable way to reproduce this bug that doesn't require waiting a full day. The result is not as severe as the message only shows up twice at startup, but maybe its the same root cause:
1. Create an event (doesn't have to be recurring), without an alarm
2. Go into offline mode
3. Add an alarm to the item and dismiss it
4. Restart
Now you have two messages with mItemInfoCache[aNewItem.id] being null, coming from the modify that is being done at startup by the offline cache. The item is not very much editable, as with the other situation.
Debug info tells me, that there is no metadata for this item in the sqlite database and the metadata is retrieved before the errors show up.
Assignee | ||
Comment 20•13 years ago
|
||
Hey Mohit, thanks to the shorter STRs I likely found the problem. When an item is modified in the storage calendar, everything related is removed and the new item is written.
Unfortunately the metadata is also removed in that process, which is not added back. This patch doesn't remove the metadata during a modify action and fixes the issue for me.
Could you give it a test run?
Assignee | ||
Comment 21•13 years ago
|
||
I'm going to push this to get some testing in 1.2, I think it won't do any harm and just make things better. I'd still appreciate a review.
Assignee | ||
Comment 22•13 years ago
|
||
Pushed to comm-central changeset 7fea8872e552
Status: ASSIGNED → RESOLVED
Closed: 13 years ago
Resolution: --- → FIXED
Target Milestone: --- → 1.4
Assignee | ||
Comment 23•13 years ago
|
||
Backported to releases/comm-aurora changeset d68585c44d73
Target Milestone: 1.4 → 1.3
Assignee | ||
Comment 24•13 years ago
|
||
Backported to releases/comm-beta changeset 9db859c4e543
Target Milestone: 1.3 → 1.2
Assignee | ||
Comment 25•13 years ago
|
||
sfleiter found a small issue with the patch. The next push messages fix that.
Assignee | ||
Comment 26•13 years ago
|
||
Pushed to comm-central changeset ace0712e72cd
Target Milestone: 1.2 → 1.4
Assignee | ||
Comment 27•13 years ago
|
||
Backported to releases/comm-aurora changeset d27f4570cdce
Target Milestone: 1.4 → 1.3
Assignee | ||
Comment 28•13 years ago
|
||
Backported to releases/comm-beta changeset bebd8b92e89b
Target Milestone: 1.3 → 1.2
Comment 29•13 years ago
|
||
Comment on attachment 590588 [details] [diff] [review]
Fix - v1
Review of attachment 590588 [details] [diff] [review]:
-----------------------------------------------------------------
I guess we could choose not to delete the meta data when its a modify. However, I am concerned if changing function signature would break other things.
Setting plus to speed up things.
Attachment #590588 -
Flags: review?(mohit.kanwal) → review+
You need to log in
before you can comment on or make changes to this bug.
Description
•