Tickets :: [#12595] AS: Message delete + add leads to broken XML stream

6.0.0-beta1

7/15/25

Summary	AS: Message delete + add leads to broken XML stream
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Resolved
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	thomas.jarosch (at) intra2net (dot) com
Created	08/21/2013 (4346 days ago)
Due
Updated	08/22/2013 (4345 days ago)
Assigned	08/21/2013 (4346 days ago)
Resolved	08/22/2013 (4345 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

08/22/2013 03:38:01 AM	Michael Rubinsky	State ⇒ Resolved

08/22/2013 03:17:04 AM	Git Commit	Comment #2	Reply to this comment
Changes have been made in Git (master): commit d38375252e0077ff9b25d3a20c8f047f10e4b336 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Wed Aug 21 23:14:12 2013 -0400 ~~Bug: 12595~~: Fix sending of empty array attributes. Fixes bogus logging, as well as some fringe-case wbxml corruption. .../lib/Horde/ActiveSync/Message/Base.php \| 35 ++++++++++--------- 1 files changed, 18 insertions(+), 17 deletions(-) http://git.horde.org/horde-git/-/commit/d38375252e0077ff9b25d3a20c8f047f10e4b336

08/21/2013 03:00:20 PM	Thomas Jarosch	Assigned to Michael Rubinsky State ⇒ Assigned

08/21/2013 03:00:05 PM	Thomas Jarosch	Comment #1 Priority ⇒ 1. Low Patch ⇒ No Milestone ⇒ Queue ⇒ Synchronization Summary ⇒ AS: Message delete + add leads to broken XML stream Type ⇒ Bug State ⇒ Unconfirmed	Reply to this comment
Hi, when I delete a message and add a new one at the same time (needed to trigger a "ping" response on an IMAP server without CONDSTORE / modseq), the ActiveSync XML stream is broken. Here's the output enriched with some custom loggers: -------------------------------------------------------------- 2013-08-21T16:16:44+02:00 INFO: [2977] Found 2 message changes in 4eaa9b8f. 2013-08-21T16:16:44+02:00 INFO: [2977] No PIM changes present, returning all messages. 2013-08-21T16:16:44+02:00 INFO: Old SYNCKEY: {52149b50-8680-4b35-a0db-0466ac100163}61, New SYNCKEY: {52149b50-8680-4b35-a0db-0466ac100163}62 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Folders> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Folder> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <SyncKey> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O {52149b50-8680-4b35-a0db-0466ac100163}62 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </SyncKey> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <FolderId> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 4eaa9b8f 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </FolderId> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Status> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 1 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </Status> 2013-08-21T16:16:44+02:00 INFO: [2977] Horde_Core_ActiveSync_Driver::getMessage(INBOX, 186885) 2013-08-21T16:16:44+02:00 INFO: Sending PLAINTEXT Message. 2013-08-21T16:16:44+02:00 INFO: Validating UTF-8 data coming from iso-8859-1 2013-08-21T16:16:44+02:00 INFO: FETCHING VERB 2013-08-21T16:16:44+02:00 INFO: RETURNING VERB 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Commands> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Add> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <ServerEntryId> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 186885 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </ServerEntryId> 2013-08-21T16:16:44+02:00 ERR: TOMJ: wrote end tag for messageChange() SERVERENTRYID 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Data> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:To> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O xxxxxx 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:To> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:From> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O xxxxxxxxxxxxxxxxx 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:From> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Subject> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O sync ~~#11~~ 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:Subject> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:ThreadTopic> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O sync ~~#11~~ 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:ThreadTopic> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:DateReceived> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 2013-08-21T14:16:29.000Z 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:DateReceived> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:DisplayTo> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O xxxxxx 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:DisplayTo> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Importance> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 1 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:Importance> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Read> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 0 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:Read> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:MessageClass> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O IPM.Note 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:MessageClass> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Reply-To> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O xxxxxx 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:Reply-To> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:InternetCPID> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 65001 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:InternetCPID> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <AirSyncBase:NativeBodyType> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 1 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </AirSyncBase:NativeBodyType> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <AirSyncBase:Body> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <AirSyncBase:Type> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 1 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </AirSyncBase:Type> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <AirSyncBase:EstimatedDataSize> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 372 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </AirSyncBase:EstimatedDataSize> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <AirSyncBase:Data> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O xxxx 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </AirSyncBase:Data> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </AirSyncBase:Body> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Flag/> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:ContentClass> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O urn:content-classes:message 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </POOMMAIL:ContentClass> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <POOMMAIL:Categories/> 2013-08-21T16:16:44+02:00 ERR: TOMJ: wrote end tag for messageChange() SYNC_DATA 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </Data> 2013-08-21T16:16:44+02:00 ERR: TOMJ: wrote end tag for messageChange() 2013-08-21T16:16:44+02:00 INFO: [2977] Updating state during change 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <Remove> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O <ServerEntryId> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O 186884 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </ServerEntryId> 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </Remove> 2013-08-21T16:16:44+02:00 ERR: TOMJ: wrote end tag for messageDeletion() 2013-08-21T16:16:44+02:00 INFO: [2977] Updating state during delete 2013-08-21T16:16:44+02:00 DEBUG: [2977] O </Add> 2013-08-21T16:16:44+02:00 ERR: TOMJ: wrote end tag for SYNC_COMMANDS -------------------------------------------------------------- -> The "<Remove>" command is inside the "<Add>" tag. This is wrong. The XML stream is missing an end tag somewhere. When I comment out this line in Message/Base.php::encodeStream() $encoder->startTag($tag, null, true); the XML output is fine again. So it looks like the wbxml output of empty tags is somehow not working correctly. Thomas