[#13052] ActiveSync no longer works
Summary ActiveSync no longer works
Queue Synchronization
Queue Version Git master
Type Bug
State Not A Bug
Priority 2. Medium
Owners mrubinsk@horde.org
Requester lehmann@ans-netz.de
Created 2014-03-14 (2073 days ago)
Due
Updated 2014-03-27 (2060 days ago)
Assigned 2014-03-20 (2067 days ago)
Resolved 2014-03-27 (2060 days ago)
Milestone
Patch No

Comments
lehmann@ans-netz.de 2014-03-14 21:16:20
Horde Kronolith ActiveSync does no longer work with my Android Phone. 
Nothing is synchronized, neither Horde -> Android, nor Android -> Horde.

I've attached the horde and the android log file (both contained in 
horde_sync.txt) for one Sync Request.

You can see, that the android throws an 
ArrayIndexOutOfBoundsException. I guess the content sent by Horde is 
wrong.

arjen+horde@de-korte.org 2014-03-15 08:54:57
Bug #13022 might have the same root cause as this. Which ActiveSync 
client are you running on Android?

lehmann@ans-netz.de 2014-03-17 05:52:25
> Bug #13022 might have the same root cause as this. Which ActiveSync 
> client are you running on Android?

The ActiveSync client which is shipped with Android 4.2.1. I knew that 
it worked once in the past but I don't know when it stopped working to 
sync :/
I switched to CalDAV to get back the syncronisatzion but I rather 
would like to sync all my stuff with ActiveSync

Michael Rubinsky <mrubinsk@horde.org> 2014-03-20 01:15:53
Your synclog does not include the actual data being sent.

lehmann@ans-netz.de 2014-03-20 05:31:08
> Your synclog does not include the actual data being sent.

I've posted all data Horde and my Mobile logged. Nothing more was logged.
As you can see in the mobiles log, The mobile failed to process:

2014-03-14T22:07:07+01:00 DEBUG: [44210] O   <Folders>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O    <Folder>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     <SyncKey>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O       
{53235d61-7a94-4399-88a1-9bb74e6f48ba}2
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     </SyncKey>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     <FolderId>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O      @Calendar@
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     </FolderId>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     <Status>
2014-03-14T22:07:07+01:00 DEBUG: [44210] O      1
2014-03-14T22:07:07+01:00 DEBUG: [44210] O     </Status>

If you think my log misses some information, please tell me how to get it.

Git Commit <commits@lists.horde.org> 2014-03-24 05:08:14
Changes have been made in Git (master):

commit 6a4b0c8538c84001dd327f598c618b0a0628a3b8
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Mon Mar 24 00:10:16 2014 -0400

     Revert "Default to EAS 14.1"

     This reverts commit 91b38c1af3389e897a5ff6d836cf925a8fd1b059.

     Figures. Adding a default that was supposed to make testing easier
     broke functionality because no unit test was covering the functionality.

     Possible fix for Bug: 13052

  framework/ActiveSync/lib/Horde/ActiveSync.php |    2 +-
  1 files changed, 1 insertions(+), 1 deletions(-)



Michael Rubinsky <mrubinsk@horde.org> 2014-03-24 05:08:43
Does this fix it for you?

lehmann@ans-netz.de 2014-03-24 08:01:54
The error is not gone. Please see the attached logfile.

- The first two logs where written when a new event was created on the 
mobile and the mobile tried to "upload" this change to horde

- I then deleted this event on the mobile, and restarted the sync (the 
mobile had nothing to upload then) - this resulted in the other two 
log fragments


arjen+horde@de-korte.org 2014-03-24 08:27:19
> Does this fix it for you?

Probably not, because Android 4.2.1 uses EAS 14.1, so reverting that 
commit is not going to change the outcome of the detection which 
version to use.


Michael Rubinsky <mrubinsk@horde.org> 2014-03-25 21:01:56
> The error is not gone. Please see the attached logfile.
>
> - The first two logs where written when a new event was created on 
> the mobile and the mobile tried to "upload" this change to horde

The first log segment shows Android crashing before it receives 
anything from horde. This is absolutely not a horde issue.

> - I then deleted this event on the mobile, and restarted the sync 
> (the mobile had nothing to upload then) - this resulted in the other 
> two log fragments

The second log fragment looks like it might be due to the wrong EAS 
version being used. I know you said that's not the case, but it's the 
only explanation I can come up with.

Since I can't reproduce any of this, you are going to have to track 
this down further on your own.


lehmann@ans-netz.de 2014-03-26 17:42:51
I wonder why you are not able to reproduce it?!

As I also develop Android apps, I just fired up a clean android 4.4.2 
emulator on my Desktop and configured an Exchange Account and ran the 
Calendar sync... See the attached exception

How can it work on an Android phone at all? I can also try other 
Android versions down to 2.x if you have any android version you are 
sure will work...

Checking the source at (no idea what Android version it is) 
https://android.googlesource.com/platform/packages/apps/Exchange/+/ics-mr1/src/com/android/exchange/adapter/Parser.java

