Tickets :: [#14255] Shared calendar Android 6 - /POOMCAL:Exception

6.0.0-beta1

7/17/25

Summary	Shared calendar Android 6 - /POOMCAL:Exception
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Resolved
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	samuel.wolf (at) wolf-maschinenbau (dot) de
Created	02/14/2016 (3441 days ago)
Due
Updated	02/18/2016 (3437 days ago)
Assigned	02/18/2016 (3437 days ago)
Resolved	02/18/2016 (3437 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

02/18/2016 10:53:57 PM	Michael Rubinsky	Comment #34 State ⇒ Resolved	Reply to this comment
WooHoo! :)

02/18/2016 10:52:35 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #33	Reply to this comment
Hah :) It's fixed, wow, thank you very much.

02/18/2016 10:49:14 PM	Michael Rubinsky	Comment #32	Reply to this comment
Hah :) No worries, I'm pretty confident it's right now, so I'll just go ahead and release the package so you can update easier.

02/18/2016 10:41:38 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #31	Reply to this comment
...oh thats my fault sorry. I overwrite the wrong file.

02/18/2016 10:39:16 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #30	Reply to this comment
Anything in the server error log? Good point! [Thu Feb 18 23:21:46.998344 2016] [:error] [pid 26177] [client xx.xx.xx.xx:56902] PHP Fatal error: Cannot redeclare class Horde_ActiveSync_Message_Exception in /usr/share/php/Horde/ActiveSync/Exception.php on line 0 wget https://raw.githubusercontent.com/horde/horde/d067bef227edaeff223e5d89fc092f4829bc75e5/framework/ActiveSync/lib/Horde/ActiveSync/Message/Exception.php b82c7eafebf9a972c9a161ff7f4aec50 Exception.php

02/18/2016 10:33:29 PM	Michael Rubinsky	Comment #29	Reply to this comment
Anything in the server error log?

02/18/2016 10:21:52 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #28	Reply to this comment
Yeah, try resetting the state, or recreating the account on device. Try both, but the sync stop in the middle: 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:Recurrence> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:Type> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 5 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:Type> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:Interval> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 1 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:Interval> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:DayOfMonth> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 8 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:DayOfMonth> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:MonthOfYear> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 6 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:MonthOfYear> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:CalendarType> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 1 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:CalendarType> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O <POOMCAL:FirstDayOfWeek> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O 1 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:FirstDayOfWeek> 2016-02-18T23:15:25+01:00 DEBUG: [26154] O </POOMCAL:Recurrence> 2016-02-18T22:16:26+00:00 INFO: [26370] Horde_Core_ActiveSync_Driver::authenticate() attempt for samuel 2016-02-18T22:16:26+00:00 INFO: [26370] PING request received for user samuel 2016-02-18T22:16:26+00:00 INFO: [26370] Device entry exists for ANDROID1436587622439, updating userAgent, version, and supported. 2016-02-18T22:16:26+00:00 INFO: [26370] Request being handled for device: ANDROID1436587622439, Supporting protocol version: 14.1, Using Horde_ActiveS ync v2.31.3

02/18/2016 10:08:19 PM	Michael Rubinsky	Comment #27	Reply to this comment
Yeah, try resetting the state, or recreating the account on device.

02/18/2016 10:04:44 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #26	Reply to this comment
Device stop syncing complete now: 2016-02-18T22:02:20+00:00 DEBUG: [25783] I <FolderHierarchy:FolderSync> 2016-02-18T22:02:20+00:00 DEBUG: [25783] I <FolderHierarchy:SyncKey> 2016-02-18T22:02:20+00:00 DEBUG: [25783] I {56c636ad-a45c-4bab-8514-6272c0a8372d}3 2016-02-18T22:02:20+00:00 DEBUG: [25783] I </FolderHierarchy:SyncKey> 2016-02-18T22:02:20+00:00 INFO: [25783] Creating new Horde_ActiveSync_SyncCache. 2016-02-18T22:02:20+00:00 INFO: [25783] Loading state for synckey {56c636ad-a45c-4bab-8514-6272c0a8372d}3 2016-02-18T22:02:20+00:00 WARN: [25783] Could not find state for synckey {56c636ad-a45c-4bab-8514-6272c0a8372d}3. Reset the states, something I missing?

