[#13022] Exceptions to events break ActiveSync synchronization
Summary Exceptions to events break ActiveSync synchronization
Queue Synchronization
Queue Version Git master
Type Bug
State Not Reproducible
Priority 1. Low
Owners mrubinsk@horde.org
Requester arjen+horde@de-korte.org
Created 2014-03-07 (1936 days ago)
Due
Updated 2016-01-30 (1242 days ago)
Assigned 2014-03-20 (1923 days ago)
Resolved 2016-01-30 (1242 days ago)
Milestone
Patch No

Comments
arjen+horde@de-korte.org 2014-03-07 15:52:24
I have several Android devices where the Calendar stopped 
synchronizing after a while (e-mail and tasks are still synchronized). 
It turns out this probably has something to do with exceptions to 
recurring events. After a recurring event is created and an exception 
is created (by removing one of the recurrences), the calendar on the 
device will no longer be synchronized. In the horde.log, a message as 
follows is logged:

2014-03-07T16:03:58+01:00 ERR: horde [horde] SQL QUERY FAILED: 
SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry 
'{5319cacf-9574-43ab-9b49-57e2c0a8010a}129' for
         INSERT INTO horde_activesync_state (sync_key, sync_data, sync_devid,
           sync_mod, sync_folderid, sync_user, sync_pending, sync_timestamp)
           VALUES ('{5319cacf-9574-43ab-9b49-57e2c0a8010a}129',
           
'C:34:"Horde_ActiveSync_Folder_Collection":88:{{"s":[],"f":"@Calendar@
           ","c":"Calendar","lsd":1392989648,"sd":1394199248,"i":true,"v":1}}',
           'ANDROID1325376003337', 8864, '@Calendar@', 'test', 'a:0:{}',
           1394204638) [pid 25266 on line 200 of 
"/usr/share/php5/PEAR/Horde/Db/Adapter/Pdo/Base.php"]

Importing the attached .ics file into an empty calendar results in 
similar behavior (the calendar is no longer synchronized and a message 
about the duplicate entry is logged). After removing the lines 
starting with 'EXDATE' from the .ics file and importing it will 
successfully synchronize to the device however, so it looks like the 
device doesn't like the exceptions. Strangely enough, if the exception 
is created on the device, the change is propagated to Horde without 
problems and the calendar on the device remains synchronized.

The device I tested this with is running Android 4.2.2 with Google 
Agenda (version 201308023).

Michael Rubinsky <mrubinsk@horde.org> 2014-03-07 16:03:16
I have no trouble locally with exceptions. I literally have dozens of 
them in my calendar and it syncs fine.

Possibly an issue with the timezone of the EXDATE, I'll take a look 
when I have time.

Michael Rubinsky <mrubinsk@horde.org> 2014-03-07 16:09:18
It would be helpful to have a synclog of the failed event being synched.

arjen+horde@de-korte.org 2014-03-07 19:02:13
> It would be helpful to have a synclog of the failed event being synched.

Sent through private mail (because of size of the attachment). There 
is nothing sensitive in this log, the account was created for testing 
purposes only and the agenda contains only one recurring event.

Michael Rubinsky <mrubinsk@horde.org> 2014-03-11 15:23:52

commit 111a5bdba46a28674b939c4e2ba5485c98c3f5f7
Author: Michael J Rubinsky <mrubinsk at horde.org>
Date:   Tue Mar 11 11:17:21 2014 -0400

     Ensure the exception is the same timezone as the the start time.

  kronolith/lib/Event.php |    8 +++++---
  1 files changed, 5 insertions(+), 3 deletions(-)

http://github.com/horde/horde/commit/111a5bdba46a28674b939c4e2ba5485c98c3f5f7
http://git.horde.org/horde-git/-/commit/111a5bdba46a28674b939c4e2ba5485c98c3f5f7

Michael Rubinsky <mrubinsk@horde.org> 2014-03-11 15:24:18
Does this fix it for you?

arjen+horde@de-korte.org 2014-03-11 20:47:13
> Does this fix it for you?

I'm afraid not. None of my accounts is able to synchronize the 
calendar anymore. Not even the ones that previously did. Even 
reverting the changes doesn't fix this.

To make sure there is no old data is (re)used, I removed the accounts 
on the devices, then dropped the horde_activesync_* tables and created 
them again through 'horde-db-migrate'. After setting up the accounts 
again on the devices, nothing changed. E-mail and tasks are 
synchronized, the calendar is not with the same error message as 
reported before:

NOTICE: [5706] Error saving state for synckey 
{531f7162-4c9c-42ab-a9d1-1648c0a8010a}5: SQLSTATE[23000]: Integrity 
constraint violation: 1062 Duplicate entry 
'{531f7162-4c9c-42ab-a9d1-1648c0a8010a}5' for key 'PRIMARY' - removing 
previous sync state and trying again.

After trying a couple of times, the following is logged:

INFO: UNSETTING collection @Calendar@ (@Calendar@) PINGABLE flag.

arjen+horde@de-korte.org 2014-03-11 21:08:59
>> Does this fix it for you?
>
> I'm afraid not. None of my accounts is able to synchronize the 
> calendar anymore. Not even the ones that previously did. Even 
> reverting the changes doesn't fix this.

Seems to be unrelated to this change. Reverting to 
Horde_ActiveSync-2.12.4 fixed the calendar synchronization for 
accounts that previously worked.

arjen+horde@de-korte.org 2014-03-12 21:34:59
This report can be closed.

I installed a different application for ActiveSync on one of these 
devices (Moxier Mail). All accounts that previously failed to 
synchronize using the built-in Android 4.2.2 Email and Calendar 
applications now synchronize just fine.

I blame Google for their shoddy ActiveSync implementation. Sorry for 
all the noise.

arjen+horde@de-korte.org 2014-03-15 15:47:33
> This report can be closed.

No, not quite. I found some new information leading me to believe 
Horde is sending something odd which triggers this. In the device log, 
I see the following entries when an occurence of a repeating event is 
removed:

E/Calendar[test@de-korte.org](20302): Uncaught exception in 
EasSyncServicejava.lang.NumberFormatException: Invalid int: "null"
E/Calendar[test@de-korte.org](20302): Sync ended due to an exception.

I'm still looking for a way to find what exactly is being sent. Any 
pointers to a direction how to check that are appreciated.

Michael Rubinsky <mrubinsk@horde.org> 2014-03-20 01:13:30

> E/Calendar[test@de-korte.org](20302): Uncaught exception in 
> EasSyncServicejava.lang.NumberFormatException: Invalid int: "null"
> E/Calendar[test@de-korte.org](20302): Sync ended due to an exception.
>
> I'm still looking for a way to find what exactly is being sent. Any 
> pointers to a direction how to check that are appreciated.

http://wiki.horde.org/ActiveSync#toc23



arjen+horde@de-korte.org 2014-03-20 10:24:50
>
>> E/Calendar[test@de-korte.org](20302): Uncaught exception in
>> EasSyncServicejava.lang.NumberFormatException: Invalid int: "null"
>> E/Calendar[test@de-korte.org](20302): Sync ended due to an exception.
>>
>> I'm still looking for a way to find what exactly is being sent. Any
>> pointers to a direction how to check that are appreciated.
>
> http://wiki.horde.org/ActiveSync#toc23

I enabled the debug log on the Android client, the result is attached 
here. Note this is for Horde_ActiveSync-2.12.4, as later versions 
break synchronisation with older clients (from which we still have a 
couple in daily use). If needed, I can setup a testserver with the 
latest version and sniff the traffic (the production server doesn't 
allow non-SSL traffic at all).

I don't know what is going on, but the CalTimeZone is looking really 
weird on this device.

arjen+horde@de-korte.org 2014-03-20 13:36:52
> I don't know what is going on, but the CalTimeZone is looking really 
> weird on this device.

The weird part being that it mentions

     [8:19:55] CalendarUtility|  Using cached TimeZone Africa/Ceuta

which probably is what is sent by Horde, but when I look in the 
preferences for this test user, it mentions 'Europe/Amsterdam'. The 
latter is probably from

     $_prefs['timezone']['value'] = 'Europe/Amsterdam';

which is defined in 'horde/config/prefs.local.php'. There is no 
'timezone' in the horde_prefs table for this user.

arjen+horde@de-korte.org 2014-03-20 20:10:05
And even if the user has a timezone defined in the preferences, the 
event has explicitly set the timezone (instead of the default one), 
when synchronizing it the Android client still insists the timezone is 
'Africa/Ceuta'. I wonder if the timezone is sent to the client at all. 
I'll see what tcpdump can do for me...

arjen+horde@de-korte.org 2014-03-21 10:02:23
It's getting worse. I'm trying to setup a test server (which is 
basically a copy of the production server), but I can't get the 
Calendar to sync at all. Log captured with tshark attached.

arjen+horde@de-korte.org 2014-03-21 12:14:17
> It's getting worse. I'm trying to setup a test server (which is 
> basically a copy of the production server), but I can't get the 
> Calendar to sync at all. Log captured with tshark attached.

The above was due to a permissions problem to access some PHP files. 
Well, that was embarrassing. After fixing this, the test-server now 
behaves like the production server, so find attached the tshark 
capture of removing an occurrence of  recurring event.

arjen+horde@de-korte.org 2014-03-21 12:16:30
And the log from the device. The error occurs at 13:05:05.

Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 06:20:33
The tshark trace shows Horde is returning a 500 error. This should 
also be shown in your horde log and/or webserver log. There should 
also be a logged explanation as to why.

arjen+horde@de-korte.org 2014-03-25 07:29:54
> The tshark trace shows Horde is returning a 500 error. This should 
> also be shown in your horde log and/or webserver log. There should 
> also be a logged explanation as to why.

I only see 500 errors in the first capture log I posted. This was due 
to a permissions problem when I copied the configuration from the 
production server to a test server, which I wrote about in Comment 
#16. Pear seems to ignore the umask setting, so Horde_Timezone was 
installed on the test server with the system wide umask 027 and owner 
root:root, so although the files existed, it wasn't readable by Apache.

After I figured out what the problem was, I posted a second capture- 
and device log (Comment #16 and #17) and as far as I can tell there 
are no 500 errors in there. The problem with the calendar 
synchronization is still there, as can be seen in the device debug log 
too.

arjen+horde@de-korte.org 2014-03-25 07:55:50
The server log is in 'capture.log[1].gz' and the device debug log is 
in 'emaillog.txt.gz'. All other attachments to this report can be 
removed (I don't seem to have sufficient rights to do that).

Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 14:32:46
Sorry about that. Could have sworn I grabbed the most recent one. I 
see the correct one now.

Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 17:06:36
I have no idea what could be causing your issues.

The capture shows nothing but normal, expected data being transferred. 
The only thing I noticed is that the tags for DELETED and 
EXCEPTIONORIGINALDATE are in the reverse order that the specs show in 
an *example*, though the spec explicitly marks them as allowed to be 
sent in any order. I've switched the order in Git, maybe your client 
is buggy and expects them in a certain order?



arjen+horde@de-korte.org 2014-03-25 20:39:20
Tried that, but now the client refuses to synchronize:

[19:32:21] Exception| Stack trace follows...
java.lang.ArrayIndexOutOfBoundsException: length=34; index=39
         at com.android.exchange.adapter.Parser.push(Parser.java:422)
         at com.android.exchange.adapter.Parser.getNext(Parser.java:506)
         at com.android.exchange.adapter.Parser.nextTag(Parser.java:304)
         at 
com.android.exchange.adapter.FolderSyncParser.parse(FolderSyncParser.java:150)
         at 
com.android.exchange.EasAccountService.sync(EasAccountService.java:337)
         at 
com.android.exchange.EasAccountService.run(EasAccountService.java:165)
         at java.lang.Thread.run(Thread.java:838)

I have no idea what is going on, but a similar 
ArrayIndexOutOfBoundsException is also logged in Bug #13052. Same root 
cause?

Currently I can't explain why some (older) accounts synchronize 
properly across all devices, but a new account created from scratch 
won't. I also don't understand where the timezone Africa/Ceuta is 
coming from in the device log. I have configured PHP to use 
Europe/Amsterdam and user preferences are also locked to this same 
timezone. If I export to ICS, it correctly shows Europe/Amsterdam. But 
what is logged on the device doesn't look anything like that (see 
emaillog.txt.gz). I see weird things logged like

[19:37:12] Calendar[arjen@de-korte.org]| All-day event arrived in: 
Africa/Ceuta
[19:37:12] Calendar[arjen@de-korte.org]| Not an all-day event locally: 
Europe/Amsterdam

Apparently, the device has the correct timezone (which is what I 
configured in the Android settings), but events arrive with a 
different timezone. Could it be there is something wrong with the 
timezone settings in Kronolith?

Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 21:03:56
> Tried that, but now the client refuses to synchronize:
>
> [19:32:21] Exception| Stack trace follows...
> java.lang.ArrayIndexOutOfBoundsException: length=34; index=39
>         at com.android.exchange.adapter.Parser.push(Parser.java:422)
>         at com.android.exchange.adapter.Parser.getNext(Parser.java:506)
>         at com.android.exchange.adapter.Parser.nextTag(Parser.java:304)
>         at 
> com.android.exchange.adapter.FolderSyncParser.parse(FolderSyncParser.java:150)
>         at 
> com.android.exchange.EasAccountService.sync(EasAccountService.java:337)
>         at 
> com.android.exchange.EasAccountService.run(EasAccountService.java:165)
>         at java.lang.Thread.run(Thread.java:838)
>
> I have no idea what is going on, but a similar 
> ArrayIndexOutOfBoundsException is also logged in Bug #13052. Same 
> root cause?

No idea. I have no idea as to what can be causing that issue, if it's 
not due to the EAS version mismatch.

> Currently I can't explain why some (older) accounts synchronize 
> properly across all devices, but a new account created from scratch 
> won't.

The previous issues with the EAS version mismatch would explain this.

> I also don't understand where the timezone Africa/Ceuta is coming 
> from in the device log. I have configured PHP to use 
> Europe/Amsterdam and user preferences are also locked to this same 
> timezone. If I export to ICS, it correctly shows Europe/Amsterdam. 
> But what is logged on the device doesn't look anything like that 
> (see emaillog.txt.gz). I see weird things logged like
>
> [19:37:12] Calendar[arjen@de-korte.org]| All-day event arrived in: 
> Africa/Ceuta
> [19:37:12] Calendar[arjen@de-korte.org]| Not an all-day event 
> locally: Europe/Amsterdam
>
> Apparently, the device has the correct timezone (which is what I 
> configured in the Android settings), but events arrive with a 
> different timezone. Could it be there is something wrong with the 
> timezone settings in Kronolith?

No idea. The timezone blob sent to the device looks correct, so I 
doubt it's a problem with Kronolith or ActiveSync. Unfortunately, 
since I can't reproduce any of this, you are going to have to tackle 
this on your own.


arjen+horde@de-korte.org 2014-03-25 21:13:54
>> Currently I can't explain why some (older) accounts synchronize
>> properly across all devices, but a new account created from scratch
>> won't.
>
> The previous issues with the EAS version mismatch would explain this.

No, not really. This is on a device that uses EAS 14.1 and is also 
happened with Horde_ActiveSync-2.12.4 (so before the regression was 
introduced). With older accounts, I mean Horde accounts, users with 
Horde accounts created years ago (some dating back to 2008).

>> Apparently, the device has the correct timezone (which is what I
>> configured in the Android settings), but events arrive with a
>> different timezone. Could it be there is something wrong with the
>> timezone settings in Kronolith?
>
> No idea. The timezone blob sent to the device looks correct, so I 
> doubt it's a problem with Kronolith or ActiveSync. Unfortunately, 
> since I can't reproduce any of this, you are going to have to tackle 
> this on your own.

I was already afraid you were going to tell me that sooner or later... :-)

Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 23:07:27
> No, not really. This is on a device that uses EAS 14.1 and is also 
> happened with Horde_ActiveSync-2.12.4 (so before the regression was 
> introduced). With older accounts, I mean Horde accounts, users with 
> Horde accounts created years ago (some dating back to 2008).

Ah. Sorry, I thought you meant older activesync accounts.

>> No idea. The timezone blob sent to the device looks correct, so I
>> doubt it's a problem with Kronolith or ActiveSync. Unfortunately,
>> since I can't reproduce any of this, you are going to have to tackle
>> this on your own.
>
> I was already afraid you were going to tell me that sooner or later... :-)

