6.0.0-git
2019-09-17

[#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 (at) horde (dot) org
Requester arjen+horde (at) de-korte (dot) org
Created 2014-03-07 (2020 days ago)
Due
Updated 2016-01-30 (1326 days ago)
Assigned 2014-03-20 (2007 days ago)
Resolved 2016-01-30 (1326 days ago)
Milestone
Patch No

History
2016-01-30 19:49:43 Michael Rubinsky State ⇒ Not Reproducible
 
2015-02-05 15:17:50 Michael Rubinsky Comment #30
State ⇒ Stalled
Reply to this comment
Stalling. Cannot reproduce and sounds like a client issue anyway.
2014-03-27 22:01:26 arjen+horde (at) de-korte (dot) org Comment #29
New Attachment: emaillog.txt.zip Download
Reply to this comment
And the device log.
2014-03-27 22:00:31 arjen+horde (at) de-korte (dot) org Comment #28
New Attachment: ANDROID1395852622431.txt.gz Download
Reply to this comment
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.
2014-03-27 07:53:19 arjen+horde (at) de-korte (dot) org Comment #27 Reply to this comment
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'?
2014-03-25 23:07:27 Michael Rubinsky Comment #26 Reply to this comment
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 :)
2014-03-25 21:13:54 arjen+horde (at) de-korte (dot) org Comment #25 Reply to this comment
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).

[Show Quoted Text - 9 lines]
I was already afraid you were going to tell me that sooner or later... :-)
2014-03-25 21:03:56 Michael Rubinsky Comment #24 Reply to this comment

[Show Quoted Text - 18 lines]
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.

[Show Quoted Text - 16 lines]
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.

2014-03-25 20:39:20 arjen+horde (at) de-korte (dot) org Comment #23 Reply to this comment
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?
2014-03-25 17:06:36 Michael Rubinsky Comment #22 Reply to this comment
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?


2014-03-25 14:33:58 Michael Rubinsky Deleted Original Message
 
2014-03-25 14:33:23 Michael Rubinsky Deleted Original Message
 
2014-03-25 14:32:46 Michael Rubinsky Comment #21 Reply to this comment
Sorry about that. Could have sworn I grabbed the most recent one. I 
see the correct one now.
2014-03-25 07:55:50 arjen+horde (at) de-korte (dot) org Comment #20 Reply to this comment
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).
2014-03-25 07:29:54 arjen+horde (at) de-korte (dot) org Comment #19 Reply to this comment
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.
2014-03-25 06:20:33 Michael Rubinsky Comment #18 Reply to this comment
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.
2014-03-21 12:16:30 arjen+horde (at) de-korte (dot) org Comment #17
New Attachment: emaillog.txt.gz Download
Reply to this comment
And the log from the device. The error occurs at 13:05:05.
2014-03-21 12:14:17 arjen+horde (at) de-korte (dot) org Comment #16
New Attachment: capture.log[1].gz Download
Reply to this comment
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.
2014-03-21 10:02:23 arjen+horde (at) de-korte (dot) org Comment #15
New Attachment: capture.log.gz
Reply to this comment
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.
2014-03-20 20:10:05 arjen+horde (at) de-korte (dot) org Comment #14 Reply to this comment
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...
2014-03-20 13:36:52 arjen+horde (at) de-korte (dot) org Comment #13 Reply to this comment
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.
2014-03-20 10:25:31 arjen+horde (at) de-korte (dot) org New Attachment: emaillog.zip
 
2014-03-20 10:24:50 arjen+horde (at) de-korte (dot) org Comment #12 Reply to this comment

[Show Quoted Text - 9 lines]
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.
2014-03-20 01:13:47 Michael Rubinsky State ⇒ Feedback
 
2014-03-20 01:13:30 Michael Rubinsky Comment #11 Reply to this comment
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


2014-03-15 15:47:33 arjen+horde (at) de-korte (dot) org Comment #10 Reply to this comment
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.
2014-03-13 04:08:36 Michael Rubinsky State ⇒ Resolved
 
2014-03-12 21:34:59 arjen+horde (at) de-korte (dot) org Comment #9 Reply to this comment
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.
2014-03-11 21:08:59 arjen+horde (at) de-korte (dot) org Comment #8 Reply to this comment
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.
2014-03-11 20:47:13 arjen+horde (at) de-korte (dot) org Comment #7 Reply to this comment
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.
2014-03-11 15:24:18 Michael Rubinsky Comment #6
State ⇒ Feedback
Reply to this comment
Does this fix it for you?
2014-03-11 15:23:52 Michael Rubinsky Comment #5 Reply to this comment

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
2014-03-07 19:02:13 arjen+horde (at) de-korte (dot) org Comment #4 Reply to this comment
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.
2014-03-07 16:09:18 Michael Rubinsky Comment #3 Reply to this comment
It would be helpful to have a synclog of the failed event being synched.
2014-03-07 16:03:41 Michael Rubinsky Version ⇒ Git master
Queue ⇒ Synchronization
 
2014-03-07 16:03:16 Michael Rubinsky Comment #2
Assigned to Michael Rubinsky
State ⇒ Assigned
Reply to this comment
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.
2014-03-07 15:52:24 arjen+horde (at) de-korte (dot) org Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Summary ⇒ Exceptions to events break ActiveSync synchronization
Queue ⇒ Kronolith
Milestone ⇒
Patch ⇒ No
New Attachment: Event-breaks-sync.ics Download
Reply to this comment
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).

Saved Queries