[sync] syncing delete of already deleted msg blocks sync

Mon Dec 16 10:43:19 UTC 2013

Hi,

as I cannot currently reach bugs.horde.org (I'm assuming it's because  
of the announced server maintenance), I'm posting this bug report here:

  From time to time my mobile device (Android) "looses sync" with the  
Horde server, but resetting the device in the user's Horde ActiveSync  
settings immediately re-establishes full functionality. Today I was  
able to track down at least one probable cause.

I had been working with the web UI of Horde, where I deleted messages  
from my inbox, which seems not to have been synced to the mobile  
device (i.e. because the phone went offline for whatever reason before  
catching the delete operation per ActiveSync). I then had to work via  
the mobile device and noticed that these messages were still displayed  
in the inbox, so I "swiped them away" within the mobile's mail  
application.

Noticing (some hours) later that new messages didn't make it to the  
mobile device, I had a look at the Apache log, the ActiveSync log and  
the regular Horde log:

- the mobile device is issuing ActiveSync calls as expected

- the ActiveSync log displays an IMAP error:

--- cut here ---
[...]
2013-12-16T10:57:47+01:00 INFO: [24668] Obtaining collection class of  
Email for collection id 4fcfa220
2013-12-16T10:57:47+01:00 INFO: [24668] Initializing state for  
collection: INBOX, synckey: {528f17e2-809c-43a6-b9bb-************}619
2013-12-16T10:57:47+01:00 INFO: [24668] Loading state for synckey  
{528f17e2-809c-43a6-b9bb-************}619
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      <Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       <ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I         IGNORESMS_SMS_1386841131191
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       </ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      </Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      <Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       <ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I         37740
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       </ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      </Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      <Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       <ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I         37732
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       </ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      </Remove>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I      <Modify>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       <ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I         37741
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       </ServerEntryId>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       <Data>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I        <POOMMAIL:Read>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I          1
2013-12-16T10:57:47+01:00 DEBUG: [24668] I        </POOMMAIL:Read>
2013-12-16T10:57:47+01:00 DEBUG: [24668] I       </Data>
2013-12-16T10:57:47+01:00 INFO: [24668]  
Horde_Core_ActiveSync_Driver::_smartStatMessage(INBOX, 37741)
2013-12-16T10:57:47+01:00 INFO: [24668]  
Horde_Core_ActiveSync_Driver::changeMessage(INBOX, 37741 ...)
2013-12-16T10:57:48+01:00 INFO: [24668] Updating state during flags
2013-12-16T10:57:48+01:00 DEBUG: [24668] I      </Modify>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I      <Modify>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I       <ServerEntryId>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I         37733
2013-12-16T10:57:48+01:00 DEBUG: [24668] I       </ServerEntryId>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I       <Data>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I        <POOMMAIL:Read>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I          1
2013-12-16T10:57:48+01:00 DEBUG: [24668] I        </POOMMAIL:Read>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I       </Data>
2013-12-16T10:57:48+01:00 INFO: [24668]  
Horde_Core_ActiveSync_Driver::_smartStatMessage(INBOX, 37733)
2013-12-16T10:57:48+01:00 INFO: [24668]  
Horde_Core_ActiveSync_Driver::changeMessage(INBOX, 37733 ...)
2013-12-16T10:57:48+01:00 INFO: [24668] Updating state during flags
2013-12-16T10:57:48+01:00 DEBUG: [24668] I      </Modify>
2013-12-16T10:57:48+01:00 DEBUG: [24668] I     </Commands>
2013-12-16T10:57:48+01:00 INFO: [24668] Polling  
Horde_Core_ActiveSync_Driver::_getMailFolders()
2013-12-16T10:57:49+01:00 INFO: [24668]  
Horde_Core_ActiveSync_Driver::moveMessage(INBOX,  
[IGNORESMS_SMS_1386841131191,37740,37732], INBOX/Trash)
2013-12-16T10:57:49+01:00 ERR: Der E-Mail-Server hat einen IMAP-Fehler  
gemeldet.
--- cut here ---

