[horde] AS email not current

Sat Apr 13 07:09:07 UTC 2013

----- Message from Michael J Rubinsky <mrubinsk at horde.org> ---------
     Date: Sat, 13 Apr 2013 02:45:17 -0400
     From: Michael J Rubinsky <mrubinsk at horde.org>
Reply-To: mrubinsk at horde.org
  Subject: Re: [horde] AS email not current
       To: horde at lists.horde.org

> Quoting Simon Wilson <simon at simonandkate.net>:
>
>>>> Quoting simon at simonandkate.net:
>>>>
>>>>> Simon Wilson
>>>>> M: 0400 12 11 16
>>>>>
>>>>> On 06/03/2013, at 11:42 AM, Michael J Rubinsky  
>>>>> <mrubinsk at horde.org> wrote:
>>>>>
>>>>>>
>>>>>> Quoting simon at simonandkate.net:
>>>>>>
>>>>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>>>>
>>>>>>>>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>>>>>>>>
>>>>>>>>>>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On 02/03/2013 4:22 AM, Simon Wilson wrote:
>>>>>>>>>>>>>>>>>> But if I delete emails in Imp, the deleted messages are not
>>>>>>>>>>>>>>>>>> sync'ed, and those emails continue to show in the  
>>>>>>>>>>>>>>>>>> iOS devices
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> http://wiki.horde.org/ActiveSync
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> "Deleting from a MUA: If the MUA is not configured to move
>>>>>>>>>>>>>>>>> messages to the trash, and instead just flags them as
>>>>>>>>>>>>>>>>> deleted, these message deletions will NOT be synched to the
>>>>>>>>>>>>>>>>> ActiveSync client, as there is no equivalent command in the
>>>>>>>>>>>>>>>>> protocol. These messages will only be removed from the
>>>>>>>>>>>>>>>>> ActiveSync client once expunged from the mailbox. This is in
>>>>>>>>>>>>>>>>> accordance with the ActiveSync protocol specs.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> *If you wish to ensure all message deletions are synched
>>>>>>>>>>>>>>>>> quickly to the device, you should configure the use of a
>>>>>>>>>>>>>>>>> Trash folder.*"
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>> Horde mailing list
>>>>>>>>>>>>>>>>> Frequently Asked Questions: http://horde.org/faq/
>>>>>>>>>>>>>>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> As per my other reply, Imp is configured to move to trash
>>>>>>>>>>>>>>>> folder, and purge from Inbox.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> It does not just flag as deleted.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Simon
>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> OK - did an experiment... deleting an email on the same iOS
>>>>>>>>>>>>>>> device in Apple Mail (via a direct IMAP connection), and the
>>>>>>>>>>>>>>> resultant sync back to the AS email connection removes the
>>>>>>>>>>>>>>> deleted email correctly.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Delete an email in Imp and it does not.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> My Imp's mail deletion prefs are set as per following  
>>>>>>>>>>>>>>> screen shot:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> http://www.simonandkate.net/impprefs.png
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> So what is happening in Imp that it is not flagging those
>>>>>>>>>>>>>>> deletions back through AS?
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Not sure. Those settings are correct.
>>>>>>>>>>>>>> --
>>>>>>>>>>>>>> mike
>>>>>>>>>>>>>
>>>>>>>>>>>>> :( troubleshooting suggestions?
>>>>>>>>>>>>>
>>>>>>>>>>>>> If I empty the AS log, delete an email in Imp, and post the sync
>>>>>>>>>>>>> log will that help?
>>>>>>>>>>>>
>>>>>>>>>>>> I doubt it, though I'll look at it if you send it me. The device
>>>>>>>>>>>> is not being told to remove the email, so it won't be in the log.
>>>>>>>>>>>>
>>>>>>>>>>>>> What about Imap log for the delete transaction?
>>>>>>>>>>>>
>>>>>>>>>>>> Not really. The email is obviously being removed from your INBOX
>>>>>>>>>>>> since you no longer see it in IMP (or other MUA).
>>>>>>>>>>>>
>>>>>>>>>>>>> What is the process that a delete triggers?
>>>>>>>>>>>>
>>>>>>>>>>>> This happens in one of two ways depending on the features of your
>>>>>>>>>>>> IMAP server. If you don't support CONDSTORE or per-mailbox MODSEQ
>>>>>>>>>>>> values (which, if I remember right from looking at your log, is
>>>>>>>>>>>> your case) - we basically compare the UID list that we have
>>>>>>>>>>>> cached in the ActiveSync state with what the IMAP server returns
>>>>>>>>>>>> as being present in the mailbox. Anything not listed in the IMAP
>>>>>>>>>>>> server's list of UIDs, but present in the ActiveSync list is
>>>>>>>>>>>> removed from the device.
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>> Does AS care WHERE the email is deleted to? I have Cyrus IMAP
>>>>>>>>>>>>> with a "Deleted Items" folder that Imp calls Trash, seems to
>>>>>>>>>>>>> function fine. Should I be using virtual trash in Imp?
>>>>>>>>>>>>
>>>>>>>>>>>> It doesn't matter. From the point of view of ActiveSync, the
>>>>>>>>>>>> message is just vanished from the INBOX (or whatever folder we
>>>>>>>>>>>> are talking about). Adding it to the Deleted Items/Trash/Whatever
>>>>>>>>>>>> folder is a separate operation.
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> mike
>>>>>>>>>>>
>>>>>>>>>>> Thanks Mike. You know how much I hate it when things start working
>>>>>>>>>>> by themselves with no change????? Lots.
>>>>>>>>>>>
>>>>>>>>>>> I tried today in Outlook with an IMAP connection to my mailbox.
>>>>>>>>>>> Deleted some emails. When my iOS devices next connected, the
>>>>>>>>>>> mailbox changes (deletions) were correctly sent through. So that
>>>>>>>>>>> is with both Apple Mail and MS Outlook 2010 that deletions in
>>>>>>>>>>> other MUAs are correctly sync'ed through AS.
>>>>>>>>>>>
>>>>>>>>>>> Then tried in Imp again. And it updated. :-O
>>>>>>>>>>>
>>>>>>>>>>> Man I hate that.
>>>>>>>>>>>
>>>>>>>>>>> I haven't changed ANYTHING.
>>>>>>>>>>>
>>>>>>>>>>> Anyway, apologies for the noise, I'll monitor and see if  
>>>>>>>>>>> it reoccurs.
>>>>>>>>>>>
>>>>>>>>>>> Simon.
>>>>>>>>>>
>>>>>>>>>> I spoke too soon. It was updating automatically for a while, then
>>>>>>>>>> stopped again.
>>>>>>>>>>
>>>>>>>>>> At this stage I have one email that ActiveSync thinks is there but
>>>>>>>>>> that isn't.
>>>>>>>>>>
>>>>>>>>>> I have confirmed that the email does NOT exist in the Cyrus
>>>>>>>>>> partition, so the IMAP delete has successfully completed.
>>>>>>>>>>
>>>>>>>>>> Is there any way to see what UIDs ActiveSync has cached, and what
>>>>>>>>>> it is getting from IMAP to compare?
>>>>>>>>>>
>>>>>>>>>> I then deleted a second email from Imp, and it also hung up...
>>>>>>>>>> deleted OK on the Cyrus partition, but AS still thinks it's there.
>>>>>>>>>>
>>>>>>>>>> Third email deleted then from Outlook - and it also hung up... as
>>>>>>>>>> per last one, gone in Cyrus, AS still thinks it's there.
>>>>>>>>>>
>>>>>>>>>> Sounding to me like AS caching something incorrectly reading the
>>>>>>>>>> Cyrus list. Could it be related to bug 11115?
>>>>>>>>>>
>>>>>>>>>> Simon
>>>>>>>>>
>>>>>>>>> I have the following set in backends.local.php. Cache was set to
>>>>>>>>> true, but setting to false hasn't changed anything. :
>>>>>>>>>
>>>>>>>>> <?php
>>>>>>>>>
>>>>>>>>> $servers['imap'] = array(
>>>>>>>>> 'disabled' => false,
>>>>>>>>> 'name' => 'Cyrus IMAP Server',
>>>>>>>>> 'hostspec' => 'server04.simonandkate.lan',
>>>>>>>>> 'hordeauth' => true,
>>>>>>>>> 'protocol' => 'imap',
>>>>>>>>> 'secure' => 'tls',
>>>>>>>>> 'port' => 143,
>>>>>>>>> 'quota' => array(
>>>>>>>>>   'driver' => 'imap',
>>>>>>>>>   'params' => array(
>>>>>>>>>           'hide_quota_when_unlimited' => true,
>>>>>>>>>           'unit' => 'MB'
>>>>>>>>>    )
>>>>>>>>> ),
>>>>>>>>> 'maildomain' => 'simonandkate.net',
>>>>>>>>> 'acl' => true,
>>>>>>>>> 'cache' => false,
>>>>>>>>> //    'debug' => ($GLOBALS['registry']->getAuth() == 'simon') ?
>>>>>>>>> '/var/log/hordeas/impdebug' : false,
>>>>>>>>> 'debug' => '/var/log/hordeas/impdebug',
>>>>>>>>> 'debug_raw' => false,
>>>>>>>>> );
>>>>>>>>>
>>>>>>>>> Setting Impdebug gives some info...
>>>>>>>>>
>>>>>>>>> Initial connection:
>>>>>>>
>>>>>>>>> Snip
>>>>>>>
>>>>>>>>> Doing an update on the iPhone's AS Inbox generates this IMAP  
>>>>>>>>> debug log:
>>>>>>>>>
>>>>>>>>> http://www.simonandkate.net/imaplog.txt
>>>>>>>>>
>>>>>>>>> That UID list returned from Cyrus is correct - 46072 is the last
>>>>>>>>> (newest) email that is actually in the mailbox. It appears that
>>>>>>>>> Cyrus is sending the correct info. Imp shows this correctly. Yet AS
>>>>>>>>> into iOS is not showing this, with four emails showing that  
>>>>>>>>> are newer.
>>>>>>>>>
>>>>>>>>> The AS log for this is as follows:
>>>>>>>>>
>>>>>>>>> http://www.simonandkate.net/asimap.txt
>>>>>>>>>
>>>>>>>>> That also shows the correct UID sequence. Yet iPhone continues to
>>>>>>>>> show the old list of emails - not being told to update?
>>>>>>>>
>>>>>>>> Actually, this log was very helpful. It doesn't contain *any* UID
>>>>>>>> Sequences at all. I'm not talking about just the UIDNEXT value, but
>>>>>>>> the entire sequence of message UIDs that ActiveSync thinks is on the
>>>>>>>> device. This should be visible in the 'm' parameter of the state that
>>>>>>>> is saved (and would basically look like a large array of integers).
>>>>>>>> Yours is showing an empty array. This would definitely cause deleted
>>>>>>>> emails from not being detected since we perform an array_diff on the
>>>>>>>> list we have and the list the IMAP server has. The question is, *why*
>>>>>>>> you don't have a valid list of UIDs. Something must be wiping in the
>>>>>>>> code somewhere, I'll have to dig further on that during my next coding
>>>>>>>> sprint later this week.
>>>>>>> Yay!! I was starting to get a bit disheartened, but that's  
>>>>>>> great news that the log gives you something useful.
>>>>>>
>>>>>> I've spent about an hour trying to reproduce this and can't.  
>>>>>> I've disabled features on my IMAP server to emulate not having  
>>>>>> per-mailbox MODSEQ values like your IMAP server, tried IMAP  
>>>>>> caching on/off, performed dozens of mailbox operations from  
>>>>>> various MUAs and activesync clients. I'm not able to lose  
>>>>>> ActiveSync's internal message cache nor am I able to see any  
>>>>>> code path where the message state would be reset.
>>>>>>
>>>>>> You are going to need to start from a fresh account,  
>>>>>> synchronize it, and find the point where your log goes from  
>>>>>> having the proper state to an empty state.
>>>>>>
>>>>>> 2013-03-05T20:39:14-05:00 DEBUG: [8689] Saving state: Array
>>>>>> (
>>>>>> [0] => {51369e16-4154-423a-bcf7-21f2c0a8015f}25
>>>>>> [1] => Horde_Db_Value_Binary Object
>>>>>>    (
>>>>>>        [_value:protected] =>  
>>>>>> C:28:"Horde_ActiveSync_Folder_Imap":1184:{a:5:{s:1:"s";a:3:{s:7:"uidnext";s:6:"168028";s:11:"uidvalidity";s:10:"1292457115";s:13:"highestmodseq";i:0;}s:1:"m";a:21:{i:167587;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167604;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167612;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167638;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167642;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167643;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167648;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167665;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167666;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167672;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167679;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167712;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167721;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167753;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167758;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:168018;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168019;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:1
 6
> 8
>>
>>> 2
>>>> 4;a
>>>>>> :2:{s:4:
>>>>>> "read";i:1;s:7:"flagged";i:0;}i:168025;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168026;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168027;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}
>>>>>>    )
>>>>>>
>>>>>> [2] => ApplGB024LGPZ3A
>>>>>> [3] => 1362533954
>>>>>> [4] => INBOX
>>>>>> [5] => mike
>>>>>> [6] => 0
>>>>>> )
>>>>>> Note the entries after the "m" value. This is the message state  
>>>>>> for this folder. Now, YOUR log looks like this:
>>>>>>
>>>>>> 2013-03-04T11:30:07+00:00 DEBUG: [14497] Saving state: Array
>>>>>> (
>>>>>> [0] => {51347830-a744-4382-b47a-214dc0a801e6}110
>>>>>> [1] => Horde_Db_Value_Binary Object
>>>>>>    (
>>>>>>        [_value:protected] =>  
>>>>>> C:28:"Horde_ActiveSync_Folder_Imap":174:{a:5:{s:1:"s";a:3:{s:13:"highestmodseq";i:0;s:7:"uidnext";s:5:"46217";s:11:"uidvalidity";s:10:"1238677126";}s:1:"m";a:0:{}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}
>>>>>>    )
>>>>>>
>>>>>> [2] => Appl79030T3BA4S
>>>>>> [3] => 1362396607
>>>>>> [4] => INBOX
>>>>>> [5] => simon
>>>>>> [6] => 0
>>>>>> )
>>>>>>
>>>>>> Note the "m";a:0: value. This means your internal message state  
>>>>>> is empty. I.e., the ActiveSync state cache thinks the INBOX on  
>>>>>> your device is empty - so we have no context to pass to  
>>>>>> Horde_Imap_Client when asking for the list of vanished  
>>>>>> messages. (This will always return an empty list).
>>>>>>
>>>>>>
>>>>>> --
>>>>>> mike
>>>>>>
>>>>>> The Horde Project (www.horde.org)
>>>>>> mrubinsk at horde.org
>>>>>
>>>>> Ok. I'll remove the device from AS in horde, remove its log  
>>>>> file, and connect as my test account, that only has about 3  
>>>>> emails in it and 2 appts. Will the horde inline debug function  
>>>>> that can be thrown into the php help me anywhere?
>>>>
>>>> Possibly, though since I have no idea where this is being  
>>>> cleared, I don't know where to tell you to put it yet.
>>>>
>>>>
>>>> -- 
>>> Finally got some time to test this some more.
>>>
>>> I took my iPad, deleted the account on it, restarted it. Removed  
>>> the Horde AS device log file, and removed from the AS device list  
>>> in Horde.
>>>
>>> Added as my test account on the iPad, and added ONLY mail.  
>>> Interestingly, the autodiscover redirect failed to strip the  
>>> @domain name, and I had to manually configure.
>>>
>>> Immediately sync'ed up, and iPad showed no emails (3 in the  
>>> account but too old, so were filtered out).
>>>
>>> Sent an email to the account, and it appeared fine on the iPad.  
>>> Read it in Imp, and the flag change worked and synced to iPad.
>>>
>>> Deleted it in Imp, and it disappeared in iPad. The log shows "m";a:1.
>
> And this is *still* wrong. That is actually not even a valid  
> serialized value.
>
> According to your earlier logs, your IMAP server does not support  
> per-mailbox MODSEQ values. In this case, the messages array (which  
> is what "m" represents) contains both the message uids AND the flag  
> data (see my example posted earlier in the thread above). Unless  
> *this* account, for some reason, has MODSEQ support enabled, this  
> makes absolutely no sense to me whatsoever.
>
>
>
> -- 
> mike
>

The whole line from when using my test account is in the link I posted:

[_value:protected] =>  
C:28:"Horde_ActiveSync_Folder_Imap":215:{a:5:{s:1:"s";a:3:{s:13:"highestmodseq";i:0;s:7:"uidnext";s:2:"19";s:11:"uidvalidity";s:10:"1238677130";}s:1:"m";a:1:{i:18;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}

Simon.

--
Simon Wilson
M: 0400 12 11 16
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: PGP Digital Signature
URL: <http://lists.horde.org/archives/horde/attachments/20130413/340508bf/attachment.bin>