Tickets :: [#14874] ActiveSync Protocol Error when syncing E-Mails

6.0.0-beta1

7/3/25

Summary	ActiveSync Protocol Error when syncing E-Mails
Queue	Synchronization
Queue Version	FRAMEWORK_5_2
Type	Bug
State	Not A Bug
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	j.beyer (at) celano (dot) de
Created	11/13/2018 (2424 days ago)
Due
Updated	11/17/2018 (2420 days ago)
Assigned	11/13/2018 (2424 days ago)
Resolved	11/13/2018 (2424 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

11/17/2018 06:38:52 AM	build+horde (at) de-korte (dot) org	Comment #10	Reply to this comment
You don't have to use a vendor provided app to use ActiveSync. There are clients that are properly implementing ActiveSync. Use those, rather than a known broken one.

11/16/2018 03:28:22 PM	j (dot) beyer (at) celano (dot) de	Comment #9	Reply to this comment
The vendor needs to follow the specifications of the protocol they are implementing. He should but does he care? The "Application" info in the Horde ActiveSync Display reads "SonyG8232/8.0.0-EAS-2.0". This is no Android user app but a preinstalled Android account driver. I don't know how to contact Sony with this problem. The general support hotline will probably not understand what I am talking about. An even if they do they will not ship a new firmware for this. For the time being I will reset the device status if the problem reoccurs.

11/16/2018 03:09:52 PM	Michael Rubinsky	Comment #8	Reply to this comment
Thanks for the link to the protocol specs. I had a look around but I cannot match the log with the spec. The log contains XML elements like "Commands" that are described in the spec (see chap. 2.2.3.32) but the description of this elements implies a specific parent element (Collection) that is not shown in the log as XML but as "COLLECTIONS" (see 1st post). I assume this is a logging thing. Correct. The "Folders" element represents the "COLLECTIONS" and the "Folder" element is a single "COLLECTION". [Show Quoted Text - 10 lines][Hide Quoted Text] According to the spec the Commands tag is optional to the Collection but must contain something if present, otherwise "the server may return a protocol status error". In this case the tag is present but empty and a violation of the protocol like you said. The option is not to return a protocol status error. I agree that this will probably not help if the client insists but I would like to try and change this. It will probably take a few days until the error occurs again. Until then I will try to prepare a patched version. Sorry, but we will not ignore this error. It's an outright protocol error. Ignoring this may lead to other unknown errors since the presence of the COMMANDS tag leads to certain assumptions about what has to happen next, server side. The vendor needs to follow the specifications of the protocol they are implementing.

11/14/2018 05:50:28 PM	j (dot) beyer (at) celano (dot) de	Comment #7	Reply to this comment
Thanks for the link to the protocol specs. I had a look around but I cannot match the log with the spec. The log contains XML elements like "Commands" that are described in the spec (see chap. 2.2.3.32) but the description of this elements implies a specific parent element (Collection) that is not shown in the log as XML but as "COLLECTIONS" (see 1st post). I assume this is a logging thing. According to the spec the Commands tag is optional to the Collection but must contain something if present, otherwise "the server may return a protocol status error". In this case the tag is present but empty and a violation of the protocol like you said. The option is not to return a protocol status error. I agree that this will probably not help if the client insists but I would like to try and change this. It will probably take a few days until the error occurs again. Until then I will try to prepare a patched version.

11/14/2018 08:21:03 AM	build+horde (at) de-korte (dot) org	Comment #6	Reply to this comment
The protocol specifications are public, see https://interoperability.blob.core.windows.net/files/MS-ASCMD/[MS-ASCMD].pdf Regarding workarounds for broken clients, guessing what a client meant by violating the protocol is tricky. Sometimes ignoring such commands may be feasible, but more often than not, if a client is not receiving the expected response from the server, it will just try again. It would be best if you could convince the vendor of your ActiveSync enabled mail client to adhere to the protocol specs and if it doesn't, switch to a different one.

11/14/2018 07:49:01 AM	j (dot) beyer (at) celano (dot) de	Comment #5	Reply to this comment
I haven't checked the ActiveSync Protocol specs, but I wonder what would happen if the ActiveSync parser would assume a "status update" like command in this case. The user did a refresh swipe in the E-Mail client when the error occurred and could not help himself out of this situation. Even if the missing command is not in line with the protocol specs we can assume that there will be no update of the Android client on most devices (if at all) so a workaround should be considered. I would like to modify the code my installation the next time the error occurs if this idea is feasible at all. If you think it could work please point me in the right direction (file name, sub name).

11/13/2018 02:33:12 PM	j (dot) beyer (at) celano (dot) de	Comment #4	Reply to this comment
[Show Quoted Text - 20 lines][Hide Quoted Text] 1) What version Horde_ActiveSync are you using? 2) What ActiveSync client is this? The best way for me to see what's going on is a wireshark dump of the conversation, but if i can get access to the same client you are using I can try to reproduce without one. Nevermind. Your client is broken. It is sending an empty "COMMANDS" element: [25543][2018-11-13T09:23:11+01:00] I: <Commands /> This is a violation of the EAS specification: MS-ASCMD Section 2.2.3.22 COMMANDS: [...] This element is optional. If it is present, it MUST include at least one operation. It is a child of the Collection element. Thanks for the info. Got the sync working again for this user: - disabled sync on the client - reset status on the server - enabled sync for contacts and calendar - enabled sync for E-Mail Maybe this approach changed the client status in a way that the empty "command" was not sent again.

