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)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: Fallen, Assigned: Fallen)

Details

Attachments

(1 file)

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.
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.
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.
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.
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
(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?
Currently, it is more a suspicion than knowledge since it only occurred twice. But I will test and report tomorrow!
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.
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.
(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.
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 ...
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 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?
(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.
(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.
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?
(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.
(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.
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.
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.
Attached patch Fix - v1 (deleted) β€” β€” Splinter Review
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: nobody → philipp
Status: NEW → ASSIGNED
Attachment #590588 - Flags: review?(mohit.kanwal)
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.
Status: ASSIGNED → RESOLVED
Closed: 13 years ago
Resolution: --- → FIXED
Target Milestone: --- → 1.4
Target Milestone: 1.4 → 1.3
Target Milestone: 1.3 → 1.2
sfleiter found a small issue with the patch. The next push messages fix that.
Target Milestone: 1.2 → 1.4
Target Milestone: 1.4 → 1.3
Target Milestone: 1.3 → 1.2
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.

Attachment

General

Created:
Updated:
Size: