[kronolith] Import of Google Calendar (ICS) destroys users calendar and makes sync impossible

Michael J Rubinsky mrubinsk at horde.org
Sat Sep 29 01:12:36 UTC 2012 

Quoting Michael J Rubinsky <mrubinsk at horde.org>:

> Quoting Christian Bierwirth <chris at cb-solutions.de>:
>
>> Am 25.09.2012 15:37, schrieb Michael J Rubinsky:
>>>
>>> Quoting Christian Bierwirth <chris at cb-solutions.de>:
>>>
>>>> Am 24.09.2012 16:29, schrieb Michael J Rubinsky:
>>>>>
>>>>> Quoting Christian Bierwirth <chris at cb-solutions.de>:
>>>>>
>>>>>> Hi all,
>>>>>>
>>>>>> I've got an issue with an imported google-calendar
>>>>>>
>>>>>> First of all I'm using horde-webmail-edition 4.0.8, updated with
>>>>>> PEAR to the current level.
>>>>>>
>>>>>> Normal sync of calendars and addresses works fine with Android 4.1.1
>>>>>> on several galaxy-nexus smartphones with several accounts. The
>>>>>> problem occured when I imported the ICS-export of a new users
>>>>>> google-calendar. The Import worked fine, I could see all enries and
>>>>>> modify/delete them. Syncing with Android didn't work at all from
>>>>>> this point on while it did before with some test-events. I post a
>>>>>> snippet of  the debug-log at the end of this mail.
>>>>>>
>>>>>> Furthermore it is not possible to purge all the events in the
>>>>>> screwed up calender anymore after the import. Though it's no problem
>>>>>> to delete a single event. I tried several ways:
>>>>>>
>>>>>> - delete the user's standard-calendar
>>>>>> - create a new calendar, make it the standard calendar and try to
>>>>>> delete the now non-standard-calendar
>>>>>> - export the new calendar, containing one single test-event,
>>>>>> reimport it in the standard-calendar, overwriting all events
>>>>>>
>>>>>> the error always shown is:
>>>>>>
>>>>>> "Kalender von user at domain.tld" kann nicht gelöscht werden: "Kalender
>>>>>> von user at domain.tld" kann nicht gelöscht werden:
>>>>>> 20120918102621.QMxlDmRHsl5QWDAthn4AHvA at www.domain.tld not found
>>>>>
>>>>> It sounds to me like there was some error on import, or a corrupt
>>>>> event in the imported data. The error message (if I'm translating it
>>>>> correctly) means that a specific event in that calendar was not found,
>>>>> so it could not be deleted.  This was causing the entire delete
>>>>> operation to fail. I have fixed this particular issue in git.
>>>>>
>>>>>
>>>>>> (no paste error, this duplication is shown as posted here)
>>>>>>
>>>>>> So there is no way back to a working sync for this user?
>>>>>>
>>>>>> Any suggestions?
>>>>>>
>>>>>> If more information is needed I'll post it here.
>>>>>>
>>>>>> Thanks in advance!
>>>>>>
>>>>>> Chris
>>>>>>
>>>>>>
>>>>>> ##### Here comes the snippet of the logfile #####
>>>>>>
>>>>>>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: Horde::getMessage(Calendar,
>>>>>> 20120918102544.03hUWmRHsl5QWDAIGLmQIDA at www.domain.tld)
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O      <Add>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O       <ServerEntryId>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O
>>>>>> 20120918102544.03hUWmRHsl5QWDAIGLmQIDA at www.domain.tld
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O       <ServerEntryId/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O       <Data>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Timezone>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O
>>>>>> xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w==
>>>>>>
>>>>>>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Timezone/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:DtStamp>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         20120922T173255Z
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:DtStamp/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:StartTime>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         20120904T110100Z
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:StartTime/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Subject>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         Sol
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Subject/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:UID>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O
>>>>>> 32303132303931383130323534342E30336855576D5248736C355157444149474C6D51494441407777772E63622D736F6C7574696F6E732E6465
>>>>>>
>>>>>>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:UID/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Location>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         Jcs
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Location/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:EndTime>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         20120904T123100Z
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:EndTime/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Recurrence>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Type>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O          1
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Type/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Interval>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O          1
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Interval/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:DayOfWeek>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O          4
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:DayOfWeek/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:Recurrence/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:Sensitivity>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         0
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:Sensitivity/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:BusyStatus>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         2
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:BusyStatus/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:BodyTruncated>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         0
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:BodyTruncated/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O        <POOMCAL:Categories>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Category>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O
>>>>>> http://schemas.google.com/g/2005#event
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O         <POOMCAL:Category/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O <POOMCAL:Categories/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O       <Data/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O      <Add/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: Updating state during change
>>>>>> 2012-09-22T19:32:55+02:00 INFO: [androidc<DEVID>] Exported maxItems
>>>>>> of messages: 4 - more available.
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O     <Commands/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O    <Folder/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: [androidc<DEVID>] Saving state: Array
>>>>>> (
>>>>>>    [0] => {505df5f7-ae4c-416a-8436-258bb0090a9d}2
>>>>>>    [1] =>
>>>>>> a:35:{i:0;a:3:{s:2:"id";s:58:"20120918102543.WEbrdWRHsl5QWDAH8rqwIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:1;a:3:{s:2:"id";s:58:"20120918102543.BHacdGRHsl5QWDAH7aMgIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:2;a:3:{s:2:"id";s:58:"20120918102543.Wd3HHmRHsl5QWDAH6LbQIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:3;a:3:{s:2:"id";s:58:"20120918102543NPvXIWRHsl5QWDAH3nrwIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:4;a:3:{s:2:"id";s:58:"20120918102543.DinODGRHsl5QWDAH474wIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:5;a:3:{s:2:"id";s:58:"20120918102543.4l2rGGRHsl5QWDAHtz_AIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:6;a:3:{s:2:"id";s:58:"20120921163301.C5cGPmRHsl5QXHqdCe9m2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:7;a:3:{s:2:"id";s:58:"
>>>>>>
>>>>>>
>>>>>> 20120918102544.F0tdFGRHsl5QWDAIdySwIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:8;a:3:{s:2:"id";s:58:"20120921163301aAQoGWRHsl5QXHqdD_eG2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:9;a:3:{s:2:"id";s:58:"20120918102544.AGRbEWRHsl5QWDAIKZKAIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:10;a:3:{s:2:"id";s:58:"20120921163249.jHPkU2RHsl5QXHqRGQpG3EA at wwwdomain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:11;a:3:{s:2:"id";s:58:"20120920143331.aohQFGRHsl5QWw0b5w-1SBA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:12;a:3:{s:2:"id";s:58:"20120918102544.pD-xf2RHsl5QWDAIHmUQIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:13;a:3:{s:2:"id";s:58:"20120921163246sw70MmRHsl5QXHqOZS0G3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:14;a:3:{s:2:"id";s:58:"20120918102544.N2qtMGRHsl5QWDAIWTEgIDA at www.cb-
>>>>>>
>>>>>>
>>>>>> solutions.de";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:15;a:3:{s:2:"id";s:58:"20120921163246.TFe1RWRHsl5QXHqOcT6m3EA at www.domaintld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:16;a:3:{s:2:"id";s:58:"20120921163259.-TEXGWRHsl5QXHqbVz522vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:17;a:3:{s:2:"id";s:58:"20120921163246.jnodAGRHsl5QXHqOjQYm3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:18;a:3:{s:2:"id";s:58:"20120921163300.byPAXmRHsl5QXHqc7Vp22vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:19;a:3:{s:2:"id";s:58:"20120918102544.zRXaZGRHsl5QWDAIA6sAIDA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:20;a:3:{s:2:"id";s:58:"20120921163249.Wqu0A2RHsl5QXHqRoAwm3EA at www.domaintld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:21;a:3:{s:2:"id";s:58:"20120921163248.MAJqTGRHsl5QXHqQOwB23EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"
>>>>>>
>>>>>>
>>>>>> flags";s:10:"NewMessage";}i:22;a:3:{s:2:"id";s:58:"20120921163247.cqPKNGRHsl5QXHqPtjOm3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:23;a:3:{s:2:"id";s:58:"20120921163258.cqU6G2RHsl5QXHqa1i-G2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:24;a:3:{s:2:"id";s:58:"20120921163258.vI5GQmRHsl5QXHqaF2bm2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:25;a:3:{s:2:"id";s:58:"20120921163245.zF0vGWRHsl5QXHqN0E-m3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:26;a:3:{s:2:"id";s:58:"20120921163258.oqYOMWRHsl5QXHqama0m2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:27;a:3:{s:2:"id";s:58:"20120921163250.AKn5U2RHsl5QXHqSAIUW3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:28;a:3:{s:2:"id";s:58:"20120921163250.CZF9VGRHsl5QXHqSUZyW3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:29;a:3:{s:2:"id"
>>>>>>
>>>>>>
>>>>>> ;s:58:"20120921163300.Jc4aRGRHsl5QXHqcixvG2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:30;a:3:{s:2:"id";s:58:"20120921163247.HVwkMmRHsl5QXHqPCjyW3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:31;a:3:{s:2:"id";s:58:"20120921163300.MVwhTWRHsl5QXHqcOjem2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:32;a:3:{s:2:"id";s:58:"20120921163259.bNS_TGRHsl5QXHqb1NOm2vA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:33;a:3:{s:2:"id";s:58:"20120921163248.RmPuXWRHsl5QXHqQw5km3EA at www.domaintld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}i:34;a:3:{s:2:"id";s:58:"20120921163247.4_lhEGRHsl5QXHqPTzUm3EA at www.domain.tld";s:4:"type";s:6:"change";s:5:"flags";s:10:"NewMessage";}}
>>>>>>
>>>>>>
>>>>>>    [2] => androidc<DEVID>
>>>>>>    [3] => 1348335175
>>>>>>    [4] => Calendar
>>>>>>    [5] => mail at domain.tld
>>>>>> )
>>>>>>
>>>>>> 2012-09-22T19:32:55+02:00 NOTICE: [androidc<DEVID>] Error saving
>>>>>> state for synckey {505df5f7-ae4c-416a-8436-258bb0090a9d}2:
>>>>>> SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate
>>>>>> entry '{505df5f7-ae4c-416a-8436-258bb0090a9d}2' for key 'PRIMARY' -
>>>>>> removing previous sync state and trying again.
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O   <Folders/>
>>>>>> 2012-09-22T19:32:55+02:00 DEBUG: O  <Synchronize/>
>>>>>> 2012-09-22T19:32:55+02:00 INFO: User mail at domain.tld logged off
>>>>>
>>>>>
>>>>> This error is usually do to the device either not receiving the full
>>>>> server response or it not liking the data that it did receive. It
>>>>> handles this by requesting a SYNC with the same sync_id again - this
>>>>> is normal and expected in this case. We need to figure out what about
>>>>> the sync'd events the device does not like.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> mike
>>>>>
>>>>> The Horde Project (www.horde.org)
>>>>> mrubinsk at horde.org
>>>>>
>>>>>
>>>>
>>>> Hi Mike,
>>>>
>>>> thanks for your response. Do you need any more information than already
>>>> posted? Unfortunately the whole logfile ist about 80MBs in size. I could
>>>> ask the calendars owner for the google-ICS-exportfile if this would
>>>> help.
>>>
>>> If you can get me the ICS export, I'll try to take a look when I can.
>>>
>>
>> No Prob. Will send this lateron (actually I'm at work) to your
>> @horde.org address.
>>
>> Thanks again
>>
>> Chris
>
> Whatever is happening, it's only happening on Android. I've tested  
> on multiple iOS devices, a WinMo device and Android. There is  
> something in one of those events that Android does not like so it  
> ignores it and pretends it never received the data - so it send the  
> same synckey again to signify this.  I'll look and see if I can  
> figure out what the data is....

It was a bug in how we were generating the alarm values. Certain types  
of VALARM data were causing a broken, negative, value for this field.  
Android was choking on this value causing the entire sync to fail,  
while other clients were just ignoring it.

The root cause (the incorrect imported alarms) has been fixed in Git  
for Kronolith 3.0.18.


-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 6062 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.horde.org/archives/kronolith/attachments/20120928/82b950eb/attachment.bin>

More information about the kronolith mailing list