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 | 03/07/2014 (4135 days ago) |
Due | |
Updated | 01/30/2016 (3441 days ago) |
Assigned | 03/20/2014 (4122 days ago) |
Resolved | 01/30/2016 (3441 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
State ⇒ Stalled
New Attachment: emaillog.txt.zip
New Attachment: ANDROID1395852622431.txt.gz
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.
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'?
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).
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 just can't continue to try to trace a problem I can't create :)
properly across all devices, but a new account created from scratch
won't.
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).
not due to the EAS version mismatch.
properly across all devices, but a new account created from scratch
won't.
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.
[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 rootcause?
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?
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?
see the correct one now.
in 'emaillog.txt.gz'. All other attachments to this report can be
removed (I don't seem to have sufficient rights to do that).
also be shown in your horde log and/or webserver log. There should
also be a logged explanation as to why.
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 wasinstalled 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
#16and#17) and as far as I can tell thereare no 500 errors in there. The problem with the calendar
synchronization is still there, as can be seen in the device debug log
too.
also be shown in your horde log and/or webserver log. There should
also be a logged explanation as to why.
New Attachment: emaillog.txt.gz
New Attachment: capture.log[1].gz
basically a copy of the production server), but I can't get the
Calendar to sync at all. Log captured with tshark attached.
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.
New Attachment: capture.log.gz
basically a copy of the production server), but I can't get the
Calendar to sync at all. Log captured with tshark attached.
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...
weird on this device.
[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.
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.
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.
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.
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.
calendar anymore. Not even the ones that previously did. Even
reverting the changes doesn't fix this.
Horde_ActiveSync-2.12.4 fixed the calendar synchronization for
accounts that previously worked.
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.
State ⇒ Feedback
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
is nothing sensitive in this log, the account was created for testing
purposes only and the agenda contains only one recurring event.
Queue ⇒ Synchronization
Assigned to Michael Rubinsky
State ⇒ Assigned
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.
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Type ⇒ Bug
Summary ⇒ Exceptions to events break ActiveSync synchronization
Queue ⇒ Kronolith
Milestone ⇒
Patch ⇒ No
New Attachment: Event-breaks-sync.ics
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).