02/18/2016 09:55:06 PM	Michael Rubinsky	Comment #25	Reply to this comment
Can you see if these changes fix it for you?

02/18/2016 09:53:30 PM	Git Commit	Comment #24	Reply to this comment
Changes have been made in Git (master): commit d067bef227edaeff223e5d89fc092f4829bc75e5 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Thu Feb 18 16:52:51 2016 -0500 Better fix for ~~Bug: 14255~~ Don't fail, but attempt to correct the values. .../lib/Horde/ActiveSync/Message/Exception.php \| 18 ++++++++---------- 1 files changed, 8 insertions(+), 10 deletions(-) http://github.com/horde/horde/commit/d067bef227edaeff223e5d89fc092f4829bc75e5

02/18/2016 09:22:54 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #23	Reply to this comment
Just released a new Horde_ActiveSync package which should hopefully fix this for you. Instal it, but still the same error: 2016-02-18T22:21:08+01:00 DEBUG: [24577] O 1 2016-02-18T22:21:08+01:00 DEBUG: [24577] O </POOMCAL:FirstDayOfWeek> 2016-02-18T22:21:08+01:00 DEBUG: [24577] O </POOMCAL:Recurrence> 2016-02-18T22:21:08+01:00 ERR: [24577] Unknown backend error skipping message: Pre-encoding validation failded for Horde_ActiveSync_Message_Exception item 2016-02-18T22:21:08+01:00 INFO: [24577] Updating state during change 2016-02-18T22:21:08+01:00 INFO: [24577] Peak memory usage after message: 6815744 Caching issue?

02/18/2016 09:18:44 PM	Michael Rubinsky	Comment #22	Reply to this comment
Just released a new Horde_ActiveSync package which should hopefully fix this for you.

02/18/2016 08:56:19 PM	Git Commit	Comment #21	Reply to this comment
Changes have been made in Git (master): commit 4406462d3e47e0462c31555c4f67cc2cd36c3530 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Thu Feb 18 15:54:31 2016 -0500 ~~Bug: 14255~~ Exceptions may not have a starttime set. .../lib/Horde/ActiveSync/Message/Exception.php \| 52 ++++++++++++++++++++ 1 files changed, 52 insertions(+), 0 deletions(-) http://github.com/horde/horde/commit/4406462d3e47e0462c31555c4f67cc2cd36c3530

02/18/2016 08:40:40 PM	Michael Rubinsky	Comment #20	Reply to this comment
There is also another error in the log, see attachment. Now we are getting somewhere :) Think I see the issue now.

02/18/2016 07:49:41 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #19 New Attachment: Horde_Debug_Log.txt	Reply to this comment
Does removing the event and recreating it do anything useful? If I delete the event the sync stop with the next event of the shared calendar. But if I open the event and save it in my local calendar the device sync it and stop again on the next event of the shared calendar. There is also another error in the log, see attachment.

02/18/2016 06:58:12 PM	Michael Rubinsky	State ⇒ Feedback

02/18/2016 06:58:00 PM	Michael Rubinsky	Comment #18	Reply to this comment
Can't reproduce at all. Not sure what else to do at this point. Maybe a wiretrace will show something, but otherwise out of ideas. Does removing the event and recreating it do anything useful?

02/17/2016 07:52:51 PM	Michael Rubinsky	Comment #17 State ⇒ Assigned	Reply to this comment
Ah, ok. You are still seeing the the calendar issue. You are correct, my patch was only for the mail issue.