11/13/2018 02:26:40 PM	Michael Rubinsky	Comment #3 State ⇒ Not A Bug Assigned to Michael Rubinsky	Reply to this comment
1) What version Horde_ActiveSync are you using? 2) What ActiveSync client is this? The best way for me to see what's going on is a wireshark dump of the conversation, but if i can get access to the same client you are using I can try to reproduce without one. Nevermind. Your client is broken. It is sending an empty "COMMANDS" element: [25543][2018-11-13T09:23:11+01:00] I: <Commands /> This is a violation of the EAS specification: MS-ASCMD Section 2.2.3.22 COMMANDS: [...] This element is optional. If it is present, it MUST include at least one operation. It is a child of the Collection element.

11/13/2018 02:20:07 PM	Michael Rubinsky	Comment #2 State ⇒ Feedback Priority ⇒ 1. Low	Reply to this comment
1) What version Horde_ActiveSync are you using? 2) What ActiveSync client is this? The best way for me to see what's going on is a wireshark dump of the conversation, but if i can get access to the same client you are using I can try to reproduce without one.

11/13/2018 09:04:10 AM	j (dot) beyer (at) celano (dot) de	Comment #1 Priority ⇒ 2. Medium State ⇒ Unconfirmed Patch ⇒ No Milestone ⇒ Queue ⇒ Synchronization Summary ⇒ ActiveSync Protocol Error when syncing E-Mails Type ⇒ Bug	Reply to this comment
The client fails to sync E-Mails with the server after several weeks of operation for a specific user. Forcing the sync on the client side does not help. Resetting the device status on the sever side does not help. It might be caused by a new mail in the inbox but we have not been able to find out which. Accessing the inbox with imp is no problem. Devices of other users sync successfully at the same time. [25543][2018-11-13T09:23:11+01:00] INFO: Policykey: 1214345194 verified. [25543][2018-11-13T09:23:11+01:00] >>>: Creating new Horde_ActiveSync_SyncCache. [25543][2018-11-13T09:23:11+01:00] I: <Synchronize> [25543][2018-11-13T09:23:11+01:00] I: <Folders> [25543][2018-11-13T09:23:11+01:00] I: <Folder> [25543][2018-11-13T09:23:11+01:00] I: <SyncKey> [25543][2018-11-13T09:23:11+01:00] I: {5bac8aa3-5a98-4bb9-ae32-2a6bc0a86537}1382 [25543][2018-11-13T09:23:11+01:00] I: </SyncKey> [25543][2018-11-13T09:23:11+01:00] I: <FolderId> [25543][2018-11-13T09:23:11+01:00] I: F6ef86f85 [25543][2018-11-13T09:23:11+01:00] I: </FolderId> [25543][2018-11-13T09:23:11+01:00] I: <DeletesAsMoves> [25543][2018-11-13T09:23:11+01:00] I: 1 [25543][2018-11-13T09:23:11+01:00] I: </DeletesAsMoves> [25543][2018-11-13T09:23:11+01:00] I: <GetChanges /> [25543][2018-11-13T09:23:11+01:00] I: <WindowSize> [25543][2018-11-13T09:23:11+01:00] I: 10 [25543][2018-11-13T09:23:11+01:00] I: </WindowSize> [25543][2018-11-13T09:23:11+01:00] I: <Options> [25543][2018-11-13T09:23:11+01:00] I: <FilterType> [25543][2018-11-13T09:23:11+01:00] I: 3 [25543][2018-11-13T09:23:11+01:00] I: </FilterType> [25543][2018-11-13T09:23:11+01:00] I: <MIMESupport> [25543][2018-11-13T09:23:11+01:00] I: 2 [25543][2018-11-13T09:23:11+01:00] I: </MIMESupport> [25543][2018-11-13T09:23:11+01:00] I: <AirSyncBase:BodyPreference> [25543][2018-11-13T09:23:11+01:00] I: <AirSyncBase:Type> [25543][2018-11-13T09:23:11+01:00] I: 4 [25543][2018-11-13T09:23:11+01:00] I: </AirSyncBase:Type> [25543][2018-11-13T09:23:11+01:00] I: <AirSyncBase:TruncationSize> [25543][2018-11-13T09:23:11+01:00] I: 4096 [25543][2018-11-13T09:23:11+01:00] I: </AirSyncBase:TruncationSize> [25543][2018-11-13T09:23:11+01:00] I: </AirSyncBase:BodyPreference> [25543][2018-11-13T09:23:11+01:00] I: </Options> [25543][2018-11-13T09:23:11+01:00] I: <Commands /> [25543][2018-11-13T09:23:11+01:00] >>>: COLLECTIONS: Obtaining collection class of Email for collection id F6ef86f85 [25543][2018-11-13T09:23:11+01:00] >>>: COLLECTIONS: Obtaining collection type of 2 for collection id F6ef86f85 [25543][2018-11-13T09:23:11+01:00] INFO: COLLECTIONS: Initializing state for collection: INBOX, synckey: {5bac8aa3-5a98-4bb9-ae32-2a6bc0a86537}1382 [25543][2018-11-13T09:23:11+01:00] >>>: STATE: Loading state for synckey {5bac8aa3-5a98-4bb9-ae32-2a6bc0a86537}1382 [25543][2018-11-13T09:23:11+01:00] >>>: STATE: Found 81 changes remaining from previous SYNC. [25543][2018-11-13T09:23:11+01:00] I: </Folder> [25543][2018-11-13T09:23:11+01:00] INFO: Processed 0 incoming changes [25543][2018-11-13T09:23:11+01:00] I: </Folders> [25543][2018-11-13T09:23:11+01:00] >>>: COLLECTIONS: Collection added to collection handler: collection: INBOX, synckey: {5bac8aa3-5a98-4bb9-ae32-2a6bc0a86537}1382. [25543][2018-11-13T09:23:11+01:00] I: </Synchronize> [25543][2018-11-13T09:23:11+01:00] >>>: COLLECTIONS: Loading default OPTIONS for F6ef86f85 collection. [25543][2018-11-13T09:23:11+01:00] >>>: Clearing all collection synckeys from the cache. [25543][2018-11-13T09:23:11+01:00] ERR: Unmatched end tag: [25543][2018-11-13T09:23:11+01:00] ERR: [25543][2018-11-13T09:23:11+01:00] O: <Synchronize> [25543][2018-11-13T09:23:11+01:00] O: <Status> [25543][2018-11-13T09:23:11+01:00] O: 4 [25543][2018-11-13T09:23:11+01:00] O: </Status> [25543][2018-11-13T09:23:11+01:00] O: </Synchronize> [25543][2018-11-13T09:23:11+01:00] ERR: PROTOCOL ERROR: Missing closing SYNC tag [25543][2018-11-13T09:23:11+01:00] INFO: Maximum memory usage for ActiveSync request: 17825792 bytes. The FolderId is set. I cannot find an unmatched end tag in this log. Please advice. Horde Groupware Webmail Edition 5.2.22 Horde_ActiveSync 2.39.2 Sony Xperia Android 8.0 E-Mail Client