Feel free to update the ticket with any new information or questions, 
I just can't continue to try to trace a problem I can't create :)

arjen+horde@de-korte.org 2014-03-27 07:53:19
In the mean time I have migrated from PHP-5.4.26 to PHP-5.5.10 and 
PHP-FPM to mod_php, which made no difference whatsoever.

I tried setting up events in various timezones and notice that 
whatever timezone I configure for an event, it is sent to the client 
with what is logged on the client as timezone 'Africa/Ceuta'. Could 
this be due to an uncaught exception, leading to Horde not setting any 
timezone at all and the client then defaulting to 'Africa/Ceuta'?

arjen+horde@de-korte.org 2014-03-27 22:00:31
There is something really messed up in the calendar synchronization. 
When I use the timezone 'Europe/Amsterdam', the device chokes on the 
data it receives from Horde. However, when I select timezone 
'America/New York', something different happens. Besides jumping the 
timestamps representation in the logs between the local timezone 
'Europe/Amsterdam' and 'America/New York', it now synchronizes the 
calendar. Sort of. As the end of the 'ANDROID1395852622431.txt.gz´ 
shows, Horde sees that events are changed, but somehow doesn't send 
the changes to the device. I'll attach the device log next.

arjen+horde@de-korte.org 2014-03-27 22:01:26
And the device log.

Michael Rubinsky <mrubinsk@horde.org> 2015-02-05 15:17:50
Stalling. Cannot reproduce and sounds like a client issue anyway.