Tickets :: [#12370] Error 500 in communicating with ActiveSync server

6.0.0-beta1

7/15/25

Summary	Error 500 in communicating with ActiveSync server
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Resolved
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	software-horde (at) interfasys (dot) ch
Created	06/18/2013 (4410 days ago)
Due
Updated	07/03/2013 (4395 days ago)
Assigned	06/21/2013 (4407 days ago)
Resolved	07/03/2013 (4395 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

07/03/2013 01:50:48 PM	Michael Rubinsky	State ⇒ Resolved

07/03/2013 10:46:13 AM	software-horde (at) interfasys (dot) ch	Comment #9	Reply to this comment
Does this fix? Yes, it did. No more errors in the logs. Thank you.

07/01/2013 04:00:46 PM	Michael Rubinsky	Comment #8 Assigned to Michael Rubinsky	Reply to this comment
Does this fix?

07/01/2013 04:00:15 PM	Git Commit	Comment #7	Reply to this comment
Changes have been made in Git (master): commit dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Mon Jul 1 11:58:53 2013 -0400 ~~Bug: 12370~~ Attempt to work around broken Blackberry clients. .../lib/Horde/ActiveSync/Request/Sync.php \| 9 +++++++-- 1 files changed, 7 insertions(+), 2 deletions(-) http://git.horde.org/horde-git/-/commit/dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021

06/30/2013 11:17:23 PM	software-horde (at) interfasys (dot) ch	Comment #6	Reply to this comment
[Show Quoted Text - 11 lines][Hide Quoted Text] 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Remove> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <ServerEntryId /> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Remove> This is not a valid request being made by your client. It is telling Horde to remove an entry, but is not telling Horde what entry to remove. What client is this, and what did you do on the client to trigger this request? The client is BlackBerry 10 v10.1 Since this has been going on for weeks, I'm not sure what the original request was, but this is happening every 10 minutes.

06/27/2013 05:16:14 PM	Michael Rubinsky	Comment #5	Reply to this comment
2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Remove> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <ServerEntryId /> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Remove> This is not a valid request being made by your client. It is telling Horde to remove an entry, but is not telling Horde what entry to remove. What client is this, and what did you do on the client to trigger this request?

06/25/2013 05:21:29 PM	software-horde (at) interfasys (dot) ch	Comment #4	Reply to this comment
The 500 response is probably due to the device still requesting the state that is no longer available on the server (since you say it's not listed as a device in Horde). This is supposed to trigger the device to initiate a new sync pairing with the server. Without a sync log, I can't tell you much more than this. DId you try re-creating the account on the client? I've just checked the logs and it's still there. So I had a look at the log and found an unmatched end tag error: 2013-06-25T19:08:29+02:00 DEBUG: [3478] SYNC request received for user user@domain.com 2013-06-25T19:08:29+02:00 INFO: [3478] Device entry exists for BB24XOXOX, updating userAgent and version. 2013-06-25T19:08:29+02:00 INFO: [3478] Request being handled for device: BB24XOXO Supporting protocol version: 14.1 2013-06-25T19:08:29+02:00 INFO: [3478] Handling SYNC command. 2013-06-25T19:08:29+02:00 INFO: [3478] Checking policykey for device: BB24XOXO user: user@domain.com 2013-06-25T19:08:29+02:00 INFO: [3478] Policykey: 0 verified. 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Synchronize> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Folders> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Folder> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <SyncKey> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I {51af577d-396c-4be0-9c84-39ca4e2e3851}28 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </SyncKey> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <FolderId> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 57f5ffb8 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </FolderId> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <DeletesAsMoves /> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <GetChanges /> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <WindowSize> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 100 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </WindowSize> 2013-06-25T19:08:29+02:00 INFO: [3478] Requesting WINDOWSIZE of 100 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Options> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <FilterType> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 0 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </FilterType> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <MIMESupport> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 2 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </MIMESupport> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <MIMETruncation> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 3 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </MIMETruncation> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <AirSyncBase:BodyPreference> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <AirSyncBase:Type> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 4 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </AirSyncBase:Type> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <AirSyncBase:TruncationSize> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I 200000 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </AirSyncBase:TruncationSize> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </AirSyncBase:BodyPreference> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Options> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Commands> 2013-06-25T19:08:29+02:00 INFO: [3478] Obtaining collection class of Email for collection id 57f5ffb8 2013-06-25T19:08:29+02:00 INFO: [3478] Initializing state for collection: Drafts, synckey: {51af577d-396c-4be0-9c84-39ca4e2e3851}28 2013-06-25T19:08:29+02:00 INFO: [3478] Loading state for synckey {51af577d-396c-4be0-9c84-39ca4e2e3851}28 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <Remove> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I <ServerEntryId /> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Remove> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Commands> 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Folder> 2013-06-25T19:08:29+02:00 INFO: [3478] Polling Horde_Core_ActiveSync_Driver::_getMailFolders() 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for INBOX: 05108b74 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for Drafts: 57f5ffb8 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for Junk: 39b8f3c6 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for Sent: fa37da9d 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for Trash: a9249169 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for INBOX/spam: c0c7a594 2013-06-25T19:08:29+02:00 INFO: [3478] Found serverid for INBOX: 05108b74 2013-06-25T19:08:29+02:00 INFO: [3478] Horde_Core_ActiveSync_Driver::moveMessage(Drafts, [], Trash) 2013-06-25T19:08:29+02:00 INFO: [3478] Updating state during delete 2013-06-25T19:08:29+02:00 INFO: [3478] Processed 1 incoming changes 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Folders> 2013-06-25T19:08:29+02:00 INFO: [3478] Collection added to collection handler: collection: Drafts, synckey: {51af577d-396c-4be0-9c84-39ca4e2e3851}28. 2013-06-25T19:08:29+02:00 DEBUG: [3478] I </Synchronize> 2013-06-25T19:08:29+02:00 ERR: [3478] Unmatched end tag: 2013-06-25T19:08:29+02:00 ERR: 2013-06-25T19:08:29+02:00 DEBUG: [3478] O <Synchronize> 2013-06-25T19:08:29+02:00 DEBUG: [3478] O <Status> 2013-06-25T19:08:29+02:00 DEBUG: [3478] O 4 2013-06-25T19:08:29+02:00 DEBUG: [3478] O </Status> 2013-06-25T19:08:29+02:00 DEBUG: [3478] O </Synchronize> 2013-06-25T19:08:29+02:00 ERR: PROTOCOL ERROR: Missing closing SYNC tag 2013-06-25T19:08:29+02:00 INFO: [3478] User user@domain.com logged off

06/25/2013 02:43:37 PM	software-horde (at) interfasys (dot) ch	Comment #3	Reply to this comment
The 500 response is probably due to the device still requesting the state that is no longer available on the server (since you say it's not listed as a device in Horde). This is supposed to trigger the device to initiate a new sync pairing with the server. Without a sync log, I can't tell you much more than this. DId you try re-creating the account on the client? OK. I couldn't get a log, probably because the device wasn't associated any more. I had to delete and re-create the account for things to go back to normal.

06/21/2013 04:12:18 PM	Michael Rubinsky	Comment #2 State ⇒ Feedback	Reply to this comment
The 500 response is probably due to the device still requesting the state that is no longer available on the server (since you say it's not listed as a device in Horde). This is supposed to trigger the device to initiate a new sync pairing with the server. Without a sync log, I can't tell you much more than this. DId you try re-creating the account on the client?

06/18/2013 04:31:50 PM	software-horde (at) interfasys (dot) ch	Comment #1 Milestone ⇒ State ⇒ Unconfirmed Patch ⇒ No Queue ⇒ Synchronization Summary ⇒ Error 500 in communicating with ActiveSync server Type ⇒ Bug Priority ⇒ 1. Low	Reply to this comment
During an imap server upgrade, an account on the device got disconnected from the server and has not been able to reconnect after that. I have not been able to identify what's wrong. The device is no longer listed in the list of activesync devices in Horde and trying to re-sync from the device always fails. Here is what I can see in the logs: 2013-06-18T18:20:36+02:00 ERR: HORDE [horde] Returning HTTP 500 while handling Sync command. [pid 5208 on line 156 of "/var/www/html/webmail/rpc.php"] 2013-06-18T18:20:36+02:00 ERR: HORDE [horde] Error in communicating with ActiveSync server: Received FALSE while handling Sync command. [pid 5208 on line 160 of "/usr/local/lib/php/Horde/Rpc/ActiveSync.php"] 2013-06-18T18:20:36+02:00 ERR: HORDE [horde] #0 /var/www/html/webmail/rpc.php(156): Horde_Rpc_ActiveSync->getResponse(NULL) #1 {main} [pid 5208 on line 160 of "/usr/local/lib/php/Horde/Rpc/ActiveSync.php"] 2013-06-18T18:20:36+02:00 ERR: HORDE [horde] Buffer contents: jEN4 [pid 5208 on line 160 of "/usr/local/lib/php/Horde/Rpc/ActiveSync.php"]