Tickets :: [#13638] Error 500: Unexpected tag

6.0.0-alpha12

6/12/25

Summary	Error 500: Unexpected tag
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Duplicate
Priority	1. Low
Owners
Requester	software-horde (at) interfasys (dot) ch
Created	10/20/2014 (3888 days ago)
Due
Updated	10/20/2014 (3888 days ago)
Assigned	10/20/2014 (3888 days ago)
Resolved	10/20/2014 (3888 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

10/20/2014 04:51:48 PM	Michael Rubinsky	Comment #4 State ⇒ Duplicate	Reply to this comment
~~Bug: 13636~~

10/20/2014 03:43:21 PM	software-horde (at) interfasys (dot) ch	Comment #3	Reply to this comment
Looks like it's related to the recurring task issue. 2014-10-20T15:46:57+02:00 INFO: [30955] Horde_Core_ActiveSync_Driver::authenticate() attempt for user@domain.tld 2014-10-20T15:46:57+02:00 INFO: [30955] SYNC request received for user user@domain.tld 2014-10-20T15:46:57+02:00 INFO: [30955] Device entry exists for BBALPHA, updating userAgent and version. 2014-10-20T15:46:57+02:00 INFO: [30955] Request being handled for device: BBALPHA, Supporting protocol version: 14.1, Using Horde_ActiveSync v2.19.3 2014-10-20T15:46:57+02:00 INFO: [30955] GET VARIABLES: Array 2014-10-20T15:46:57+02:00 INFO: [30955] Handling SYNC command. 2014-10-20T15:46:57+02:00 INFO: [30955] Checking policykey for device: BBALPHA user: user@domain.tld 2014-10-20T15:46:57+02:00 INFO: [30955] Stored key: 2580378812 2014-10-20T15:46:57+02:00 INFO: [30955] Policykey: 2580378812 verified. 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Synchronize> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Folders> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Folder> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <SyncKey> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I {542e663e-c458-4948-96a6-1a73904cae96}15 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </SyncKey> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <FolderId> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I T1414366e 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </FolderId> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <GetChanges /> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <WindowSize> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 100 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </WindowSize> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Options> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <FolderType> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I Tasks 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </FolderType> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <AirSyncBase:BodyPreference> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <AirSyncBase:Type> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 1 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </AirSyncBase:Type> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </AirSyncBase:BodyPreference> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </Options> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Commands> 2014-10-20T15:46:57+02:00 INFO: [30955] Initializing state for collection: Tasks:HLdveJeR72nn-LWQ8dPdtA1, synckey: {542e663e-c458-4948-96a6-1a73904cae96}15 2014-10-20T15:46:57+02:00 INFO: [30955] Loading state for synckey {542e663e-c458-4948-96a6-1a73904cae96}15 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Add> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <ClientEntryId> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 36 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </ClientEntryId> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <Data> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:Subject> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I Recurito 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:Subject> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:Importance> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 1 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:Importance> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:UtcDueDate> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 2014-10-19T22:00:00.000Z 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:UtcDueDate> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:DueDate> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 2014-10-20T00:00:00.000Z 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:DueDate> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:ReminderSet> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 0 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:ReminderSet> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:Complete> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 0 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </POOMTASKS:Complete> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <AirSyncBase:Body> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <AirSyncBase:Type> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I 1 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </AirSyncBase:Type> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <AirSyncBase:Data /> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I </AirSyncBase:Body> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:Recurrence> 2014-10-20T15:46:57+02:00 DEBUG: [30955] I <POOMTASKS:Regenerate> 2014-10-20T15:46:57+02:00 ERR: Tag POOMTASKS:Regenerate unexpected in type XML type Horde_ActiveSync_Message_TaskRecurrence 2014-10-20T15:46:57+02:00 ERR: Unexpected tag To further debug this issue, we need details of the Horde -> Device connection. It may also be beneficial to obtain a network capture.

10/20/2014 03:04:43 PM	Michael Rubinsky	Comment #2 State ⇒ Feedback	Reply to this comment
To further debug this issue, we need details of the Horde -> Device connection. It may also be beneficial to obtain a network capture. To enable debugging, see instructions contained in the ActiveSync section of Horde's configuration. Also, see http://wiki.horde.org/ActiveSync for more details. Debugging should not be enabled on a production server, Attach/post only the portion of the log that directly deals with the problem reported (it may be simplest to clear the log file and then perform the event that causes the error).

10/20/2014 02:56:35 PM	software-horde (at) interfasys (dot) ch	Comment #1 Priority ⇒ 1. Low Type ⇒ Bug Summary ⇒ Error 500: Unexpected tag Queue ⇒ Synchronization Milestone ⇒ Patch ⇒ No State ⇒ Unconfirmed	Reply to this comment
I think this is related to the fact that messages on the device are truncated and it is requesting more content. Device BlackBerry 10.3.1.x 2014-10-20T15:46:14+02:00 ERR: HORDE Buffer contents: [pid 34557 on line 162 of "/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"] 2014-10-20T15:46:46+02:00 ERR: HORDE Returning HTTP 500 while handling Sync command. [pid 30955 on line 159 of "/var/www/html/webmail/rpc.php"] 2014-10-20T15:46:46+02:00 ERR: HORDE Error in communicating with ActiveSync server: Unexpected tag [pid 30955 on line 162 of "/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"] 2014-10-20T15:46:46+02:00 ERR: HORDE #0 /usr/local/php54/lib/php/Horde/ActiveSync/Message/Base.php(353): Horde_ActiveSync_Message_Base->decodeStream(Object(Horde_ActiveSync_Wbxml_Decoder)) #1 /usr/local/php54/lib/php/Horde/ActiveSync/Request/Sync.php(979): Horde_ActiveSync_Message_Base->decodeStream(Object(Horde_ActiveSync_Wbxml_Decoder)) #2 /usr/local/php54/lib/php/Horde/ActiveSync/Request/Sync.php(803): Horde_ActiveSync_Request_Sync->_parseSyncCommands(Array) #3 /usr/local/php54/lib/php/Horde/ActiveSync/Request/Sync.php(209): Horde_ActiveSync_Request_Sync->_parseSyncFolders() #4 /usr/local/php54/lib/php/Horde/ActiveSync/Request/Base.php(253): Horde_ActiveSync_Request_Sync->_handle() #5 /usr/local/php54/lib/php/Horde/ActiveSync.php(880): Horde_ActiveSync_Request_Base->handle() #6 /usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php(143): Horde_ActiveSync->handleRequest('Sync', 'BBALPHA') #7 /var/www/html/webmail/rpc.php(159): Horde_Rpc_ActiveSync->getResponse(NULL) #8 {main} [pid 30955 on line 162 of "/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"] 2014-10-20T15:46:46+02:00 ERR: HORDE Buffer contents: [pid 30955 on line 162 of "/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"]