02/17/2016 07:50:19 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #16	Reply to this comment
The changes I made will be in the next package update anyway, so hopefully it will prevent whatever happened from happening again. But this fix only the mail issue or should it fix the calendar issue as well? Still have the problem with the calendar (but don't try your commit since I think this is only for the mail issue).

02/17/2016 07:43:55 PM	Michael Rubinsky	Comment #15 State ⇒ Resolved	Reply to this comment
Well, that's still sort of good news :) The changes I made will be in the next package update anyway, so hopefully it will prevent whatever happened from happening again.

02/17/2016 07:23:26 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #14	Reply to this comment
Is badly broken. The client is sending an empty <Data> field. In otherwords, it's telling the server to modify the email with UID 9655, but is not telling the server what to modify. I am really sorry, I can not reproduce the issue now. :-( No idea whats going wrong two days before.

02/17/2016 06:09:53 PM	Michael Rubinsky	Comment #13	Reply to this comment
[Show Quoted Text - 13 lines][Hide Quoted Text] Changes have been made in Git (master): commit f201f65d59e3dc05d5ca0f312042a9f1ebaf41a0 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Wed Feb 17 12:28:50 2016 -0500 ~~Bug: 14255~~ Work around broken clients that send empty <Data> tags. .../lib/Horde/ActiveSync/Request/Sync.php \| 79 +++++++++++--------- 1 files changed, 43 insertions(+), 36 deletions(-) http://github.com/horde/horde/commit/f201f65d59e3dc05d5ca0f312042a9f1ebaf41a0 Are you able to test to see if this solves at least the looping email request for you?

02/17/2016 05:29:41 PM	Git Commit	Comment #12	Reply to this comment
Changes have been made in Git (master): commit f201f65d59e3dc05d5ca0f312042a9f1ebaf41a0 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Wed Feb 17 12:28:50 2016 -0500 ~~Bug: 14255~~ Work around broken clients that send empty <Data> tags. .../lib/Horde/ActiveSync/Request/Sync.php \| 79 +++++++++++--------- 1 files changed, 43 insertions(+), 36 deletions(-) http://github.com/horde/horde/commit/f201f65d59e3dc05d5ca0f312042a9f1ebaf41a0

02/17/2016 05:17:19 PM	Michael Rubinsky	Comment #11	Reply to this comment
There is more broken than I guess, at the moment the device loop with a mail. This: 2016-02-15T21:43:34+00:00 DEBUG: [27458] I <Modify> 2016-02-15T21:43:34+00:00 DEBUG: [27458] I <ServerEntryId> 2016-02-15T21:43:34+00:00 DEBUG: [27458] I 9655 2016-02-15T21:43:34+00:00 DEBUG: [27458] I </ServerEntryId> 2016-02-15T21:43:34+00:00 DEBUG: [27458] I <Data /> 2016-02-15T21:43:34+00:00 DEBUG: [27458] I </Modify> Is badly broken. The client is sending an empty <Data> field. In otherwords, it's telling the server to modify the email with UID 9655, but is not telling the server what to modify.

02/16/2016 03:42:20 PM	Michael Rubinsky	Comment #10	Reply to this comment
There is more broken than I guess, at the moment the device loop with a mail. Indeed. Looks like it's sending unexpected wbxml.

02/15/2016 10:09:04 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #9	Reply to this comment
You said it was a shared calendar. Does the same thing happen with a similar recurring event on your personal calendar? Yes was a shared calendar. I create a event* with repeat 4 following days in the own calendar, no problems. * was not a similar since the original event repeat all 2 weeks. Off-topic: Can not delete repeat event with kronolith gui, but on the smartphone calendar. Does the event actually have any exceptions? If so, are they changes to an event or was the instance removed? No, nothing of both. Were the exceptions created by the calendar owner, or another user? Event was created by another user. As soon I disable the shared calander and reset/delete the ActiveSync state the device works. Android 6.0 Moto G 3rd Gen.

02/15/2016 09:49:00 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	New Attachment: ActiveSync_Debug.log

02/15/2016 09:48:19 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #8	Reply to this comment
There is more broken than I guess, at the moment the device loop with a mail.

02/15/2016 02:47:45 PM	Michael Rubinsky	Comment #7	Reply to this comment
Spent the last 2 hours trying to get the Android 6 emulator to sync the calendar at all. Going to have to give up on this for now, until I can get my hands on a physical Android 6 device. Something i can do? Thanks for the offer, but at this point I'm not sure. I need to be able to trace the code while it's syncing to see what is causing this. I'm pretty sure 6.0.0 is badly broken with respect to EAS but the 6.0.1 update isn't available for the emulator yet. That being said, I'm having a hard time figuring out how the Android version would cause the data being sent FROM the server to be corrupt. Maybe a few questions: You said it was a shared calendar. Does the same thing happen with a similar recurring event on your personal calendar? Does the event actually have any exceptions? If so, are they changes to an event or was the instance removed? Were the exceptions created by the calendar owner, or another user?

02/15/2016 10:54:02 AM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #6	Reply to this comment
Spent the last 2 hours trying to get the Android 6 emulator to sync the calendar at all. Going to have to give up on this for now, until I can get my hands on a physical Android 6 device. Something i can do?

02/15/2016 04:23:03 AM	Michael Rubinsky	Comment #5	Reply to this comment
Spent the last 2 hours trying to get the Android 6 emulator to sync the calendar at all. Going to have to give up on this for now, until I can get my hands on a physical Android 6 device.

02/15/2016 12:24:51 AM	Michael Rubinsky	Comment #4 Assigned to Michael Rubinsky State ⇒ Assigned	Reply to this comment
[Show Quoted Text - 12 lines][Hide Quoted Text] Can you check to be sure you have the latest Horde_ActiveSync package (2.31.2)? Yes: root@wds:~# pear list -c horde \| grep kro kronolith 4.2.14 stable root@wds:~# pear list -c horde \| grep Active Horde_ActiveSync 2.31.2 stable root@wds:~# Try Horde_ActiveSync 2.31.1, same problem. In my eyes this problem start with the upgrade from Android 5.1.1 to 6.0. Oh well. So much for the easy fix. The only 6.0 client I have is the SDK emulator, which is having a hard time connecting to my VMs, but I'll keep trying.

02/14/2016 11:17:14 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #3	Reply to this comment
Can you check to be sure you have the latest Horde_ActiveSync package (2.31.2)? Yes: root@wds:~# pear list -c horde \| grep kro kronolith 4.2.14 stable root@wds:~# pear list -c horde \| grep Active Horde_ActiveSync 2.31.2 stable root@wds:~# Try Horde_ActiveSync 2.31.1, same problem. In my eyes this problem start with the upgrade from Android 5.1.1 to 6.0.

02/14/2016 11:08:37 PM	Michael Rubinsky	Comment #2 State ⇒ Feedback	Reply to this comment
Can you check to be sure you have the latest Horde_ActiveSync package (2.31.2)?

02/14/2016 06:45:11 PM	samuel (dot) wolf (at) wolf-maschinenbau (dot) de	Comment #1 Priority ⇒ 1. Low State ⇒ Unconfirmed Patch ⇒ No Milestone ⇒ Summary ⇒ Shared calendar Android 6 - /POOMCAL:Exception Type ⇒ Bug Queue ⇒ Synchronization	Reply to this comment
As soon I enable the sync for a shared calendar my Android 6 device sync endless. 2016-02-14T19:26:36+01:00 INFO: [10012] Updating state during change 2016-02-14T19:26:36+01:00 INFO: [10012] Peak memory usage after message: 6815744 2016-02-14T19:26:36+01:00 DEBUG: [10012] O </POOMCAL:Exception> "Support separate calendars?" is enable.