[sync] syncing delete of already deleted msg blocks sync
Michael J Rubinsky
mrubinsk at horde.org
Mon Dec 16 14:24:30 UTC 2013
Quoting "Jens-U. Mozdzen" <jmozdzen at nde.ag>:
> 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.
This is *exactly* what we already do. See
Horde_ActiveSync_Imap_Adapter::moveMessage(). We first perform a
search against the originating mailbox for all of the ids we are
attempting to move. Any ids not found in the originating mailbox are
removed from the move command.
We will need to see an IMAP debug log of what is happening on the
server when this is occurring.
--
mike
The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5849 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/sync/attachments/20131216/701ca3d4/attachment.bin>
More information about the sync
mailing list