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

noreply at bugs.horde.org noreply at bugs.horde.org
Wed Aug 21 15:00:05 UTC 2013 

DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: http://bugs.horde.org/ticket/12595
------------------------------------------------------------------------------
  Ticket             | 12595
  Created By         | Thomas Jarosch <thomas.jarosch at intra2net.com>
  Summary            | AS: Message delete + add leads to broken XML stream
  Queue              | Synchronization
  Version            | Git master
  Type               | Bug
  State              | Unconfirmed
  Priority           | 1. Low
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------


Thomas Jarosch <thomas.jarosch at intra2net.com> (2013-08-21 15:00) wrote:

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

More information about the bugs mailing list