- the Horde log shows that it is an error when moving a file to  the  
Trahs folder:

--- cut here ---
2013-12-16T10:57:49+01:00 ERR: HORDE [horde] #0  
/usr/share/php5/PEAR/Horde/Imap/Client/Socket.php(3941):  
Horde_Imap_Client_Socket->_getLine(Object(Horde_Imap_Client_Interaction_Pipeline))
#1 /usr/share/php5/PEAR/Horde/Imap/Client/Socket.php(3871):  
Horde_Imap_Client_Socket->_sendCmdChunk(Object(Horde_Imap_Client_Interaction_Pipeline),  
Array)
#2 /usr/share/php5/PEAR/Horde/Imap/Client/Socket.php(2231):  
Horde_Imap_Client_Socket->_sendCmd(Object(Horde_Imap_Client_Interaction_Pipeline))
#3 /usr/share/php5/PEAR/Horde/Imap/Client/Base.php(2370):  
Horde_Imap_Client_Socket->_search(Object(Horde_Imap_Client_Search_Query),  
Array)
#4 /usr/share/php5/PEAR/Horde/ActiveSync/Imap/Adapter.php(566):  
Horde_Imap_Client_Base->search(Object(Horde_Imap_Client_Mailbox),  
Object(Horde_Imap_Client_Search_Query))
#5 /usr/share/php5/PEAR/Horde/Core/ActiveSync/Driver.php(1170):  
Horde_ActiveSync_Imap_Adapter->moveMessage('INBOX', Array,  
'INBOX/Trash')
#6 /usr/share/php5/PEAR/Horde/ActiveSync/Connector/Importer.php(274):  
Horde_Core_ActiveSync_Driver->moveMessage('INBOX', Array, 'INBOX/Trash')
#7 /usr/share/php5/PEAR/Horde/ActiveSync/Request/Sync.php(1031):  
Horde_ActiveSync_Connector_Importer->importMessageMove(Array,  
'3f55f1d7')
#8 /usr/share/php5/PEAR/Horde/ActiveSync/Request/Sync.php(794):  
Horde_ActiveSync_Request_Sync->_parseSyncCommands(Array)
#9 /usr/share/php5/PEAR/Horde/ActiveSync/Request/Sync.php(208):  
Horde_ActiveSync_Request_Sync->_parseSyncFolders()
#10 /usr/share/php5/PEAR/Horde/ActiveSync/Request/Base.php(249):  
Horde_ActiveSync_Request_Sync->_handle()
#11 /usr/share/php5/PEAR/Horde/ActiveSync.php(894):  
Horde_ActiveSync_Request_Base->handle()
#12 /usr/share/php5/PEAR/Horde/Rpc/ActiveSync.php(143):  
Horde_ActiveSync->handleRequest('Sync', 'SEC********7FB1...')
#13 /srv/www/htdocs.www.nde.ag.ssl/horde/rpc.php(156):  
Horde_Rpc_ActiveSync->getResponse(NULL)
#14 {main} [pid 24668 on line 162 of  
"/usr/share/php5/PEAR/Horde/Rpc/ActiveSync.php"]
2013-12-16T10:57:49+01:00 ERR: HORDE [horde] Buffer contents:  [pid  
24668 on line 162 of "/usr/share/php5/PEAR/Horde/Rpc/ActiveSync.php"]
--- cut here ---

It seems the ActiveSync code tries to move a message to Trash, that  
has already been moved ("deleted") via the web UI, hence the error.  
 From then on, the operation is retried at every sync, obviously fails  
each time and no other sync actions are performed, practically  
"detaching" the mobile device.

Once the device is reset in Horde's ActiveSync settings, causing a  
full resync, everything is back in order.

The proper reaction to the situation would IMO be to check if the  
error is reported because the message does not exist in the IMAP store  
plus the target folder is the trash folder and if so, to *ignore* the  
error.

Regards,
Jens