I guess, that the xml might be invalid or "to deep" as only a depth of 
32 tags seems to be supported - check line 426 where the assignment 
takes place and line 81 where the array is declared.
Another point is - why is the xml not completly logged? Is it invalid 
in genral or just not logged completly?

  DEBUG: [9357] O   <Folders>
  DEBUG: [9357] O    <Folder>
  DEBUG: [9357] O     <SyncKey>
  DEBUG: [9357] O      {53330849-eef8-45ba-9b6a-6e4a4e6f48ba}2
  DEBUG: [9357] O     </SyncKey>
  DEBUG: [9357] O     <FolderId>
  DEBUG: [9357] O      @Calendar@
  DEBUG: [9357] O     </FolderId>
  DEBUG: [9357] O     <Status>
  DEBUG: [9357] O      1
  DEBUG: [9357] O     </Status>
  INFO: [9357] Horde_Core_ActiveSync_Driver::getMessage(@Calendar@, 
20130525100228.Q9N04N7InFClaWmpHdJ8Vg1@nnnn)


Michael Rubinsky <mrubinsk@horde.org> 2014-03-26 19:25:11
> I guess, that the xml might be invalid or "to deep" as only a depth 
> of 32 tags seems to be supported - check line 426 where the 
> assignment takes place and line 81 where the array is declared.
> Another point is - why is the xml not completly logged? Is it 
> invalid in genral or just not logged completly?

There is probably an error or uncaught exception being thrown 
somewhere that stops processing. Check the server error log and/or the 
horde debug log.

Also  wireshark trace will show  exactly what is being sent to the 
client, so that would be useful in figuring out what is wrong with the 
wbxml, though my guess is that some error text is being leaked into 
the wbxml stream.


>
>  DEBUG: [9357] O   <Folders>
>  DEBUG: [9357] O    <Folder>
>  DEBUG: [9357] O     <SyncKey>
>  DEBUG: [9357] O      {53330849-eef8-45ba-9b6a-6e4a4e6f48ba}2
>  DEBUG: [9357] O     </SyncKey>
>  DEBUG: [9357] O     <FolderId>
>  DEBUG: [9357] O      @Calendar@
>  DEBUG: [9357] O     </FolderId>
>  DEBUG: [9357] O     <Status>
>  DEBUG: [9357] O      1
>  DEBUG: [9357] O     </Status>
>  INFO: [9357] Horde_Core_ActiveSync_Driver::getMessage(@Calendar@, 
> 20130525100228.Q9N04N7InFClaWmpHdJ8Vg1@nnnn)
>

Michael Rubinsky <mrubinsk@horde.org> 2014-03-26 19:26:26
> How can it work on an Android phone at all? I can also try other 
> Android versions down to 2.x if you have any android version you are 
> sure will work...

It works on ALL of my test android devices from 2.x to 4.4.2 (various 
different ROMS) as well as the emulator.

lehmann@ans-netz.de 2014-03-26 21:14:10
>> How can it work on an Android phone at all? I can also try other
>> Android versions down to 2.x if you have any android version you are
>> sure will work...
>
> It works on ALL of my test android devices from 2.x to 4.4.2 
> (various different ROMS) as well as the emulator.

OK, I'll setup a clean Kronolith installation in a VM on the weekend 
and will try to further debug this problem. Problem in my setup is, 
that everything is done over SSL and wireshark won't work...

Michael Rubinsky <mrubinsk@horde.org> 2014-03-26 21:23:26
> Problem in my setup is, that everything is done over SSL and 
> wireshark won't work...

If you have access to the server certs, you can configure Wireshark to 
use them. Just have to make sure to start the trace before the initial 
negotiation takes place.

lehmann@ans-netz.de 2014-03-27 19:03:54
With wireshark I was able to find the problem...


0360  46 61 74 61 6c 20 65 72 72 6f 72 3c 2f 62 3e 3a   Fatal error</b>:
0370  20 20 43 6c 61 73 73 20 27 48 6f 72 64 65 5f 4d     Class 'Horde_M
0380  61 70 69 5f 54 69 6d 65 7a 6f 6e 65 27 20 6e 6f   api_Timezone' no
0390  74 20 66 6f 75 6e 64 20 69 6e 20 3c 62 3e 2f 75   t found in <b>/u
03a0  73 72 2f 6c 6f 63 61 6c 2f 73 68 61 72 65 2f 70   sr/local/share/p
03b0  65 61 72 2f 48 6f 72 64 65 2f 41 63 74 69 76 65   ear/Horde/Active
03c0  53 79 6e 63 2f 4d 65 73 73 61 67 65 2f 41 70 70   Sync/Message/App
03d0  6f 69 6e 74 6d 65 6e 74 2e 70 68 70 3c 2f 62 3e   ointment.php</b>
03e0  20 6f 6e 20 6c 69 6e 65 20 3c 62 3e 32 37 39 3c    on line <b>279<
03f0  2f 62 3e 3c 62 72 20 2f 3e 0a                     /b><br />.

kinda bad that this can be found nowhere..... installed Horde_Mapi and 
now it works. Sorry for the noise - obviously the FreeBSD port misses 
this dependency.... I'll inform the port maintainer